Nginx - request_time和upstream_response_time詳解

前言

最近分析伺服器性能，考慮到nginx在前面做反向代理，這裡查一下nginx日志來反應伺服器處理時間的問題。

網上查了查資料，這裡記錄一下。

注：本文提到的所有變量，如果需要區分，則均為ngx_http_upstream_module中的變量，不再做釋義。如需要使用其他module中的參數，請參考nginx官方文檔

1、Nginx内時間定義

1.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。

指的就是從接受使用者請求的第一個位元組到發送完響應資料的時間，即$request_time包括接收用戶端請求資料的時間、後端程式響應的時間、發送響應資料給用戶端的時間(不包含寫日志的時間)。

官方文檔：http://nginx.org/en/docs/http/ngx_http_log_module.html

1.2、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向後端建立連接配接開始到接受完資料然後關閉連接配接為止的時間。

從上面的描述可以看出，$request_time肯定比$upstream_response_time值大；尤其是在用戶端采用POST方式送出較大的資料，響應體比較大的時候。在用戶端網絡條件差的時候，$request_time還會被放大。

官方文檔：http://nginx.org/en/docs/http/ngx_http_upstream_module.html

除了上述的request_time和upstream_response_time比較常用，在新的Nginx版本中對整個請求各個處理階段的耗時做了近一步的細分：

1.3 $upstream_connect_time(1.9.1)：

機關為秒。

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.

跟後端server建立連接配接的時間，如果是到後端使用了加密的協定，該時間将包括握手的時間。

1.4 $upstream_header_time(1.7.10)：

機關為秒。

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.

接收後端server響應頭的時間。

2、場景

2.1 流程說明

如果把整個過程補充起來的話 應該是：

［1使用者請求］［2建立 Nginx 連接配接］［3發送響應］［4接收響應］［5關閉  Nginx 連接配接］

那麼 upstream_response_time 就是 2+3+4+5 

但是 一般這裡面可以認為 ［5關閉 Nginx 連接配接］ 的耗時接近 0

是以 upstream_response_time 實際上就是 2+3+4 

而 request_time 是 1+2+3+4

二者之間相差的就是 ［1使用者請求］的時間。

來個網上的圖說明情況：

從上圖中我們不難得出如下結論

程式真正的運作時間 = $upstream_header_time - $upstream_connect_time

$request_time 中包含了資料傳回時間

$request_time 中包含了日志列印的時間

2.2 場景舉例

2.2.1 場景：nginx日志出現大量逾時報警，這個時候發現$upstream_header_time正常，但是$request_time、$upstream_response_time很大

分析：根據上面的示意圖，這個時候便反映出是上遊程式執行較慢、或發送資料量大，需要排查執行程式的相關慢日志

2.2.2 場景：同樣是ngxin日志出現大量逾時報警，這個時候發現$request_time很大，但是$upstream_response_time正常

分析：$upstream_response_time正常，說明程式執行完畢且正常傳回，那麼這個時候需要驗證是資料傳回過慢還是日志列印出現了阻塞。

原因：

資料傳回慢可以通過抓包分析，通常來說是使用者網絡原因引起的；

日志列印出現阻塞，可能是機器io出現了問題，這個一般很容易發現；

還有可能是nginx配置了相關參數，導緻了延遲關閉，這裡隻要根據問題現象一步一步排查即可。

也可能傳回給用戶端是https，大資料加解密耗時

解決方法：

把你的伺服器放在high-speed network高性能網絡上，讓client能夠快速通路

使用緩存CND、Nginx緩存

或者将你的伺服器靠近使用者，多IDC進行對不同區域使用者服務。如：中國IDC、南韓IDC

去掉一些低效率算法，參考： Nagle's algorithm

調整伺服器的TCP堆棧（參考 這篇文章）. 然而調整TCP堆棧不會有多大作用，因為核心預設配置已經做了優化調整了。

除了以上舉的兩個例子，還有各種組合可以分析，比如

2.2.3 $upstream_connect_time很大

可能是網絡通信出現了問題；

2.2.4 $upstream_header_time很小，但是$upstream_response_time很大，可能是資料回寫nginx出現了問題。

不難看出，通過這些變量，便可以快速定位到問題環節，而不至于毫無頭緒的到處排查，可以說是事半功倍。

3 request_time與upstream_response_time比較

3.1 一般request_time比upstream_response_time大

如果使用者端網絡狀況較差 或者傳遞資料本身較大 

再考慮到 當使用 POST 方式傳參時 Nginx 會先把 request body 緩存起來

而這些耗時都會累積到 ［1使用者請求］ 頭上去

這樣就解釋了：為什麼 request_time 有可能會比 upstream_response_time 要大。

因為使用者端的狀況通常千差萬别 無法控制 ，是以并不應該被納入到測試和調優的範疇裡面

更值得關注的應該是 upstream_response_time

是以在實際工作中 如果想要關心哪些請求比較慢的話，記得要在配置檔案的 log_format 中加入 $upstream_response_time  

3.2 upstream_response_time比request_time 大

在我的測試中，我居然發現了這個情況

log_format  f_access_log  '$remote_addr *$connection  [$time_local] "$request" '

            '$status $body_bytes_sent  $request_time $upstream_response_time';

時間是這樣的結果：0.039 0.040

3.2.1 為什麼大呢？

    最開始我猜測可能是有點計算誤差吧，大多數情況是兩者相等或者request_time較大。但是還是不死心，網上查了查原因，最終找打了一個合理的解釋，nginx.org官網有個說明：https://forum.nginx.org/read.php?21,284448,284450#msg-284450

  $ upstream_response_time由clock_gettime(CLOCK_MONOTONIC_COARSE)計算，預設情況下，它可以過去4毫秒，相反，$ request_time由gettimeofday()計算。 是以最終upstream_response_time可能比response_time更大。

3.2.2 為什麼調用不同函數呢？

那問題又來了，為什麼兩個時間不用同一個函數計算呢？可能有以下幾個原因：

clock_gettime比gettimeofday更加精确

但是gettimeofday比clock_gettime效率更高，gettimeofday走的是vsyscall[1]（虛拟系統粗糙的描述就是不經過核心程序的切換就可以調用一段預定好的核心代碼），沒有線程切換的開銷。

clock_gettime本身的執行就非常耗費時間，其大概的調用路徑是：clock_gettime -> sys_call -> sys_clock_gettime -> getnstimeofday -> read_tsc -> native_read_tsc

    是以這裡我大膽猜測一下，可能是Nginx為了效率，在某些操作比較多的時間計算上調用的是gettimeofday函數。

大家可以參考這篇文章：https://www.cnblogs.com/raymondshiquan/articles/gettimeofday_vs_clock_gettime.html

4 指導意義

是以在通過nginx的access_log來分析後端程式接口響應的時候，需要在nginx的log_format中添加$upstream_response_time字段。