Opened 5 years ago

Last modified 5 years ago

#1965 accepted defect

$request_time less than $upstream_response_time

Reported by: learn0208@… Owned by:
Priority: minor Milestone:
Component: nginx-core Version: 1.14.x
Keywords: request_time Cc:
uname -a: Linux NGINX-192-168-11-5-B28 3.10.0-693.el7.x86_64 #1 SMP Tue Aug 22 21:09:27 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
nginx -V: nginx version: nginx/1.14.0
built by gcc 4.8.5 20150623 (Red Hat 4.8.5-16) (GCC)
built with OpenSSL 1.0.2k-fips 26 Jan 2017
TLS SNI support enabled
configure arguments: --prefix=/usr/local/nginx --with-http_stub_status_module --with-http_ssl_module --with-http_realip_module --add-module=/root/rpmbuild/SOURCES/nginx-sticky-module-1.1 --add-module=/root/rpmbuild/SOURCES/nginx_upstream_check_module-master --add-module=/root/rpmbuild/SOURCES/ngx_devel_kit-0.3.0rc1 --add-module=/root/rpmbuild/SOURCES/lua-nginx-module-0.10.13 --add-module=/root/rpmbuild/SOURCES/nginx-module-vts-0.1.18 --with-ld-opt=-Wl,-rpath,/usr/local/luajit/lib --with-stream

Description (last modified by learn0208@…)

nginx logformat:
log_format main escape=json '{ "http_x_forwarded_for": "[$http_x_forwarded_for]", '
'"remote_addr": "$remote_addr", '
'"remote_user": "$remote_user", '
'"time_local": "[$time_local]", '
'"request_method": "$request_method", '
'"request_host": "$scheme://$host", '
'"request_host_1": "$host", '
'"service_line": "itservice.api", '
'"request_uri": "$uri", '
'"query_string": "$query_string", '
'"server_protocol": "$server_protocol", '
'"status": "$status", '
'"body_bytes_sent": "$body_bytes_sent", '
'"http_referer": "$http_referer", '
'"http_user_agent": "$http_user_agent",'
'"request_time": "$request_time", '
'"upstream_addr": "[$upstream_addr]", '
'"req_id": "$request_id", '
'"upstream_response_time": "$upstream_response_time" '
' }';

nginx log:
{ "http_x_forwarded_for": "[]", "remote_addr": "192.168.11.130", "remote_user": "", "time_local": "[29/Apr/2020:01:11:33 +0800]", "request_method": "GET", "request_host": "​https://xxx.abc.com", "request_host_1": "xxx.abc.com", "service_line": "itservice.api", "request_uri": "/api/v1/sensitive-info/batch/getUserInfo", "query_string": "batchNumber=xxx&userId=xxx&dataType=1", "server_protocol": "HTTP/1.1", "status": "200", "body_bytes_sent": "113", "http_referer": "", "http_user_agent": "Apache-HttpClient/4.5.10 (Java/1.8.0_211)","request_time": "0.011", "upstream_addr": "[192.168.10.182:80]", "req_id": "6bdcc5ce837247323599d37aaceba33c", "upstream_response_time": "0.012" }

issue:
upstream_response_time: 0.012
request_time: 0.011
In this log, the requset_time is less than upstream_response_time. Why does this happen?

Change History (2)

comment:1 by learn0208@…, 5 years ago

Description: modified (diff)

comment:2 by Maxim Dounin, 5 years ago

Status: new → accepted

That's because $upstream_response_time uses monotonic time as clock_gettime(CLOCK_MONOTONIC_COARSE) ono Linux (see ticket #189), and it might be slightly wrong due to low accuracy (with typical CONFIG_HZ=250 it is only updated once per 4ms). In contrast, $request_time currently uses gettimeofday() and might be wrong if wall clock time changes.

In this particular case the difference 0.012 vs. 0.011 is clearly due to CLOCK_MONOTONIC_COARSE being used with CONFIG_HZ=250. As mentioned in #1678, a possible solution might be to avoid using CLOCK_MONOTONIC_COARSE and switch to CLOCK_MONOTONIC instead. This way $upstream_response_time will be identical to $request_time as long as there are no wall clock time changes.

We can also consider switching $request_time to use monotonic time as well. Though, as discussed privately after a similar question in the russian mailing list (​here), this may have bad side effects for very long requests on 32-bit platforms, and needs additional investigation.

Note: See TracTickets for help on using tickets.