189 8069 5689
最近计划着重分析一下线上各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
http://nginx.org/en/docs/http/ngx_http_log_module.html