strace is a command line program that runs from one of the Linux shells. A shell is another program that allows a system administrator to interact with a Linux operating system – for example to run strace.
The strace utility is the crudest form of trouble shooting in Linux. It essentially hijacks the target program and traces all system function calls. Think of it as another program that attaches to the target program and snoops on its actions. The output of strace isn’t pretty either. One has to build a certain understanding and intuitiveness to make good use of it.
So how many times have you wondered what that Apache process is doing exactly pegging the CPU? Or how many times have you wondered why a certain PHP process dies unexpectedly? Well strace might help answer those questions. The strace output looks like this (don’t let this scare you. I’ll explain):
Process 6716 attached - interrupt to quit
restart_syscall(<... resuming interrupted call ...>) = 0
gettimeofday({1249790094, 207969}, NULL) = 0
open("/sys/devices/system/cpu/cpu0/cpufreq/scaling_governor", O_RDONLY) = 18
read(18, "ondemand\n", 1024) = 9
read(18, "", 1024) = 0
close(18) = 0
open("/sys/devices/system/cpu/cpu0/cpufreq/scaling_cur_freq", O_RDONLY) = 18
read(18, "1200000\n", 1024) = 8
read(18, "", 1024) = 0
close(18) = 0
read(3, 0x80708a4, 4096) = -1 EAGAIN (Resource temporarily unavailable)
gettimeofday({1249790094, 209927}, NULL) = 0
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=8, events=POLLIN|POLLPRI}, {fd=10, events=POLLIN|POLLPRI}, {fd=11, events=POLLIN|POLLPRI}, {fd=12, events=POLLIN|POLLPRI}, {fd=14, events=POLLIN|POLLPRI}, {fd=13, events=POLLIN|POLLPRI}, {fd=15, events=POLLIN|POLLPRI}, {fd=16, events=POLLIN|POLLPRI}], 10, 0) = 0
select(4, [3], [3], NULL, NULL) = 1 (out [3])
writev(3, [{"5\30\4\0\327W\300\2#\0\300\2S\0\27\0\233\4\5\0\330W\300"..., 520}], 1) = 520
read(3, 0x80708a4, 4096) = -1 EAGAIN (Resource temporarily unavailable)
read(3, 0x80708a4, 4096) = -1 EAGAIN (Resource temporarily unavailable)
gettimeofday({1249790094, 212466}, NULL) = 0
poll([{fd=4, events=POLLIN}, {fd=3, events=POLLIN}, {fd=8, events=POLLIN|POLLPRI}, {fd=10, events=POLLIN|POLLPRI}, {fd=11, events=POLLIN|POLLPRI}, {fd=12, events=POLLIN|POLLPRI}, {fd=14, events=POLLIN|POLLPRI}, {fd=13, events=POLLIN|POLLPRI}, {fd=15, events=POLLIN|POLLPRI}, {fd=16, events=POLLIN|POLLPRI}], 10, 996) = 0
gettimeofday({1249790095, 208261}, NULL) = 0
open("/sys/devices/system/cpu/cpu0/cpufreq/scaling_governor", O_RDONLY) = 18
Each line in the above output represents an action made by the target program except the first two lines. The first one informs us that strace will begin tracing the program in question. The second one is made to recover from a half executed function system call.
The remaining lines are of importance and that’s what we need to study to figure what our target program is doing. Each line represents a function call the program is making and the result of the call. For example, this system call open
open("/sys/devices/system/cpu/cpu0/cpufreq/scaling_governor", O_RDONLY) = 18
opens a file with certain attributes. The returned status is 18. What does the number 18 mean? What does O_RDONLY mean? RTFM! That is Read The Fine Manual! Linux comes with documentation tools that explain all these function calls and whatnot. In this example, open is the function. We can search for it and read its manual as such:
# apropos open
open (3posix) – open a file
# man 3 open
The manual page format can be cumbersome at first and it takes a bit of time to get used to it. Don’t let it discourage you! From reading manual we are able to understand more about the function call. Per the manual, return value 18 represents the “lowest numbered unused file descriptor.” We also understand what O_RDONLY means: Open file for reading only. Etcetera.
If you look back up at the strace output, you’ll note that shortly after the open() function call was made, close(18) followed it. We’ll need to go through the same process to read up on the system call close(). But the value 18 is deja vu! That’s the file descriptor number returned by open(). In other words, the program is opening a file /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor read-only then and then closing it.
We cannot go over each and every system call but you should be able to use the above process to understand pretty much any system call. But what would one be looking for when a program is not doing what it’s supposed to do and is failing? The Matrix sends agents after it to kill it! Just kidding! You have to go through each and every system call and check on the return status in the manual to understand if that is normal behavior or not. You can redirect the strace output to file so you can sift the (enormous) amount of data it produces:
strace -o /tmp/progra_strace.out -p
That’s all for today folks. I hope you enjoyed this one!
UNIXy Break-Fix apache process, linux, php process, strace, strace apache, strace php, syscall, system call, truss