In an attempt to learn how DTrace probes and Apache work, I called up my friend Clay last week, and we sat down to integrate some probes into Apache. After looking through the Apache source code and analyzing the available documentation on statically defined probes, we determined that adding probes would be simple, but getting apache to build would be a bit tedious (luckily Clay is an autoconf/libtool expert!!). After mucking with the build process for a few hours, Clay was able to tweak the APR (Apache Portable Runtime) Makefile.in, and we were able to integrate numerous DTrace probes into Apache. The first probe we added was in the apr_palloc() routine:
$ dtrace -l | grep apr_palloc
10 apache_apr1940 libapr-0.so.0 apr_palloc apr_palloc-entry
17 apache_apr17002 libapr-0.so.0 apr_palloc apr_palloc-entry
36851 apache_apr1939 libapr-0.so.0 apr_palloc apr_palloc-entry
This probe would be helpful for figuring out which pools were accessed, and for determing the number of bytes allocated to each pool:
$ dtrace -n '::apr_palloc: { printf("Allocated %d bytes to pool %s", (*(int *)(copyin(arg0,sizeof(int)))), copyinstr(arg1)); }'
dtrace: description '::apr_palloc: ' matched 3 probes
CPU ID FUNCTION:NAME
0 10 apr_palloc:apr_palloc Allocated 16 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 84 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 340 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 280 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 60 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 16 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 16 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 16 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 20 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 20 bytes to pool transaction
0 10 apr_palloc:apr_palloc Allocated 392 bytes to pool request
0 10 apr_palloc:apr_palloc Allocated 16 bytes to pool request
0 10 apr_palloc:apr_palloc Allocated 20 bytes to pool request
0 10 apr_palloc:apr_palloc Allocated 8 bytes to pool request
We can also use this probe to understand how frequently apr_palloc() gets called:
$ dtrace -q -n '::apr_palloc: { @calls[probefunc,pid] = count(); } dtrace:::END { printa(@calls); }'
^C
apr_palloc 1939 4
apr_palloc 1940 156
apr_palloc 17002 654
After toying with the memory management layer (the really interesting stuff comes from the Apache allocator() routines – but that is a BLOG entry in and of itself), we decided to add a probe to display incoming connections:
$ dtrace -l | grep apr_socket_accept
5 apache_apr9965 libapr-0.so.0 apr_socket_accept apr_socket_accept
12 apache_apr9966 libapr-0.so.0 apr_socket_accept apr_socket_accept
36845 apache_apr9976 libapr-0.so.0 apr_socket_accept apr_socket_accept
$ dtrace -q -n '::apr_socket_accept: { printf(" Pid: %d
Result: %d
IP Address: %x
SRC Port %d “,pid, *(int *)copyin(arg0,4), *(int *)copyin(arg1,4), *(short int *)copyin(arg2,4)); }‘`
Pid: 9999
Result: 10
IP Address: c0a80103
SRC Port 33874
Pid: 9976
Result: 10
IP Address: c0a80108
SRC Port 61918
Pid: 9966
Result: 10
IP Address: c0a80108
SRC Port 61919
This probe will display the httpd process id that accept()‘ed the
connection along with the SRC port ad IP address of the client. Since we
could get this information from either snoop(1m) or the dtrace syscall
provider, we decided to move on to the request processing routines.
After analyzing the files in
APACHE_SRC_ROOT/srclib/apr/network_io/unix, we decided to add
probes to the APR send and receive routines:
$ dtrace -l | egrep '(apr_socket_recv|apr_socket_send)'
6 apache_apr9965 libapr-0.so.0 apr_socket_recv apr_socket_recv
7 apache_apr9965 libapr-0.so.0 apr_socket_send apr_socket_send
13 apache_apr9966 libapr-0.so.0 apr_socket_recv apr_socket_recv
14 apache_apr9966 libapr-0.so.0 apr_socket_send apr_socket_send
36846 apache_apr9976 libapr-0.so.0 apr_socket_recv apr_socket_recv
36847 apache_apr9976 libapr-0.so.0 apr_socket_send apr_socket_send
Once the probes were integrated into the send and receive routines, we could use our probes to view the data read and written by each httpd process (this information can also be obtained from the syscall provider’s read and write probes):
$ dtrace -q -n '::apr_socket_recv: { printf("Received the following
buffer
%s
“,copyinstr(arg0)); }‘`
Received the following buffer
Received the following buffer
GET / HTTP/1.1
Host: 192.168.1.3:8080
User-Agent: Mozilla/5.0 (Macintosh; U; PPC Mac OS X Mach-O; en-US;
rv:1.8) Gecko/20051111 Firefox/1.5
Accept:
text/xml,application/xml,application/xhtml+xml,text/html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Acc
Received the following buffer
Received the following buffer
GET /apache_pb.gif HTTP/1.1
Host: 192.168.1.3:8080
User-Agent: Mozilla/5.0 (Macintosh; U; PPC Mac OS X Mach-O; en-US;
rv:1.8) Gecko/20051111 Firefox/1.5
Accept: image/png,*/*;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept
Received the following buffer
HTTP/1.1 304 Not Modified
Date: Mon, 21 Nov 2005 00:08:30TGMT:00-04:00
Server: Apache
Connection: Keep-Alive
Keep-Alive: timeout=15, max=99
ETag: "4be83-916-a64a7c40"
- [20/Nov/2005:19:08:30 -0500] "GET / HTTP/1.1" 304 -
y: negotiate,accept-language,accept
I was amazed at how easy it was to add probes, and found this excercise extremely beneficial! While I learned after the fact that the pid provider would do everything we wanted, it was still a fun learning experience, and helped me understand Apache at a more granular level! Viva la DTrace!