Nginx-ru mailing list archive (nginx-ru@sysoev.ru)
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]
замирания sendfile?
Здравствуйте, Nginx-ru.
обновился с RELEASE-5.4 i386 до RELEASE-7.0 amd64
nginx старый был 0.5.х - 0.3.х, точно посмотреть уже нельзя
диски рассыпались.
вылезла проблема при загрузке больших файлов на сервер - 504
большой файл - это фото на 7мб =)
после выключения sendfile проблема исчезла
не могу понять где ошибка
в бсд, nginx или моих кривых руках.
--
на машинке крутятся два одинаковых nginx
фронтенд и бэкенд в джейле.
s1# uname -rm
7.0-RELEASE-p5 amd64
собран из cvs bsd, (RELENG_7_0)
s1# /usr/local/packages/nginx/sbin/nginx -v
nginx version: nginx/0.6.32
./configure --prefix=/usr/local/packages/nginx --conf-path=/usr/local/etc/nginx/nginx.conf --error-log-path=/var/log/nginx-error.log --pid-path=/var/run/nginx.pid --lock-path=/var/run/nginx.lock --user=www --group=www --without-select_module --without-poll_module --with-http_realip_module --with-http_stub_status_module --without-http_ssi_module --without-http_auth_basic_module --without-http_limit_zone_module --without-http_browser_module --http-log-path=/var/log/nginx-access.log --http-client-body-temp-path=/tmp/nginx/clientbody --http-proxy-temp-path=/tmp/nginx/proxytemp --http-fastcgi-temp-path=/tmp/nginx/fastcgitemp --with-debug
nginx-frontend.conf
---------
http {
include mime.types;
default_type application/octet-stream;
sendfile on; # off;
tcp_nodelay on;
server {
listen xx.xx.xx.xx;
charset utf-8;
access_log off;
server_name domain.ru www.domain.ru;
client_max_body_size 20m;
client_body_buffer_size 16k;
client_body_timeout 120;
client_header_timeout 120;
# client_body_in_file_only on;
proxy_send_timeout 90;
proxy_read_timeout 90;
location / {
proxy_pass http://10.0.0.1/;
proxy_set_header Host $http_host;
proxy_set_header X-Real-IP $remote_addr;
}
location /my/photos/ {
proxy_ignore_client_abort off;
proxy_connect_timeout 10;
proxy_buffering on;
proxy_read_timeout 900;
proxy_send_timeout 900;
proxy_pass http://10.0.0.1/my/photos/;
proxy_set_header Host $http_host;
proxy_set_header X-Real-IP $remote_addr;
# error_log /var/log/nginx-photo-debug.log debug;
}
.....
}
}
в джейле точно такой же нжинкс, работает с php-cgi
http {
include mime.types;
default_type application/octet-stream;
sendfile on; # off
tcp_nodelay on;
server {
listen 80;
charset utf-8;
access_log off;
server_name domain.ru www.domain.ru;
log_not_found off;
tcp_nopush on;
client_max_body_size 20m;
client_body_buffer_size 128k;
fastcgi_intercept_errors on;
fastcgi_read_timeout 120;
fastcgi_send_timeout 120;
set_real_ip_from 10.0.0.1/32;
real_ip_header X-Real-IP;
add_header P3P "CP=\"PSA OUR UNI COM\"";
location / {
root /var/web/www/project;
expires -1d;
rewrite ^/(.*)$ /service.php?$1 break;
include fastcgi514.conf;
# error_log /var/log/nginx-photo-debug.log debug;
}
}
}
удалось поймать в дебаг лог сессию
начало:
2008/10/27 23:03:56 [debug] 35513#0: *58 http cl:7428479 max:20971520
2008/10/27 23:03:56 [debug] 35513#0: *58 generic phase: 3
2008/10/27 23:03:56 [debug] 35513#0: *58 post rewrite phase: 4
2008/10/27 23:03:56 [debug] 35513#0: *58 generic phase: 5
2008/10/27 23:03:56 [debug] 35513#0: *58 access phase: 6
2008/10/27 23:03:56 [debug] 35513#0: *58 post access phase: 7
2008/10/27 23:03:56 [debug] 35513#0: *58 malloc: 00000008012E0000:16384
2008/10/27 23:03:56 [debug] 35513#0: *58 http read client request body
2008/10/27 23:03:56 [debug] 35513#0: *58 recv: eof:0, avail:0, err:0
2008/10/27 23:03:56 [debug] 35513#0: *58 http client request body recv -2
2008/10/27 23:03:56 [debug] 35513#0: *58 http client request body rest 7428479
2008/10/27 23:03:56 [debug] 35513#0: *58 event timer add: 38:
900000:1225138736718
2008/10/27 23:03:56 [debug] 35513#0: *58 http read client request body
2008/10/27 23:03:56 [debug] 35513#0: *58 recv: eof:0, avail:472, err:0
2008/10/27 23:03:56 [debug] 35513#0: *58 recv: fd:38 472 of 16384
2008/10/27 23:03:56 [debug] 35513#0: *58 http client request body recv 472
2008/10/27 23:03:56 [debug] 35513#0: *58 http client request body rest 7428007
2008/10/27 23:03:56 [debug] 35513#0: *58 event timer: 38, old: 1225138736718,
new: 1225138736728
2008/10/27 23:03:56 [debug] 35513#0: *58 http read client request body
2008/10/27 23:03:56 [debug] 35513#0: *58 recv: eof:0, avail:472, err:0
2008/10/27 23:03:56 [debug] 35513#0: *58 recv: fd:38 472 of 15912
2008/10/27 23:03:56 [debug] 35513#0: *58 http client request body recv 472
2008/10/27 23:03:56 [debug] 35513#0: *58 http client request body rest 7427535
2008/10/27 23:03:56 [debug] 35513#0: *58 event timer: 38, old: 1225138736718,
new: 1225138736728
2008/10/27 23:03:56 [debug] 35513#0: *58 http read client request body
2008/10/27 23:03:56 [debug] 35513#0: *58 recv: eof:0, avail:472, err:0
2008/10/27 23:03:56 [debug] 35513#0: *58 recv: fd:38 472 of 15440
2008/10/27 23:03:56 [debug] 35513#0: *58 http client request body recv 472
2008/10/27 23:03:56 [debug] 35513#0: *58 http client request body rest 7427063
2008/10/27 23:03:56 [debug] 35513#0: *58 event timer: 38, old: 1225138736718,
new: 1225138736729
и так далее вычитывается весь файл от клиента
2008/10/27 23:04:25 [debug] 35513#0: *58 recv: eof:0, avail:4431, err:0
2008/10/27 23:04:25 [debug] 35513#0: *58 recv: fd:38 4431 of 4431
2008/10/27 23:04:25 [debug] 35513#0: *58 http client request body recv 4431
2008/10/27 23:04:25 [debug] 35513#0: *58 http client request body rest 0
дальше интереснее
2008/10/27 23:04:25 [debug] 35513#0: *58 event timer del: 38: 1225138765296
2008/10/27 23:04:25 [debug] 35513#0: *58 write: 951, 00000008012E0000, 6527,
7421952
2008/10/27 23:04:25 [debug] 35513#0: *58 http init upstream, client timer: 0
2008/10/27 23:04:25 [debug] 35513#0: *58 http script copy: ""
2008/10/27 23:04:25 [debug] 35513#0: *58 http script var: ""
2008/10/27 23:04:25 [debug] 35513#0: *58 http script copy: ""
2008/10/27 23:04:25 [debug] 35513#0: *58 http script copy: ""
2008/10/27 23:04:25 [debug] 35513#0: *58 http script var: ""
2008/10/27 23:04:25 [debug] 35513#0: *58 http script copy: ""
2008/10/27 23:04:25 [debug] 35513#0: *58 http script copy: ""
2008/10/27 23:04:25 [debug] 35513#0: *58 http proxy header: "Accept: image/gif,
image/x-xbitmap, image/jpeg, image/pjpeg, ap
2008/10/27 23:04:25 [debug] 35513#0: *58 http proxy header: "Referer:
http://domain.ru/my/photos/";
2008/10/27 23:04:25 [debug] 35513#0: *58 http proxy header: "Accept-Language:
ru"
2008/10/27 23:04:25 [debug] 35513#0: *58 http proxy header: "Content-Type:
multipart/form-data; boundary=-------------------
2008/10/27 23:04:25 [debug] 35513#0: *58 http proxy header: "UA-CPU: x86"
2008/10/27 23:04:25 [debug] 35513#0: *58 http proxy header: "Accept-Encoding:
gzip, deflate"
2008/10/27 23:04:25 [debug] 35513#0: *58 http proxy header: "User-Agent:
Mozilla/4.0 (compatible; MSIE 7.0; Windows NT 5.1;
2008/10/27 23:04:25 [debug] 35513#0: *58 http proxy header: "Content-Length:
7428479"
2008/10/27 23:04:25 [debug] 35513#0: *58 http proxy header: "Cache-Control:
no-cache"
2008/10/27 23:04:25 [debug] 35513#0: *58 http proxy header: "Cookie:
__utma=187418488.1544683336.1222420170.1225130878.12251
2008/10/27 23:04:25 [debug] 35513#0: *58 http proxy header:
2008/10/27 23:04:25 [debug] 35513#0: *58 http cleanup add: 00000008011C5570
2008/10/27 23:04:25 [debug] 35513#0: *58 get rr peer, try: 1
2008/10/27 23:04:25 [debug] 35513#0: *58 socket 1022
2008/10/27 23:04:25 [debug] 35513#0: *58 connect to 10.0.0.1:80, fd:1022 #48985
2008/10/27 23:04:25 [debug] 35513#0: *58 kevent set event: 1022: ft:-1 fl:0025
2008/10/27 23:04:25 [debug] 35513#0: *58 kevent set event: 1022: ft:-2 fl:0025
2008/10/27 23:04:25 [debug] 35513#0: *58 http upstream connect: -2
2008/10/27 23:04:25 [debug] 35513#0: *58 event timer add: 1022:
10000:1225137875485
2008/10/27 23:04:25 [debug] 35513#0: *58 http upstream send request handler
2008/10/27 23:04:25 [debug] 35513#0: *58 http upstream send request
2008/10/27 23:04:25 [debug] 35513#0: *58 chain writer buf fl:0 s:937
2008/10/27 23:04:25 [debug] 35513#0: *58 chain writer buf fl:1 s:7428479
2008/10/27 23:04:25 [debug] 35513#0: *58 chain writer in: 00000008011C55D8
2008/10/27 23:04:25 [debug] 35513#0: *58 tcp_nopush
2008/10/27 23:04:25 [debug] 35513#0: *58 sendfile() sent only 5033 bytes (35:
Resource temporarily unavailable)
2008/10/27 23:04:25 [debug] 35513#0: *58 sendfile: -1, @0 5033:7428479
2008/10/27 23:04:25 [debug] 35513#0: *58 chain writer out: 00000008011C55E8
2008/10/27 23:04:25 [debug] 35513#0: *58 event timer del: 1022: 1225137875485
2008/10/27 23:04:25 [debug] 35513#0: *58 event timer add: 1022:
900000:1225138765485
первая задержка на 5 сек
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request handler
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer in: 00000008011C55E8
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile() sent only 16384 bytes (35:
Resource temporarily unavailable)
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile: -1, @4096 16384:7424383
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer out: 00000008011C55E8
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer del: 1022: 1225138765485
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer add: 1022:
900000:1225138770549
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request handler
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer in: 00000008011C55E8
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile() sent only 24576 bytes (35:
Resource temporarily unavailable)
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile: -1, @20480 24576:7407999
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer out: 00000008011C55E8
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer del: 1022: 1225138770549
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer add: 1022:
900000:1225138770549
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request handler
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer in: 00000008011C55E8
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile() sent only 16384 bytes (35:
Resource temporarily unavailable)
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile: -1, @45056 16384:7383423
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer out: 00000008011C55E8
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile() sent only 16384 bytes (35:
Resource temporarily unavailable)
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile: -1, @45056 16384:7383423
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer out: 00000008011C55E8
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer del: 1022: 1225138770549
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer add: 1022:
900000:1225138770549
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request handler
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer in: 00000008011C55E8
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile() sent only 24576 bytes (35:
Resource temporarily unavailable)
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile: -1, @61440 24576:7367039
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer out: 00000008011C55E8
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer del: 1022: 1225138770549
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer add: 1022:
900000:1225138770549
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request handler
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer in: 00000008011C55E8
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile() sent only 16384 bytes (35:
Resource temporarily unavailable)
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile: -1, @86016 16384:7342463
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer out: 00000008011C55E8
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer del: 1022: 1225138770549
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer add: 1022:
900000:1225138770549
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request handler
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer in: 00000008011C55E8
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile() sent only 24576 bytes (35:
Resource temporarily unavailable)
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile: -1, @102400 24576:7326079
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer out: 00000008011C55E8
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer del: 1022: 1225138770549
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer add: 1022:
900000:1225138770549
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request handler
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request
так sendfile посылает clientbody кусками по 4-16-50-65-90-114 кб
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer del: 1022: 1225138770683
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer add: 1022:
900000:1225138770683
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request handler
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer in: 00000008011C55E8
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile() sent only 131072 bytes (35:
Resource temporarily unavailable)
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile: -1, @7221248 131072:207231
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer out: 00000008011C55E8
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer del: 1022: 1225138770683
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer add: 1022:
900000:1225138770684
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request handler
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream send request
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer in: 00000008011C55E8
2008/10/27 23:04:30 [debug] 35513#0: *58 sendfile: 0, @7352320 76159:76159
2008/10/27 23:04:30 [debug] 35513#0: *58 chain writer out: 0000000000000000
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer del: 1022: 1225138770684
2008/10/27 23:04:30 [debug] 35513#0: *58 event timer add: 1022:
900000:1225138770690
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream dummy handler
2008/10/27 23:04:30 [debug] 35513#0: *58 http upstream dummy handler
пауза на 2 минуты!
после чего честно отваливаемся по таймауту)
2008/10/27 23:06:30 [debug] 35513#0: *58 http upstream process header
2008/10/27 23:06:30 [debug] 35513#0: *58 malloc: 000000080142E000:4096
2008/10/27 23:06:30 [debug] 35513#0: *58 recv: eof:1, avail:2470, err:0
2008/10/27 23:06:30 [debug] 35513#0: *58 recv: fd:1022 2470 of 4096
2008/10/27 23:06:30 [debug] 35513#0: *58 http proxy status 504 "504 Gateway
Time-out"
2008/10/27 23:06:30 [debug] 35513#0: *58 http proxy header: "Server:
nginx/0.6.32"
2008/10/27 23:06:30 [debug] 35513#0: *58 http proxy header: "Date: Mon, 27 Oct
2008 20:06:30 GMT"
2008/10/27 23:06:30 [debug] 35513#0: *58 http proxy header: "Content-Type:
text/html; charset=utf-8"
2008/10/27 23:06:30 [debug] 35513#0: *58 http proxy header: "Content-Length:
2297"
2008/10/27 23:06:30 [debug] 35513#0: *58 http proxy header: "Connection: close"
2008/10/27 23:06:30 [debug] 35513#0: *58 http proxy header done
2008/10/27 23:06:30 [debug] 35513#0: *58 HTTP/1.1 504 Gateway Time-out^
2008/10/27 23:06:30 [debug] 35513#0: *58 write new buf t:1 f:0
00000008011C58B0, pos 00000008011C58B0, size: 173 file: 0, si
2008/10/27 23:06:30 [debug] 35513#0: *58 http write filter: l:0 f:0 s:173
2008/10/27 23:06:30 [debug] 35513#0: *58 file cleanup: fd:951
2008/10/27 23:06:30 [debug] 35513#0: *58 http upstream process upstream
2008/10/27 23:06:30 [debug] 35513#0: *58 pipe read upstream: 1
2008/10/27 23:06:30 [debug] 35513#0: *58 pipe preread: 2297
2008/10/27 23:06:30 [debug] 35513#0: *58 pipe buf free s:0 t:1 f:0
000000080142E000, pos 000000080142E0AD, size: 2297 file:
2008/10/27 23:06:30 [debug] 35513#0: *58 input buf #0
2008/10/27 23:06:30 [debug] 35513#0: *58 pipe write downstream: 1
2008/10/27 23:06:30 [debug] 35513#0: *58 pipe write downstream flush in
2008/10/27 23:06:30 [debug] 35513#0: *58 http output filter "/my/photos/add/?"
2008/10/27 23:06:30 [debug] 35513#0: *58 copy filter: "/my/photos/add/?"
2008/10/27 23:06:30 [debug] 35513#0: *58 write old buf t:1 f:0
00000008011C58B0, pos 00000008011C58B0, size: 173 file: 0, si
2008/10/27 23:06:30 [debug] 35513#0: *58 write new buf t:1 f:0
000000080142E000, pos 000000080142E0AD, size: 2297 file: 0, s
2008/10/27 23:06:30 [debug] 35513#0: *58 http write filter: l:0 f:0 s:2470
2008/10/27 23:06:30 [debug] 35513#0: *58 http write filter limit 0
2008/10/27 23:06:30 [debug] 35513#0: *58 writev: 2470 of 2470
2008/10/27 23:06:30 [debug] 35513#0: *58 http write filter 0000000000000000
2008/10/27 23:06:30 [debug] 35513#0: *58 copy filter: 0 "/my/photos/add/?"
2008/10/27 23:06:30 [debug] 35513#0: *58 pipe write downstream done
2008/10/27 23:06:30 [debug] 35513#0: *58 event timer del: 1022: 1225138770690
2008/10/27 23:06:30 [debug] 35513#0: *58 event timer add: 1022:
900000:1225138890709
2008/10/27 23:06:30 [debug] 35513#0: *58 http upstream exit: 0000000000000000
2008/10/27 23:06:30 [debug] 35513#0: *58 finalize http upstream request: 0
2008/10/27 23:06:30 [debug] 35513#0: *58 finalize http proxy request
2008/10/27 23:06:30 [debug] 35513#0: *58 free rr peer 1 0
--
С уважением,
Nk mailto:nk@xxxxxxxxxxxxxx
|
