Request Time in Nginx Log as always 0.000 for HIT Request

classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

Request Time in Nginx Log as always 0.000 for HIT Request

zakirenish
We are observing a behavior where request time and upstream response time is
logged as same value when request is MISS in log file.

And when there is HIT for the request , request time is logged as 0.000 for
all the requests.

Please help what could be the reason for this , we tried compiling from
source , rpm , upgrading and downgrading the version of Nginx.

But always the case remains same.

Please help what could be causing this behavior

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,288938,288938#msg-288938

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: Request Time in Nginx Log as always 0.000 for HIT Request

Maxim Dounin
Hello!

On Sat, Aug 01, 2020 at 04:31:14PM -0400, anish10dec wrote:

> We are observing a behavior where request time and upstream response time is
> logged as same value when request is MISS in log file.
>
> And when there is HIT for the request , request time is logged as 0.000 for
> all the requests.

nginx updates internal time only once per event loop iteration, so
it is relatively easy to see $request_time logged as 0 (or
identical to $upstream_response_time as long as there was an
request to upstream).  This implies:

- the request can be read immediately without waiting for
  additional data from client;

- the response is small enough to fit into the socket buffer.

--
Maxim Dounin
http://mdounin.ru/
_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: Request Time in Nginx Log as always 0.000 for HIT Request

zakirenish
In our case response body is of size around 4MB to 8MB and its showing
0.000.

Since "request time" is for analyzing the time taken for delivering the
content to client , we are not able to get the actual value or time taken .

Even on slow user connection its showing 0.000 .
Generally it should be much higher as it captures the total time taken for
delivering last byte of the content to user.

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,288938,288954#msg-288954

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: Request Time in Nginx Log as always 0.000 for HIT Request

Maxim Dounin
Hello!

On Mon, Aug 03, 2020 at 03:54:15PM -0400, anish10dec wrote:

> In our case response body is of size around 4MB to 8MB and its showing
> 0.000.
>
> Since "request time" is for analyzing the time taken for delivering the
> content to client , we are not able to get the actual value or time taken .
>
> Even on slow user connection its showing 0.000 .
> Generally it should be much higher as it captures the total time taken for
> delivering last byte of the content to user.

The $request_time variable shows the time from reading the the
first byte of the request from the client to sending the last byte
of the response to the socket buffer.  Note the difference: not
deliverying the last byte to the user, but sending the response to
the socket buffer.  With large enough socket buffers and/or small
enough responses $request_time can be 0, and usually this is
expected result since all request processing happens within a
single event loop iteration.

In some extreme cases $request_time can be seen to be 0 even if
sending the response is slow and takes significant time: this
might happen if reading from disk is very slow (slower than
sending to the client), so nginx never blocks on sending.  Most
often this happens when using sendfile, and the sendfile_max_chunk
directive (http://nginx.org/r/sendfile_max_chunk) can be used to
limit the amount of data sent within a single event loop
iteration.  Given the response sizes this is unlikely your case
though, as 4M to 8M looks quite comparable to modern sizes of
socket buffers, especially when using auto-tuning.

--
Maxim Dounin
http://mdounin.ru/
_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx
Reply | Threaded
Open this post in threaded view
|

Re: Request Time in Nginx Log as always 0.000 for HIT Request

zakirenish
Thanks Maxim for the explanation.

Is there a way to figure out how much time Nginx took to deliver the files
to the end user.

Posted at Nginx Forum: https://forum.nginx.org/read.php?2,288938,289054#msg-289054

_______________________________________________
nginx mailing list
[hidden email]
http://mailman.nginx.org/mailman/listinfo/nginx