Re: http request cpu usage and URL (Apache Users)

On Mon, Dec 8, 2014 at 4:30 PM, Rose, John B <jbrose@xxxxxxx> 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/