In this post I’m going to describe some simple uses for one of my favorite command line tools: strace. In the next post, I’ll show how I used strace to fix a bug in ruby 1.8.7′s threading implementation which had significant performance implications.
strace comes standard with all linux distributions I’ve used and for good reason. strace is a handy command line tool which allows you to see which system calls a particular user application is hitting, the arguments passed passed in, and the return values. This is particularly useful if you are trying to debug cryptic error messages from poorly documented software or if you are interested in taking a peak under the hood of an application you are tuning, debugging, or optimizing. As a rule of thumb, if some command-line utility is misbehaving before googling or bugging some one, I always run strace and take a look at where it is choking up.
Let’s look at a simple C program and a simple ruby program and compare the strace output to see how both apps interact with kernel.
main(int argc, char *argv)
Both programs look pretty simple, but the strace output is not so simple. I like to use “strace -ttT executable” which gives the time each syscall was made and how long each syscall took. Check the strace man page for more flags – it is very flexible. strace allows you to track the syscall counts, filter for specific syscalls, and more.
At a high level: wow. A lot of stuff happens when you execute code, especially ruby code! Let’s take a look at some stuff in particular.
When the C-version of hello starts up, the binary is passed to execve to be executed, the heap is extended with a call to brk, and various regions of RAM are mmapped for shared libraries. Finally, we see that write is called and passed a file descriptor of 1, our message, and the length. So, this strace gives us an idea of the startup cost for a simple C executable and what syscalls that executable hits.
Let’s compare this to the strace for our ruby test script.
The ruby version of hello incurs a much greater initialization cost, but this makes sense. First, the ruby interpreter needs to be loaded which memory maps various regions of RAM for shared libraries. We can see from the strace which libraries ruby loads; in this case we see things like: libruby, libdl, libc, and libcrypt just to name a few. In the end though, ruby also calls the write system call, passes a file descriptor of 1, the message, and the length.
If a syscall fails, you would see error codes returned from the syscalls — on your local box try something like “strace /dev/null/nada” and you should see some “No such file or directory” errors.
That’s about it for my first post – If you don’t recognize some of the listed syscalls, their arguments, or return values consult the almighty man pages for more information. I hope you will work strace into your toolbox if you haven’t already. For those of you who already know about strace, this should serve as a nice warmup before we start digging into ruby internals in my next blog post.