[PR #139] [MERGED] Add timep #3828

New Issue

GiteaMirror · 2026-07-10T17:53:26-05:00

GiteaMirror commented

2026-07-10 17:53:26 -05:00

📋 Pull Request Information

Original PR: https://github.com/awesome-lists/awesome-bash/pull/139
Author: @jkool702
Created: 7/17/2025
Status: ✅ Merged
Merged: 7/25/2025
Merged by: @hyperupcall

Base: master ← Head: master

📝 Commits (1)

195c6f6 Update README.md

📊 Changes

1 file changed (+1 additions, -0 deletions)

View changed files

📝 README.md (+1 -0)

📄 Description

New App Submission

I've read the contribution guidelines.

NOTE: I officially released timep within the past few days, but I've been working on the code for several months. It began life in this repo, but after 250 commits and 22 different timep_testing branches I figured it was time to give it its own dedicated repo. Hopefully this meets the "at least 90 days old" criteria.

Repo or homepage link: https://github.com/jkool702/timep

Description: timep is an efficient and accurate state-of-the-art trap-based profiler and flamegraph generator for bash code. timep does much more than "providing per-command execution times" -- it maps the full call-stack tree for the bash code being profiled, and (optionally) uses that call-stack tree to generate a FlameGraph of the profiled bash commands!

timep will automatically set up timing instrumentation using DEBUG/EXIT/RETURN traps and run your code (redirecting stdin to it if needed). It overloads the trap builtin with a trap function that allows the instrumentation to continue to work even if the code being profiled sets its own DEBUG/EXIT/RETURN traps. ZERO changes need to be made to the code - just source timep.bash and add timep before whatever you want to profile.

Why I think it's awesome: I think timep is "awesome" because it is the first of its kind.

Sure there are other profilers for bash out there, but (to the best of my knowledge) these all basically just give you per command (or per line) execution time. timep gives you this as well (of course), but timep is the first profiler to also map structure as it profiles. For each command it figures out both:

what type of command it is (normal command, subshell, background fork, simple fork, function, process/command substitution) and
where in the call-stack it is (run by function d, which is part of subshell c, which is part of function b, which is part of background fork a, which was forked by the main process).

Some of this info is readily available...much of it is not. For the ladder the required info is inferred (usually with the help of /proc). For example - from inside the child's debug trap, it is virtually impossible to tell if you are in a subshell or a background fork. Both cases will increment $BASH_SUBSHELL, and (from the child's perspective) neither will change $!. So timep infers this by reading and keeping track of PGID and TPID (read from /proc/$BASHPID/stat whenever $BASHPID changes). There are a handful of distinct patterns in how the TPID/PGID of parent and child are related that correspond to it being a background fork....if it doesnt match one of them its a subshell.

Oh, and the "directly being able to create a flamegraph (where all you need to do is use timep --flame instead of timep) is pretty awesome too. To clarify - this is NOT a flamegraph generated via perf - this is a flamegraph where each top-level box represents the runtime of a particular bash command, and the different levels represent entering a function or a subshell. it is a bash native flamegraph showing actual shell commands, not the calls made by the bash binary.

EXAMPLE OUTPUT:

below is an example of the profile generated for a relatively simple function.

At the bottom is a flamegraph generated from my forkrun code that computes a bunch of checksums (13 different ones) on a bunch of small files on a ramdisk (620k / 14 gb). twice (once newline-delimited, once null-delimited). Each run has 28 active workers running a function ff, which computes the 13 checksums one at a time for that batch of files.

You can clearly see both runs, and within each run you can clearly see the 28 workers running ff (plus a few other things like the main process waiting), and within each ff call you can clearly see the 13 different checksums, with their widths proportional to the relative runtimes.

Like I said...first of its kind ;)

NOTE: the flamegraph should zoom in when you click on a box. if it doesnt, download the .svg image from here and then open that locally-saved .svg file.

TIME PROFILE

