Deep Dive into Nginx request_time and upstream_response_time: Causes and Solutions

When using a gateway, developers often monitor log parameters such as request_time and upstream_response_time to assess service health. Although both record durations, many are unclear about their exact meanings and the scenarios in which they are used.

Problem Introduction

Users reported that request_time values were markedly larger than upstream_response_time, sometimes reaching around 5 seconds while the upstream time stayed below 0.01 seconds. The article investigates the cause and impact of this discrepancy.

Parameter Introduction

request_time

Official definition: "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." In plain terms, it measures the interval from the gateway receiving the first client byte to the moment the log is written after the last byte is sent.

upstream_response_time

Official definition: "keeps time spent on receiving the response header 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." It represents the time from the gateway establishing a connection to the upstream service until the last byte from the upstream is received.

Problem Tracing

Initial suspicion of network latency and I/O overload was ruled out via monitoring data. The focus shifted to Nginx configuration and source code.

Log Analysis

Log samples showed request_time values ranging from 2 seconds to 10 seconds, with the majority (≈98 %) clustering around 5 seconds.

Packet Capture Analysis

Detailed TCP traces revealed that after the server sent a FIN packet, the client delayed sending its ACK/FIN for several seconds (e.g., 2.6 s, 3.5 s, 4.7 s). These delays contributed to the inflated request_time values.

Source Code Inspection

The relevant Nginx functions are ngx_http_finalize_connection, ngx_http_set_lingering_close, and ngx_http_lingering_close_handler. Key excerpts:

static void ngx_http_finalize_connection(ngx_http_request_t *r) {
    /* ... */
    if (!ngx_terminate && !ngx_exiting && r->keepalive && clcf->keepalive_timeout > 0) {
        ngx_http_set_keepalive(r);
        return;
    }
    /* lingering_close handling */
    if (clcf->lingering_close == NGX_HTTP_LINGERING_ALWAYS
        || (clcf->lingering_close == NGX_HTTP_LINGERING_ON && (r->lingering_close
            || r->header_in->pos < r->header_in->last
            || r->connection->read->ready
            || r->connection->pipeline))) {
        ngx_http_set_lingering_close(r->connection);
        return;
    }
    ngx_http_close_request(r, 0);
}

static void ngx_http_set_lingering_close(ngx_connection_t *c) {
    r = c->data;
    clcf = ngx_http_get_module_loc_conf(r, ngx_http_core_module);
    if (r->lingering_time == 0) {
        r->lingering_time = ngx_time() + (time_t)(clcf->lingering_time / 1000);
    }
    rev = c->read;
    rev->handler = ngx_http_lingering_close_handler;
    ngx_add_timer(rev, clcf->lingering_timeout);
    if (rev->ready) {
        ngx_http_lingering_close_handler(rev);
    }
}

static void ngx_http_lingering_close_handler(ngx_event_t *rev) {
    timer = (ngx_msec_t) r->lingering_time - (ngx_msec_t) ngx_time();
    if ((ngx_msec_int_t) timer <= 0) {
        ngx_http_close_request(r, 0);
        return;
    }
    do {
        n = c->recv(c, buffer, NGX_HTTP_LINGERING_BUFFER_SIZE);
        if (n == NGX_AGAIN) { break; }
        if (n == NGX_ERROR || n == 0) { ngx_http_close_request(r, 0); return; }
    } while (rev->ready);
    clcf = ngx_http_get_module_loc_conf(r, ngx_http_core_module);
    timer *= 1000;
    if (timer > clcf->lingering_timeout) { timer = clcf->lingering_timeout; }
    ngx_add_timer(rev, timer);
}

The lingering_timeout directive (default 5 s) controls how long Nginx waits for additional client data before forcibly closing the connection. If the client does not send data within this period, the connection is closed and the log is finally written, inflating request_time.

Configuration Verification

Changing lingering_time to 3 seconds and observing logs showed that >99 % of the previously 5‑second entries now fell around 3 seconds, confirming the root cause.

Conclusion

The excessive request_time values stem from Nginx’s lingering close behavior, specifically the default lingering_timeout 5s. Adjusting this timeout (or disabling lingering close) aligns log times with actual request processing, eliminating misleading delays.