Viewing HTTP requests with DTrace Apache Top

I worked with my friend Clay last night to add POSIX signal handlers and additional fields to the DTrace apachetop Perl script:

$ apachetop.pl

21:12:39    Requests:    347 (  69/sec)    Bytes:  35349b (7069b/sec,  101b/request)
Requests:   GETs:  347    POSTs:    0    HEADs:    0    TRACEs:    0
Responses:   1XX:    0      2XX:  301      3XX:   46       4XX:    0      5XX:    0

Requests   Requests/Sec   Bytes Sent    URI                                     
      13            2.6        13312    /blah                                   
       6            1.2            0    /manual/ja/mod/directives.html          
       6            1.2            0    /manual/ru/mod/directives.html          
       6            1.2            0    /manual/de/mod/directives.html          
       6            1.2            0    /manual/en/mod/directives.html          
       6            1.2            0    /manual/es/mod/directives.html          
       6            1.2            0    /manual/ko/mod/directives.html          
       2            0.4            0    /manual/ja/mod/                         
       2            0.4            0    /manual/es/mod/                         
       2            0.4            0    /manual/de/mod/                         
       2            0.4            0    /manual/ko/mod/                         
       2            0.4            0    /manual/en/mod/                         
       1            0.2            0    /manual/ja/mod/mod_negotiation.html     
       1            0.2            0    /manual/ja/mod/mod_isapi.html           
       1            0.2            0    /manual/ko/mod/mod_file_cache.html      
       1            0.2          344    /manual/ko/ru/mod/directives.html       
       1            0.2            0    /manual/ja/mod/mod_asis.html            
       1            0.2            0    /manual/es/mod/mod_autoindex.html       
       1            0.2            0    /manual/ru/mod/beos.html                
       1            0.2            0    /manual/ko/mod/mod_setenvif.html    

This version more closely resembles the awesome apachetop C program, but uses mod_dtrace instead of FAM and the Apache access_log to retrieve request data. Hope folks find this useful!

Solaris 10 Apache DTrace module

I sent the following e-mail message to the DTrace mailing list today announcing the release of mod_dtrace version 0.2a:

I have been working on an Apache DTrace module for the past few weeks, and just released version 0.2a. This module integrates Dtrace probes into Apache through the Apache hook framework. These probes can be used to observe and correlate a wide-variety of application and system behavior, which I have found useful for correlating network and virtual memory events with the requests served by Apache. I have written a few scripts to show some of the things I have been able to do with mod_dtrace, and have attached [1] some screenshots to this e-mail. If your interested in using mod_dtrace, you can grab the source code and shell scripts from my web site:

http://prefetch.net

This is still a work in progress, and I would love to get feedback (e.g., script enhancements, code enhancements, feature requests, recommendations etc.) from the folks on the list. I would like to thank Clay McClure, Brendan Gregg, Adam Leventhal, Bryan Cantrill, Sean McGrath and Mike Shapiro for all of their help! Thanks a ton guys!!!!!! You rock!!!!!!!!!!!!!

As mentioned in the e-mail, you can view the mod_dtrace source code and scripts by surfing over to my website. Happy mod_dtracing!!!!!!!!!!!

Monitoring Apache memory allocation with DTrace

The Apache web server uses an abstraction concept called a pool to simplify memory management in the Apache web server. Memory can be allocated and assigned to a pool (there are several pools, with different lifetimes depending on how long the memory needs to stick around) through numerous routines, including the apr_palloc() routine. This routine contains the following prototype:

void *apr_palloc(apr_pool_t *pool, apr_size_t size)

apr_palloc() and the underlying allocator routines try to allocated memory in chunks, which ensures that brk() and company aren’t called excessively. To get a better idea of how often apr_palloc() requested memory from chunks already allocated (the underlying allocator uses malloc() ), I created the following D script:

$ dtrace -q -p 4551 -n ‘
pid$target::malloc:entry
{
@malloc[probefunc] = count();
}

pid$target::apr_palloc:entry
{
@palloc[probefunc] = count();
}’

malloc                                                           22
apr_palloc                                                      671

Wow — apr_palloc() was called 671 times for 3 GET requests, and malloc() was called 22 times to meet the demand for memory (this is another reason why it’s a good idea to comment out unused modules). To see the size of each request I used the following D script:

$ dtrace -q -p 4551 -n ‘
pid$target::malloc:entry
{
@malloc[probefunc] = quantize(arg0);
}

pid$target::apr_palloc:entry
{
@palloc[probefunc] = quantize(arg1);
}’

  malloc                                            
           value  ------------- Distribution ------------- count    
              32 |                                         0        
              64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@     20       
             128 |                                         0        
             256 |                                         0        
             512 |                                         0        
            1024 |                                         0        
            2048 |                                         0        
            4096 |                                         0        
            8192 |@@@@                                     2        
           16384 |                                         0        

  apr_palloc                                        
           value  ------------- Distribution ------------- count    
               0 |                                         0        
               1 |                                         1        
               2 |@@@@                                     68       
               4 |@@                                       26       
               8 |@@@@@@@@@                                142      
              16 |@@@@@@@@@@@@@@                           219      
              32 |@@@@@                                    72       
              64 |@@                                       33       
             128 |@                                        10       
             256 |@@@                                      54       
             512 |                                         3        
            1024 |                                         0        
            2048 |                                         1        
            4096 |                                         1        
            8192 |                                         0    

One item to note — the malloc() calls may have come from a module directly, which could have thrown off the analysis performed here. I tried to issue several requests prior to capturing the data, and may need to spend some time correlating the malloc() calls with the code that actually issued them. Apache and DTrace rock!