nginx & upstream_response_time

[Marcin Deranek]

Hi,

Currently I'm running nginx 1.2.4 with uwsgi backend. To my
understanding $upstream_response_time should represent time taken
to deliver content by upsteam (in my case uwsgi backend). It looks like
it't not the case for myself.

uwsgi specific snippet:

server {
  ...
  uwsgi_buffering  off;
  uwsgi_buffer_size  1M;
  uwsgi_buffers  2 1M;
  uwsgi_busy_buffers_size  1M;

  location / {
    uwsgi_pass  unix:/var/run/uwsgi/uwsgi.sock;
    include  uwsgi_params;
    uwsgi_modifier1  5;
  }
}

On backend I'm running uWSGI with 1 worker only. Backend app
(PSGI) generates 900kB output then waits for 10s and finishes response:

my $app = sub {
    my $env = shift;
    return sub {
        my $respond = shift;
        my $writer = $respond->([200, ['Content-Type', 'text/html']]);
        for (1..900) {
            my $dt = localtime;
            $writer->write("[ $dt ]: " . "x" x 1024 . "\n");
        }
        sleep 10;
        $writer->close();
    };
};


When I use "slow" client connecting to nginx (eg. socat
TCP:127.0.0.1:80,rcvbuf=128 STDIO) I can see the following hapening:
Backend server gets busy only for ~10s (this is what I expect). If I
issue 2 concurrent requests one is served immediately and 2nd one after
~10s. This behaviour would indicate that backend was able to deliver
content in ~10s (whole response was buffered as buffer size is big
enough to accommodate full response and we have only 1 worked at the
backend). Unfortunately access log disagrees with that as it makes
$upstream_response_time almost equal to $request_time (eg. ~1000s vs
~10s of expected). Is this an expected behaviour ?
Regards,

Marcin