When troubleshooting long-running requests in Nginx, understanding exactly when the $time_local timestamp is recorded becomes crucial. The variable actually represents the time when Nginx finishes processing the request and writes the log entry, not when the request started.

For requests taking 10 seconds (as in your case), this means:

# Example log entry showing finish time
192.168.1.1 - - [10/Oct/2023:15:30:45 +0000] "GET /slow-endpoint HTTP/1.1" 200 1234

The timestamp (15:30:45) reflects when the response was completed, not when it began at ~15:30:35.

If you need request start time, consider these alternatives:

log_format timed_log '$remote_addr - $remote_user [$time_iso8601] '
                    '"$request" $status $body_bytes_sent '
                    '"$http_referer" "$http_user_agent" '
                    'request_time=$request_time '
                    'upstream_time=$upstream_response_time';

Key metrics:

• $request_time: Total elapsed time from first byte received to last byte sent
• $msec: Current time with millisecond resolution

Here's a complete log format example that captures both temporal aspects:

http {
    log_format detailed '$remote_addr - $remote_user [$time_local] '
                        'start_time=$msec '
                        'request_time=$request_time '
                        '"$request" $status $body_bytes_sent';
    
    server {
        access_log /var/log/nginx/access.log detailed;
        # ... other server config
    }
}

This provides:

1. The finish time ($time_local)
2. The precise start time (via $msec)
3. The duration ($request_time)

With the enhanced logging, you can reconstruct complete request timelines:

# Sample log output
192.168.1.1 - - [10/Oct/2023:15:30:45 +0000] start_time=1602336645.320 request_time=10.005 "GET /slow-endpoint HTTP/1.1" 200 1234

This shows:

• Request finished at 15:30:45
• Started at timestamp 1602336645.320 (Unix time with milliseconds)
• Took 10.005 seconds to complete

When analyzing long-running requests in Nginx logs (some taking up to 10 seconds in our case), we need to understand precisely what the $time_local variable represents. According to the Nginx source code and core documentation, this variable records the time when the logging occurs - which is typically at the end of the request processing.

The timing behavior becomes clear when examining the logging module's implementation. Nginx processes the log write operation during the request cleanup phase, after all response data has been sent to the client. Here's the relevant snippet from the Nginx source:

static void
ngx_http_log_handler(ngx_http_request_t *r)
{
    ngx_http_log_ctx_t *ctx = r->connection->log->data;
    
    /* This executes in the request cleanup phase */
    ngx_http_log_write(r, ctx->file, &ctx->format, ctx->buf);
}

For timing measurements, consider these alternatives:

log_format timing '$remote_addr - $remote_user [$time_local] '
                 '"$request" $status $body_bytes_sent '
                 'Request-Time:$request_time '
                 'Upstream-Time:$upstream_response_time';

The $request_time variable provides the total request duration with millisecond resolution.

Here's how a 10-second request would appear in different log formats:

# Standard format (time_local shows completion time)
192.168.1.1 - - [10/Oct/2023:15:32:45 +0000] "GET /slow-endpoint HTTP/1.1" 200 1234

# With timing information added
192.168.1.1 - - [10/Oct/2023:15:32:45 +0000] "GET /slow-endpoint HTTP/1.1" 200 1234 Request-Time:10.005 Upstream-Time:9.872

For comprehensive performance analysis:

1. Always include $request_time in your log format
2. For upstream requests, capture $upstream_response_time
3. Consider microsecond-resolution timing with $msec for precise benchmarks