David Reid wrote:
What follows is a profile for beos bone running 1000 connections using a single thread (-DONE_PROCESS). Columns are
no. of calls time in calls time incl sub calls function name
Raises some interesting questions, like how many times do we call ap_palloc/ap_pcalloc/lock/unlock and stat for 1000 requests? I've chopped some of the lower order ones off the end to try and stop it being too huge.
It'd be interesting to know where the ap_pallocs & ap_pcalloc are as it looks like we're using a good few pre request...
The following data might be useful. It's a fragment of a gprof function call profile showing the major callers of apr_palloc/apr_pcalloc. In the test case that produced this profile, I sent the httpd 500,000 requests for a server-parsed file that included 5 other server-parsed files.
The biggest customers of apr_palloc include ap_merge_per_dir_configs (from directory_walk), bucket brigades (apr_brigade_create plus apr_pool_cleanup_register for the registration of bucket cleanups), subrequest creation (in particular the creation of tables in the sub-request_rec), and lots of apr_pstrcat and apr_pstrdup operations.
The brigade overhead in particular might explain a lot of the slowness of mod_include in 2.0, relative to 1.3. Does anybody have ideas on how to optimize this? For clarity, I've omitted all callers that did less than one apr_palloc or apr_palloc call per request:
#of calls function
---------------- -------------------------
0.00 0.00 500000/231005645 basic_http_header [111]
0.00 0.00 500000/231005645 apr_itoa [138]
0.00 0.00 500000/231005645 apr_parse_addr_port [139]
0.00 0.00 1000000/231005645 ap_getword_white [127]
0.00 0.00 1000000/231005645 apr_sockaddr_ip_get [128]
0.00 0.00 1500000/231005645 config_log_transaction [102]
0.00 0.00 1500000/231005645 get_mime_headers [85]
0.00 0.00 2500000/231005645 apr_table_copy [78]
0.00 0.00 3000000/231005645 ap_make_method_list [67]
0.00 0.00 3000000/231005645 analyze_ct [61]
0.00 0.00 3000000/231005645 find_ct [51]
0.00 0.00 3000000/231005645 ap_set_last_modified [92]
0.00 0.00 3000000/231005645 directory_walk [39]
0.00 0.00 3500000/231005645 apr_off_t_toa [88]
0.00 0.00 3500233/231005645 apr_array_make [70]
0.00 0.00 4500000/231005645 mmap_setaside [66]
0.00 0.00 9000000/231005645 ap_merge_per_dir_configs [37]
0.00 0.00 9000000/231005645 merge_core_dir_configs [40]
0.00 0.00 9500050/231005645 apr_pstrndup [64]
0.00 0.00 11500020/231005645 apr_table_make [46]
0.00 0.00 12500233/231005645 apr_pstrcat [60]
0.00 0.00 19000000/231005645 apr_brigade_create [41]
0.00 0.00 19500969/231005645 apr_pstrdup [49]
0.00 0.00 27000000/231005645 apr_array_copy_hdr [45]
0.00 0.00 30000070/231005645 apr_pool_cleanup_register [43]
0.00 0.00 48501583/231005645 apr_pcalloc [36]
[23] 10.3 0.00 0.00 231005645 apr_palloc [23]
The numbers in the column just before the function names mean that, for example, apr_pcalloc made 48,501,583 of the 231,005,645 calls to apr_palloc in the test.
The top callers of apr_pcalloc were:
#of calls function
---------------- -------------------------
0.00 0.00 500000/48501583 ap_http_filter <cycle 3> [118]
0.00 0.00 500000/48501583 ap_new_connection [99]
0.00 0.00 500000/48501583 ap_read_request [38]
0.00 0.00 500000/48501583 ap_content_length_filter <cycle 1> [58]
0.00 0.00 500000/48501583 core_output_filter [108]
0.00 0.00 500000/48501583 core_create_req [116]
0.00 0.00 1500006/48501583 alloc_socket [112]
0.00 0.00 2500000/48501583 make_sub_request [30]
0.00 0.00 3000000/48501583 includes_filter <cycle 1> [55]
0.00 0.00 3000000/48501583 apr_array_cat [94]
0.00 0.00 3000000/48501583 apr_mmap_create [73]
0.00 0.00 3000008/48501583 apr_file_open [65]
0.00 0.00 3500014/48501583 create_empty_config [87]
0.00 0.00 8500000/48501583 add_any_filter [68]
0.00 0.00 17500253/48501583 make_array_core [52]
[36] 2.2 0.00 0.00 48501583 apr_pcalloc [36]
0.00 0.00 48501583/231005645 apr_palloc [23]
