proxy_store takes long time fetching from the upstream

[Pahud]

Hi list,
this is my config

----------------------------

user nginx nginx;
worker_processes 8;

error_log /var/log/nginx/error_log info;

events {
   worker_connections  8192;
   use epoll;
}

http {
   include     /etc/nginx/mime.types;
   default_type   application/octet-stream;

   log_format main
      '$remote_addr - $remote_user [$time_local] '
         '"$request" $status $bytes_sent '
      '"$http_referer" "$http_user_agent" '
      '"$gzip_ratio"';


      client_max_body_size    10m;
       client_body_buffer_size 256k;
       proxy_connect_timeout  90;
       proxy_send_timeout      90;
       proxy_read_timeout      90;
       proxy_buffer_size      4k;
       proxy_buffers          10 32k;
       proxy_busy_buffers_size 64k;
       proxy_temp_file_write_size 64k;

   upstream backend{
      server 192.168.172.254:3128;
   }

   server {
      listen      127.0.0.1:8888;
      server_name localhost;

      access_log  /var/log/nginx/localhost.access_log main;
      error_log   /var/log/nginx/localhost.error_log debug;
      proxy_temp_path   /cache/temp;
      root  /cache/$host;

      location / {
         index index.shtml;
         error_page 404 = /fetch$uri;
      }
      location /fetch{
         internal;
         proxy_pass http://backend;
         proxy_store on;
         proxy_store_access user:rw group:rw all:rw;
         proxy_set_header Host $host;
         proxy_set_header X-Real_IP $remote_addr;
         proxy_set_header Via "pahud/nginx";
         #proxy_buffering off;
         alias /cache/$host;
      }

   }

}

----------------------------


so nginx is listening on localhost:8888 and when trying to fetch a missing
jpg it goes to upstream proxy to fetch it. So I made a try here:

pahud at gentoo-9 ~ $[15:24:07] time curl -L -v
http://farm4.static.flickr.com/3081/3144192428_7dcf9da972.jpg -x
127.0.0.1:8888 -o /dev/null
* About to connect() to proxy 127.0.0.1 port 8888 (#0)
*   Trying 127.0.0.1... connected
* Connected to 127.0.0.1 (127.0.0.1) port 8888 (#0)
> GET http://farm4.static.flickr.com/3081/3144192428_7dcf9da972.jpg HTTP/1.1
> User-Agent: curl/7.18.2 (i686-pc-linux-gnu) libcurl/7.18.2 OpenSSL/0.9.8g
zlib/1.2.3
> Host: farm4.static.flickr.com
> Pragma: no-cache
> Accept: */*
> Proxy-Connection: Keep-Alive
>
< HTTP/1.1 200 OK
< Server: nginx/0.7.30
< Date: Mon, 29 Dec 2008 07:24:10 GMT
< Content-Type: image/jpeg
< Connection: keep-alive
< Last-Modified: Sun, 28 Dec 2008 13:32:53 GMT
< Accept-Ranges: bytes
< Content-Length: 165659
< Expires: Mon, 28 Jul 2014 23:30:00 GMT
< Cache-Control: max-age=315360000
< X-Cache: HIT from photocache416.flickr.gq1.yahoo.com
< X-Cache-Lookup: HIT from photocache416.flickr.gq1.yahoo.com:80
< X-Cache: MISS from gateway.office
< Via: 1.1 photocache416.flickr.gq1.yahoo.com:80 (squid/2.7.STABLE2), 1.0
gateway.office:3128 (squid/2.6.STABLE12)
<
{ [data not shown]
  % Total    % Received % Xferd  Average Speed   Time    Time     Time
 Current
                                 Dload  Upload   Total   Spent    Left
 Speed
100  161k  100  161k    0     0   2695      0  0:01:01  0:01:01 --:--:--
 3893* Connection #0 to host 127.0.0.1 left intact

* Closing connection #0

real    1m1.462s
user    0m0.000s
sys     0m0.004s


Well, it took 1m 1.462s to complete. But if I directly fetch from my
upstream server:

pahud at gentoo-9 ~ $[15:26:26] time curl -L -v
http://farm4.static.flickr.com/3081/3144192428_7dcf9da972.jpg -x
192.168.172.254:3128 -o /dev/null
* About to connect() to proxy 192.168.172.254 port 3128 (#0)
*   Trying 192.168.172.254... connected
* Connected to 192.168.172.254 (192.168.172.254) port 3128 (#0)
> GET http://farm4.static.flickr.com/3081/3144192428_7dcf9da972.jpg HTTP/1.1
> User-Agent: curl/7.18.2 (i686-pc-linux-gnu) libcurl/7.18.2 OpenSSL/0.9.8g
zlib/1.2.3
> Host: farm4.static.flickr.com
> Pragma: no-cache
> Accept: */*
> Proxy-Connection: Keep-Alive
>
* HTTP 1.0, assume close after body
< HTTP/1.0 200 OK
< Last-Modified: Sun, 28 Dec 2008 13:32:53 GMT
< Accept-Ranges: bytes
< Content-Length: 165659
< Content-Type: image/jpeg
< Date: Mon, 29 Dec 2008 07:26:42 GMT
< Server: Apache/2.0.52 (Red Hat)
< Expires: Mon, 28 Jul 2014 23:30:00 GMT
< Cache-Control: max-age=315360000
< X-Cache: HIT from photocache416.flickr.gq1.yahoo.com
< X-Cache-Lookup: HIT from photocache416.flickr.gq1.yahoo.com:80
< X-Cache: MISS from gateway.office
< Via: 1.1 photocache416.flickr.gq1.yahoo.com:80 (squid/2.7.STABLE2), 1.0
gateway.office:3128 (squid/2.6.STABLE12)
* HTTP/1.0 proxy connection set to keep alive!
< Proxy-Connection: keep-alive
<
{ [data not shown]
  % Total    % Received % Xferd  Average Speed   Time    Time     Time
 Current
                                 Dload  Upload   Total   Spent    Left
 Speed
100  161k  100  161k    0     0  25465      0  0:00:06  0:00:06 --:--:--
34140* Connection #0 to host 192.168.172.254 left intact

* Closing connection #0

real    0m6.514s
user    0m0.000s
sys     0m0.000s


Only 6 seconds!!

Can someone tell me how can I find the bottleneck?

pahud
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://nginx.org/pipermail/nginx/attachments/20081229/0b2faa1f/attachment.html>