簡(jiǎn)介
在Nginx作為反向代理期間，因?yàn)楹芏嘈阅軉栴}排查都會(huì)涉及到Nginx日志中反應(yīng)服務(wù)器處理時(shí)間响谓。并且在網(wǎng)上看到較詳細(xì)的時(shí)間變量講解的文檔债查，此處記錄一下，便于之后做分析使用(參考文檔放置文末)卵蛉。
本文提到的所有變量颁股，如果需要區(qū)分，則均為ngx_http_upstream_module中的變量傻丝，不再做釋義甘有。如需要使用其他module中的參數(shù)，請(qǐng)參考nginx官方文檔
Nginx中時(shí)間定義
$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服務(wù)葡缰，從發(fā)起請(qǐng)求的客戶端獲取到第一個(gè)字節(jié)開始亏掀，到返回給客戶端最后一個(gè)字節(jié)后忱反，日志寫入文件所經(jīng)過的時(shí)間。單位為秒滤愕。
$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服務(wù)温算，與上游服務(wù)建立連接所經(jīng)過的時(shí)間。單位為秒间影。在使用SSL的情況下注竿，握手過程所消耗的時(shí)間也會(huì)被記錄下來(lái)。多次請(qǐng)求建立的時(shí)間魂贬，使用逗號(hào)與冒號(hào)分隔巩割，格式可參考$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服務(wù)随橘，從上游服務(wù)接收響應(yīng)頭所經(jīng)過的時(shí)間喂分。單位為秒。多次請(qǐng)求響應(yīng)的時(shí)間机蔗，使用逗號(hào)與冒號(hào)分隔蒲祈，格式可參考$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服務(wù)萝嘁，從上游服務(wù)接收響應(yīng)內(nèi)容所經(jīng)過的時(shí)間梆掸。單位為秒。多次請(qǐng)求響應(yīng)的時(shí)間牙言，使用逗號(hào)與冒號(hào)分隔酸钦，格式可參考$upstream_addr變量。
流程說(shuō)明
以上是Nginx官方給出的參數(shù)解讀咱枉，但是看起來(lái)不是很清晰卑硫，但是可以通過下面的時(shí)序圖作為參考
在這個(gè)時(shí)序圖中可以看到
程序真正運(yùn)行的時(shí)間 = $upstream_header_time - $upstream_context_time
在$request_time中包含了數(shù)據(jù)返回的時(shí)間以及日志打印的時(shí)間。
所以來(lái)說(shuō)整個(gè)請(qǐng)求處理流程蚕断，如下所示
「1用戶請(qǐng)求」「2建立Nginx連接」「3發(fā)送響應(yīng)」「4接收響應(yīng)」「5關(guān)閉Nginx連接」
$request_time = 1 + 2 + 3 + 4 + 5
$upstream_response_time = 2 + 3 + 4 + 5(「關(guān)閉Nginx連接」的操作耗時(shí)可以認(rèn)為是0)
兩者相差的就只有一個(gè)「用戶請(qǐng)求」耗時(shí)欢伏。在正常的請(qǐng)求時(shí)間中，$request_time一般是等于或者大于$upstream_response_time
場(chǎng)景
場(chǎng)景1：Nginx日志出現(xiàn)大量超時(shí)告警亿乳，發(fā)現(xiàn)$upstream_header_time正常硝拧，但是$request_time和$upstream_response_time很大
分析：根據(jù)上圖，這時(shí)候反應(yīng)的是上游程序執(zhí)行較慢葛假，或發(fā)送數(shù)據(jù)量大障陶，需要排查執(zhí)行程序的相關(guān)慢日志；
場(chǎng)景2：Nginx日志出現(xiàn)大量超時(shí)告警聊训，發(fā)現(xiàn)$request_time很大抱究，但是upstream_response_time正常，說(shuō)明程序執(zhí)行完畢且正常返回带斑，這時(shí)就要驗(yàn)證是數(shù)據(jù)返回過慢還是日志打印出現(xiàn)了阻塞
原因：
1媳维、數(shù)據(jù)返回慢可以通過抓包分析酿雪，通常來(lái)說(shuō)是用戶網(wǎng)絡(luò)引起的遏暴；
2侄刽、日志打印出現(xiàn)阻塞，可能是機(jī)器的IO出現(xiàn)問題朋凉，一般可以查看系統(tǒng)監(jiān)控或者手動(dòng)查看IO發(fā)現(xiàn)州丹；
3、也可能是因?yàn)镹ginx配置了相關(guān)的參數(shù)杂彭，導(dǎo)致了延遲關(guān)閉墓毒，這需要根據(jù)問題現(xiàn)象一步步排查；
4亲怠、也可能是返回給客戶端的是https所计，大數(shù)據(jù)加解密耗時(shí)；
solution
把你的服務(wù)器放在high-speed network高性能網(wǎng)絡(luò)上团秽，讓client能夠快速訪問
使用緩存CND主胧、Nginx緩存
或者將你的服務(wù)器靠近用戶，多IDC進(jìn)行對(duì)不同區(qū)域用戶服務(wù)习勤。如：中國(guó)IDC踪栋、韓國(guó)IDC
去掉一些低效率算法，參考： Nagle's algorithm
調(diào)整服務(wù)器的TCP堆棧（參考 這篇文章）. 然而調(diào)整TCP堆棧不會(huì)有多大作用图毕，因?yàn)閮?nèi)核默認(rèn)配置已經(jīng)做了優(yōu)化調(diào)整了
除以上兩個(gè)場(chǎng)景案例夷都，還可以組合分析。
(1)予颤、upstream_header_time小党饮，$upstream_response_time大，可能是數(shù)據(jù)回寫Nginx出了問題笆焰；
(3)劫谅、$request_time比$upstream_response_time大，考慮用戶網(wǎng)絡(luò)狀態(tài)嚷掠，或者傳遞的數(shù)據(jù)本身就大捏检，當(dāng)使用POST請(qǐng)求傳參時(shí)，Nginx會(huì)先把request body緩存起來(lái)不皆，而這些耗時(shí)都是累積到「1用戶請(qǐng)求」贯城，所以$request_time會(huì)比$upstream_response_time大
其他狀況
$upstream_reponse_time比$request_time大，在官網(wǎng)上有個(gè)說(shuō)明：https://forum.nginx.org/read.php?21,284448,284450#msg-284450
$upstream_response_time由clock_gettime(CLOCK_MONOTONIC_COARSE)計(jì)算霹娄，默認(rèn)情況下能犯，它可以過去4毫秒鲫骗，相反，$request_time由gettimeofday()計(jì)算踩晶。 所以最終$upstream_response_time可能比$response_time更大执泰。
測(cè)試案例
除了在日志中添加日志的方法之外，還可以通過CURL命令來(lái)分析請(qǐng)求耗時(shí)的情況
time_namelookup：DNS 域名解析的時(shí)候渡蜻，就是把域名(http)轉(zhuǎn)換成 ip 地址的過程
time_connect：TCP 連接建立的時(shí)間术吝，就是三次握手的時(shí)間
time_appconnect：SSL/SSH 等上層協(xié)議建立連接的時(shí)間，比如 connect/handshake 的時(shí)間
time_redirect：從開始到最后一個(gè)請(qǐng)求事務(wù)的時(shí)間
time_pretransfer：從請(qǐng)求開始到響應(yīng)開始傳輸?shù)臅r(shí)間
time_starttransfer：從請(qǐng)求開始到第一個(gè)字節(jié)將要傳輸?shù)臅r(shí)間
time_total：這次請(qǐng)求花費(fèi)的全部時(shí)間
curl -o /dev/null -s -w speed_download:%{speed_download},"\n"time_namelookup:%{time_namelookup},"\n"time_connect:%{time_connect},"\n"time_pretransfer:%{time_pretransfer},"\n"time_starttransfer:%{time_starttransfer},"\n"time_total:%{time_total},"\n" "http://XXXX"
參考
超好用的Nginx日志時(shí)間變量——助你快速定位問題 - 掘金
Nginx - request_time和upstream_response_time的區(qū)別 - That's_it - 博客園
nginx優(yōu)化之request_time 和upstream_response_time差別 - dongruiha - 博客園
Nginx - request_time和upstream_response_time詳解
使用 curl 命令分析請(qǐng)求的耗時(shí)情況
