最近計劃著重分析一下線上各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請求(非keep alive)生命週期的多個階段（以下C指代使用者端，N指代nginx伺服器，S指代上游server）：
其中1-2和9-11這5個階段 的速度直接受到C到N之間的網路質量影響，伺服器端雖然可以通過降低傳輸資料量、使用更快的協定(如HTTP3.0基於QUIC)等降低傳輸耗時，但無法起到決定性的作用，一般可視為超出了可優化的控制範圍。
3-8這6個階段一般都發生在內網，即N與S都處於同一個機房(甚至同一個機架/同一臺物理機上)，網路質量穩定且RTT基本在1ms內，網路耗時較少，正常情況下其主要時間應集中在階段5--各種業務邏輯處理資料並生成結果--這也正是一般後端優化的目標階段。
參考: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 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_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，可在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，追溯程式碼可以發現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