ПРОЕКТЫ 


  АРХИВ 


Apache-Talk @lexa.ru 

Inet-Admins @info.east.ru 

Filmscanners @halftone.co.uk 

Security-alerts @yandex-team.ru 

nginx-ru @sysoev.ru 


  СТАТЬИ 


  ПЕРСОНАЛЬНОЕ 


  ПРОГРАММЫ 



ПИШИТЕ
ПИСЬМА












     АРХИВ :: nginx-ru
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




 




Copyright © Lexa Software, 1996-2009.