Blog O’ Matty

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!

It looks like SysAdmin magazine just published my article titled Veritas Volume Manager Recovery Features. If you are looking for ways to increase system recoverability and to get alerted when issues popup in VxVM environments, you may enjoy this article

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:

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!!!!!!!!!!!

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!

If you ever find the need to debug Apache and want stop httpd from forking and detaching from the controlling terminal, you can start httpd with the ONE_PROCESS and NO_DETACH options:

$ /usr/sbin/httpd -DONE_PROCESS -DNO_DETACH

Once you are done debugging, you can hit control-c and the process will exit. Giddie up!

I read through the black Friday comments on Engadget, and find it amusing that people would get up at 1am to fight with people for a $378 HP laptop or a high definition television. Luckily for me I got up late this afternoon, and was super relaxed from a long night (and day) of sleep. Viva la no shopping!

Ugh — I went to patch my machines today, and it looks like the smpatch(1m) utility is broken again:

Nov 25 17:18:50 tigger root: [ID 702911 user.crit]  => com.sun.patchpro.interpreter.PatchListExpressionTree@128635 <=Internal error within exression Interpreter...
Nov 25 17:18:50 tigger root: [ID 702911 user.crit]  => com.sun.patchpro.interpreter.PatchListExpressionTree@128635 <=com.sun.patchpro.interpreter.ParseException: Encountered "haspackage " SUNWust1 11.10.0,REV=2005.08.10.02.13" at line 1, column 2.
Nov 25 17:18:50 tigger Was expecting one of:
Nov 25 17:18:50 tigger     "\n" ...
Nov 25 17:18:50 tigger      …
Nov 25 17:18:50 tigger      …
Nov 25 17:18:50 tigger root: [ID 702911 user.crit]  => com.sun.patchpro.interpreter.PatchListExpressionTree@128635 <=    "haspackage"  …
Nov 25 17:18:50 tigger     “haspackage” “”"  “”" …
Nov 25 17:18:50 tigger     “haspatch” …
Nov 25 17:18:50 tigger     “hasexactpatch” …
Nov 25 17:18:50 tigger     “haspatchbasecode” …
Nov 25 17:18:50 tigger root: [ID 702911 user.crit]  => com.sun.patchpro.interpreter.PatchListExpressionTree@128635 <=    "isosname" ...
Nov 25 17:18:50 tigger     "isosversion" ...
Nov 25 17:18:50 tigger     "isplatform" ...
Nov 25 17:18:50 tigger     "isarchitecture" ...
Nov 25 17:18:50 tigger     "hasrealization" ...
Nov 25 17:18:50 tigger root: [ID 702911 user.crit]  => com.sun.patchpro.interpreter.PatchListExpressionTree@128635 <=    "hasexactrealization" ...

I appreciate what Sun is trying to do with this utility, but it is causing users and administrators a lot of pain. If anyone from Sun is reading this, can you please revert back to Recommended patch clusters until smpatch is permanently fixed?

While looking around the Apache module directory yesterday I came across the mod_log_forensic module. This module will log the request headers from each connection, which can be useful for investigating problematic connections and security incidents. To enable mod_log_forensic during the Apache configuration process, the “–enable-log_forensic=shared” option can be passed as an argument to the configure script:

$ configure –prefix=/tmp/apache –enable-mods-shared=most –enable-log_forensic=shared

To enable mod_log_forensic, the ForensicLog command needs to be added to indicate the location to log the request headers:

$ grep ForensicLog httpd.conf
ForensicLog logs/forensic_log

Once the forensic module is setup, each request to the server will generate a log entry similar to the following:

+q4ViwcCoAQMAAEqfC5MAAAAC|GET /apache_pb.gif HTTP/1.1|Accept:*/*|Accept-Language:en|Accept-Encoding:gzip, deflate|Referer:http%3a//192.168.1.3%3a8080/|User-Agent:Mozilla/5.0 (Macintosh; U; PPC Mac OS X; en) AppleWebKit/416.11 (KHTML, like Gecko) Safari/416.12|Connection:keep-alive|Host:192.168.1.3%3a8080
-q4ViwcCoAQMAAEqfC5MAAAAC

The funny looking string of characters (the forensic id) is written before and after each request, and the headers are printed between the identifiers. This is nifty stuff!