Log nginx "queue time"

I don't know if "queue time" is the right term for what i'm trying to log, maybe TTFB (time to first byte) is more correct.

I'm trying to explain better with a test I did:
I wrote a little python app (flask framework), with one function (one endpoint) that need about 5 seconds to complete the process (but same result with a sleep of 5 seconds).
I used uWSGI as application server, configured with 1 process and 1 thread, and nginx as reverse proxy.
With this configuration if i do two concurrent requests from the browser what i see is that the first finishes in about 5 seconds and the second finishes in about 10 second.
That's all right, with only one uWSGI process the second request must wait the first is completed, but what i want to log is the time the second request stay in "queue" waiting to be processed from uWSGI.

I tried all the nginx log variables I could find and could seem relevant to my need:

$request_time

request processing time in seconds with a milliseconds resolution; time elapsed between the first bytes were read from the client and the log write after the last bytes were sent to the client
$upstream_response_time

keeps time spent on receiving the response from the upstream server; the time is kept in seconds with millisecond resolution.
$upstream_header_time

keeps time spent on receiving the response header from the upstream server (1.7.10); the time is kept in seconds with millisecond resolution.

but all of them report the same time, about 5 second, for both requests.
I also tried to add to log the variable $msec

time in seconds with a milliseconds resolution at the time of the log write

and a custom variable $my_start_time, initialized at the start of the server section with set $my_start_time "${msec}"; in this context msec is:

current time in seconds with the milliseconds resolution

but also in this case the difference between the two times is about 5 seconds for both requests.

I suppose nginx should know the time that i try to log or at least the total time of the request from which i can subtract the "request time" and get the waiting time.

If i analyze the requests with the chrome browser and check the waterfall i see, for the first request, a total time of about 5 seconds of which almost all in the row "Waiting (TTFB)" while for the second request i see a total time of about 10 seconds with about 5 in the row "Waiting (TTFB)" and about 5 in the row "Stalled".
The time i want log from server side is the "Stalled" time reported by chrome; from this question:

Understanding Chrome network log "Stalled" state

i understand that this time is related to proxy negotiation, so i suppose it is related with nginx that act as reverse proxy.

The test configuration is done with long process in order to measure these times more easily, but the time will be present, albeit shorter, whenever there are more concurrent requests then uWSGI processes.

Did I miss something in my elucubrations?
What is the correct name of this "queue time"?
How can i log it?

Thanks in advance for any suggestion

Recommended topics

Hot tags