$request_time less than $upstream_response_time

[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?

[Maxim Dounin]

That's because $upstream_response_time uses monotonic time as clock_gettime(CLOCK_MONOTONIC_COARSE) on 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.

[Maxim Dounin <mdounin@…>]

In 7939:9e7de0547f09/nginx:

Removed CLOCK_MONOTONIC_COARSE support.

While clock_gettime(CLOCK_MONOTONIC_COARSE) is faster than
clock_gettime(CLOCK_MONOTONIC), the latter is fast enough on Linux for
practical usage, and the difference is negligible compared to other costs
at each event loop iteration. On the other hand, CLOCK_MONOTONIC_COARSE
causes various issues with typical CONFIG_HZ=250, notably very inaccurate
limit_rate handling in some edge cases (ticket #1678) and negative difference
between $request_time and $upstream_response_time (ticket #1965).