[D]Tracing Apache request processing with pid-based tools

 (truss, DTrace pid provider, etc.)

 A few of the well-known tricks (try a web search for >apache pid provider<):

  • reconfigure the Apache MPM to have a single process for handling requests
  • enable multiple listening sockets, then use pstack or other tools to find which process holds the accept mutex and is blocked in one of the poll functions; that process will handle the next connection
  • trace or attach to all the possible pids
mod_backdoor is another way. mod_backdoor provides an alternative way to send requests to httpd when the normal way doesn't work. (Read the docs for more background.) When you send requests to the mod_backdoor address, a specific, predictable process will handle that request, making the processing of that request easy to observe. The process id can be easily found by a script, making it even easier.

Here's an example of setting up mod_backdoor with Sun Web Stack on Solaris 10:

# wget http://people.apache.org/~trawick/mod_backdoor.c
# # make sure ar is found, or apxs will fail
# PATH=$PATH:/usr/ccs/bin
# export PATH
# /opt/webstack/apache2/2.2/bin/apxs -ci mod_backdoor.c
# echo "LoadModule backdoor_module /var/opt/webstack/apache2/2.2/libexec/mod_backdoor.so" > backdoor.conf
# echo "BackdoorAddress 127.0.0.1:65535" >> backdoor.conf
# cp backdoor.conf /etc/opt/webstack/apache2/2.2/conf.d/
Test the configuration change:
# /opt/webstack/apache2/2.2/bin/apachectl -t
Syntax OK
Restart Apache:
# svcadm restart sun-apache22
Make sure mod_backdoor is working:
$ firefox http://127.0.0.1:65535/

Now set up tracing. In this simple example, I'll just trace the names of all the APR calls. dtbd.sh is a helper script to find the backdoor pid and pass it to a DTrace script, and aprfuncs.d is the DTrace script.

dtbd.sh:

#!/bin/sh

LOG=/var/opt/webstack/apache2/2.2/logs/error_log
BDMSG=`grep "mod_backdoor daemon " $LOG | tail -1`

if echo $BDMSG | grep "mod_backdoor daemon not available" >/dev/null 2>&1; then
  echo "mod_backdoor was disabled when Apache restarted." 1>&2
  exit 1
fi

BDPID=`echo $BDMSG | sed -e 's/.\*mod_backdoor daemon initialized (pid \\([0-9]\*\\))/\\1/'`

echo "Running $1 against pid $BDPID..."
$1 $BDPID
aprfuncs.d:
#!/usr/sbin/dtrace -s

pid$1::apr_\*:entry
{
  printf("%s", probename);
}
Make both scripts executable, then start the tracing with the following command.  The trace data will appear once you send a request to the backdoor address:
# ./dtbd.sh ./aprfuncs.d
Running ./aprfuncs.d against pid 3124...
dtrace: script './aprfuncs.d' matched 734 probes
CPU     ID                    FUNCTION:NAME
  0  42954                 apr_palloc:entry entry
  0  42954                 apr_palloc:entry entry
  0  42954                 apr_palloc:entry entry
  0  43015      apr_sockaddr_vars_set:entry entry
  0  43015      apr_sockaddr_vars_set:entry entry
  0  42972  apr_pool_cleanup_register:entry entry
  0  42954                 apr_palloc:entry entry
  0  42954                 apr_palloc:entry entry
  0  42954                 apr_palloc:entry entry
  0  42780             apr_table_make:entry entry
  0  42954                 apr_palloc:entry entry
  0  42954                 apr_palloc:entry entry
  0  43016        apr_socket_addr_get:entry entry
  0  43014        apr_sockaddr_ip_get:entry entry
  0  42954                 apr_palloc:entry entry
  0  43013     apr_sockaddr_ip_getbuf:entry entry
(and on and on and on and on)
Comments:

Post a Comment:
Comments are closed for this entry.
About

Jeff Trawick

Search

Archives
« April 2014
SunMonTueWedThuFriSat
  
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
   
       
Today