Want to know how to get rough profiling of any tool written in any language, whether you control the source or not? Keep reading.

For example, here's the output you get when you compile Go from source code. Each of these lines prints out a few seconds apart. How would you go about getting timings for each individual step, or how would you notice if one step was suddenly executing much more slowly than it did three days ago?

$ GOROOT_BOOTSTRAP=~/go1.10 ./make.bash
Building Go cmd/dist using /Users/kevin/go1.10.
Building Go toolchain1 using /Users/kevin/go1.10.
Building Go bootstrap cmd/go (go_bootstrap) using Go toolchain1.
Building Go toolchain2 using go_bootstrap and Go toolchain1.
Building Go toolchain3 using go_bootstrap and Go toolchain2.
Building packages and commands for darwin/amd64.
---
Installed Go for darwin/amd64 in /Users/kevin/go
Installed commands in /Users/kevin/go/bin

There are a few different methods you can use to get a sense for this, but I wanted to share my favorite one. Don't reach for a profiler, don't try to set a global variable, or do start/stop timing in code. Don't even start figuring out how to configure a logger to print timestamps, and use a log output format.

Then when you've done all this, rerun the command and pass it through a command that attaches timestamps to every output line. For example, I have a tool called tss (based on ts in the moreutils package) that does this. Pipe your command to tss and you'll get output like this:

$ GOROOT_BOOTSTRAP=~/go1.10 ./make.bash | tss
     11ms         Building Go cmd/dist using /Users/kevin/go1.10.
    690ms   679ms Building Go toolchain1 using /Users/kevin/go1.10.
  11.435s 10.745s Building Go bootstrap cmd/go (go_bootstrap) using Go toolchain1.
  18.483s  7.048s Building Go toolchain2 using go_bootstrap and Go toolchain1.
  40.788s 22.305s Building Go toolchain3 using go_bootstrap and Go toolchain2.
 1m0.112s 19.324s Building packages and commands for darwin/amd64.
1m19.053s 18.942s ---
1m19.053s      0s Installed Go for darwin/amd64 in /Users/kevin/go
1m19.053s      0s Installed commands in /Users/kevin/go/bin

The first column is the amount of time that has elapsed since the tool was invoked. The second column is the amount of time that has elapsed since the previous line was printed.

The good thing about this technique is you can use it in pretty much any situation - you don't have to know anything about the code besides:

• how to invoke it
• a rough idea of which code paths get hit
• how to print things to stdout

Just start adding print lines around interesting bits of code.

For example, you might have this in your test suite in Ruby to empty the database. How much time does this add to every test in your suite? Put print lines before and after to find out.

config.after(:each) do
  puts "database clean start"
  DatabaseCleaner.clean
  puts "database clean end"
end

Similarly, if you wanted to find out why it takes so long for your test suite to start running or your web framework to boot, you can annotate your spec_helper or bootstrap file, the top of the test file, before and after require lines, and the start and end of the first test in the suite. You can even drill down into third party libraries, just find the source file on disk and start adding print statements.

You can also use it with strace! strace will show you a list of the syscalls being opened by your program. Passing the output through tss can show you which syscall activity is taking a lot of time, or when your program is doing a lot of stuff without going to the disk.

Caveats

If you pipe program a to program b, and program a exits with a non-zero return code, Bash will by default report a return code of zero for the entire operation. This means if you are piping output to tss or ts you may accidentally change a failing program to a passing one. Use set -o pipefail in Bash scripts to ensure that Bash will return a non-zero return code if any part of a pipe operation fails. Or add this to a Makefile:

SHELL = /bin/bash -o pipefail

Second, the program being profiled may not flush output to stdout, that is, it may print something but it may not appear on the screen at the same time it was printed. If the timings on screen don't seem to match up with your intuition, check that the program is flushing print statements to the stdout file descriptor after printing them.

Liked what you read? I am available for hire.