nginx源碼層面探究request_time、upstream_response_time、upstream_connect_time與upstream_header_time指標具體含義

来源:https://www.cnblogs.com/AcAc-t/archive/2022/06/29/nginx_request_time_upstream_respone_time_analysis.html
-Advertisement-
Play Games

基本概念 指針代表記憶體地址。 通常在類型關鍵字的後面加字元*來表示指針，表示指針指向什麼類型的值。比如，char*表示一個指向字元的指針，float*表示一個指向float類型值的指針。 指針指向的可能還是指針，這時要用兩個星號**表示。 int** foo; 指針變數初始化 聲明指針變數之後，編譯 ...


背景概述

最近計划著重分析一下線上各api的HTTP響應耗時情況，檢查是否有介面平均耗時、99分位耗時等相關指標過大的情況，瞭解到nginx統計請求耗時有四個指標：request_time、upstream_response_time、upstream_connect_time與upstream_header_time，在查找資料的過程中，發現無論是nginx官方文檔還是熱心網友們的分享，都並沒有讓自己感覺特別詳細、明白地說清楚了這四個指標詳細具體含義的資料，於是自己動手探究了一番nginx源碼，嘗試從其中找出這4個指標的代碼級別具體含義。
特別說明：本文代碼分析基於nginx 1.10.0版本，從源碼層面分析一次完整HTTP請求log中request_time、upstream_response_time、upstream_connect_time與upstream_header_time四個指標的具體含義，本文中得出的相應結論僅基於個人學習、研究所得，非權威結論，如有不當之處歡迎指正、一起探討。

一次完整HTTP請求/響應的各耗時階段拆分

首先詳細拆分一下一個完整HTTP請求(非keep alive)生命周期的多個階段（以下C指代客戶端，N指代nginx伺服器，S指代上游server）：

  1. C向N發起TCP三次握手建立連接成功，C開始向N通過TCP發送HTTP請求具體數據(header/body...)
  2. N開始接收到C發送的數據到全部接收完成
  3. N作為代理向S發起TCP三次握手並建立連接成功，N開始向S發送HTTP數據
  4. S開始接收N發送的數據並全部接收完成
  5. S業務代碼根據業務規則進行處理完成並生成HTTP響應結果
  6. S開始將響應結果發送給N
  7. N開始接收響應結果並接收header部分完成
  8. N接收S返回的全部響應結果完成
  9. N開始向C返回全部的HTTP響應結果
  10. C開始接收N返回的數據並全部接收完成
  11. N向C發起四次揮手關閉TCP連接

其中1-2和9-11這5個階段 的速度直接受到C到N之間的網路質量影響，服務端雖然可以通過降低傳輸數據量、使用更快的協議(如HTTP3.0基於QUIC)等降低傳輸耗時，但無法起到決定性的作用，一般可視為超出了可優化的控制範圍。
3-8這6個階段一般都發生在內網，即N與S都處於同一個機房(甚至同一個機架/同一臺物理機上)，網路質量穩定且RTT基本在1ms內，網路耗時較少，正常情況下其主要時間應集中在階段5--各種業務邏輯處理數據並生成結果--這也正是一般後端優化的目標階段。

各耗時指標nginx官方解釋 && 疑問

參考:http://nginx.org/en/docs/http/ngx_http_log_module.html

$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是N接收到C第一個位元組數起至N向C發送完最後一個位元組數止後日誌記錄的時間。
疑問：接收到第一個位元組包括TCP三次握手的位元組嗎？發送完最後一個位元組的具體定義是什麼--N發送最後一個位元組必須收到C的ACK才算發送完成？
參考: http://nginx.org/en/docs/http/ngx_http_upstream_module.html

$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.

upstream_connect_time記錄N與S建立起一個連接的耗時，在SSL中也包括SSL握手的時間。
疑問：有一絲不確定這個時間具體是指N到S的 TCP三次握手開始到連接建立完成時間--對應上面階段3？

