Opened 4 years ago
Last modified 15 months ago
#1965 accepted defect
$request_time less than $upstream_response_time
Reported by: | 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 )
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?
That's because
$upstream_response_time
uses monotonic time asclock_gettime(CLOCK_MONOTONIC_COARSE)
on Linux (see ticket #189), and it might be slightly wrong due to low accuracy (with typicalCONFIG_HZ=250
it is only updated once per 4ms). In contrast,$request_time
currently usesgettimeofday()
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 withCONFIG_HZ=250
. As mentioned in #1678, a possible solution might be to avoid usingCLOCK_MONOTONIC_COARSE
and switch toCLOCK_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.