Forum: NGINX nginx & upstream_response_time

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

Hello!

On Tue, Oct 02, 2012 at 03:44:38PM +0200, Marcin Deranek wrote:

>   ...
>   uwsgi_buffering  off;

[...]

> 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 ?

You asked nginx to work in unbuffered mode, and in this mode
doesn't pay much attention to what happens with backend connection
if it isn't able to write data it already has to a client.  In
particular it won't detect connection close by the backend (and
stop counting $upstream_response_time).

This is probably could be somewhat enhanced, but if you care about
$upstream_response_time it most likely means you don't need
"uwsgi_buffering off" and vice versa.

--
Maxim Dounin
http://nginx.com/support.html

Hi Maxim,

On Tue, 2 Oct 2012 18:30:07 +0400
Maxim Dounin <mdounin@mdounin.ru> wrote:

> You asked nginx to work in unbuffered mode, and in this mode
> doesn't pay much attention to what happens with backend connection
> if it isn't able to write data it already has to a client.  In
> particular it won't detect connection close by the backend (and
> stop counting $upstream_response_time).

I see.

> This is probably could be somewhat enhanced, but if you care about
> $upstream_response_time it most likely means you don't need
> "uwsgi_buffering off" and vice versa.

Well, I don't completely agree. As it was explained at
http://forum.nginx.org/read.php?2,193347,193446#msg-193446 some sort of
buffering still takes place even though we work in unbuffered mode. The
only reason why we went for unbuffered mode is latency.
Regards,

Marcin