nginx源码层面探究request_time、upstream_response_time、upstream_connect_time与upstream_heade

背景概述

最近计划着重分析一下线上各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

签名：拥抱开源，拥抱自由 【文章转自防cc http://www.558idc.com/gfcdn.html 复制请保留原URL】