testfunc() { 
f() { echo "f: $*"; }
g() ( echo "g: $*"; )
h() { 
	echo "h: $*"; 
	f "$@"; 
	g "$@";
}

echo 0
{ echo 1; }
( echo 2 )
echo 3 &
{ echo 4; } &

echo 5 | cat | tee

for (( kk=6; kk<10; kk++ )); do
	echo $kk
	h $kk
	for jj in {1..3}; do
		f $kk $jj
		g $kk $jj
	done
done
}


timep testfunc

gives

1.0:    (0.023018s|100.00%)     (1x) << (FUNCTION): testfunc "${@}" >>
|-- 1.0:        (0.000064s|00.27%)      (1x) testfunc "${@}"
|
|   8.0:        (0.000065s|00.28%)      (1x) echo 0
|
|   9.0:        (0.000665s|02.88%)      (1x) echo 1
|
|   10.0:       (0.000124s|00.53%)      (1x) << (SUBSHELL) >>
|   |-- 10.0:           (0.000124s|00.53%|100.00%)      (1x) echo 2
|
|   11.0:       (0.000450s|01.95%)      (1x) echo 3 (&)
|
|   12.0:       (0.001524s|06.62%)      (1x) << (BACKGROUND FORK) >>
|   |-- 12.0:   (0.000148s|00.64%|100.00%)      (1x) echo 4
|
|   13.0:       (0.004917s|21.36%)      (1x) echo 5 | cat | tee
|
|   15.0:       (0.000304s|01.32%)      (5x) ((kk=6))
|
|   15.1:       (0.000310s|01.34%)      (5x) ((kk<10))
|
|   16.0:       (0.000256s|01.11%)      (4x) echo $kk
|
|   17.0:       (0.004565s|19.83%)      (4x) << (FUNCTION): h $kk >>
|   |-- 1.0:    (0.000224s|00.97%|05.57%)       (4x) h $kk
|   |   8.0:    (0.000265s|01.15%|06.53%)       (4x) echo "h: $*"
|   |   9.0:    (0.000501s|02.17%|12.46%)       (4x) << (FUNCTION): f "$@" >>
|   |   |-- 1.0:        (0.000168s|00.72%|44.68%)       (3x) f "$@"
|   |   |-- 8.0:        (0.000208s|00.90%|55.31%)       (3x) echo "f: $*"
|   |   10.0:   (0.003575s|15.53%|75.40%)       (4x) << (FUNCTION): g "$@" >>
|   |   |-- 1.0:        (0.002258s|09.80%|84.62%)       (3x) g "$@"
|   |   |   330.0:      (0.000410s|01.78%|15.37%)       (3x) << (SUBSHELL) >>
|   |-- |-- |-- 330.0:  (0.000410s|01.78%|100.00%)      (3x) echo "g: $*"
|   |-- 1.0:            (0.000166s|00.72%|04.90%)       (3x) h $kk
|   |   8.0:            (0.000199s|00.86%|05.82%)       (3x) echo "h: $*"
|   |   9.0:            (0.000373s|01.62%|11.03%)       (3x) << (FUNCTION): f "$@" >>
|   |   |-- 1.0:        (0.000224s|00.97%|44.71%)       (4x) f "$@"
|   |   |-- 8.0:        (0.000277s|01.20%|55.28%)       (4x) echo "f: $*"
|   |   10.0:           (0.003064s|13.31%|78.22%)       (3x) << (FUNCTION): g "$@" >>
|   |-- 1.0:                    (0.000054s|00.23%|04.70%)       (1x) h $kk
|   |   8.0:                    (0.000063s|00.27%|05.48%)       (1x) echo "h: $*"
|   |   9.0:                    (0.000124s|00.53%|10.80%)       (1x) << (FUNCTION): f "$@" >>
|   |   10.0:                   (0.000907s|03.94%|79.00%)       (1x) << (FUNCTION): g "$@" >>
|   |   |-- 1.0:        (0.003042s|13.21%|85.07%)       (4x) g "$@"
|   |   |   330.0:      (0.000533s|02.31%|14.91%)       (4x) << (SUBSHELL) >>
|   |   |-- |-- 330.0:                  (0.000123s|00.53%|100.00%)      (1x) echo "g: $*"
|
|   18.0:       (0.000729s|03.16%)      (12x) for jj in {1..3}
|
|   19.0:       (0.001532s|06.65%)      (12x) << (FUNCTION): f $kk $jj >>
|   |-- 1.0:            (0.000444s|01.92%|43.31%)       (8x) f $kk $jj
|   |-- 8.0:            (0.000583s|02.53%|56.67%)       (8x) echo "f: $*"
|   |-- 1.0:    (0.000668s|02.90%|43.66%)       (12x) f $kk $jj
|   |-- 8.0:    (0.000864s|03.75%|56.32%)       (12x) echo "f: $*"
|
|   20.0:       (0.007511s|32.63%)      (12x) << (FUNCTION): g $kk $jj >>
|   |-- 1.0:    (0.006468s|28.09%|86.14%)       (12x) g $kk $jj
|   |   330.0:  (0.001043s|04.53%|13.84%)       (12x) << (SUBSHELL) >>
|   |-- |-- 330.0:      (0.000805s|03.49%|100.00%)      (9x) echo "g: $*"
|   |-- 1.0:            (0.005236s|22.74%|86.09%)       (10x) g $kk $jj
|   |   330.0:          (0.000849s|03.68%|13.89%)       (10x) << (SUBSHELL) >>
|   |-- |-- 330.0:      (0.001043s|04.53%|100.00%)      (12x) echo "g: $*"
|-- |-- |-- 330.0:                      (0.000232s|01.00%|100.00%)      (2x) echo "g: $*"


