Just another WordPress site

Main menu

Post navigation

Profiling and Tracing Processes in Linux

This article shows how a Linux process can be traced and profiled. Using the “last” command as an example, profiling is used to explain why a process was very slow, and why another, very similar, process (dump-utmp) was much faster. “Tracing” here means seeing what a process is doing at any moment. “Profiling” means showing (afterwards) how long it spent doing different things.

“Last” is a Linux command that reads and summarizes the utmp file, where login records are stored. I had a “last” command taking hours to complete because the utmp file had grown large (1.9 Gb). Used strace to see what it was doing.

Last processes the wtmp file in reverse, which is why it is calling llseek() all the time to move backwards in the file (by 16 k chunks). However this does not explain the slowness. The “last” process was maxing out one CPU, ie. it was CPU bound. Why so ?

The “last” process is spending nearly all of its time (99.92%) in strncmp(), a compute-intensive C library function for comparing 2 strings. Which explains why the last process was hogging a whole CPU and executing so slowly.

The wmtp file had grown so large because the system (an FTP server) was receiving up to 300 FTP connections per minute and logging them all.

Regarding wtmp, there exists another command called dump-utmp, which can process the whole 1.9 Gb utmp file in 2.5 minutes (“last” would take at least 3 hours, possibly many more, if left to complete. The full command was:

# dump-utmp ./wtmp > test.out

Using strace and ltrace on dump-utmp shows that the command processes the wtmp file forwards and so does not need to call lseek() all the time like “last“. Also it just seems to read and write the data, not bothering with comparing strings or other processing, and produces a much more “raw” report than the output of “last“.

So Linux contains some pretty cool tracing tools. The above was on Red Hat. A quick shufty indicates ltrace and strace are readily available in Fedora 16 and Debian Squeeze, for example.

Footnote

Truss offers strace-like functionality in Solaris. Use truss -p for tracing system calls, and truss -c -p for profiling. The options for tracing library calls are a little more complicated – see this example.