strace – tracing syscall by example
Posted by danielJul 6
The strace command allows us to trace the system calls made by a program. In this blog, I will show you how you can use strace to capture some of the syscalls made by Apache when clients make http requests. strace has several options, but here we will consider only the following options –
<code>-p : attach to the process with the process ID pid -o filename : write the strace output to the file filename rather than to stderr -ff : If the -o filename option is in effect, each processes trace is written to filename.pid where pid is the numeric process id of each process. -e expr : to filter only specific syscalls (eg. open, fstat etc.)</code>
We will attach strace to the parent process for the apache threads. With -ff specified, strace will trace all children of the parent process and saves the trace output to a file named filename.PID. We will be using ab(Apache HTTP server benchmarking tool) to generate traffic to the web server and see which files apache opens during client requests by explicitly looking for open syscall.
1. Let us find the parent process –
ns1 strace # ps xo comm,pid,ppid | grep apache2 apache2 2062 1
The PID to trace in this case is 2062.
2. Run strace command, while this is running, launch another session and run the ab command –
ns1 strace # strace -ff -o wiki.home.net -e trace=open,close -p 2062
Process 2062 attached - interrupt to quit
Process 18526 attached
Process 18531 attached
Process 18532 attached
Process 18536 attached
Process 18537 attached
Process 18538 attached
Process 18539 attached
Process 18526 detached
Process 18531 detached
Process 18532 detached
Process 18538 detached
^CProcess 2062 detached
Process 18536 detached
Process 18537 detached
Process 18539 detached
140706133405:root:homevm:/home/daniel:# ab -n 25 -c 10 http://wiki.home.net./
This is ApacheBench, Version 2.3 <$Revision: 655654 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking wiki.home.net. (be patient).....done
Server Software: Apache/2.2.22
Server Hostname: wiki.home.net.
Server Port: 80
Document Path: /
Document Length: 0 bytes
Concurrency Level: 10
Time taken for tests: 20.595 seconds
Complete requests: 25
Failed requests: 0
Write errors: 0
Non-2xx responses: 25
Total transferred: 11300 bytes
HTML transferred: 0 bytes
Requests per second: 1.21 [#/sec] (mean)
Time per request: 8237.856 [ms] (mean)
Time per request: 823.786 [ms] (mean, across all concurrent requests)
Transfer rate: 0.54 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 1 282 459.3 2 1004
Processing: 5372 6551 733.6 6846 7631
Waiting: 367 1546 734.1 1842 2629
Total: 5374 6833 991.9 7199 8049
Percentage of the requests served within a certain time (ms)
50% 7170
66% 7616
75% 7819
80% 7933
90% 8005
95% 8013
98% 8049
99% 8049
100% 8049 (longest request)
3. Once ab completes, stop the strace command and do ls in current directory to see the output of strace command for each apache thread which was serving the http request as well as the strace output for the parent process
ns1 strace # ls -l total 88 -rw-r--r-- 1 root root 10617 Jul 6 13:34 wiki.home.net.18526 -rw-r--r-- 1 root root 10617 Jul 6 13:34 wiki.home.net.18531 -rw-r--r-- 1 root root 10617 Jul 6 13:34 wiki.home.net.18532 -rw-r--r-- 1 root root 10441 Jul 6 13:34 wiki.home.net.18536 -rw-r--r-- 1 root root 10441 Jul 6 13:34 wiki.home.net.18537 -rw-r--r-- 1 root root 10617 Jul 6 13:34 wiki.home.net.18538 -rw-r--r-- 1 root root 10441 Jul 6 13:34 wiki.home.net.18539 -rw-r--r-- 1 root root 581 Jul 6 13:34 wiki.home.net.2062
4. As you can see the apache parent process doesn’t serve any client requests, the child threads are the ones serving the client requests and in each strace output for the child threads we can see the files accesses/opend –
strace output for parent process -
ns1 strace # cat wiki.home.net.2062
close(20) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
close(20) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
close(20) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
close(20) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
close(20) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
close(20) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
close(20) = 0
--- SIGCHLD (Child exited) @ 0 (0) ---
ns1 strace # head -25 wiki.home.net.18526
open("/proc/sys/kernel/ngroups_max", O_RDONLY) = 20
close(20) = 0
open("/etc/group", O_RDONLY|O_CLOEXEC) = 20
close(20) = 0
open("/.htaccess", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/var/.htaccess", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
open("/var/www/.htaccess", O_RDONLY|O_CLOEXEC) = -1 ENOENT (No such file or directory)
close(22) = 0
close(22) = 0
close(22) = 0
open("/var/www/wiki/index.php", O_RDONLY) = 22
close(22) = 0
open("/var/www/wiki/includes/WebStart.php", O_RDONLY) = 22
close(22) = 0
open("/var/www/wiki/includes/Init.php", O_RDONLY) = 22
close(22) = 0
open("/var/www/wiki/includes/AutoLoader.php", O_RDONLY) = 22
close(22) = 0
open("/var/www/wiki/includes/profiler/Profiler.php", O_RDONLY) = 22
close(22) = 0
open("/var/www/wiki/includes/Defines.php", O_RDONLY) = 22
close(22) = 0
open("/var/www/wiki/includes/normal/UtfNormalDefines.php", O_RDONLY) = 22
close(22) = 0
open("/var/www/wiki/includes/DefaultSettings.php", O_RDONLY) = 22
5 comments
You must be logged in to post a comment.