TOTAL RUN TIME: 0.023018s

FLAMEGRAPH

_{🔄 This issue represents a GitHub Pull Request. It cannot be merged through Gitea due to API limitations.}

## 📋 Pull Request Information **Original PR:** https://github.com/awesome-lists/awesome-bash/pull/139 **Author:** [@jkool702](https://github.com/jkool702) **Created:** 7/17/2025 **Status:** ✅ Merged **Merged:** 7/25/2025 **Merged by:** [@hyperupcall](https://github.com/hyperupcall) **Base:** `master` ← **Head:** `master` --- ### 📝 Commits (1) - [`195c6f6`](https://github.com/awesome-lists/awesome-bash/commit/195c6f641f49baedc460e56c2ef060a9e65be179) Update README.md ### 📊 Changes **1 file changed** (+1 additions, -0 deletions) <details> <summary>View changed files</summary> 📝 `README.md` (+1 -0) </details> ### 📄 Description #### New App Submission - [X] I've read the [contribution guidelines](https://github.com/awesome-lists/awesome-bash/blob/master/contributing.md). NOTE: I officially released `timep` within the past few days, but I've been working on the code for several months. It began life in [this](https://github.com/jkool702/misc-public-scripts/tree/timep_testing_22) repo, but after 250 commits and 22 different `timep_testing` branches I figured it was time to give it its own dedicated repo. Hopefully this meets the "at least 90 days old" criteria. **Repo or homepage link**: https://github.com/jkool702/timep **Description:** `timep` is an efficient and accurate state-of-the-art trap-based profiler and flamegraph generator for bash code. `timep` does much more than "providing per-command execution times" -- it maps the full call-stack tree for the bash code being profiled, and (optionally) uses that call-stack tree to generate a FlameGraph of the profiled bash commands! `timep` will automatically set up timing instrumentation using DEBUG/EXIT/RETURN traps and run your code (redirecting stdin to it if needed). It overloads the `trap` builtin with a `trap` function that allows the instrumentation to continue to work even if the code being profiled sets its own DEBUG/EXIT/RETURN traps. **ZERO** changes need to be made to the code - just source `timep.bash` and add `timep` before whatever you want to profile. **Why I think it's awesome:** I think `timep` is "awesome" because it is the first of its kind. Sure there are other profilers for bash out there, but (to the best of my knowledge) these all basically just give you per command (or per line) execution time. `timep` gives you this as well (of course), but `timep` is the first profiler to also map **structure** as it profiles. For each command it figures out both: * what *type* of command it is (normal command, subshell, background fork, simple fork, function, process/command substitution) and * *where* in the call-stack it is (run by function d, which is part of subshell c, which is part of function b, which is part of background fork a, which was forked by the main process). Some of this info is readily available...much of it is not. For the ladder the required info is inferred (usually with the help of /proc). For example - from inside the child's debug trap, it is virtually impossible to tell if you are in a subshell or a background fork. Both cases will increment `$BASH_SUBSHELL`, and (from the child's perspective) neither will change `$!`. So `timep` infers this by reading and keeping track of PGID and TPID (read from /proc/$BASHPID/stat whenever $BASHPID changes). There are a handful of distinct patterns in how the TPID/PGID of parent and child are related that correspond to it being a background fork....if it doesnt match one of them its a subshell. Oh, and the "directly being able to create a flamegraph (where all you need to do is use `timep --flame` instead of `timep`) is pretty awesome too. To clarify - this is NOT a flamegraph generated via `perf` - this is a flamegraph where each top-level box represents the runtime of a particular bash command, and the different levels represent entering a function or a subshell. it is a bash native flamegraph showing actual shell commands, not the calls made by the bash binary. EXAMPLE OUTPUT: below is an example of the profile generated for a relatively simple function. At the bottom is a flamegraph generated from my `forkrun` code that computes a bunch of checksums (13 different ones) on a bunch of small files on a ramdisk (620k / 14 gb). twice (once newline-delimited, once null-delimited). Each run has 28 active workers running a function `ff`, which computes the 13 checksums one at a time for that batch of files. You can clearly see both runs, and within each run you can clearly see the 28 workers running ff (plus a few other things like the main process waiting), and within each ff call you can clearly see the 13 different checksums, with their widths proportional to the relative runtimes. Like I said...first of its kind ;) NOTE: the flamegraph should zoom in when you click on a box. if it doesnt, download the .svg image from [here](https://github.com/jkool702/timep/blob/main/TESTS/FORKRUN/flamegraph.svg) and then open that locally-saved .svg file. **TIME PROFILE** ``` testfunc() { f() { echo "f: $*"; } g() ( echo "g: $*"; ) h() { echo "h: $*"; f "$@"; g "$@"; } echo 0 { echo 1; } ( echo 2 ) echo 3 & { echo 4; } & echo 5 | cat | tee for (( kk=6; kk<10; kk++ )); do echo $kk h $kk for jj in {1..3}; do f $kk $jj g $kk $jj done done } timep testfunc ``` gives ``` 1.0: (0.023018s|100.00%) (1x) << (FUNCTION): testfunc "${@}" >> |-- 1.0: (0.000064s|00.27%) (1x) testfunc "${@}" | | 8.0: (0.000065s|00.28%) (1x) echo 0 | | 9.0: (0.000665s|02.88%) (1x) echo 1 | | 10.0: (0.000124s|00.53%) (1x) << (SUBSHELL) >> | |-- 10.0: (0.000124s|00.53%|100.00%) (1x) echo 2 | | 11.0: (0.000450s|01.95%) (1x) echo 3 (&) | | 12.0: (0.001524s|06.62%) (1x) << (BACKGROUND FORK) >> | |-- 12.0: (0.000148s|00.64%|100.00%) (1x) echo 4 | | 13.0: (0.004917s|21.36%) (1x) echo 5 | cat | tee | | 15.0: (0.000304s|01.32%) (5x) ((kk=6)) | | 15.1: (0.000310s|01.34%) (5x) ((kk<10)) | | 16.0: (0.000256s|01.11%) (4x) echo $kk | | 17.0: (0.004565s|19.83%) (4x) << (FUNCTION): h $kk >> | |-- 1.0: (0.000224s|00.97%|05.57%) (4x) h $kk | | 8.0: (0.000265s|01.15%|06.53%) (4x) echo "h: $*" | | 9.0: (0.000501s|02.17%|12.46%) (4x) << (FUNCTION): f "$@" >> | | |-- 1.0: (0.000168s|00.72%|44.68%) (3x) f "$@" | | |-- 8.0: (0.000208s|00.90%|55.31%) (3x) echo "f: $*" | | 10.0: (0.003575s|15.53%|75.40%) (4x) << (FUNCTION): g "$@" >> | | |-- 1.0: (0.002258s|09.80%|84.62%) (3x) g "$@" | | | 330.0: (0.000410s|01.78%|15.37%) (3x) << (SUBSHELL) >> | |-- |-- |-- 330.0: (0.000410s|01.78%|100.00%) (3x) echo "g: $*" | |-- 1.0: (0.000166s|00.72%|04.90%) (3x) h $kk | | 8.0: (0.000199s|00.86%|05.82%) (3x) echo "h: $*" | | 9.0: (0.000373s|01.62%|11.03%) (3x) << (FUNCTION): f "$@" >> | | |-- 1.0: (0.000224s|00.97%|44.71%) (4x) f "$@" | | |-- 8.0: (0.000277s|01.20%|55.28%) (4x) echo "f: $*" | | 10.0: (0.003064s|13.31%|78.22%) (3x) << (FUNCTION): g "$@" >> | |-- 1.0: (0.000054s|00.23%|04.70%) (1x) h $kk | | 8.0: (0.000063s|00.27%|05.48%) (1x) echo "h: $*" | | 9.0: (0.000124s|00.53%|10.80%) (1x) << (FUNCTION): f "$@" >> | | 10.0: (0.000907s|03.94%|79.00%) (1x) << (FUNCTION): g "$@" >> | | |-- 1.0: (0.003042s|13.21%|85.07%) (4x) g "$@" | | | 330.0: (0.000533s|02.31%|14.91%) (4x) << (SUBSHELL) >> | | |-- |-- 330.0: (0.000123s|00.53%|100.00%) (1x) echo "g: $*" | | 18.0: (0.000729s|03.16%) (12x) for jj in {1..3} | | 19.0: (0.001532s|06.65%) (12x) << (FUNCTION): f $kk $jj >> | |-- 1.0: (0.000444s|01.92%|43.31%) (8x) f $kk $jj | |-- 8.0: (0.000583s|02.53%|56.67%) (8x) echo "f: $*" | |-- 1.0: (0.000668s|02.90%|43.66%) (12x) f $kk $jj | |-- 8.0: (0.000864s|03.75%|56.32%) (12x) echo "f: $*" | | 20.0: (0.007511s|32.63%) (12x) << (FUNCTION): g $kk $jj >> | |-- 1.0: (0.006468s|28.09%|86.14%) (12x) g $kk $jj | | 330.0: (0.001043s|04.53%|13.84%) (12x) << (SUBSHELL) >> | |-- |-- 330.0: (0.000805s|03.49%|100.00%) (9x) echo "g: $*" | |-- 1.0: (0.005236s|22.74%|86.09%) (10x) g $kk $jj | | 330.0: (0.000849s|03.68%|13.89%) (10x) << (SUBSHELL) >> | |-- |-- 330.0: (0.001043s|04.53%|100.00%) (12x) echo "g: $*" |-- |-- |-- 330.0: (0.000232s|01.00%|100.00%) (2x) echo "g: $*" TOTAL RUN TIME: 0.023018s ``` **FLAMEGRAPH** ![flamegraph (4)](https://github.com/user-attachments/assets/3a562820-5e7a-426d-bc8b-7c0a31e50699) --- <sub>🔄 This issue represents a GitHub Pull Request. It cannot be merged through Gitea due to API limitations.</sub>

GiteaMirror added the pull-request label 2026-07-10 17:53:27 -05:00

GiteaMirror closed this issue

2026-07-10 17:53:33 -05:00

Sign in to join this conversation.

1 Participants

Notifications

Due Date

No due date set.

Dependencies

No dependencies set.

Reference: github-starred/awesome-bash#3828