It looks like SysAdmin magazine is running my article Debugging Web Applications in this months issue. If you are looking for ways to debug problematic web servers and applications, this article might be for you.
I decided to re-partition my x86 laptop hard drive today, which required me to re-install FreeBSD (the disk label changed rather drastically). After I hit “commit” to propogate the changes, I hit “control-alt-F2” and was thrown into virtual terminal #2. This virtual terminal contained the output from the package extractions, and I found it a bit more useful that the progress meter that was updating in virtual terminal #1. I digs me some FreeBSD!
I have been spending a good bit of time trying to understand how Apache works, and started to wonder which methods could be used to understand how large software packages work. After pondering this for a bit, it dawned on me that DTrace’s flowindent and ustack() / stack() functions are ideal for reverse engineering software. To illustrate what I am talking about, say you want to see what to watch the call flow between the Apache ap_run_create_connection() and ap_run_process_connection() hooks. You can read the source code to put together a call flow diagram, or you can run the following DTrace script:
$ cat apacheflow.d
#pragma D option flowindent
pid$target::ap_run_create_connection:entry
{
self->follow = 1;
}
pid$target::ap_run_process_connection:return
{
self->follow = 0
}
pid$target:::entry,
pid$target:::return
/ self->follow /
{}
$ dtrace -ppgrep httpd -s apacheflow.d
dtrace: script 'apacheflow.d' matched 16943 probes
CPU FUNCTION
0 -> ap_run_create_connection
0 -> core_create_conn
0 -> apr_palloc
0 <- apr_palloc
0 -> memset
0 <- memset
0 -> ap_update_child_status
0 <- ap_update_child_status
0 -> ap_update_child_status_from_indexes
0 <- ap_update_child_status_from_indexes
0 -> ap_create_conn_config
0 <- ap_create_conn_config
0 -> create_empty_config
0 -> apr_palloc
0 <- apr_palloc
0 -> memset
0 <- memset
0 <- create_empty_config
[ ..... ]
0 <- ap_rgetline_core
0 -> apr_time_now
0 -> gettimeofday
0 <- gettimeofday
0 <- apr_time_now
0 -> apr_brigade_destroy
0 -> apr_pool_cleanup_kill
0 <- apr_pool_cleanup_kill
0 <- apr_brigade_destroy
0 -> apr_brigade_cleanup
0 <- apr_brigade_cleanup
0 <- ap_read_request
0 <- ap_process_http_connection
I have found this useful for watching specific call paths, and for understanding the system impacts of specific call paths. Since you can also instrument each and every instruction in a function*, Clay thinks this could be useful for viewing branches while reading the output of dis(1).
Unfortunately you cannot view the original instruction that was executed, but it sounds like Adam Leventhalis working on a fix for this! When his fix is put back into Solaris, this will be sweeeeeet!
While trussing a process today, I came across several lines similar to the following:
$ truss -r all -w all -x all -v all -leaf -p 1234
[ ..... ]
sys#208(0x0000000F, 0x10009E050, 0x00000000, 0x00000000, 0x00000000) =
0x00000000 [0x10009E050]
This line doesn’t contain the system call name, but contains a “sys#” block to indicate which system call was invoked (in this case system call #208). To get a text description for system call #208, the grep utility can be used (you could also look through the source code):
$ grep 208 /usr/include/sys/syscall.h
#define SYS_sparc_utrap_install 208
If you have never poked around syscall.h, I highly recommend doing so.
I have been playing with DTrace now for 4 - 5 months, and have created numerous notes to help me remember the probes that can be used to understand vmstat and mpstat output. To ease life in the future (finding this stuff at 3am when a “situation” arises is a pain), I wrote a DTrace mpstat and vmstat cookbook titled Understanding mpstat and vmstat with DTrace. Hope folks find this useful.