为 Nginx 启用带请求消耗时间的 access log

我是用 Nginx 作为 Proxy 来跑 Web Server 的，最近想做一件事情，就是 Profile 一下我的 Web Server 的运行状况，其中一个基本的点就是：性能。在参考了一些资料后，我打算先从 Web Server 的请求时间做起来。

默认情况下，Nginx 的 access log 是不会显示请求时间（request time）的，这需要我们给它的配置文件自定义一下 log format。

编辑 /etc/nginx/nginx.conf，在 http 那块配置里面，加上如下代码：

log_format timed_combined '$remote_addr - $remote_user [$time_local]  ' 
                                                 '"$request" $status $body_bytes_sent '
                                                 '"$http_referer" "$http_user_agent" $request_time';

然后，在具体的 nginx server 配置里的 access_log 后面，加上一句 timed_combined 即可：

access_log /path/to/access.log timed_combined;

这样，在 access_log 的最后一行，就会出现 0.xxx （单位秒）的数据出现，代表 Nginx 从收到客户端请求、到发送完响应的整个时间，叫 request_time。

于是这里会有一个问题冒出来，如果 Nginx 本身接受用户请求花了比较久的时间，比如用户 POST 比较大的文件数据，那么少说得好几秒吧，这时 request_time 就反应不了后端 Upstream 的运行情况了。所以这里建议再同时启用一个：upstream_response_time。

这个 upstream_response_time 很明白，就是在 Nginx 接受完 client 的请求后，再和 upstream server 请求的过程，这个指标才能真正反应 upstream server 的响应情况，虽然通常它的值会和 request_time 一样，但是也强烈建议加上。

所以新的 log_format 如下：

log_format timed_combined '$remote_addr - $remote_user [$time_local]  ' 
                                                 '"$request" $status $body_bytes_sent '
                                                 '"$http_referer" "$http_user_agent" $request_time $upstream_response_time';

加好以后，来软启动一下 Nginx，以下 tip 复制自 Nginx 官网 Log Rotation：

$ mv access.log access.log.0
$ kill -USR1 `cat master.nginx.pid`
$ sleep 1
$ gzip access.log.0    # do something with access.log.0

最后，等新的 access.log 产生以后，过个一段时间，你就可以用来分析 Web Server 的性能了。