(bug?)Timeout when proxy-pass 0 byte file

I been expirencing very slow page load when use nginx as frontend(with
proxy_pass) for a while.

After some test and debug, i found that it always timeout on response
of 0 byte file.

So i think there might be a bug when nginx running on proxy mode and
serving 0 byte files. The frontend will consider there should be more
data and wait until timeout or something like this.

Btw. Nginx is great. Thanks

tomasen

Hello!

On Tue, Sep 29, 2009 at 10:08:51PM +0800, tOmasEn wrote:

I been expirencing very slow page load when use nginx as frontend(with
proxy_pass) for a while.

After some test and debug, i found that it always timeout on response
of 0 byte file.

So i think there might be a bug when nginx running on proxy mode and
serving 0 byte files. The frontend will consider there should be more
data and wait until timeout or something like this.

Could you please provide nginx -V output and debug log?

Maxim D.

here is my conf

http{

proxy_buffer_size 4k;
proxy_buffers 1024 4k;
proxy_temp_path /data/nginx/proxy_temp ;
proxy_cache_path /data/nginx/proxy_cache levels=1:2
keys_zone=cache1:1000m;

server{

location ~* .(ico|css|js|gif|jp?g|png|xsl)$ {
proxy_set_header X-Forwarded-For
$proxy_add_x_forwarded_for;
proxy_set_header Host $http_host;
proxy_redirect off;
proxy_pass http://61.129.66.75:80;
proxy_cache_key shtatic$request_uri;
proxy_cache cache1;
break;
}

}

the initiall request when there isn’t and cache, everything is ok. the
following request to same url will wait until timeout.

this is the debug log around the second request:

2009/09/30 10:53:57 [debug] 6733#0: event timer del: -1: 1254279237061
2009/09/30 10:53:57 [debug] 6733#0: http file cache expire
2009/09/30 10:53:57 [debug] 6733#0: malloc: 000000000BB9B890:62
2009/09/30 10:53:57 [debug] 6733#0: http file cache size: 1
2009/09/30 10:53:57 [debug] 6733#0: event timer add: -1:
10000:1254279247061
2009/09/30 10:53:57 [debug] 6733#0: posted events 0000000000000000
2009/09/30 10:53:57 [debug] 6733#0: epoll timer: 10000
2009/09/30 10:54:07 [debug] 6733#0: timer delta: 10000
2009/09/30 10:54:07 [debug] 6733#0: event timer del: -1: 1254279247061
2009/09/30 10:54:07 [debug] 6733#0: http file cache expire
2009/09/30 10:54:07 [debug] 6733#0: malloc: 000000000BB9B890:62
2009/09/30 10:54:07 [debug] 6733#0: http file cache size: 1
2009/09/30 10:54:07 [debug] 6733#0: event timer add: -1:
10000:1254279257061
2009/09/30 10:54:07 [debug] 6733#0: posted events 0000000000000000
2009/09/30 10:54:07 [debug] 6733#0: epoll timer: 10000
2009/09/30 10:54:15 [debug] 6732#0: timer delta: 38923
2009/09/30 10:54:15 [debug] 6732#0: posted events 0000000000000000
2009/09/30 10:54:15 [debug] 6732#0: worker cycle
2009/09/30 10:54:15 [debug] 6732#0: epoll timer: 1
2009/09/30 10:54:15 [debug] 6732#0: timer delta: 4
2009/09/30 10:54:15 [debug] 6732#0: *4 event timer del: 13:
1254279255991
2009/09/30 10:54:15 [debug] 6732#0: *4 http keepalive handler
2009/09/30 10:54:15 [debug] 6732#0: *4 close http connection: 13
2009/09/30 10:54:15 [debug] 6732#0: *4 free: 000000000BC58070
2009/09/30 10:54:15 [debug] 6732#0: *4 free: 0000000000000000
2009/09/30 10:54:15 [debug] 6732#0: *4 free: 000000000BB9B890, unused: 8
2009/09/30 10:54:15 [debug] 6732#0: *4 free: 000000000BB9BAE0, unused:
128
2009/09/30 10:54:15 [debug] 6732#0: posted events 0000000000000000
2009/09/30 10:54:15 [debug] 6732#0: worker cycle
2009/09/30 10:54:15 [debug] 6732#0: epoll timer: -1
2009/09/30 10:54:17 [debug] 6733#0: timer delta: 10001
2009/09/30 10:54:17 [debug] 6733#0: event timer del: -1: 1254279257061
2009/09/30 10:54:17 [debug] 6733#0: http file cache expire
2009/09/30 10:54:17 [debug] 6733#0: malloc: 000000000BB9B890:62
2009/09/30 10:54:17 [debug] 6733#0: http file cache size: 1
2009/09/30 10:54:17 [debug] 6733#0: event timer add: -1:
10000:1254279267063
2009/09/30 10:54:17 [debug] 6733#0: posted events 0000000000000000
2009/09/30 10:54:17 [debug] 6733#0: epoll timer: 10000
2009/09/30 10:54:27 [debug] 6733#0: timer delta: 10000
2009/09/30 10:54:27 [debug] 6733#0: event timer del: -1: 1254279267063
2009/09/30 10:54:27 [debug] 6733#0: http file cache expire
2009/09/30 10:54:27 [debug] 6733#0: malloc: 000000000BB9B890:62
2009/09/30 10:54:27 [debug] 6733#0: http file cache size: 1
2009/09/30 10:54:27 [debug] 6733#0: event timer add: -1:
10000:1254279277063
2009/09/30 10:54:27 [debug] 6733#0: posted events 0000000000000000
2009/09/30 10:54:27 [debug] 6733#0: epoll timer: 10000
2009/09/30 10:54:37 [debug] 6733#0: timer delta: 10001
2009/09/30 10:54:37 [debug] 6733#0: event timer del: -1: 1254279277063
2009/09/30 10:54:37 [debug] 6733#0: http file cache expire
2009/09/30 10:54:37 [debug] 6733#0: malloc: 000000000BB9B890:62
2009/09/30 10:54:37 [debug] 6733#0: http file cache size: 1
2009/09/30 10:54:37 [debug] 6733#0: event timer add: -1:
10000:1254279287064
2009/09/30 10:54:37 [debug] 6733#0: posted events 0000000000000000
2009/09/30 10:54:37 [debug] 6733#0: epoll timer: 10000
2009/09/30 10:54:47 [debug] 6733#0: timer delta: 10000
2009/09/30 10:54:47 [debug] 6733#0: event timer del: -1: 1254279287064
2009/09/30 10:54:47 [debug] 6733#0: http file cache expire
2009/09/30 10:54:47 [debug] 6733#0: malloc: 000000000BB9B890:62
2009/09/30 10:54:47 [debug] 6733#0: http file cache size: 1
2009/09/30 10:54:47 [debug] 6733#0: event timer add: -1:
10000:1254279297064
2009/09/30 10:54:47 [debug] 6733#0: posted events 0000000000000000
2009/09/30 10:54:47 [debug] 6733#0: epoll timer: 10000
2009/09/30 10:54:57 [debug] 6733#0: timer delta: 10000
2009/09/30 10:54:57 [debug] 6733#0: event timer del: -1: 1254279297064
2009/09/30 10:54:57 [debug] 6733#0: http file cache expire
2009/09/30 10:54:57 [debug] 6733#0: malloc: 000000000BB9B890:62
2009/09/30 10:54:57 [debug] 6733#0: http file cache size: 1
2009/09/30 10:54:57 [debug] 6733#0: event timer add: -1:
10000:1254279307064
2009/09/30 10:54:57 [debug] 6733#0: posted events 0000000000000000
2009/09/30 10:54:57 [debug] 6733#0: epoll timer: 10000
2009/09/30 10:55:07 [debug] 6733#0: timer delta: 10002
2009/09/30 10:55:07 [debug] 6733#0: event timer del: -1: 1254279307064
2009/09/30 10:55:07 [debug] 6733#0: http file cache expire
2009/09/30 10:55:07 [debug] 6733#0: malloc: 000000000BB9B890:62
2009/09/30 10:55:07 [debug] 6733#0: http file cache size: 1
2009/09/30 10:55:07 [debug] 6733#0: event timer add: -1:
10000:1254279317066
2009/09/30 10:55:07 [debug] 6733#0: posted events 0000000000000000
2009/09/30 10:55:07 [debug] 6733#0: epoll timer: 10000
2009/09/30 10:55:17 [debug] 6733#0: timer delta: 10000
2009/09/30 10:55:17 [debug] 6733#0: event timer del: -1: 1254279317066
2009/09/30 10:55:17 [debug] 6733#0: http file cache expire
2009/09/30 10:55:17 [debug] 6733#0: malloc: 000000000BB9B890:62
2009/09/30 10:55:17 [debug] 6733#0: http file cache size: 1
2009/09/30 10:55:17 [debug] 6733#0: event timer add: -1:
10000:1254279327066
2009/09/30 10:55:17 [debug] 6733#0: posted events 0000000000000000
2009/09/30 10:55:17 [debug] 6733#0: epoll timer: 10000
2009/09/30 10:55:27 [debug] 6733#0: timer delta: 10001
2009/09/30 10:55:27 [debug] 6733#0: event timer del: -1: 1254279327066
2009/09/30 10:55:27 [debug] 6733#0: http file cache expire
2009/09/30 10:55:27 [debug] 6733#0: malloc: 000000000BB9B890:62
2009/09/30 10:55:27 [debug] 6733#0: http file cache size: 1
2009/09/30 10:55:27 [debug] 6733#0: event timer add: -1:
10000:1254279337067
2009/09/30 10:55:27 [debug] 6733#0: posted events 0000000000000000
2009/09/30 10:55:27 [debug] 6733#0: epoll timer: 10000
2009/09/30 10:55:37 [debug] 6733#0: timer delta: 10000
2009/09/30 10:55:37 [debug] 6733#0: event timer del: -1: 1254279337067
2009/09/30 10:55:37 [debug] 6733#0: http file cache expire
2009/09/30 10:55:37 [debug] 6733#0: malloc: 000000000BB9B890:62
2009/09/30 10:55:37 [debug] 6733#0: http file cache size: 1
2009/09/30 10:55:37 [debug] 6733#0: event timer add: -1:
10000:1254279347067
2009/09/30 10:55:37 [debug] 6733#0: posted events 0000000000000000
2009/09/30 10:55:37 [debug] 6733#0: epoll timer: 10000
2009/09/30 10:55:47 [debug] 6733#0: timer delta: 10001
2009/09/30 10:55:47 [debug] 6733#0: event timer del: -1: 1254279347067
2009/09/30 10:55:47 [debug] 6733#0: http file cache expire
2009/09/30 10:55:47 [debug] 6733#0: malloc: 000000000BB9B890:62
2009/09/30 10:55:47 [debug] 6733#0: http file cache size: 1
2009/09/30 10:55:47 [debug] 6733#0: event timer add: -1:
10000:1254279357068
2009/09/30 10:55:47 [debug] 6733#0: posted events 0000000000000000
2009/09/30 10:55:47 [debug] 6733#0: epoll timer: 10000
2009/09/30 10:55:57 [debug] 6733#0: timer delta: 10001
2009/09/30 10:55:57 [debug] 6733#0: event timer del: -1: 1254279357068
2009/09/30 10:55:57 [debug] 6733#0: http file cache expire
2009/09/30 10:55:57 [debug] 6733#0: malloc: 000000000BB9B890:62
2009/09/30 10:55:57 [debug] 6733#0: http file cache size: 1
2009/09/30 10:55:57 [debug] 6733#0: event timer add: -1:
10000:1254279367069
2009/09/30 10:55:57 [debug] 6733#0: posted events 0000000000000000
2009/09/30 10:55:57 [debug] 6733#0: epoll timer: 10000
2009/09/30 10:56:07 [debug] 6733#0: timer delta: 10000
2009/09/30 10:56:07 [debug] 6733#0: event timer del: -1: 1254279367069
2009/09/30 10:56:07 [debug] 6733#0: http file cache expire
2009/09/30 10:56:07 [debug] 6733#0: malloc: 000000000BB9B890:62
2009/09/30 10:56:07 [debug] 6733#0: http file cache size: 1
2009/09/30 10:56:07 [debug] 6733#0: event timer add: -1:
10000:1254279377069
2009/09/30 10:56:07 [debug] 6733#0: posted events 0000000000000000
2009/09/30 10:56:07 [debug] 6733#0: epoll timer: 10000
2009/09/30 10:56:17 [debug] 6733#0: timer delta: 10001
2009/09/30 10:56:17 [debug] 6733#0: event timer del: -1: 1254279377069
2009/09/30 10:56:17 [debug] 6733#0: http file cache expire
2009/09/30 10:56:17 [debug] 6733#0: malloc: 000000000BB9B890:62
2009/09/30 10:56:17 [debug] 6733#0: http file cache size: 1
2009/09/30 10:56:17 [debug] 6733#0: event timer add: -1:
10000:1254279387070
2009/09/30 10:56:17 [debug] 6733#0: posted events 0000000000000000
2009/09/30 10:56:17 [debug] 6733#0: epoll timer: 10000

and -V output:
–with-http_ssl_module --with-md5-asm --with-sha1-asm
–with-http_xslt_module --add-module=/home/nginx_uploadprogress_module
–with-debug

Hello!

On Wed, Sep 30, 2009 at 12:42:52PM +0400, Maxim D. wrote:

On Wed, Sep 30, 2009 at 11:26:59AM +0800, tOmasEn wrote:

[…]

the initiall request when there isn’t and cache, everything is ok. the
following request to same url will wait until timeout.

Ok, so the problem is cache. Thanks, I’m able to reproduce it
here. I’ll take a look later today how to fix it.

Patch.

Maxim D.

Hello!

On Wed, Sep 30, 2009 at 10:48:27PM +0400, Maxim D. wrote:

Ok, so the problem is cache. Thanks, I’m able to reproduce it
here. I’ll take a look later today how to fix it.

Patch.

No, this patch is wrong. Corrected patch attached.

Maxim D.

So i think there might be a bug when nginx running on proxy mode and
tomasen


从我的移动设备发送

Hello!

On Wed, Sep 30, 2009 at 11:26:59AM +0800, tOmasEn wrote:

server{

}

the initiall request when there isn’t and cache, everything is ok. the
following request to same url will wait until timeout.

Ok, so the problem is cache. Thanks, I’m able to reproduce it
here. I’ll take a look later today how to fix it.

Maxim D.

[…]

Hello!

On Fri, Oct 02, 2009 at 01:29:56AM +0400, Maxim D. wrote:

[…]

the initiall request when there isn’t and cache, everything is ok. the
following request to same url will wait until timeout.

Ok, so the problem is cache. Thanks, I’m able to reproduce it
here. I’ll take a look later today how to fix it.

Patch.

No, this patch is wrong. Corrected patch attached.

No, this patch is wrong too as it will trigger “[alert] … zero
size buf in output” messages in error log for empty cached
subrequests. Corrected patch attached.

Maxim D.

After some test and debug, i found that it always timeout on response

@@ -798,7 +798,7 @@ ngx_http_cache_send(ngx_http_request_t *

 size = c->length - c->body_start;
 if (size == 0) {
  •    return rc;
    
  •    return ngx_http_send_special(r, NGX_HTTP_LAST);
    

    }

    b->file_pos = c->body_start;