ngx_http_log_request_speed

The ngx_http_log_request_speed module is helping you to find the heavy requests of your webpage. I originally wrote the module for myself to be able to find the urls of our website that take long time to process, which are probably also the heavy ones that generate a lot of load on the server. By analyzing the slow request logs we can get hints on which parts of the website that we should probably recheck for their efficiency.

http {
      log_request_speed_filter on;
      log_request_speed_filter_timeout 3;
      ...
}

Directives

log_request_speed_filter

syntax: log_request_speed_filter [on|off]

default: n/a

context: location, server, http

This directive enables the log_request_speed filter for the location/server/http block you specify it in.

log_request_speed_filter_timeout

syntax: log_request_speed_filter_timeout [num sec]

default: 5

context: location, server, http

The timeout defines how long a request at least has to take to get logged. If the timeout is for example set to 5 seconds, a request that takes 4 seconds won't get a request speed log entry, a 6 seconds taking one will get logged.

Usage

When a request gets to the log request speed filter and takes at least the defined timeout there will be an error log entry like the following:

2009/11/27 04:44:06 [error] 23261#0: *600563358 --- process request time: 3737 ---  while reading response header from upstream, 
client: 80.143.168.130, server: www.domain.com, request: "GET /nachrichten/read/in/neu/369217567 HTTP/1.1", 
upstream: "fastcgi://10.20.0.159:9000", host: "www.domain.com", referrer: "http://www.domain.com/nachrichten/in/neu/1"

The request time in the log is in miliseconds.

Once you got your nginx logging the request times, you can use the analyzer.pl script to find the requests that took the longest time at average.

# cd ~/request_speed_log_analyzer
# tail -n 10000 /var/log/nginx/error.log  | grep 'process request' | ./analyzer.pl  -r

POST /message/ajaxWrite/from_profile/toni32 HTTP/1.1 --- avg ms: 3110, value count: 1
POST /sessionupdate_prod.php HTTP/1.1 --- avg ms: 3312, value count: 137
GET /favoriten/1 HTTP/1.1 --- avg ms: 3345, value count: 76
GET /nachrichten/read/in/neu/369217567 HTTP/1.1 --- avg ms: 3737, value count: 1
POST /login_prod.php HTTP/1.1 --- avg ms: 4117, value count: 14
GET /wan/isonline?NICKNAME=luckynight&rtime=1259292758 HTTP/1.1 --- avg ms: 5267, value count: 1
GET /sessionupdate_prod.php HTTP/1.1 --- avg ms: 5572, value count: 8 <--- THE WINNER