When does nginx $upstream_response_time start/stop specifically

user_1215036 0
Viewed 3331

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?
query-performance nginx performance
2 Answers

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->repponse_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.

user_81741780
Related