Tracing apr calls in Apache using dtrace

pid provider can be used to trace apr calls in apache. At first step we need to create probes for the apache processes. Following script will create probes for a single process.

# createprobes.d
pid$1::apr_*:entry
/execname == "httpd"/
{
}

pid$1::apr_*:return
/execname == "httpd"/
{
}

profile:::tick-2sec
{
    exit(0);
}

Now run the script for all httpd processes.

# for each in `pgrep httpd`; 
do 
   echo "each = $each"; 
   dtrace -s createprobes.d $each; 
done

Once the probes are created, we can use the dtrace script can be used to trace apr calls in apache.

pid*::apr_*:entry
/execname == "httpd"/
{
}

pid*::apr_*:return
/execname == "httpd"/
{
}

To execute the above script, we do not need any builtin probes inside apache. It is the pid provider which inserts the probe in user code.
If we run this script we see the following output (snippet)

# dtrace -s apr-trace.d
CPU     ID                    FUNCTION:NAME
  0  73552  apr_pool_cleanup_register:entry
  0  73535                 apr_palloc:entry
  0  78695                apr_palloc:return
  0  79116 apr_pool_cleanup_register:return
  0  79191         apr_socket_accept:return
    ...

To measure the time taken for each apr routine, we need to do the difference between the timing. Here is the aprtime.d

pid*::apr_*:entry
/execname == "httpd"/
{
    ts[probefunc] = timestamp;
}

pid*::apr_*:return
/execname == "httpd"/
{
    printf("%d nsecs", timestamp - ts[probefunc]);
}

# dtrace -s aprtime.d
CPU     ID                    FUNCTION:NAME
  0  78695                apr_palloc:return 16834 nsecs
  0  79116 apr_pool_cleanup_register:return 51750 nsecs
  0  79078     apr_thread_mutex_lock:return 11250 nsecs
  0  79086    apr_thread_cond_signal:return 14750 nsecs
  0  79080   apr_thread_mutex_unlock:return 31167 nsecs
  0  79078     apr_thread_mutex_lock:return 6500 nsecs
  ...

Posted at 04:24PM Aug 22, 2008 by Basant Kukreja in apache  |  Comments[0]