python - nginx日志如何正确显示整个http请求的服务端处理时间？

Question

我的服务器端架构，是一个nginx+4个python的tornado服务，nginx做负载均衡，我在nginx中使用以下日志来记录每次请求的服务器端处理时间：

log_format     mylog     '$remote_addr - $remote_user [$time_local] '
                              ' "$request   $status cost:$request_time"  $body_bytes_sent '
                              ' "$http_referer" "$http_user_agent" "$http_host" ';
                              
 其中：$request_time表示每次请求的耗费时间（秒）

但是我发现这个时间和tornado端打印出来的时间存在一个数量级的差距，，nginx显示几百毫秒，而对应接口在tornado端只用了几十毫秒
以下为tornado端日志
2015-11-23 11:00:09,586:web.py:log_request:[line:1816] INFO 200 GET /posts_act (144.0.8.123) 23.29ms
以下为nginx端日志：
"GET /posts_act HTTP/1.1 200 cost:1.346"
"GET /posts_act HTTP/1.1 200 cost:0.116"

请问，我应该以哪个为准，，为什么相差这么大？如何做到统一，至少不会差距这么大？也妨碍了我进行系统监控，不知道问题出在nginx还是tornado

Answer 1

$request_time和$upstream_response_time之间差别：

$request_time包含了用户数据接收时间，而真正程序的响应时间应该用$upstream_response_time

下面介绍下2者的差别：

1、request_time
官网描述：request processing time in seconds with a milliseconds resolution; time elapsed between the first bytes were read from the client and the log write after the last bytes were sent to the client 。
指的就是从接受用户请求的第一个字节到发送完响应数据的时间，即包括接收请求数据时间、程序响应时间、输出
响应数据时间。

2、upstream_response_time
官网描述：keeps times of responses obtained from upstream servers; times are kept in seconds with a milliseconds resolution. Several response times are separated by commas and colons like addresses in the $upstream_addr variable

http://blog.sina.com.cn/s/blog_4f9fc6e10102uxib.html