upstream_response_time larger than request_time

[Maxim Dounin]

Hello!

On Tue, Jun 04, 2019 at 12:02:47PM -0400, kron wrote:

> Доброго дня.
> Наблюдаю странную картину в логах. Логируется две переменных - request_time
> и upstream_response_time.
> Судя по документации логично предположить, что request_time будет всегда
> либо больше, либо равной upstream_response_time, но по факту оказалось, что
> upstream_response_time хоть и не значительно, но бывает больше чем
> request_time. Хотелось бы понять в каких случаях такое возможно?
> 
> Пример таймингов:
> request_time upstream_response_time method
> 5.954 5.956 GET
> 5.421 5.424 GET
> 30.576 30.577 GET
> 2.302 2.304 GET
> 2.298 2.300 GET
> 1.923 1.924 GET
> 1.898 1.900 GET
> 1.802 1.804 GET
> 1.774 1.776 GET
> 1.683 1.684 GET
> 
> версия nginx - 1.15.5

Это связано с тем, что сейчас на Линуксе $upstream_response_time 
считается через clock_gettime(CLOCK_MONOTONIC_COARSE), и при 
типичных значениях CONFIG_HZ=250 оно может отставать на время до 4 
миллисекунд.  В то же время время для расчёта $request_time 
используется не монотонное время, а результат gettimeofday(), то 
есть время по настенным часам.  Так что в некоторых случаях 
$upstream_response_time может быть незначительно больше 
$request_time.

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