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
  • 移動開發（一）：使用.NET MAUI開發第一個安卓APP
    移動開發（一）：使用.NET MAUI開發第一個安卓APP 對於工作多年的C#程式員來說，近來想嘗試開發一款安卓APP，考慮了很久最終選擇使用.NET MAUI這個微軟官方的框架來嘗試體驗開發安卓APP，畢竟是使用Visual Studio開發工具，使用起來也比較的順手，結合微軟官方的教程進行了安卓 ...
  • wpf ToggleButton選中效果和一個登錄界面
    前言 QuestPDF 是一個開源 .NET 庫，用於生成 PDF 文檔。使用了C# Fluent API方式可簡化開發、減少錯誤並提高工作效率。利用它可以輕鬆生成 PDF 報告、發票、導出文件等。 項目介紹 QuestPDF 是一個革命性的開源 .NET 庫，它徹底改變了我們生成 PDF 文檔的方 ...
  • 彈幕樹洞項目功能新增篇
    項目地址 項目後端地址： https://github.com/ZyPLJ/ZYTteeHole 項目前端頁面地址： ZyPLJ/TreeHoleVue (github.com) https://github.com/ZyPLJ/TreeHoleVue 目前項目測試訪問地址： http://tree ...
  • 第27篇 sqlserver2022詳細安裝步驟
    話不多說，直接開乾 一.下載 1.官方鏈接下載： https://www.microsoft.com/zh-cn/sql-server/sql-server-downloads 2.在下載目錄中找到下麵這個小的安裝包 SQL2022-SSEI-Dev.exe，運行開始下載SQL server； 二. ...
  • .NET 開源高性能 MQTT 類庫
    前言 隨著物聯網（IoT）技術的迅猛發展，MQTT（消息隊列遙測傳輸）協議憑藉其輕量級和高效性，已成為眾多物聯網應用的首選通信標準。 MQTTnet 作為一個高性能的 .NET 開源庫，為 .NET 平臺上的 MQTT 客戶端與伺服器開發提供了強大的支持。 本文將全面介紹 MQTTnet 的核心功能 ...
  • Serilog文檔翻譯系列（六） - 可用的接收器、增強器、格式化輸出
    Serilog支持多種接收器用於日誌存儲，增強器用於添加屬性，LogContext管理動態屬性，支持多種輸出格式包括純文本、JSON及ExpressionTemplate。還提供了自定義格式化選項，適用於不同需求。 ...
  • 警惕 Visual Studio 屬性求值副作用導致邏輯不符合預期
    目錄簡介獲取 HTML 文檔解析 HTML 文檔測試參考文章 簡介 動態內容網站使用 JavaScript 腳本動態檢索和渲染數據，爬取信息時需要模擬瀏覽器行為，否則獲取到的源碼基本是空的。 本文使用的爬取步驟如下： 使用 Selenium 獲取渲染後的 HTML 文檔 使用 HtmlAgility ...
  • [使用目前最新版]HybridCLR6.9.0+YooAsset2.2.4實現純C# Unity熱更新方案 (一)
    1.前言 什麼是熱更新 游戲或者軟體更新時，無需重新下載客戶端進行安裝，而是在應用程式啟動的情況下，在內部進行資源或者代碼更新 Unity目前常用熱更新解決方案 HybridCLR，Xlua，ILRuntime等 Unity目前常用資源管理解決方案 AssetBundles，Addressable， ...
  • 在 ASP.NET Core Web API 中使用操作篩選器統一處理通用操作
    本文章主要是在C# ASP.NET Core Web API框架實現向手機發送驗證碼簡訊功能。這裡我選擇是一個互億無線簡訊驗證碼平臺，其實像阿裡雲，騰訊雲上面也可以。 首先我們先去 互億無線 https://www.ihuyi.com/api/sms.html 去註冊一個賬號 註冊完成賬號後，它會送 ...
  • 第28篇 如何.net中實現高效可靠數據同步api
    通過以下方式可以高效，並保證數據同步的可靠性 1.API設計 使用RESTful設計，確保API端點明確，並使用適當的HTTP方法（如POST用於創建，PUT用於更新）。 設計清晰的請求和響應模型，以確保客戶端能夠理解預期格式。 2.數據驗證 在伺服器端進行嚴格的數據驗證，確保接收到的數據符合預期格 ...
所有分類