httpd-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jeff Trawick <traw...@gmail.com>
Subject Re: [users@httpd] http request cpu usage and URL
Date Tue, 09 Dec 2014 00:57:11 GMT
On Mon, Dec 8, 2014 at 4:30 PM, Rose, John B <jbrose@utk.edu> wrote:

>  Looking at "top" output we have some occasional http requests that
> generate a wildly disproportionate amount of %cpu usage compared to the
> more frequent %.
>

Some httpd child processes may be handling far more requests than the
others.


>
>  If you want to tie that process listing to the URL being accessed to see
> if there was a pattern of a specific web site or page causing that high cpu
> usage, any suggested methods of doing that?
>

mod_status with ExtendedStatus On shows the active requests and the CPU per
child process. With prefork you can see But with the worker and event MPMs
it will be hard to tie the CPU to a particular request.

If you're brave (a.k.a. you can try it in a test environment), try this
module I wrote just now:

http://emptyhammock.com/downloads/mod_request_cpu.c

This uses a Linux feature to get the elapsed per-thread CPU for processing
a request, for logging in the access log.

/*
 * Building the module:
 *   /path/to/apxs -ci mod_request_cpu.c
 *
 * Configuration:
 *   LoadModule request_cpu_module modules/mod_request_cpu.so
 *   Add "%Z" to your access log configuration
 */

I used it with this access log format:

LogFormat "%h %l %u %t \"%r\" %>s %b %D %Z" commoncpu

The %D (existing feature) is the elapsed time in microseconds.  %Z is
provided by mod_request_cpu and gives the user and system microseconds
(suffixed by "u" and "s"), as in the following examples:

127.0.0.1 - - [08/Dec/2014:19:43:44 -0500] "GET /server-status/ HTTP/1.1"
200 16248 33964 33721u,0s

That's 33964 microseconds elapsed time (%D), 28657 microseconds user CPU,
and 0 microseconds system CPU (both from %Z).

127.0.0.1 - - [08/Dec/2014:19:43:44 -0500] "GET /server-status/ HTTP/1.1"
200 16253 33877 28657u,0s
127.0.0.1 - - [08/Dec/2014:19:43:44 -0500] "GET /server-status/ HTTP/1.1"
200 16246 29015 26633u,0s
127.0.0.1 - - [08/Dec/2014:19:43:44 -0500] "GET /server-status/ HTTP/1.1"
200 16240 31987 31751u,0s
127.0.0.1 - - [08/Dec/2014:19:43:44 -0500] "GET /server-status/ HTTP/1.1"
200 21544 26221 22305u,0s
127.0.0.1 - - [08/Dec/2014:19:43:44 -0500] "GET /server-status/ HTTP/1.1"
200 16247 30902 30722u,0s
127.0.0.1 - - [08/Dec/2014:19:43:44 -0500] "GET /server-status/ HTTP/1.1"
200 16242 35939 34450u,47s
127.0.0.1 - - [08/Dec/2014:19:43:44 -0500] "GET /server-status/ HTTP/1.1"
200 16234 38101 34502u,8s
127.0.0.1 - - [08/Dec/2014:19:43:44 -0500] "GET /server-status/ HTTP/1.1"
200 16235 31423 29342u,0s

This is for the same CPU-intensive request over and over, and you see
different values logged.  The time starts after httpd reads the request
header.

It builds with 2.2 and 2.4, but I only tested it with 2.4.

(Now that I wasted the last 59 minutes on this I guess someone will tell me
an existing way to do the same thing :) )


>  Thanks
>
>
>
>
>


-- 
Born in Roswell... married an alien...
http://emptyhammock.com/

Mime
View raw message