Inconsistent time measurement in Nginx

[Maxim Dounin]

Hello!

On Tue, Sep 28, 2021 at 10:27:55AM +0800, Zexuan Luo wrote:

> Hi, Nginx developers:
> 
> Currently, the request_time uses ngx_timeofday to get the time, which
> finally will call gettimeofday. Meanwhile, the upstream_x_time series
> uses ngx_current_msec to calculate the time, which finally will call
> ngx_monotonic_time.
> 
> On Linux, the gettimeofday will call clock_gettime(CLOCK_REALTIME,
> &ts) while the ngx_monotonic_time will call
> clock_gettime(CLOCK_MONOTONIC_COARSE, &ts).
> 
> So the request_time uses CLOCK_REALTIME and the upstream_x_time series
> uses CLOCK_MONOTONIC_COARSE. As they are different sources, sometimes
> we observe that the upstream_response_time is larger than
> request_time. This behavior is unexpected and has caused bug in our
> software.
> 
> A similar report can be also found in
> https://stackoverflow.com/questions/53978695/how-can-request-time-be-less-than-upstream-response-time-in-nginx.
> 
> Is this behavior intended? Why not use the same time measurement for
> all metrics? Thanks for your reply.

The $upstream_response_time variable was changed to use 
ngx_current_msec in 59fc60585f1e 
(http://hg.nginx.org/nginx/rev/59fc60585f1e) as part of 
$upstream_connect_time introduction, because it is easier to code 
and more appropriate for time interval measurements, especially 
following introduction of CLOCK_MONOTONIC usage.

The $response_time still uses ngx_timeofday() for mostly historic 
reasons.  Likely it will be changed to use ngx_current_msec, 
though this needs to be done with care, notably because 
ngx_current_msec can overflow on 32-bit platforms.  At some point 
there was a patch by Sergey Kandaurov to do the change, though it 
was postponed due to questions on what happens on overflows in 
limit_rate handling.

-- 
Maxim Dounin
http://mdounin.ru/