extended module timing

IBM HTTP Server 7.0.0.23 and 8.0.0.4 contain additional mod_mpmstats functionality. This functionality is intended to help discover the source of delays in request processing, especially when third-party modules are being used.

The added functionality includes:

• Generating mod_mpmstats reports for slow requests only

• Reporting on slow modules as they finish

• Logging per-module and per-phase response times

All of the added functionality requires ExtendedStatus to be enabled as well as new directives (SlowThreshold, TrackHooks, TrackHooksOptions).
In testing of short static files, only 2-3 milliseconds were added when all new options were used.

Generating mod_mpmstats reports for slow requests only

To enable, Set SlowThreshold directive globally (with a value representing # of seconds, or "500ms").

IBM HTTP Server V7 and later configures mod_mpmstats by default. The periodic reporting in mod_mpmstats helps identify when delays or hangs are driving the server towards reaching MaxClients.

The TrackModules reporting has an important limitation for isolating relatively short delays as opposed to outright hangs, because it aggregates the active modules for all requests throughout the server without regard for ones that may not be delayed at all.

When the new directive SlowThreshold is used, with an argument in number of seconds, mod_mpmstats will generate an additional report that includes a summary of active modules in pending requests that have already been running for at least the specified number of seconds. This additional message is issued during the normal ReportInterval.

Configuration:

SlowThreshold 10

Output:

  [Wed Jan 11 18:48:12 2012] [notice] mpmstats: rdy 27 bsy 23 rd 0 wr 23 ka 0 log 0 dns 0 cls 0
  [Wed Jan 11 18:48:12 2012] [notice] mpmstats: bsy: 23 in mod_was_ap22_http.c
  [Wed Jan 11 18:48:12 2012] [notice] mpmstats (long-running requests): bsy: 3 in mod_was_ap22_http.c 
    

Reporting on slow modules as they finish

To enable:

• Set SlowThreshold globally (# of seconds, or "500ms")

• Set TrackHooks allhooks (or specific hooks descibed in appendix).

• Set TrackHooksOptions logslow.

When a module returns control to IBM HTTP Server, an INFO level message can be issued if that module exceeds the specified SlowThreshold. Note that if your SlowThreshold is smaller than 1 second, you need to also set the "millis" TrackHooksOptions to catch modules returning in under a second but over the threshold.

Configuration:

    SlowThreshold 4 
    TrackHooks allhooks 
    TrackHooksOptions logslow

Output:

  error.log: [info] [client 127.0.0.1] module mod_test.c took 5000ms to return OK in phase handler

This output is written when the phase of the request finishes, it is not tied to the ReportInterval.

Note: In PH46094 and later, the notice argument can be added to TrackHooksOptions to log the error at the "notice" log level to make sure the messages are logged even at the default LogLevel WARN.

Logging per-module response times

To enable, set TrackHooks allhooks , and add %{TXX}e descibed below to LogFormat.

During the processing of typical requests, the web server proceeds through several phases of processing in which various modules can participate. One special phase, called the "handler", is where the response is ultimately generated.

For example, the WebSphere Plugin primarily acts as a handler, as does the core piece of the web server responsible for delivering static files. An overall delay in the processing of a request (as recorded by e.g. %D) is often attributed to the handler, but can also be caused by modules in other phases.

IBM HTTP Server 7.0.0.23 / 8.0.0.4 and later provides a way to track how long each module takes to complete in several important phases of Apache processing (see appendix for a list of phases)

To request tracking of a particular phase, configure the new TrackHooks directive with one or more hook names:

    TrackHooks [post_read_request | check_userid | check_user_access | auth_checker | handler | allhooks]...

You can also add the special value 'millis' to the TrackHooksOptions directive to track time in milliseconds instead of seconds, but this will incur more overhead/delays during request processing.

    TrackHooksOptions [millis | permodule | logslow | allopts]...

To log the timing info in your access log, add the corresponding variable to your LogFormat directive (see appendix).

In the example below, mod_authnz_ldap is being used to authenticate a user in front of a JSP. We can see in the final field (%D) that the overall request took 2.5 seconds to complete on the first request, but only about 1.2 seconds the second time.

The timing for mod_was_ap22_http.c tells us that our handler is taking 1.2-1.4 seconds by itself, which for the sake of argument is a reasonable response time.

Configuration:

    TrackHooks allhooks
    TrackHooksOptions millis permodule
    LogFormat "%h %l %u %t \"%r\" %>s %b TRH=%{TRH}e TCA=%{TCA}e TCU=%{TCU}e TPR=%{TPR}e TAC=%{TAC}e TTN=%{TTN}e %{JSESSIONID}C %{WAS}e %D" mpmext
    CustomLog logs/access-detailed-timing.log mpmext

Output:

   ... 200 663 TRH=mod_was_ap22_http.c:1414ms TAC=- TCU=mod_auth_basic.c:460ms TPR=- TAC=mod_authnz_ldap.c:1093ms 2553985
   ... 200 990 TRH=mod_was_ap22_http.c:1205ms TAC=- TCU=mod_auth_basic.c:156ms TPR=- TAC=- 1220757

The new fields give us a good hint as to why the first request took so much longer. We can see that both "mod_auth_basic" and "mod_authnz_ldap" used all of the extra time in the first request, and used negligible time for the second request.

• We know that LDAP results can be cached by the server.

• LDAP is configured for both Authentication and Authorization

• A quirk of how IHS diagnostic enhancements works will always bill Authentication configured with AuthBasicProvider to "mod_auth_basic"

• So the overall response time delay is explained by this request having uncached authentication and authorization credentials for the user.

Note, if seconds or milliseconds logging is in use, and a module takes less than 1 second or 1 millisecond, it is not logged in the %{TXX}e environemnt variables.

Appendix

SlowThreshold

This directive causes mod_mpmstats to generate an additional report that includes a summary of active modules in pending requests that have already been running for at least the specified number of seconds.

Syntax: SlowThreshold #-of-seconds | #-of-millisecondsms
Example:
SlowThreshold 5
or
SlowThreshold 5000ms
Default: None

TrackHooks

This directive allows indicating particular phases to be tracked and reported on by specifying the corresponding hook names. It also provides an option to indicate that 'all' phases are to be tracked.

Syntax: TrackHooks [ post_read_request | check_userid | check_user_access | auth_checker | handler | allhooks ]
{Multiple options can be specified. 'allhooks' precludes having to specify any others.}
Example:
TrackHooks post_read_request check_userid
or
TrackHooks allhooks
Default: None.

TrackHooksOptions

This directive allows specifying various options for how the hooks specified by the TrackHooks directive are tracked/reported.

Syntax: TrackHooksOptions [ millis | permodule | logslow | allopts ]
{Multiple options can be specified}. 'allopts' precludes having to specify any others.

  - millis      : If specified, indicates to track time in milliseconds instead of seconds 
                  (note: this will incur more overhead/delays during request processing.)
  - permodule   : If specified, the LogFormat variables (%{TXX}) will list the time spent in each module 
                  taking more than 1 second / 1 millisecond (depending on whether 'millis' is set or not)
  - logslow     : If specified, causes messages like "module mod_test.c took 5000ms to return OK in phase handler" 
                  to be issued to the log when the SlowThreshold is exceeded.
  - allopts     : Encompasses all of the options listed above.  It precludes having to list each separately.
  

Example:
TrackHooksOptions millis permodule logslow
or
TrackHooksOptions allopts
Default: None

Hooks (phases) and custom log variables

TrackHooks argument (phases)	LogFormat variable	description
post_read_request	%{TPR}e	General purpose "early" hook
check_userid	%{TCU}e	Authentication
check_user_access	%{TCA}e	Access control not dependent on username
auth_checker	%{TAC}e	Authorization (require ... )
handler	%{TRH}e	Actual generation of response
translate_name	%{TTN}e	Mapping of URI to Filesystem (including mod_rewrite, mod_proxy, and WAS Plug-in). 9.0.5.4/8.5.5.18 and later.
allhooks	%{TPR}e %{TCU}e %{TCA}e %{TAC}e %{TRH}e	Encompasses all phases listed above (not a phase itself)