When does nginx $upstream_response_time start/stop specifically

Question

Does anyone know when, specifically, the clock for $upstream_response_time begins and ends?

The documentation seems a bit vague:

keeps time spent on receiving the response from the upstream server; the time is kept in seconds with millisecond resolution. Times of several responses are separated by commas and colons like addresses in the $upstream_addr variable.

There is also an $upstream_header_time value, which adds more confusion.

1. I assume $upstream_connect_time stops once the connection is established, but before it is accepted upstream?

2. After this what does $upstream_response_time include?

   • Time spent waiting for upstream to accept?
   • Time spent sending the request?
   • Time spent sending the response header?

Rosenkrantz

Answer 1

A more specific definition is in their blog.

$request_time – Full request time, starting when NGINX reads the first byte from the client and ending when NGINX sends the last byte of the response body

$upstream_connect_time – Time spent establishing a connection with an upstream server

$upstream_header_time – Time between establishing a connection to an upstream server and receiving the first byte of the response header

$upstream_response_time – Time between establishing a connection to an upstream server and receiving the last byte of the response body

So

• $upstream_header_time is included in $upstream_response_time.
• Time spent connecting to upstream is not included in both of them.
• Time spent sending response to client is not included in both of them.

Denaturalize

It seems like $upstream_connect_time is included in $upstream_response_time and Dmitry's answer is correct though: nginx_http_s3_backend_connect_duration_seconds_count{status="404"} 1 nginx_http_s3_backend_connect_duration_seconds_sum{status="404"} 0.014 nginx_http_s3_backend_response_duration_seconds_count{status="404"} 1 nginx_http_s3_backend_response_duration_seconds_sum{status="404"} 0.038 nginx_http_s3_request_duration_seconds_count{status="404"} 1 nginx_http_s3_request_duration_seconds_sum{status="404"} 0.04 – Accommodation

Answer 2

I've investigated and debug the behavior around this, and it turned out as follows:

	start time	end time
$upstream_connect_time	before Nginx establishes TCP connection with upstream server	before Nginx sends HTTP request to upstream server
$upstream_header_time	before Nginx establishes TCP connection with upstream server	after Nginx receives and processes headers in HTTP response from upstream server
$upstream_response_time	before Nginx establishes TCP connection with upstream server	after Nginx receives and processes HTTP response from upstream server

source code

I'll explain how values are different between $upstream_connect_time and $upstream_response_time, as it's what I was primarily interested in.

The value of u->state->connect_time, which represents $upstream_connect_time in millisecond, is ingested in the following section: https://github.com/nginx/nginx/blob/3334585539168947650a37d74dd32973ab451d70/src/http/ngx_http_upstream.c#L2073

    if (u->state->connect_time == (ngx_msec_t) -1) {
        u->state->connect_time = ngx_current_msec - u->start_time;
    }

Whereas the value of u->state->response_time, which represents $upstream_response_time in millisecond, is set in the following section: https://github.com/nginx/nginx/blob/3334585539168947650a37d74dd32973ab451d70/src/http/ngx_http_upstream.c#L4432

    if (u->state && u->state->response_time == (ngx_msec_t) -1) {
        u->state->response_time = ngx_current_msec - u->start_time;

You can notice that both of values are calculated based on u->start_time, which is the time just before the connection is established, defined in https://github.com/nginx/nginx/blob/3334585539168947650a37d74dd32973ab451d70/src/http/ngx_http_upstream.c#L1533 (note that ngx_event_connect_peer is a function to establish TCP connection between nginx workerprocesses and upstream servers).

Therefore, both values include the time taken to establish the TCP connection. You can check this by doing a live debug with, for example, gdbserver.

Bever