nginx-0.8.1
Volkov Oleg
nginx at teratelecom.ru
Tue Jun 9 10:47:39 MSD 2009
В Пнд, 08/06/2009 в 21:10 +0400, Igor Sysoev пишет:
> On Mon, Jun 08, 2009 at 08:41:48PM +0400, Volkov Oleg wrote:
>
> > В Пнд, 08/06/2009 в 17:09 +0400, Igor Sysoev пишет:
> > > Изменения в nginx 0.8.1 08.06.2009
> > >
> > > *) Добавление: параметр updating в директивах proxy_cache_use_stale и
> > > fastcgi_cache_use_stale.
> >
> > Очень интересно ведет себя данная настройка, когда нгинкс сходит с ума с
> > количеством воркеров - 1. Параметр прекрасно работает. Тока толку... :(
> >
> > 1244479132.817 0.087 94.253.37.132 200 0.087 200
> > 1244479132.922 0.084 81.200.0.183 200 0.084 200
> > 1244479133.032 0.084 92.36.90.125 200 0.084 200
> > 1244479133.236 0.111 217.67.117.64 200 0.111 200
> > 1244479133.367 0.000 95.129.248.45 200 - -
> > 1244479133.395 0.093 91.212.80.30 200 0.093 200
> > 1244479133.916 0.086 78.85.138.233 200 0.086 200
> > 1244479134.579 0.090 94.20.21.199 200 0.090 200
> > 1244479134.746 0.106 95.129.248.47 200 0.106 200
> > 1244479135.698 0.099 89.31.88.71 200 0.099 200
> > 1244479136.254 0.102 77.108.64.196 200 0.102 200
> > 1244479136.703 0.085 85.141.0.194 200 0.085 200
> > 1244479136.958 0.085 193.93.49.65 200 0.085 200
> > 1244479137.072 0.097 91.78.58.222 200 0.097 200
> > 1244479137.324 0.092 81.22.2.5 200 0.092 200
> > 1244479137.690 0.092 89.208.180.18 200 0.092 200
> > 1244479137.789 0.000 77.52.19.123 200 - -
> > 1244479137.843 0.085 79.111.29.193 200 0.085 200
> > 1244479138.002 0.094 95.72.133.22 200 0.094 200
> > 1244479138.183 0.109 91.146.54.6 200 0.109 200
> > 1244479139.098 0.000 78.36.80.253 304 - -
> > 1244479139.143 0.088 95.215.150.11 200 0.088 200
> > 1244479139.294 0.096 87.224.242.234 200 0.096 200
> > 1244479140.129 0.093 89.113.75.19 200 0.093 200
> > 1244479140.384 0.086 77.241.44.30 200 0.086 200
> > 1244479141.164 0.442 95.71.93.90 200 0.442 200
> > 1244479141.402 0.000 78.85.144.95 200 - -
> > 1244479141.468 0.099 213.7.175.44 200 0.099 200
> > 1244479141.652 0.127 85.26.183.21 200 0.127 200
> > 1244479142.158 0.182 95.129.248.45 200 0.182 200
> > 1244479142.796 0.082 195.131.118.205 200 0.082 200
> > 1244479143.885 0.082 62.221.102.54 200 0.082 200
> > 1244479144.483 0.085 89.218.73.248 200 0.085 200
> > 1244479144.889 0.000 89.107.27.69 200 - -
> > 1244479144.967 0.099 83.149.3.62 200 0.099 200
> > 1244479145.205 0.087 77.37.220.109 200 0.087 200
> > 1244479145.279 0.000 92.50.175.49 200 - -
> > 1244479145.300 0.000 195.189.16.251 200 - -
> > 1244479145.347 0.093 85.175.193.160 200 0.093 200
> > 1244479146.289 0.000 92.101.11.198 200 - -
> > 1244479146.315 0.083 195.91.168.65 200 0.083 200
> > 1244479146.484 0.096 92.112.6.248 200 0.096 200
> > 1244479147.075 0.098 62.221.70.151 200 0.098 200
> > 1244479147.255 0.085 94.179.3.190 200 0.085 200
> > 1244479147.434 0.000 89.19.168.142 200 - -
> > 1244479147.434 0.107 95.133.57.48 200 0.107 200
> > 1244479147.491 0.000 87.224.162.241 200 - -
> > 1244479147.552 0.095 85.249.160.133 200 0.095 200
> > 1244479148.190 0.000 92.36.51.41 200 - -
> > 1244479148.246 0.083 95.37.185.223 200 0.083 200
> > 1244479148.539 0.000 95.129.248.47 200 - -
>
> Этого лог одного и того же запроса ?
Да, конечно.
> Нужен отладочный лог.
Вот пример одного из запросов. Урл заменен на ...
Файловая система xfs
Замена на tmpfs не помогает
2009/06/09 08:27:27 [debug] 18409#0: *29739 accept: 92.47.238.140 fd:123
2009/06/09 08:27:27 [debug] 18409#0: *29739 event timer add: 123:
21000:3276120054
2009/06/09 08:27:27 [debug] 18409#0: *29739 epoll add event: fd:123 op:1
ev:80000001
2009/06/09 08:27:27 [debug] 18409#0: *29739 malloc: 12BF1038:656
2009/06/09 08:27:27 [debug] 18409#0: *29739 malloc: 12DC5268:1024
2009/06/09 08:27:27 [debug] 18409#0: *29739 malloc: 13FB4A18:4096
2009/06/09 08:27:27 [debug] 18409#0: *29739 http process request line
2009/06/09 08:27:27 [debug] 18409#0: *29739 recv: fd:123 530 of 1024
2009/06/09 08:27:27 [debug] 18409#0: *29739 http request line: "GET ...
HTTP/1.1"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http uri: "..."
2009/06/09 08:27:27 [debug] 18409#0: *29739 http args: ""
2009/06/09 08:27:27 [debug] 18409#0: *29739 http exten: "html"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http process request header
line
2009/06/09 08:27:27 [debug] 18409#0: *29739 http header: "Accept: */*"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http header:
"Accept-Language: ru"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http header:
"Accept-Encoding: gzip, deflate"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http header: "User-Agent:
Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1; MRSPUTNIK 2, 0,
1, 90 SW; MRA 5.4 (build 02652); InfoPath.2; .NET CLR 2.0.50727)"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http header: "Host:
launcher.rfonline.ru"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http header: "Connection:
Keep-Alive"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http header:
"If-Modified-Since: Mon, 08 Jun 2009 21:22:58 GMT; length=12063"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http header: "Cookie:
__utma=247571994.2717693864412553000.1240629447.1244449726.1244496214.30; __utmz=247571994.1240629447.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none)"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http header done
2009/06/09 08:27:27 [debug] 18409#0: *29739 event timer del: 123:
3276120054
2009/06/09 08:27:27 [debug] 18409#0: *29739 generic phase: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 test location: "/503.html"
2009/06/09 08:27:27 [debug] 18409#0: *29739 test location: ~
"(^/.htaccess.*|^/user.html|admin\/(admin.php.*)$)"
2009/06/09 08:27:27 [debug] 18409#0: *29739 test location: ~
"^(.+\.(php|php3|html)|.*/)$"
2009/06/09 08:27:27 [debug] 18409#0: *29739 using configuration
"^(.+\.(php|php3|html)|.*/)$"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http cl:-1 max:10485760
2009/06/09 08:27:27 [debug] 18409#0: *29739 generic phase: 2
2009/06/09 08:27:27 [debug] 18409#0: *29739 post rewrite phase: 3
2009/06/09 08:27:27 [debug] 18409#0: *29739 generic phase: 4
2009/06/09 08:27:27 [debug] 18409#0: *29739 generic phase: 5
2009/06/09 08:27:27 [debug] 18409#0: *29739 add cleanup: 13FB4FEC
2009/06/09 08:27:27 [debug] 18409#0: *29739 limit zone: 949CA69E 1
2009/06/09 08:27:27 [debug] 18409#0: *29739 access phase: 6
2009/06/09 08:27:27 [debug] 18409#0: *29739 access phase: 7
2009/06/09 08:27:27 [debug] 18409#0: *29739 post access phase: 8
2009/06/09 08:27:27 [debug] 18409#0: *29739 http init upstream, client
timer: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 epoll add event: fd:123 op:3
ev:80000005
2009/06/09 08:27:27 [debug] 18409#0: *29739 perl variable handler
2009/06/09 08:27:27 [debug] 18409#0: *29739 perl variable done
2009/06/09 08:27:27 [debug] 18409#0: *29739 http script var:
"launcher.rfonline.ru"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http script var: "..."
2009/06/09 08:27:27 [debug] 18409#0: *29739 http script copy: "?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http script var: ""
2009/06/09 08:27:27 [debug] 18409#0: *29739 http cache key:
"launcher.rfonline.ru...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 add cleanup: 13FB53FC
2009/06/09 08:27:27 [debug] 18409#0: *29739 http file cache exists: 0
e:1
2009/06/09 08:27:27 [debug] 18409#0: *29739 add cleanup: 13FB544C
2009/06/09 08:27:27 [debug] 18409#0: *29739 cached open
file: /var/tmp/nginx/proxy_cache2/7/4c/d834b44900b7d1770f6819308056b4c7,
fd:4195, c:1, e:0, u:9
2009/06/09 08:27:27 [debug] 18409#0: *29739 http file cache fd: 4195
2009/06/09 08:27:27 [debug] 18409#0: *29739 read: 4195, 13FB549C, 325, 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 http file cache expired: 1
1244521644 1244521647
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream cache: 1
2009/06/09 08:27:27 [debug] 18409#0: *29739 http script copy: "Host:
launcher.rfonline.ru
2009/06/09 08:27:27 [debug] 18409#0: *29739 http script copy:
"X-Forwarded-For: "
2009/06/09 08:27:27 [debug] 18409#0: *29739 http script var:
"92.47.238.140"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http script copy: "
2009/06/09 08:27:27 [debug] 18409#0: *29739 http script copy:
"X-Real-IP: "
2009/06/09 08:27:27 [debug] 18409#0: *29739 http script var:
"92.47.238.140"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http script copy: "
2009/06/09 08:27:27 [debug] 18409#0: *29739 http script copy:
"Connection: close
2009/06/09 08:27:27 [debug] 18409#0: *29739 http proxy header: "Accept:
*/*"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http proxy header:
"Accept-Language: ru"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http proxy header:
"Accept-Encoding: gzip, deflate"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http proxy header:
"User-Agent: Mozilla/4.0 (compatible; MSIE 6.0; Windows NT 5.1; SV1;
MRSPUTNIK 2, 0, 1, 90 SW; MRA 5.4 (build 02652); InfoPath.2; .NET CLR
2.0.50727)"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http proxy header: "Cookie:
__utma=247571994.2717693864412553000.1240629447.1244449726.1244496214.30; __utmz=247571994.1240629447.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none)"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http proxy header:
2009/06/09 08:27:27 [debug] 18409#0: *29739 http cleanup add: 13FB585C
2009/06/09 08:27:27 [debug] 18409#0: *29739 get ip hash peer, try: 2
2009/06/09 08:27:27 [debug] 18409#0: *29739 get ip hash peer, hash: 0
0001
2009/06/09 08:27:27 [debug] 18409#0: *29739 socket 934
2009/06/09 08:27:27 [debug] 18409#0: *29739 epoll add connection: fd:934
ev:80000005
2009/06/09 08:27:27 [debug] 18409#0: *29739 connect to 95.129.248.69:80,
fd:934 #29741
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream connect: -2
2009/06/09 08:27:27 [debug] 18409#0: *29739 event timer add: 934:
10000:3276109059
2009/06/09 08:27:27 [debug] 18409#0: *29739 http run request: "...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream check client,
write event:1, "..."
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream recv(): -1
(11: Resource temporarily unavailable)
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream request:
"...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream send request
handler
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream send request
2009/06/09 08:27:27 [debug] 18409#0: *29739 chain writer buf fl:1 s:519
2009/06/09 08:27:27 [debug] 18409#0: *29739 chain writer in: 13FB5884
2009/06/09 08:27:27 [debug] 18409#0: *29739 writev: 519
2009/06/09 08:27:27 [debug] 18409#0: *29739 chain writer out: 00000000
2009/06/09 08:27:27 [debug] 18409#0: *29739 event timer del: 934:
3276109059
2009/06/09 08:27:27 [debug] 18409#0: *29739 event timer add: 934:
65000:3276164060
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream request:
"...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream process header
2009/06/09 08:27:27 [debug] 18409#0: *29739 malloc: 133E2DD8:4096
2009/06/09 08:27:27 [debug] 18409#0: *29739 recv: fd:934 4024 of 4024
2009/06/09 08:27:27 [debug] 18409#0: *29739 http proxy status 200 "200
OK"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http proxy header: "Date:
Tue, 09 Jun 2009 04:27:27 GMT"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http proxy header: "Server:
Apache"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http proxy header:
"X-Powered-By: PHP/5.2.8-pl2-gentoo"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http proxy header:
"Last-Modified: Tue, 09 Jun 2009 04:27:27 GMT"
2009/06/09 08:27:27 [debug] 18409#0: *29739 malloc: 12C3E0A0:4096
2009/06/09 08:27:27 [debug] 18409#0: *29739 http proxy header: "Expires:
Tue, 09 Jun 2009 04:32:27 GMT"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http proxy header:
"Connection: close"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http proxy header:
"Content-Type: text/html; charset=UTF-8"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http proxy header done
2009/06/09 08:27:27 [debug] 18409#0: *29739 http ims:1244496178
lm:1244521647
2009/06/09 08:27:27 [debug] 18409#0: *29739 parse header: "Cookie:
__utma=247571994.2717693864412553000.1240629447.1244449726.1244496214.30; __utmz=247571994.1240629447.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none)"
2009/06/09 08:27:27 [debug] 18409#0: *29739 uid cookie:
"stat_uid=X4H4Wkot5K82XUfpAyunAg==; path=/"
2009/06/09 08:27:27 [debug] 18409#0: *29739 HTTP/1.1 200 OK
2009/06/09 08:27:27 [debug] 18409#0: *29739 write new buf t:1 f:0
12C3E228, pos 12C3E228, size: 394 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 http write filter: l:0 f:0
s:394
2009/06/09 08:27:27 [debug] 18409#0: *29739 http file cache set header
2009/06/09 08:27:27 [debug] 18409#0: *29739 http cacheable: 1
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream process
upstream
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe read upstream: 1
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe preread: 3771
2009/06/09 08:27:27 [debug] 18409#0: *29739 input buf #0
2009/06/09 08:27:27 [debug] 18409#0: *29739 malloc: 1430B598:4096
2009/06/09 08:27:27 [debug] 18409#0: *29739 readv: 1:4096
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe recv chain: 320
2009/06/09 08:27:27 [debug] 18409#0: *29739 readv: 1:3776
2009/06/09 08:27:27 [debug] 18409#0: *29739 readv() not ready (11:
Resource temporarily unavailable)
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe recv chain: -2
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe buf in s:1 t:1 f:0
133E2DD8, pos 133E2F1D, size: 3771 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe buf free s:0 t:1 f:0
1430B598, pos 1430B598, size: 320 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 add cleanup: 12C3E540
2009/06/09 08:27:27 [debug] 18409#0: *29739 hashed
path: /var/tmp/nginx/proxy/8/77/0158149778
2009/06/09 08:27:27 [debug] 18409#0: *29739 temp fd:519
2009/06/09 08:27:27 [debug] 18409#0: *29739 write: 519, 133E2DD8, 4096,
0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe write downstream: 1
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe write busy: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe write: out:12C3E4D4,
f:0
2009/06/09 08:27:27 [debug] 18409#0: *29739 http output filter "...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 copy filter: "...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 malloc: 13476C30:32768
2009/06/09 08:27:27 [debug] 18409#0: *29739 read: 519, 13476C30, 3771,
325
2009/06/09 08:27:27 [debug] 18409#0: *29739 http postpone filter "...?"
12C3E5E4
2009/06/09 08:27:27 [debug] 18409#0: *29739 http gzip filter
2009/06/09 08:27:27 [debug] 18409#0: *29739 malloc: 143510C0:270336
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip alloc: n:1 s:5824
a:8192 p:143510C0
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip alloc: n:32768 s:2
a:65536 p:143530C0
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip alloc: n:32768 s:2
a:65536 p:143630C0
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip alloc: n:32768 s:2
a:65536 p:143730C0
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip alloc: n:16384 s:4
a:65536 p:143830C0
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in: 12C3E5F4
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in_buf:12C3E5A8
ni:13476C30 ai:3771
2009/06/09 08:27:27 [debug] 18409#0: *29739 malloc: 13FCBC18:8192
2009/06/09 08:27:27 [debug] 18409#0: *29739 deflate in: ni:13476C30
no:13FCBC18 ai:3771 ao:8192 fl:0 redo:0
2009/06/09 08:27:27 [debug] 18409#0: *29739 deflate out: ni:13477AEB
no:13FCBC18 ai:0 ao:8192 rc:0
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in_buf:12C3E5A8
pos:13476C30
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in: 00000000
2009/06/09 08:27:27 [debug] 18409#0: *29739 copy filter: 0 "...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe write busy: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe write: out:00000000,
f:0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe read upstream: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe buf free s:0 t:1 f:0
1430B598, pos 1430B598, size: 320 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe buf free s:0 t:1 f:0
133E2DD8, pos 133E2DD8, size: 0 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 event timer: 934, old:
3276164060, new: 3276164096
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream request:
"...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream dummy handler
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream request:
"...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream process
upstream
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe read upstream: 1
2009/06/09 08:27:27 [debug] 18409#0: *29739 readv: 2:4096
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe recv chain: 7872
2009/06/09 08:27:27 [debug] 18409#0: *29739 input buf #1
2009/06/09 08:27:27 [debug] 18409#0: *29739 input buf #2
2009/06/09 08:27:27 [debug] 18409#0: *29739 malloc: 12FCA458:4096
2009/06/09 08:27:27 [debug] 18409#0: *29739 readv: 1:4096
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe recv chain: 92
2009/06/09 08:27:27 [debug] 18409#0: *29739 readv: 1:4004
2009/06/09 08:27:27 [debug] 18409#0: *29739 readv() not ready (11:
Resource temporarily unavailable)
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe recv chain: -2
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe buf in s:1 t:1 f:0
1430B598, pos 1430B598, size: 4096 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe buf in s:1 t:1 f:0
133E2DD8, pos 133E2DD8, size: 4096 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe buf free s:0 t:1 f:0
12FCA458, pos 12FCA458, size: 92 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe write downstream: 1
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe write busy: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe write: out:12C3E4D4,
f:0
2009/06/09 08:27:27 [debug] 18409#0: *29739 http output filter "...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 copy filter: "...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 read: 519, 13476C30, 4096,
4096
2009/06/09 08:27:27 [debug] 18409#0: *29739 http postpone filter "...?"
12C3E5E4
2009/06/09 08:27:27 [debug] 18409#0: *29739 http gzip filter
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in: 12C3E6C8
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in_buf:12C3E5A8
ni:13476C30 ai:4096
2009/06/09 08:27:27 [debug] 18409#0: *29739 deflate in: ni:13476C30
no:13FCBC18 ai:4096 ao:8192 fl:0 redo:0
2009/06/09 08:27:27 [debug] 18409#0: *29739 deflate out: ni:13477C30
no:13FCBC18 ai:0 ao:8192 rc:0
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in_buf:12C3E5A8
pos:13476C30
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in: 00000000
2009/06/09 08:27:27 [debug] 18409#0: *29739 read: 519, 13476C30, 4096,
8192
2009/06/09 08:27:27 [debug] 18409#0: *29739 http postpone filter "...?"
12C3E5E4
2009/06/09 08:27:27 [debug] 18409#0: *29739 http gzip filter
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in: 12C3E6D0
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in_buf:12C3E5A8
ni:13476C30 ai:4096
2009/06/09 08:27:27 [debug] 18409#0: *29739 deflate in: ni:13476C30
no:13FCBC18 ai:4096 ao:8192 fl:0 redo:0
2009/06/09 08:27:27 [debug] 18409#0: *29739 deflate out: ni:13477C30
no:13FCBC18 ai:0 ao:8192 rc:0
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in_buf:12C3E5A8
pos:13476C30
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in: 00000000
2009/06/09 08:27:27 [debug] 18409#0: *29739 copy filter: 0 "...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe write busy: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe write: out:00000000,
f:0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe read upstream: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe buf free s:0 t:1 f:0
12FCA458, pos 12FCA458, size: 92 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe buf free s:0 t:1 f:0
1430B598, pos 1430B598, size: 0 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe buf free s:0 t:1 f:0
133E2DD8, pos 133E2DD8, size: 0 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 event timer: 934, old:
3276164060, new: 3276164097
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream request:
"...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream dummy handler
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream request:
"...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream process
upstream
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe read upstream: 1
2009/06/09 08:27:27 [debug] 18409#0: *29739 readv: 3:4096
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe recv chain: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe buf free s:0 t:1 f:0
12FCA458, pos 12FCA458, size: 92 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe buf free s:0 t:1 f:0
1430B598, pos 1430B598, size: 0 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe buf free s:0 t:1 f:0
133E2DD8, pos 133E2DD8, size: 0 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 input buf #3
2009/06/09 08:27:27 [debug] 18409#0: *29739 free: 1430B598
2009/06/09 08:27:27 [debug] 18409#0: *29739 free: 133E2DD8
2009/06/09 08:27:27 [debug] 18409#0: *29739 write: 519, 12FCA458, 92,
12288
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe write downstream: 1
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe write downstream flush
out
2009/06/09 08:27:27 [debug] 18409#0: *29739 http output filter "...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 copy filter: "...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 read: 519, 13476C30, 92,
12288
2009/06/09 08:27:27 [debug] 18409#0: *29739 http postpone filter "...?"
12C3E5E4
2009/06/09 08:27:27 [debug] 18409#0: *29739 http gzip filter
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in: 12C3E6E8
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in_buf:12C3E5A8
ni:13476C30 ai:92
2009/06/09 08:27:27 [debug] 18409#0: *29739 deflate in: ni:13476C30
no:13FCBC18 ai:92 ao:8192 fl:0 redo:0
2009/06/09 08:27:27 [debug] 18409#0: *29739 deflate out: ni:13476C8C
no:13FCBC18 ai:0 ao:8192 rc:0
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in_buf:12C3E5A8
pos:13476C30
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in: 00000000
2009/06/09 08:27:27 [debug] 18409#0: *29739 copy filter: 0 "...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 pipe write downstream done
2009/06/09 08:27:27 [debug] 18409#0: *29739 event timer: 934, old:
3276164060, new: 3276164098
2009/06/09 08:27:27 [debug] 18409#0: *29739 http file cache update
2009/06/09 08:27:27 [debug] 18409#0: *29739 http file cache rename:
"/var/tmp/nginx/proxy/8/77/0158149778" to
"/var/tmp/nginx/proxy_cache2/7/4c/d834b44900b7d1770f6819308056b4c7"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream exit: 00000000
2009/06/09 08:27:27 [debug] 18409#0: *29739 finalize http upstream
request: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 finalize http proxy request
2009/06/09 08:27:27 [debug] 18409#0: *29739 free rr peer 2 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 close http upstream
connection: 934
2009/06/09 08:27:27 [debug] 18409#0: *29739 event timer del: 934:
3276164060
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream temp fd: 519
2009/06/09 08:27:27 [debug] 18409#0: *29739 http upstream cache fd: -1
2009/06/09 08:27:27 [debug] 18409#0: *29739 http output filter "...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 copy filter: "...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http postpone filter "...?"
5F73B808
2009/06/09 08:27:27 [debug] 18409#0: *29739 http gzip filter
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in: 12C3E724
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in_buf:12C3E6F0
ni:00000000 ai:0
2009/06/09 08:27:27 [debug] 18409#0: *29739 deflate in: ni:00000000
no:13FCBC18 ai:0 ao:8192 fl:4 redo:0
2009/06/09 08:27:27 [debug] 18409#0: *29739 deflate out: ni:00000000
no:13FCC685 ai:0 ao:5523 rc:1
2009/06/09 08:27:27 [debug] 18409#0: *29739 gzip in_buf:12C3E6F0
pos:00000000
2009/06/09 08:27:27 [debug] 18409#0: *29739 free: 143510C0
2009/06/09 08:27:27 [debug] 18409#0: *29739 http chunk: 10
2009/06/09 08:27:27 [debug] 18409#0: *29739 http chunk: 2677
2009/06/09 08:27:27 [debug] 18409#0: *29739 write old buf t:1 f:0
12C3E228, pos 12C3E228, size: 394 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 write new buf t:1 f:0
00000000, pos 12C3E7B4, size: 5 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 write new buf t:0 f:0
00000000, pos 12A52BD4, size: 10 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 write new buf t:1 f:0
13FCBC18, pos 13FCBC18, size: 2677 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 write new buf t:0 f:0
00000000, pos 12A47A91, size: 7 file: 0, size: 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 http write filter: l:1 f:1
s:3093
2009/06/09 08:27:27 [debug] 18409#0: *29739 http write filter limit 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 writev: 3093
2009/06/09 08:27:27 [debug] 18409#0: *29739 http write filter 00000000
2009/06/09 08:27:27 [debug] 18409#0: *29739 copy filter: 0 "...?"
2009/06/09 08:27:27 [debug] 18409#0: *29739 http finalize request: 0,
"...?" 1
2009/06/09 08:27:27 [debug] 18409#0: *29739 set http keepalive handler
2009/06/09 08:27:27 [debug] 18409#0: *29739 http close request
2009/06/09 08:27:27 [debug] 18409#0: *29739 http log handler
2009/06/09 08:27:27 [debug] 18409#0: *29739 run cleanup: 12C3E540
2009/06/09 08:27:27 [debug] 18409#0: *29739 file cleanup: fd:519
2009/06/09 08:27:27 [debug] 18409#0: *29739 run cleanup: 13FB544C
2009/06/09 08:27:27 [debug] 18409#0: *29739 close cached open
file: /var/tmp/nginx/proxy_cache2/7/4c/d834b44900b7d1770f6819308056b4c7,
fd:4195, c:0, u:9, 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 run cleanup: 13FB53FC
2009/06/09 08:27:27 [debug] 18409#0: *29739 run cleanup: 13FB4FEC
2009/06/09 08:27:27 [debug] 18409#0: *29739 free: 12FCA458
2009/06/09 08:27:27 [debug] 18409#0: *29739 free: 13FCBC18
2009/06/09 08:27:27 [debug] 18409#0: *29739 free: 00000000
2009/06/09 08:27:27 [debug] 18409#0: *29739 free: 13476C30
2009/06/09 08:27:27 [debug] 18409#0: *29739 free: 00000000
2009/06/09 08:27:27 [debug] 18409#0: *29739 free: 00000000
2009/06/09 08:27:27 [debug] 18409#0: *29739 free: 13FB4A18, unused: 1
2009/06/09 08:27:27 [debug] 18409#0: *29739 free: 12C3E0A0, unused: 1596
2009/06/09 08:27:27 [debug] 18409#0: *29739 event timer add: 123:
75000:3276174098
2009/06/09 08:27:27 [debug] 18409#0: *29739 free: 12BF1038
2009/06/09 08:27:27 [debug] 18409#0: *29739 free: 12DC5268
2009/06/09 08:27:27 [debug] 18409#0: *29739 hc free: 00000000 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 hc busy: 00000000 0
2009/06/09 08:27:27 [debug] 18409#0: *29739 tcp_nodelay
2009/06/09 08:27:27 [debug] 18409#0: *29739 post event 537802C0
2009/06/09 08:27:27 [debug] 18409#0: *29739 delete posted event 537802C0
2009/06/09 08:27:27 [debug] 18409#0: *29739 http keepalive handler
2009/06/09 08:27:27 [debug] 18409#0: *29739 malloc: 12DC5268:1024
2009/06/09 08:27:27 [debug] 18409#0: *29739 recv: fd:123 -1 of 1024
2009/06/09 08:27:27 [debug] 18409#0: *29739 recv() not ready (11:
Resource temporarily unavailable)
У меня складывается следующее впечатление. Последовательность действий
такова
Открываем файл с кешем.
Видим что содержимое устарело
Читаем из бэкенда
Пишем в темповый файл
Переименовываем в кеш
закрываем старый файл с кешем.
Следующий запрос к кешу видит старый файл в кеше. Хотя я если во время
работы нргинкса буду делать cat из файла кеша, то буду видить каждый раз
новое содержимое.
2009/06/09 08:27:25 [debug] 18409#0: *29474 http file cache expired: 1
1244521644 1244521645
2009/06/09 08:27:27 [debug] 18409#0: *29739 http file cache expired: 1
1244521644 1244521647
2009/06/09 08:27:28 [debug] 18409#0: *28376 http file cache expired: 1
1244521644 1244521648
2009/06/09 08:27:28 [debug] 18409#0: *29914 http file cache expired: 1
1244521644 1244521648
Может попробовать закрывать старый файл кеша до переименования в него
темпового файла?
--
С уважением,
Волков Олег
More information about the nginx-ru
mailing list