Blog

Tracing system calls using “Strace”

Tags: process executionstrace

Scenario:

Suppose some program on your system refuses to work or it works, but much slower than you’ve expected. How can you investigate the reason of such undesirable behavior? This technique will often be helpful in troubleshooting, PHP issues as well. Let us see how to use the strace command.

First of all, you can read and analyse logs that this program does (if it does). It’s very useful to run unkindly program with –verbose argument or somehow else increase the log level, if the program allows that. But what can you do, if logs are poor and it’s impossible to infer the reason of badness from them? One way is to use strace program to follow system calls performed by given process.

What is strace?

Strace is quite simply a tool that traces the execution of system calls. In its simplest form it can trace the execution of a binary from start to end, and output a line of text with the name of the system call, the arguments and the return value for every system call over the lifetime of the process.

Use of strace command

Commonly to use strace you should give the following command:

 strace -o outputfile command 

Here , I am attempting to grasp the system calls during the file creation  from a users shell, where he fails to create or update a file using the command “touch /tmp/file”

 strace -o strace.out touch /tmp/file 

Here

-o strace.out option means that strace program will output all information to the file named strace.out;

touch /tmp/file is the program with arguments which is to be straced.

Strace command results
So this is what we have in strace.out:

$ cat strace.out
execve(“/usr/bin/touch”, [“touch”, “/tmp/file”], [/* 58 vars */]) = 0
brk(0) = 0x871c000
access(“/etc/ld.so.nohwcap”, F_OK) = -1 ENOENT (No such file or directory)
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb77a0000
access(“/etc/ld.so.preload”, R_OK) = -1 ENOENT (No such file or directory)
open(“/etc/ld.so.cache”, O_RDONLY|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=81742, …}) = 0
mmap2(NULL, 81742, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb778c000
close(3) = 0
access(“/etc/ld.so.nohwcap”, F_OK) = -1 ENOENT (No such file or directory)
open(“/lib/i386-linux-gnu/libc.so.6”, O_RDONLY|O_CLOEXEC) = 3
read(3, “\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0\3\0\1\0\0\0\340\233\1\0004\0\0\0″…, 512) = 512
fstat64(3, {st_mode=S_IFREG|0755, st_size=1754876, …}) = 0
mmap2(NULL, 1763964, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb75dd000
mmap2(0xb7786000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1a8000) = 0xb7786000
mmap2(0xb7789000, 10876, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb7789000
close(3) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb75dc000
set_thread_area({entry_number:-1 -> 6, base_addr:0xb75dc940, limit:1048575, seg_32bit:1, contents:0, read_exec_only:0, limit_in_pages:1, seg_not_present:0, useable:1}) = 0
mprotect(0xb7786000, 8192, PROT_READ) = 0
mprotect(0x8055000, 4096, PROT_READ) = 0
mprotect(0xb77c3000, 4096, PROT_READ) = 0
munmap(0xb778c000, 81742) = 0
brk(0) = 0x871c000
brk(0x873d000) = 0x873d000
open(“/usr/lib/locale/locale-archive”, O_RDONLY|O_LARGEFILE|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=8752496, …}) = 0
mmap2(NULL, 2097152, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb73dc000
mmap2(NULL, 4096, PROT_READ, MAP_PRIVATE, 3, 0x855000) = 0xb779f000
close(3) = 0
open(“/tmp/file”, O_WRONLY|O_CREAT|O_NOCTTY|O_NONBLOCK|O_LARGEFILE, 0666) = -1 EACCES (Permission denied)
utimensat(AT_FDCWD, “/tmp/file”, NULL, 0) = 0
close(1) = 0
close(2) = 0
exit_group(0) = ?
+++ exited with 0 +++

In this case we can see that the system calls to create the file or update the time stamp faces permission issues

open(“/tmp/file”, O_WRONLY|O_NONBLOCK|O_CREAT|O_NOCTTY|O_LARGEFILE, 0666) = -1 EACCES (Permission denied)

Lets us cross check the permission of /tmp/file

$ls -l /tmp/file
---------- 1 geo geo 0 Aug 6 13:22 /tmp/file

So it is evident that the file permissions were the culprit here. So  I went ahead and changed the permissions

$ chmod 644 /tmp/file

Now check the relevant parts of the  strace results again

mmap2(NULL, 4096, PROT_READ, MAP_PRIVATE, 3, 0x855000) = 0xb7718000
close(3) = 0
open(“/tmp/file”, O_WRONLY|O_CREAT|O_NOCTTY|O_NONBLOCK|O_LARGEFILE, 0666) = 3
dup2(3, 0) = 0
close(3) = 0
utimensat(0, NULL, NULL, 0) = 0
close(0) = 0
close(1) = 0
close(2) = 0
exit_group(0) = ?
+++ exited with 0 +++

Now you can see that the permission issue is resolved. The above example is probably one of the most easiest one.

Strace is quite powerful and is one of the most useful tool used for trouble shooting php script execution issues.

 Even if you can not understand strace command output yourself — send it to the developers, it’ll be really helpful 🙂

Category : Howtos, Linux, Troubleshooting