$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.

upstream_header_time記錄N接收到S響應header的時間。
疑問：能夠理解會包含N到S連接建立後收到S header的時間--階段4~7，但是否包括upstream_connect_time這個建連時間--階段3呢？

$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.

upstream_response_time記錄N接收S完整響應的時間。
疑問：應包含階段4-8，但是否包括upstream_connect_time這個建連時間--階段3？

如上，按照字面意思翻譯得到的各指標含義很簡潔，但是讓人不是很明瞭，不由的生出一些疑問，於是決定探究一下nginx源碼嘗試徹底弄清楚這幾個指標的具體含義。

nginx源碼探究

request_time指標

手上有一份nginx 1.10.0的源碼，雖然版本比較舊，但是想來指標統計的基本邏輯是不會變的，先探查範圍最大的指標request_time，該指標屬於模塊ngx_http_log_module,其相關代碼在http/ngx_http_variables.c 的ngx_http_variable_request_time函數中：

// http/ngx_http_variables.c
2041 static ngx_int_t
2042 ngx_http_variable_request_time(ngx_http_request_t *r,
2043     ngx_http_variable_value_t *v, uintptr_t data)
2044 {
...
2054     tp = ngx_timeofday(); // 獲取當前時刻
2055
2056     ms = (ngx_msec_int_t) // 當前時刻減去開始時刻得到耗時
2057              ((tp->sec - r->start_sec) * 1000 + (tp->msec - r->start_msec));
2058     ms = ngx_max(ms, 0);
2059
2060     v->len = ngx_sprintf(p, "%T.%03M", (time_t) ms / 1000, ms % 1000) - p;
...
2066     return NGX_OK;
2067 }

關鍵在於ngx_http_variable_request_time函數的調用時機以及r->start_sec、msec(ngx_http_request_t.start_sec/msec)的記錄時機，查找源碼可以發現ngx_http_request_t.start_sec的記錄時間位於http/ngx_http_request.c的ngx_http_create_request函數中，ngx_http_create_request函數會在ngx_http_wait_request_handler被調用，一步步往上追溯最後會發現，ngx_http_create_request實際是在N的監聽進程與C建立TCP連接後接收到數據觸發可讀事件後被調用，即start_sec/msec記錄的是連接建立後收到第一個可讀位元組時的--此時HTTP所在的應用層還未真正讀取數據，數據只是交付到了TCP所在的傳輸層。

// http/ngx_http_request.c
503 ngx_http_request_t *
 504 ngx_http_create_request(ngx_connection_t *c)
 505 {
 ...
  579     r->main = r;
 580     r->count = 1;
 581
 582     tp = ngx_timeofday();
 583     r->start_sec = tp->sec;
 584     r->start_msec = tp->msec;
 585...
  611 }

而對於ngx_http_variable_request_time的調用時機，追溯源碼發現其被放置於放在ngx_http_core_module全局變數中，而ngx_http_core_module會在ngx_http_log_init函數中註冊到main_conf，最終http/ngx_http_request.c的ngx_http_free_request函數中會調用ngx_http_log_request，而後在其中通過main_conf得到log相關handler並執行，其相關代碼如下：

