背景概述
最近計劃著重分析一下線上各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）：
- C向N發起TCP三次握手建立連接成功，C開始向N通過TCP發送HTTP請求具體資料(header/body...)
- N開始接收到C發送的資料到全部接收完成
- N作為代理向S發起TCP三次握手并建立連接成功，N開始向S發送HTTP資料
- S開始接收N發送的資料并全部接收完成
- S業務代碼根據業務規則進行處理完成并生成HTTP回應結果
- S開始將回應結果發送給N
- N開始接收回應結果并接收header部分完成
- N接收S回傳的全部回應結果完成
- N開始向C回傳全部的HTTP回應結果
- C開始接收N回傳的資料并全部接收完成
- 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
簽名：擁抱開源，擁抱自由轉載請註明出處，本文鏈接：https://www.uj5u.com/houduan/497682.html
標籤：C
上一篇：C 語言指標