Show HN: Timep – A next-gen profiler and flamegraph-generator for bash code
github.comA part of me thinks that if you have to profile a Bash script, it's a sign that you've surpassed its intended use case, and a proper programming language with all its modern tooling would be a saner way forward. But then again, that line is often blurry, and if the script has already grown in size, it might be a sunk cost to consider rewriting it, so I can see cases where this tool would come in handy.
I find it hard to believe that there is minimal overhead from the instrumentation, as the README claims. Surely the additional traps alone introduce an overhead, and tracking the elapsed time of each operation even more so. It would be interesting to know what the actual overhead is. Perhaps this is difficult to measure with a small script, whereas a larger one would show a greater difference.
The profile output is a bit difficult to parse at first glance, but I think I get it after a closer look.
In any case, this is some next-level wizardry. The amount of patience required to instrument Bash scripts must've been monumental. Kudos to you, Sir.
BTW, you're probably aware of it, but you might want to consider using Bats[1] for tests. I've found it helpful for small scripts.
EDIT: I took a look at `timep.bash`, and I may have nightmares tonight... Sweet, fancy Moses.
Also, I really don't like that it downloads and loads some random .so files, and base64-encoded blobs. I would personally not use this based on that alone, and you shouldn't assume that users will trust you. If this is required for correct functionality, have a separate well-documented step for users to download the required files manually. Or better yet: make their source visible as well, and have users compile them on their own.
>I find it hard to believe that there is minimal overhead from the instrumentation, as the README claims. Surely the additional traps alone introduce an overhead, and tracking the elapsed time of each operation even more so. It would be interesting to know what the actual overhead is.
note that timep does a 2 pass approach - it runs the code with instrumentation just logging the data it needs, and then after the code finishes it goes back and uses that data to generate the profile and flamegraphs. For "overhead" im just talking abut in the initial profiling run...total time to getting results is a bit longer (but still pretty damn fast).
if you run timep with the `-t` flag it will run profiling run of the code (with the trap-based instrumentation enabled and recording) inside of a `time { ... }` block. You can then compare that timed to the running the code without using timep, giving you overhead. I used that method while running a highly parallelized test that, between 28 persistent workers, ran around 67000 individual bash commands (and computed 17.6 million checksums of a bunch of small files in a ramdisk) in 34.5 or so seconds (without timep). using `timep -t` to run the code this increased to 38 seconds. So +10%. And thats really a worst case scenario...it indicates the per command overhead is around 1 ms. what percent if the total run time that translates to depends on the average time-per-command-run for the code you are profiling.
side note: in this case, the total time to generate a profile was ~2.5 minutes and the total time to generate a profile and flamegraphs was ~5 minutes
timep manages to keep it so low because the debug trap instrumentation is 100% bash builtins and doesnt spawn and subshells or forks - so you just have a string of builtin commands with no context switching nor any "copying the environment to fork something" to slow you down.
> The amount of patience required to instrument Bash scripts must've been monumental.
It took literally months to get everything working correctly and all the edge cases worked out properly. Bash does some borderline bizarre things behind the scenes.
> EDIT: I took a look at `timep.bash`, and I may have nightmares tonight... Sweet, fancy Moses.
Its a little bit...involved.
> Also, I really don't like that it downloads and loads some random .so files
So by default it doesnt do this. It has the ability to, but you have to to explicitly tell it to....it wont do it automatically.
By default, it will get the .so file using the base64 blob (in ascii string representation and compressed) that is built into timep.bash. This has sha256 and md5 checksums incorporated into it that get checked when the .so file is re-created using that base64 blob (to ensure no corruption).
the .so file is needed to add a bash loadable builtin that outputs microsecond granularity CPU usage time. Without this it will try and use /proc/stat, which works but the measurement is 10000x more coarse (typically it displays cpu time in number of 10 ms intervals). to get microsecond accuracy you need the .so file.
> Or better yet: make their source visible as well, and have users compile them on their own.
the source is available in the repo at https://github.com/jkool702/timep/blob/main/LIB/LOADABLES/SR...
compile instructions are at the top in commented out lines.
the code is pretty straightforward - it uses getrusage and/or (if available) clock_gettime to get cpu usage for itself and its children.
the `_timep_SETUP` function has the logic included (but not used by default - you have to manually call it with a flag) to let allow you to use a .so file that is in your current directory instead of the one generated from the builtin base64 blob. So, you are able, should you wish, to compile and have timep use your own .so for the loadable.
However, realistically, most people who might be interested in using timep wont do that. So it defaults to fully automating this and having it all self contained in a single script file, while allowing for advanced users to manually override it. I thought that was the best overall way to do it.
> using `timep -t` to run the code this increased to 38 seconds. So +10%.
Thanks. I suppose this will depend on each script, as there is another commenter here claiming that the overhead is much higher.
Re: the binary, that's fine. Your approach is surely easier to use than asking users to compile it themselves, but I would still prefer to have that option. After all, how do I know that that binary came from that source code? So a simple Make target to build it would put my concerns to rest. It's something that only has to be done once, anyway, so it's not a huge inconvenience.
In any case, it's pretty cool that you wrote the CPU time tracking in C. I wasn't even aware that Bash was so easily extensible.
You've clearly put a lot of thought and effort into this project, which is commendable. Good luck!
The better way to think about overhead with timep is "average overhead per command run" (or more specifically per debug trap fire). this value wont change all that much between profiling different bash scripts
The code that commenter was profiling was a rubix cube solver that was impressively well optimized: 100% builtins, no forking, all the expensive operations were pre-computed and saved in huge lookup tables (some of which had over 400,000 elements), vars passed by reference to avoid making copies, etc. The overhead from timep was about 230 microseconds per command, but that code was averaging a microsecond or two per command.
To put it in perspective, bash's overhead any time it calls an external binary is 1-2 ms. so in a script that did nothing but call `/bin/true` repeatedly timep's overhead would probably be a little under 20%.
> Re: the binary, that's fine. Your approach is surely easier to use than asking users to compile it themselves, but I would still prefer to have that option.
I mean technically you can, but i'll give you that its not really documented unless you read through all the comments in the code. A makefile is probably doable and would make the process more straightforward.
that said, its on my to do list to figure out how i can setup a github actions workflow to have github automatically build the .so files for all the different architectures whenever timep.c changes. Perhaps that would alleviate your concern.
> After all, how do I know that that binary came from that source code?
I mean, you can say that about virtually any compiled binary. sure , some of them (like from your distro's official repos) have been "signed off" on by someone you trust, but that is a leap of faith you have to make with anything you install from a 3rd party. And, in general, i feel like "compiling it yourself" doesnt really make it safer unless you personally (or someone you trust personally) look through the source to check that it doesnt do anything malicious.
> I wasn't even aware that Bash was so easily extensible.
bash supporting loadable builtins isnt a well known feature. Its really quite handy when you want to do something (e.g., access to a syscall) that bash doesnt support and you cant / dont want to used a external tool for it.
IMO, the biggest hurdle behind using them is that they make scripts much less portable - you either need to setup a distribution system for it (and require the target system has internet access, at least briefly) and/or require the target system has a full build environment and can compile it. which are both sorta crappy options.
unless, of course, you were to base64 encode the binary and directly include it inside of the script. ;)
Im aware of it, but have never ended up actually using it. Ive heard before the sentiment you imply - that its great for fairly simple script...but not so much for long and complicated scripts. And, well, the handful of bash projects that Ive developed enough to have the desire to add unit testing for are all range from "long and complicated" to "nightmare inducing" (lol).
Its on my "to try" list one day, but I have a sneaking suspicion that timep is not a good project to try out BATS for the first time on.
That said, migrating a large and purpose-built test suite to it would have no practical benefit, but it's worth considering for your next greenfield project. Cheers!
1. declares all the variables timep uses to track state and things like that 2. initializes all the extra stuff needed to make the instrumentation work (initial values for some variables, defining instrumented traps, setting `set -T`, etc.) 3. runs the code to be profiled. for scripts the script content is added here. For raw commands the commands are added. For functions the function is defined and then called as a function.
this is saved as a script in the timep tmpdir (by default a unique directory under /dev/shm/.timep), made executable, and then it is run. The setup is done like this for a few reasons, but the biggest of those is "to get correct LINENOs.
This makes it so that LINENO gives a correct result, only it is shifted by however many lines it takes to do steps 1 and 2.so the code records the lineno just before the "code to be profiled" starts running, so it can shift it back the right amount when it records it.
That said, timep has a handful of very minor bugs (4 to be precise) - one of them is that fir functions that call a subshell the lineno is wrong (it is shifted forward by a few hundred lines). So it isnt quite 100% perfect, but is pretty close.
(side note: the other 3 bugs have to do with command grouping in the output being ever so slightly off for deeply nested subshell + background fork sequences).
timep also includes a function that I wrote that tries to get the original function code (instead of the version that `declare -f` outputs), so that the lineno's on functions match up better with the original function definition source code.
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
with profiling there's a bunch of errors but overall it's ~300x slower https://i.imgur.com/qif7Qp3.png so i'm sceptical on all the efficiency claims
Try profiling cube.bash with the timep version in the "timep_testing" branch (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.
Sorry the overhead is too high (relative to cube.bash's insanely low avg command runtime of something like 1 microsecond) to be really useful as a profiler...hopefully itll still prove useful strictly for mapping the code execution/structure and seeing how many times a given function got called and things of that nature.