// http/ngx_http_request.c
3410 void
3411 ngx_http_free_request(ngx_http_request_t *r, ngx_int_t rc)
3412 {
...
3456     log->action = "logging request";
3457
3458     ngx_http_log_request(r);
3459
3460     log->action = "closing request";
3461
3462     if (r->connection->timedout) {
3463         clcf = ngx_http_get_module_loc_conf(r, ngx_http_core_module);
3464
3465         if (clcf->reset_timedout_connection) {
3466             linger.l_onoff = 1;
3467             linger.l_linger = 0;
3468
3469             if (setsockopt(r->connection->fd, SOL_SOCKET, SO_LINGER,
3470                            (const void *) &linger, sizeof(struct linger)) == -1)
3471             {
3472                 ngx_log_error(NGX_LOG_ALERT, log, ngx_socket_errno,
3473                               "setsockopt(SO_LINGER) failed");
3474             }
3475         }
3476     }
...
3500 ngx_http_log_request(ngx_http_request_t *r)
3501 {
3502     ngx_uint_t                  i, n;
3503     ngx_http_handler_pt        *log_handler;
3504     ngx_http_core_main_conf_t  *cmcf;
3505
3506     cmcf = ngx_http_get_module_main_conf(r, ngx_http_core_module);
3507
3509     log_handler = cmcf->phases[NGX_HTTP_LOG_PHASE].handlers.elts;
3510     n = cmcf->phases[NGX_HTTP_LOG_PHASE].handlers.nelts;
3511
3512     for (i = 0; i < n; i++) {
3513         log_handler[i](r);
3514     }
3515 }

可以看到ngx_http_log_request正好在使用setsockopt優雅關閉連接前調用，由此得出結論,request_time起始時間為N接收到TCP包觸發第一次可讀event後，應用層正式讀取數據前的時刻，而結束時間為應用層接收完全部數據，即將關閉連接前一時刻，即包括階段2~10，不包括TCP四次揮手的時間。

upstream_connect_time

upstream_connect_time、upstream_header_time與upstream_response_time三個指標均屬於ngx_http_upstream模塊，對應nginx中的connect_time、header_time、response_time三個變數，其初始化代碼位於ngx_http_upstream.c中的ngx_http_upstream_connect函數，相關代碼如下：

// http/ngx_http_upstream.c
1328 static void
1329 ngx_http_upstream_connect(ngx_http_request_t *r, ngx_http_upstream_t *u)
1330 {
1331     ngx_int_t          rc;
1332     ngx_connection_t  *c;
...
1346
1347     ngx_memzero(u->state, sizeof(ngx_http_upstream_state_t));
1348
1349     u->state->response_time = ngx_current_msec;
1350     u->state->connect_time = (ngx_msec_t) -1;
1351     u->state->header_time = (ngx_msec_t) -1;
1352
1353     rc = ngx_event_connect_peer(&u->peer);
1354
1355     ngx_log_debug1(NGX_LOG_DEBUG_HTTP, r->connection->log, 0,
1356                    "http upstream connect: %i", rc);
...
1467     ngx_http_upstream_send_request(r, u, 1);
1468 }

可以看到其初始值設置正好處於ngx_event_connect_peer函數前，即N即將開始與S建立連接之前，註意此時response_time被設置為了當前時刻時間，而後繼續追溯源碼可以發現connect_time最終在ngx_http_upstream_connect函數末尾調用的ngx_http_upstream_send_request函數中進行了賦值，相關代碼如下：

// http/ngx_http_upstream.c
1782 static void
1783 ngx_http_upstream_send_request(ngx_http_request_t *r, ngx_http_upstream_t *u,
1784     ngx_uint_t do_write)
1785 {
...
1791     ngx_log_debug0(NGX_LOG_DEBUG_HTTP, c->log, 0,
1792                    "http upstream send request");
1793
1794     if (u->state->connect_time == (ngx_msec_t) -1) {
1795         u->state->connect_time = ngx_current_msec - u->state->response_time;
1796     }
...
...
1864     if (c->read->ready) {
1865         ngx_http_upstream_process_header(r, u);
1866         return;
1867     }
1868 }

由此可以得出結論，upstream_connect_time起始時刻為N將與S建立連接前一刻，結束時刻為N與S建立連接成功後，即包括階段3。

upstream_header_time

接下來探究upstream_header_time，可在ngx_http_upstream_send_request函數末尾調用的ngx_http_upstream_process_header中發現header_time的賦值語句：

2047 static void
2048 ngx_http_upstream_process_header(ngx_http_request_t *r, ngx_http_upstream_t *u)
2049 {
...
2058
2059     c->log->action = "reading response header from upstream";
...
2104     for ( ;; ) {
2105
2106         n = c->recv(c, u->buffer.last, u->buffer.end - u->buffer.last);
...
}
...
2172     u->state->header_time = ngx_current_msec - u->state->response_time;
...
2184
2185     if (ngx_http_upstream_process_headers(r, u) != NGX_OK) {
2186         return;
2187     }
...

由此可得出結論，即header_time起始時刻應為N與S將建立連接前一刻，結束時刻為建立連接成功併在應用層接收header數據完成，即階段3~7。

upstream_response_time

最後探究upstream_response_time，追溯代碼可以發現response_time最終在ngx_http_upstream_finalize_request函數中被賦值，相關代碼如下：

// http/ngx_http_upstream.c
4064 static void
4065 ngx_http_upstream_finalize_request(ngx_http_request_t *r,
4066     ngx_http_upstream_t *u, ngx_int_t rc)
4067 {
...
4086
4087     if (u->state && u->state->response_time) {
4088         u->state->response_time = ngx_current_msec - u->state->response_time;
4089
4090         if (u->pipe && u->pipe->read_length) {
4091             u->state->response_length = u->pipe->read_length;
4092         }
4093     }
4094
4095     u->finalize_request(r, rc);
4096
4097     if (u->peer.free && u->peer.sockaddr) {
4098         u->peer.free(&u->peer, u->peer.data, 0);
4099         u->peer.sockaddr = NULL;
4100     }
4101
4102     if (u->peer.connection) {
4103
4104 #if (NGX_HTTP_SSL)
4105
4106         /* TODO: do not shutdown persistent connection */
4107
4108         if (u->peer.connection->ssl) {
4109
4110             /*
4111              * We send the "close notify" shutdown alert to the upstream only
4112              * and do not wait its "close notify" shutdown alert.
4113              * It is acceptable according to the TLS standard.
4114              */
4115
4116             u->peer.connection->ssl->no_wait_shutdown = 1;
4117
4118             (void) ngx_ssl_shutdown(u->peer.connection);
4119         }
4120 #endif
4121
4122         ngx_log_debug1(NGX_LOG_DEBUG_HTTP, r->connection->log, 0,
4123                        "close http upstream connection: %d",
4124                        u->peer.connection->fd);
4125
4126         if (u->peer.connection->pool) {
4127             ngx_destroy_pool(u->peer.connection->pool);
4128         }
4129
4130         ngx_close_connection(u->peer.connection);
4131     }
...

可以看到u->state->response_time = ngx_current_msec - u->state->response_time; 在ngx_close_connection之前執行，由此可以得出結論，upstream_response_time起始時刻為N與S將建立連接前一刻，結束時間為N接收完S全部響應數據將關閉連接前一刻，即階段3~10。

最終結論

經過源碼追溯最終可以得出request_time、upstream_response_time、upstream_connect_time與upstream_header_time四個指標的關係為:
upstream_header_time = upstream_connect_time(階段3) + N向S發送數據被接收完成時間(階段4) + S業務代碼處理數據返回並被N接收完header部分數據的時間(階段5~7)
upstream_response_time = upstream_header_time + N接收完S除header部分剩餘全部數據的時間(階段8)
request_time = N開始接收C全部數據並完成的時間(階段2) + upstream_response_time + N向C返回數據並被C接收完成的時間(階段9~10)
至於一開始對於文檔解釋request_time 接收第一個位元組的、發送完最後一個位元組的具體定義，在閱讀過程中也有了答案：
HTTP是應用層協議，其建立於傳輸層的TCP協議之上，而TCP是保證有序和可靠的--其每一個有效數據包都必須收到對端的ACK確認才算發送成功，因此站在N的角度看待數據接收與發送完成，可以得出以下結論：
其所謂的接收第一個位元組時刻必然是屬於C發向N的第一個TCP有效數據包被接收時刻--不會包括三次握手純SYN/ACK包--除非第三個握手包已經帶了有效數據。
而所謂的發送完最後一個位元組時刻則是N發向C的最後一個有效數據包被接收後，N收到了C的ACK確認時刻。
轉載請註明出處，原文地址： https://www.cnblogs.com/AcAc-t/p/nginx_request_time_upstream_respone_time_analysis.html

參考

http://nginx.org/en/docs/http/ngx_http_log_module.html

簽名：擁抱開源，擁抱自由
您的分享是我們最大的動力!

-Advertisement-
Play Games
更多相關文章
  • Vue 項目實踐指南
    Vue 框架通過數據雙向綁定和虛擬 DOM 技術，幫我們處理了前端開發中最臟最累的 DOM 操作部分， 我們不再需要去考慮如何操作 DOM 以及如何最高效地操作 DOM；但 Vue 項目中仍然存在項目首屏優化、Webpack 編譯配置優化等問題，所以我們仍然需要去關註 Vue 項目性能方面的優化，使 ...
  • 一種JavaScript響應式系統設計與實現
    一種JavaScript響應式系統實現 根據VueJs核心團隊成員霍春陽《Vue.js設計與實現》第四章前三節整理而成 1. 響應式數據與副作用函數 1.1 副作用函數 會產生副作用的函數。 如下示例所示： function effect () { document.body.innerText = ...
  • 抽獎動畫 - 鯉魚跳龍門
    pageClass: home-page-class 鯉魚跳龍門動畫 1. 需求 年中618營銷活動要求做一個鯉魚跳龍門的動畫，產品參考了支付寶上的一個動畫，要求模仿這個來做一個類似的動畫。產品提供的截屏視頻如下： 圖1 從這個視頻里得到的信息，我們可以把動畫分解一下： 321倒計時結束，動畫開始播 ...
  • 記錄--TS封裝axios
    這裡給大家分享我在網上總結出來的一些知識，希望對大家有所幫助 寫在前面 雖然說Fetch API已經使用率已經非常的高了，但是在一些老的瀏覽器還是不支持的，而且axios仍然每周都保持2000多萬的下載量，這就說明瞭axios仍然存在不可撼動的地位，接下來我們就一步一步的去封裝，實現一個靈活、可復用 ...
  • 前端 Git-Hooks 工程化實踐
    前言 前段時間，部門的前端項目遷移到 monorepo 架構，筆者在其中負責跟 git 工作流相關的事情，其中就包括 git hooks 相關的工程化的實踐。用到了一些常用的相關工具如 husky、lint-staged、commitizen、commit-lint 等，以此文記錄一下整個的實踐過程 ...
  • 前端(一)-Html
    1、網頁基本信息 | <!DOCTYPE html> | 瀏覽器使用的規範 | | | | | <head> | 網頁頭 | | <body> | 主體部分 | | <meta> | 元數據 | meta的name屬性（瞭解） | Keyword（關鍵字） | 為搜索引擎提供的關鍵字列表 | | | ...
  • 最流行的WebAssembly Web開發框架： Blazor
    最新的一份《The State of WebAssembly 2022》調查報告已出爐，“對於 WebAssembly 來說，這是相當不錯的一年”。報告的一些重點內容包括：Rust 的使用率和渴望度持續攀升Python 的使用量有了很大的提升JavaScript 已經成為一種可行的 WebAssem ...
  • spring mvc中html標簽和普通字元之間互相轉換的方法分享
    迴圈迭代： 1 public class steps { 2 public int js(int n) { 3 int one = 2; //初始化為第三級臺階最後跨一步的走法 4 int two = 1; //初始化為第三級臺階最後跨兩步（一下邁過去兩個臺階）的走法 5 int sum = 0; ...
一周排行
    -Advertisement-
    Play Games
  • C# + WPF 音頻播放器 界面優雅，體驗良好
    前言 本文介紹一款使用 C# 與 WPF 開發的音頻播放器，其界面簡潔大方，操作體驗流暢。該播放器支持多種音頻格式（如 MP4、WMA、OGG、FLAC 等），並具備標記、實時歌詞顯示等功能。 另外，還支持換膚及多語言（中英文）切換。核心音頻處理採用 FFmpeg 組件，獲得了廣泛認可，目前 Git ...
  • OAuth2.0授權-gitee授權碼模式
    OAuth2.0授權驗證-gitee授權碼模式 本文主要介紹如何筆者自己是如何使用gitee提供的OAuth2.0協議完成授權驗證並登錄到自己的系統，完整模式如圖 1、創建應用 打開gitee個人中心->第三方應用->創建應用 創建應用後在我的應用界面，查看已創建應用的Client ID和Clien ...
  • FastReport.OpenSource .Net下開源免費報表列印組件
    解決了這個問題：《winForm下，fastReport.net 從.net framework 升級到.net5遇到的錯誤“Operation is not supported on this platform.”》 本文內容轉載自：https://www.fcnsoft.com/Home/Sho ...
  • 如何在 ASP.NET Core Web API 方法執行前後 “偷偷“ 作一些 “壞“ 事？初識 ActionFilterAttribute
    國內文章 WPF 從裸 Win 32 的 WM_Pointer 消息獲取觸摸點繪製筆跡 https://www.cnblogs.com/lindexi/p/18390983 本文將告訴大家如何在 WPF 裡面，接收裸 Win 32 的 WM_Pointer 消息，從消息裡面獲取觸摸點信息，使用觸摸點 ...
  • 在 ASP.NET Core Web API 中使用異常篩選器捕獲和統一處理異常
    前言 給大家推薦一個專為新零售快消行業打造了一套高效的進銷存管理系統。 系統不僅具備強大的庫存管理功能，還集成了高性能的輕量級 POS 解決方案，確保頁面載入速度極快，提供良好的用戶體驗。 項目介紹 Dorisoy.POS 是一款基於 .NET 7 和 Angular 4 開發的新零售快消進銷存管理 ...
  • AbpHelper CLI積累與實戰分享
    ABP CLI常用的代碼分享 一、確保環境配置正確 安裝.NET CLI： ABP CLI是基於.NET Core或.NET 5/6/7等更高版本構建的，因此首先需要在你的開發環境中安裝.NET CLI。這可以通過訪問Microsoft官網下載並安裝相應版本的.NET SDK來實現。 安裝ABP ...
  • 記一次HttpClient使用問題分析
    問題 問題是這樣的：第三方的webapi，需要先調用登陸介面獲取Cookie，訪問其它介面時攜帶Cookie信息。 但使用HttpClient類調用登陸介面，返回的Headers中沒有找到Cookie信息。 分析 首先，使用Postman測試該登陸介面，正常返回Cookie信息，說明是HttpCli ...
  • .NET周刊【9月第3期 2024-09-15】
    國內文章 關於.NET在中國為什麼工資低的分析 https://www.cnblogs.com/thinkingmore/p/18406244 .NET在中國開發者的薪資偏低，主要因市場需求、技術棧選擇和企業文化等因素所致。歷史上，.NET曾因微軟的閉源策略發展受限，儘管後來推出了跨平臺的.NET ...
  • 我的網站集成ElasticSearch初體驗
    在WPF開發應用中，動畫不僅可以引起用戶的註意與興趣，而且還使軟體更加便於使用。前面幾篇文章講解了畫筆（Brush），形狀（Shape），幾何圖形（Geometry），變換（Transform）等相關內容，今天繼續講解動畫相關內容和知識點，僅供學習分享使用，如有不足之處，還請指正。 ...
  • 第23篇 委托的概述
    什麼是委托？ 委托可以說是把一個方法代入另一個方法執行，相當於指向函數的指針；事件就相當於保存委托的數組； 1.實例化委托的方式： 方式1：通過new創建實例： public delegate void ShowDelegate(); 或者 public delegate string ShowDe ...
所有分類