4 ms·
Show HN: Timep – A next-gen profiler and flamegraph-generator for bash code
Note: this is an update to [this](https://news.ycombinator.com/item?id=44568529 https://news.ycombinator.com/item?id=44568529) "Show HN" post.
timep is a state-of-the-art [debug-]trap-based bash profiler that is efficient and extremely accurate. Unlike other profilers, timep records:
1. per-command wall-clock time
2. per-command CPU time, and
3. the hierarchy of parent function calls /subshells for each command
the wall-clock + CPU time combination allows you to determine if a particular command is CPU-bound or IO-bound, and the hierarchical logging gives you a map of how the code actually executed.
The standout feature of timep is that it will take these records and automatically generate a bash-native flamegraph (that shows bash commands, not syscalls).
------------------------------------------------
USAGE
timep is extremely easy to use - just source the `timep.bash` file from the repo and add "timep" in front of whatever you want to profile. for example:
. /path/to/timep.bash
timep ./some_script
echo "stdin" | timep some_function
ZERO changes need to be made to the code being profiled!
------------------------------------------------
EXAMPLES
[test code that will be profiled](https://github.com/jkool702/timep/blob/main/TESTS/timep.tests.bash https://github.com/jkool702/timep/blob/main/TESTS/timep.test...)
[output profile for that test code](https://github.com/jkool702/timep/blob/main/TESTS/OUTPUT/out.profile https://github.com/jkool702/timep/blob/main/TESTS/OUTPUT/out...)
[flamegraph for that test code](https://github.com/jkool702/timep/blob/main/TESTS/OUTPUT/flamegraph.ALL.svg https://github.com/jkool702/timep/blob/main/TESTS/OUTPUT/fla...)
[flamegraph from a "real world" test of "forkrun", a parallelization engine written in bash](https://github.com/jkool702/timep/blob/main/TESTS/FORKRUN/flamegraph.ALL.svg https://github.com/jkool702/timep/blob/main/TESTS/FORKRUN/fl...)
In the "forkrun test", 13 different checksums were computed for ~670k small files on a ramdisk using 28 parallel workers. this was repeated twice. In total, this test ran around 67,000 individual bash commands. [This is its `perf stat` (without timep)](https://github.com/jkool702/timep/blob/main/TESTS/FORKRUN/perf.compare.txt https://github.com/jkool702/timep/blob/main/TESTS/FORKRUN/pe...).
------------------------------------------------
EFFICIENCY AND ACCURACY
The forkrun test (see "examples" section above) was basically as demanding of a workload as one can have in bash. it fully utilized 24.5 cores on a 14c/28t i9-7940x CPU, racking up >840 seconds of CPU time in ~34.5 seconds of wall-clock time. When profiling this group of 67,000 commands with timep:
1. the time it took for the code to run with the debug-trap instrumentation was ~38 seconds, an increase of just slightly over 10%. CPU time had a similiar increase.
2. the time profile was ready at +2 minutes (1 minute + 15 seconds after the profiling run finished)
3. the flamegraphs were ready at +5 minutes (4 minute + 15 seconds after the profiling run finished)
Note that timep records both "start" and "stop" timestamps for every command, and the debug trap instrumentation runs between one commands "stop" timestamp and the next commands "start" timestamp, meaning the error in the profiles timings is far less than the 10% overhead. Comparing the total (sys+user) CPU time that perf stat gave (without using timep) and the CPU time timep gives (from summing together the CPU time of all 67,000-ish commands), the difference is virtually always less than 0.5%, and often less than 0.2%. Ive seen as low as 0.04%, which is 1/3 of a second on a run that took ~850 seconds of CPU time.
------------------------------------------------
MAJOR CHANGES SINCE THE LAST "SHOW HN" POST
1. CPU time is now recorded too (instead of just wall-clock time). This is done via a loadable builtin that calls `getrusage` and (if available) `clock_gettime` to efficiently and accurate determine the CPU time of the process and all its descendants.
2. the .so file required to use the loadable builtin mentioned in #1 is built directly into the script has an embedded compressed base64 sequence. I also developed the bash-native compression scheme that it uses. The .so files for x86_64, aarch64, ppc64le and i686 are all included. Im hoping to add arm7 soon as well. the flamegraph generator perl script is also embedded, making the script 100% fully self-contained. NOTE: these embedded base64 strings include both sha256 and md5 checksums of the resulting .so file that are verified on extraction.
3. the flamegraph generation has been completely overhauled. The flamegraphs now a) are colored based on runtime (hot colors = longer runtime), b) desaturate colors for commands where cpu time << wall-clock time (e.g., blocking reads, sleep, wait, ...), and c) use a runtime-weighted CDF color mapping that ensures, regardless of the distribution of the underlying data, that the resulting flamegraph has a roughly equal amount of each color in the colorspace (where "equal" means "the same number of pixels are showing each color"). timep also combines multiple flamegraphs (that show wallclock time vs cpu time and that us the full vs folded set of traces) by vertically stacking them into a single SVG image, giving "dual stack" and "quad stack" flamegraphs.
4. the post-processing workflow has been basically completely re-written, making it more robust, easier to understand/maintain, and much faster. The "forkrun" test linked above (that ran 67,000 commands) previously took ~20 minutes. With the new version, you can get a profile in 2 minutes or a profile + flamegraph in 5 minutes - a 4x to 10x speedup!
- izabera 1y agotested it on this https://github.com/izabera/cube.bash/tree/timep https://github.com/izabera/cube.bash/tree/timep i ran `source /path/to/timep.bash; timep ./cube.bash "R U R' U' R' F R2 U' R' U' R U R' F'"` without profiling https://i.imgur.com/JE93ony.png https://i.imgur.com/JE93ony.png with profiling there's a bunch of errors but overall it's ~300x slower https://i.imgur.com/qif7Qp3.png https://i.imgur.com/qif7Qp3.png so i'm sceptical on all the efficiency claims
- jkool702 1y agoIt took some time, but I figured out what was causing the errors when profiling cube.bash - the code assigns huge (some >400,000 elements) associative arrays in a single command, and timep was taking the full (several MB) $BASH_COMMAND from those and trying to do stuff with it and bash couldnt handle it. Try profiling cube.bash with the timep version in the "timep_testing" branch (https://github.com/jkool702/timep/blob/timep_testing/timep.bash https://github.com/jkool702/timep/blob/timep_testing/timep.b...). This is my "in development" branch that contains a handful of improvements, one of which is that timep will truncate the BASH_COMMAND at 16kb. On my machine at least that timep version successfully profiles cube.bash. now - regarding efficiency. timep's overhead is more-or-less constant per command (or, more specifically, per debug trap fire). what "percent overhead" this equates to is entirely dependent on how long the average command being profiled takes to run. And for things like base.cube, that are virtually all builtin commands that dont fork, that time is low. For cube.bash it is really pretty remarkably low. Looking at the "full" profile and stack trace that timep generated, running cube.bash involved running around 7150 commands. I also profiled a modified version that stops at the ` echo scramble: "$@"` line - that one was about 3350 commands. Meaning the timed part of cube.bash (where it actually solves the cube) represents about 3800 bash commands. This part of the code (when run by timep) took 870 ms or so on my system. which puts the per-command overhead at under 1/4 of 1 ms (about 230 microseconds to be precise). 230 microseconds per command is best-in-class for a trap-based profiler - many take an order of magnitude (or more) longer and dont collect cpu times or the code structure metadata needed to reconstruct the full call stack. To put it in perspective, bash (on my system at least) has 1-2 ms overhead every time it runs an external binary. Your cube.bash is just impressively stupidly fast, so much so that the 230 microseconds still introduces considerable overhead.