STALE responses taking as much as MISS responses

[Maxim Dounin]

Hello!

On Fri, Feb 15, 2019 at 12:54:37PM -0500, joao.pereira wrote:

> We are trying to measure times using the variables referred on the following
> article and on the emails above:
> https://www.nginx.com/blog/using-nginx-logging-for-application-performance-monitoring/#var_request_time
> 
> But It came to our attention that those are not accurate, our log file:
> log_format main ‘“$request_time" - $upstream_response_time” -
> “$upstream_connect_time” - “$upstream_header_time”;
> 
> STALE only show $request_time but no $upstream_*
> Hits are taking "0.000 to 0.001 which makes no sense because we are doing
> the request from EU to US, the MISS  seems ok as they show both
> $request_time and $upstream_* , there is any way to measure these times
> properly ?

The "HIT" status means that a response was returned from cache.  
Since there is no request to the upstream server, no upstream 
times are expected to be available.  The $request_time variable 
counts time between reading the first byte of a request from the 
socket and writing the last byte of the response to the socket.  
As long as socket buffers are large enough, this can happen in one 
event loop iteration, so times like "0.000" are pretty normal for 
small responses.

The "STALE" status means that the response was returned from 
cache, as per "proxy_cache_use_stale".  And this implies that 
there will be no upstream times, much like with "HIT".

Note well that if you are using "proxy_cache_background_update", 
which uses subrequests to update cache, the main request will have 
the "STALE" status, and there will be no upstream times as 
explained above, but $request_time will still include subrequest 
execution time.  If you want to see subrequest details in log, 
including upstream times, consider the "log_subrequest" 
configuration directive (http://nginx.org/r/log_subrequest).

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