Profiling Apache modules with DTrace
While poking around the Apache source code this weekend, I started to wonder which Apache modules consumed the most CPU time servicing HTTP requests. Since I had Apache installed on a Solaris 10 box, I threw together a D script named apachemoduleprof to answer this question:
$ apachemoduleprof `pgrep httpd`
Started Apache Request Profiler (Control-C to stop...)
*** New connection ***
Connection start: 2005 Dec 12 18:38:03
Connection stop : 2005 Dec 12 18:38:04
Method URI Count
GET / 1
Module Processing Time
mod_actions.so 24005 ns
mod_expires.so 47337 ns
mod_log_forensic.so 61466 ns
mod_dir.so 74525 ns
mod_info.so 76032 ns
mod_autoindex.so 76927 ns
mod_userdir.so 80814 ns
mod_speling.so 83850 ns
mod_vhost_alias.so 84157 ns
mod_asis.so 94340 ns
mod_cgi.so 99906 ns
mod_usertrack.so 100358 ns
mod_imap.so 101102 ns
mod_cern_meta.so 112784 ns
mod_headers.so 143674 ns
mod_status.so 147744 ns
mod_access.so 169724 ns
mod_dav.so 175717 ns
mod_env.so 177622 ns
mod_unique_id.so 247845 ns
mod_negotiation.so 267640 ns
mod_auth_digest.so 272762 ns
mod_dtrace.so 372322 ns
mod_rewrite.so 437157 ns
mod_include.so 905436 ns
mod_alias.so 1717912 ns
mod_log_config.so 1982180 ns
mod_setenvif.so 2803176 ns
mod_mime.so 3748429 ns
httpd 17620455 ns
Total 32 ms
Hook Name Module Hook Function Time
ap_run_log_transaction mod_log_forensic.so log_after 20739 ns
ap_run_handler mod_actions.so action_handler 24005 ns
ap_run_pre_connection mod_dtrace.so apache_pre_connection 24587 ns
ap_run_access_checker httpd do_nothing 32272 ns
ap_run_header_parser mod_setenvif.so match_headers 40581 ns
ap_run_post_read_request mod_log_forensic.so log_before 40727 ns
ap_run_insert_filter httpd core_insert_filter 43937 ns
ap_run_post_read_request mod_dtrace.so apache_receive_request 45105 ns
ap_run_access_checker mod_dtrace.so apache_check_access 45678 ns
ap_run_insert_filter mod_expires.so expires_insert_filter 47337 ns
ap_run_handler mod_negotiation.so handle_map_file 48780 ns
ap_run_create_connection mod_dtrace.so apache_create_connection 53110 ns
ap_run_insert_filter mod_headers.so ap_headers_insert_output_filter 54983 ns
ap_run_handler mod_dav.so dav_handler 70031 ns
ap_run_handler mod_rewrite.so handler_redirect 71183 ns
ap_run_log_transaction mod_dtrace.so apache_log_request 71983 ns
ap_run_fixups mod_dir.so fixup_dir 74525 ns
ap_run_handler mod_info.so display_info 76032 ns
ap_run_handler mod_autoindex.so handle_autoindex 76927 ns
ap_run_translate_name mod_userdir.so translate_userdir 80814 ns
ap_run_fixups mod_speling.so check_speling 83850 ns
ap_run_translate_name mod_vhost_alias.so mva_translate 84157 ns
ap_run_translate_name mod_rewrite.so hook_uri2file 85999 ns
ap_run_fixups mod_headers.so ap_headers_fixup 88691 ns
ap_run_handler mod_asis.so asis_handler 94340 ns
ap_run_fixups mod_rewrite.so hook_fixup 96737 ns
ap_run_fixups mod_negotiation.so fix_encoding 98537 ns
ap_run_handler mod_cgi.so cgi_handler 99906 ns
ap_run_fixups mod_usertrack.so spot_cookie 100358 ns
ap_run_fixups mod_auth_digest.so add_auth_info 100773 ns
ap_run_handler mod_imap.so imap_handler 101102 ns
ap_run_fixups httpd core_override_type 105600 ns
ap_run_fixups mod_dav.so dav_fixups 105686 ns
ap_run_map_to_storage httpd ap_send_http_trace 108333 ns
ap_run_fixups mod_cern_meta.so add_cern_meta_data 112784 ns
ap_run_type_checker mod_negotiation.so handle_multi 120323 ns
ap_run_create_request mod_dtrace.so apache_create_request 131859 ns
ap_run_handler mod_status.so status_handler 147744 ns
ap_run_pre_connection httpd core_pre_connection 160052 ns
ap_run_access_checker mod_access.so check_dir_access 169724 ns
ap_run_fixups mod_alias.so fixup_redir 170886 ns
ap_run_post_read_request mod_auth_digest.so parse_hdr_and_update_nc 171989 ns
ap_run_fixups mod_env.so fixup_env_module 177622 ns
ap_run_type_checker mod_rewrite.so hook_mimetype 183238 ns
ap_run_post_read_request mod_unique_id.so gen_unique_id 247845 ns
ap_run_create_request httpd http_create_request 389379 ns
ap_run_translate_name httpd ap_core_translate 444739 ns
ap_run_create_request httpd core_create_req 624600 ns
ap_run_fixups mod_include.so include_fixup 905436 ns
ap_run_create_connection httpd core_create_conn 1042453 ns
ap_run_translate_name mod_alias.so translate_alias_redir 1547026 ns
ap_run_log_transaction mod_log_config.so multi_log_transaction 1982180 ns
ap_run_post_read_request mod_setenvif.so match_headers 2762595 ns
ap_run_type_checker mod_mime.so find_ct 3748429 ns
ap_run_handler httpd default_handler 6766633 ns
ap_run_map_to_storage httpd core_map_to_storage 7902457 ns
After running this a few times, I noticed that the httpd core along with a few other modules consumed most of the CPU time. To see which functions were the busiest in each module, I threw together the apachemodulefunctime D script:
$ apachemodulefunctime `pgrep httpd` mod_log_config.so
Tracing Apache Module mod_log_config.so (Control-C to stop) Module Function Time mod_log_config.so log_remote_user 21732 mod_log_config.so log_request_line 22737 mod_log_config.so clf_log_bytes_sent 24603 mod_log_config.so log_remote_logname 51210 mod_log_config.so log_remote_host 52674 mod_log_config.so constant_item 118539 mod_log_config.so log_status 140340 mod_log_config.so ap_default_log_writer 444106 mod_log_config.so config_log_transaction 523044 mod_log_config.so multi_log_transaction 597611 mod_log_config.so log_request_time 896752 Total Time: 2893348
This example shows each function that is called in the mod_log_config Apache module, and provides a timestamp from the function entry to the function exit. This was super useful information, but I also wanted to see which functions were called from mod_log_config. This was easy enough with the following DTrace script:
$ cat whocall.d
dtrace:::BEGIN
{
once = 1;
}
pid$target::log_request_time:entry
{
self->follow = 1;
}
pid$target::log_request_time:return
{
self->follow = 0;
once = 0;
}
pid$target:::entry
/self->follow && once/
{
self->ts = timestamp;
}
pid$target:::return
/self->follow && once/
{
@functions[probefunc] = count();
@total[probefunc] = sum(timestamp - self->ts);
}
dtrace:::END
{
printf("%-30s %-20s\n","Function", "Times Called");
printa("%-30s %-@20d\n",@functions);
printf("\n%-30s %-20s\n","Function", "Total Execution Time");
printa("%-30s %-@20d\n",@total);
}
$ dtrace -p `pgrep httpd` -q -s whocall.d
Function Times Called .rem 1 ap_explode_recent_localtime 1 apr_palloc 1 apr_snprintf 1 apr_time_exp_lt 1 apr_vformatter 1 cached_explode 1 explode_time 1 findenv 1 getenv 1 getsystemTZ 1 lmutex_lock 1 lmutex_unlock 1 localtime_r 1 ltzset_u 1 offtime_u 1 set_zone_context 1 strlen 1 .div 2 __moddi3 2 strcmp 2 __divdi3 3 conv_10 7 .udiv 14 Function Total Execution Time .rem 28896 strlen 30713 lmutex_lock 32096 lmutex_unlock 32096 offtime_u 34203 findenv 35492 ap_explode_recent_localtime 36634 set_zone_context 40452 .div 52620 strcmp 59259 __moddi3 61988 ltzset_u 84287 getsystemTZ 86064 cached_explode 88502 getenv 90303 localtime_r 91428 __divdi3 98886 apr_vformatter 140929 explode_time 147786 apr_snprintf 196226 apr_time_exp_lt 204179 .udiv 399397 conv_10 582217 apr_palloc 2114263
AS we can see from this output, the apr_palloc routine takes the longest time to execute. This is as expected, since apr_palloc() needs to call the Apache allocator to find free memory and allocate memory if allocation slots aren’t availablet. Now to see if there are any efficiency gains to be made in the allocator! :)
