超好用的Nginx日誌時間變量——助你快速定位問題

打開這篇文章的你，想必對於nginx的基礎日誌參數並不陌生，對於request_time參數更是熟悉得不能再熟悉了。不出意外的話，請求響應時間，這應該是現階段你對它所有的認識了。其實，request_time的含義不只僅是這樣，而且，nginx中的日誌時間變量，除了request_time，還有不少，若是配置得當的話，能夠極大地提升排查問題的效率，尤爲是超時問題。那麼廢話很少，let's begin。

注：本文提到的全部變量，若是須要區分，則均爲ngx_http_upstream_module中的變量，再也不作釋義。如須要使用其餘module中的參數，請參考nginx官方文檔

先上官方定義

(如下英文釋義均取自nginx官方文檔，最後更新時間：2019-07-11)

$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

筆者直譯：nginx服務，從發起請求的客戶端獲取到第一個字節開始，到返回給客戶端最後一個字節後，日誌寫入文件所通過的時間。單位爲秒。

$upstream_connect_time

keeps time spent on establishing a connection with the upstream server (1.9.1); the time is kept in seconds with millisecond resolution. In case of SSL, includes time spent on handshake. Times of several connections are separated by commas and colons like addresses in the $upstream_addr variable.

筆者直譯：nginx服務，與上游服務創建鏈接所通過的時間。單位爲秒。在使用SSL的狀況下，握手過程所消耗的時間也會被記錄下來。屢次請求創建的時間，使用逗號與冒號分隔，格式可參考$upstream_addr變量。

$upstream_header_time

keeps time spent on receiving the response header from the upstream server (1.7.10); 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服務，從上游服務接收響應頭所通過的時間。單位爲秒。屢次請求響應的時間，使用逗號與冒號分隔，格式可參考$upstream_addr變量。

$upstream_response_time

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服務，從上游服務接收響應內容所通過的時間。單位爲秒。屢次請求響應的時間，使用逗號與冒號分隔，格式可參考$upstream_addr變量。

定義解析

我的感受官方的定義並非很友好，首先，沒有說明計算時間的起止點，其次，沒有說明各個時間概念的關係，很容易讓人迷惑。因此，筆者結合我的理解，對定義稍做解釋，方便你們理解，若是有理解錯誤的地方，還望指出。

$request_time

（對於這個變量，官方的定義很準確，再也不作其餘釋義）

nginx服務，從發起請求的客戶端獲取到第一個字節開始，到返回給客戶端最後一個字節，日誌寫入文件後，所通過的時間。單位爲秒。

$upstream_connect_time

nginx服務，從與上游服務開始創建鏈接，到鏈接創建成功，所通過的時間。單位爲秒。

$upstream_header_time

nginx服務，從與上游服務開始創建鏈接，到接收到響應返回頭的第一個字節，所通過的時間。單位爲秒。

$upstream_response_time

nginx服務，從與上游服務開始創建鏈接，到接收完響應返回的最後一個字節，所通過的時間。單位爲秒。

結合以上釋義，即可獲得時序圖：

從上圖中咱們不可貴出以下結論

• 程序真正的運行時間 = $upstream_header_time - $upstream_connect_time
• $request_time 中包含了數據返回時間
• $request_time 中包含了日誌打印的時間

那麼問題來了，這些結論有什麼用呢？

場景舉例

場景：nginx日誌出現大量超時報警，這個時候發現$request_time、$upstream_header_time正常，可是$upstream_response_time很大

分析：根據上面的結論，這個時候便反映出是上游程序執行較慢，須要排查執行程序的相關慢日誌

場景：一樣是ngxin日誌出現大量超時報警，這個時候發現$request_time很大，可是$upstream_response_time正常

分析：$upstream_response_time正常，說明程序執行完畢且正常返回，那麼這個時候須要驗證是數據返回過慢仍是日誌打印出現了阻塞。數據返回慢能夠經過抓包分析，一般來講是用戶網絡緣由引發的；日誌打印出現阻塞，多是機器io出現了問題，這個通常很容易發現，還有多是nginx配置了相關參數，致使了延遲關閉，這裏只要根據問題現象一步一步排查便可。

除了以上舉的兩個例子，還有各類組合能夠分析，好比$upstream_connect_time很大，多是網絡通訊出現了問題；$upstream_header_time很小，可是$upstream_response_time很大，多是數據回寫nginx出現了問題。不難看出，經過這些變量，即可以快速定位到問題環節，而不至於毫無頭緒的處處排查，能夠說是事半功倍。

勇敢的少年，相信這些變量能夠幫助你很多，Hope you enjoy it!

最後有一個小題目留給你，爲何nginx全部的調用'下游'，都叫作upstream(上游)，而不是downstream或者別的什麼，這裏的設計算是反直覺麼？