nginx日誌如何正確顯示整個http請求的服務端處理時間？

01-29

我的伺服器端架構，是一個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

查了一下官方文檔，發現 $request_time 並不是服務程序的響應時間，而應該使用 $upstream_response_time。

1. $request_time

官方文檔對 $request_time 的解釋（鏈接：Module ngx_http_core_module）：

request processing time in seconds with a milliseconds resolution (1.3.9, 1.2.6); time elapsed since the first bytes were read from the client.

這個時間是從 Nginx 接收到客戶端第一個位元組的數據開始計時的，包含了接收數據、等待響應的時間。

2. $upstream_response_time

官方文檔對 $upstream_response_time 的解釋（鏈接：Module ngx_http_upstream_module）：

keeps time spent on receiving the response from the upstream server; the time is kept in seconds with millisecond resolution. Times of several responses are separated by commas and colons like addresses in the $upstream_addr variable.

這個時間是 Nginx 等待後端程序響應的時間。