замирает скачивание файлов

tswiah at innovativemarketing.com.ua tswiah at innovativemarketing.com.ua
Sat Oct 27 01:15:37 MSD 2007 

On Sat, 27 Oct 2007, Igor Sysoev wrote:

Такой же результат (замирание), но отдача из php (fastcgi) с 
помощью sendfile:

-----
2007/10/27 00:05:27 [debug] 15186#0: *127795 write new buf t:1 f:0 
08A9118C, pos 08A9118C, size: 483 file: 0, size: 0
2007/10/27 00:05:27 [debug] 15186#0: *127795 http write filter: l:0 f:0 
s:483
2007/10/27 00:05:27 [debug] 15186#0: *127795 http output filter 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127795 copy filter: 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127795 http postpone filter 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d5236
?" BFF1DBE8
2007/10/27 00:05:27 [debug] 15186#0: *127795 http postpone filter out 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d
5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127795 write old buf t:1 f:0 
08A9118C, pos 08A9118C, size: 483 file: 0, size: 0
2007/10/27 00:05:27 [debug] 15186#0: *127795 write new buf t:0 f:1 
00000000, pos 00000000, size: 0 file: 0, size: 5118288
2007/10/27 00:05:27 [debug] 15186#0: *127795 http write filter: l:1 f:0 
s:5118771
2007/10/27 00:05:27 [debug] 15186#0: *127795 http write filter limit 65536
2007/10/27 00:05:27 [debug] 15186#0: *127795 tcp_nopush
2007/10/27 00:05:27 [debug] 15186#0: *127795 writev: 483
2007/10/27 00:05:27 [debug] 15186#0: *127795 sendfile: @0 65536
2007/10/27 00:05:27 [debug] 15186#0: *127795 sendfile: 65536, @0 
65536:65536
2007/10/27 00:05:27 [debug] 15186#0: *127795 http write filter 08A913C0
2007/10/27 00:05:27 [debug] 15186#0: *127795 event timer add: 750: 
1:3726786151
2007/10/27 00:05:27 [debug] 15186#0: *127795 copy filter: -2 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127795 http finalize request: -2, 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa12
2d5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127795 event timer del: 750: 
3726786151
2007/10/27 00:05:27 [debug] 15186#0: *127795 http writer handler: 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d5236
?"
2007/10/27 00:05:27 [debug] 15186#0: *127795 http output filter 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127795 copy filter: 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127795 http postpone filter 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d5236
?" 00000000
2007/10/27 00:05:27 [debug] 15186#0: *127795 http postpone filter out 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d
5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127795 write old buf t:0 f:1 
00000000, pos 00000000, size: 0 file: 65536, size: 5052752
2007/10/27 00:05:27 [debug] 15186#0: *127795 http write filter: l:1 f:0 
s:5052752
2007/10/27 00:05:27 [debug] 15186#0: *127795 http write filter limit 65536
2007/10/27 00:05:27 [debug] 15186#0: *127795 sendfile: @65536 65536
2007/10/27 00:05:27 [debug] 15186#0: *127795 sendfile: 62853, @65536 
62853:65536
2007/10/27 00:05:27 [debug] 15186#0: *127795 http write filter 08A913C0
2007/10/27 00:05:27 [debug] 15186#0: *127795 copy filter: -2 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127795 http writer output filter: 
-2, "/data/accounts/user1/files/0552fd96cd7566c9ad2248
aa122d5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127795 event timer add: 750: 
90000:3726876151
2007/10/27 00:05:27 [debug] 15186#0: *127783 post event B76771C8
2007/10/27 00:05:27 [debug] 15186#0: *127783 delete posted event B76771C8
2007/10/27 00:05:27 [debug] 15186#0: *127783 http writer handler: 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d5236
?"
2007/10/27 00:05:27 [debug] 15186#0: *127783 http output filter 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127783 copy filter: 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127783 http postpone filter 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d5236
?" 00000000
2007/10/27 00:05:27 [debug] 15186#0: *127783 http postpone filter out 
"/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d
5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127783 write old buf t:0 f:1 
00000000, pos 00000000, size: 0 file: 128389, size: 4989899
2007/10/27 00:05:27 [debug] 15186#0: *127783 http write filter: l:1 f:0 
s:4989899
2007/10/27 00:05:27 [debug] 15186#0: *127783 http write filter limit 65536
2007/10/27 00:05:27 [debug] 15186#0: *127783 sendfile: @128389 68219
2007/10/27 00:05:27 [info] 15186#0: *127783 sendfile() failed (32: Broken 
pipe) while sending response to client, client: 213.1
86.206.55, server: shareua.com, URL: 
"/donwload/dabe77caf0b2fbdd9e78c0c92e3b8fdf/273190/Firefox_Setup_1.5.0.4.exe", 
upstream: "fastcg
i://unix:/tmp/spawn-fcgi.socket:", host: "shareua.com"
2007/10/27 00:05:27 [debug] 15186#0: *127783 http write filter FFFFFFFF
2007/10/27 00:05:27 [debug] 15186#0: *127783 copy filter: -1 "/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127783 http writer output filter: -1, "/data/accounts/user1/files/0552fd96cd7566c9ad2248
aa122d5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127783 http writer done: "/data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127783 http finalize request: -1, "/data/accounts/user1/files/0552fd96cd7566c9ad2248aa12
2d5236?"
2007/10/27 00:05:27 [debug] 15186#0: *127783 http close request
2007/10/27 00:05:27 [debug] 15186#0: *127783 http log handler
2007/10/27 00:05:27 [debug] 15186#0: *127783 close cached open file: /data/accounts/user1/files/0552fd96cd7566c9ad2248aa122d52
36, fd:286, c:1, 0
2007/10/27 00:05:27 [debug] 15186#0: *127783 free: 08A81E88
2007/10/27 00:05:27 [debug] 15186#0: *127783 free: 08A7AAC0, unused: 4
2007/10/27 00:05:27 [debug] 15186#0: *127783 free: 08A82E90, unused: 2621
2007/10/27 00:05:27 [debug] 15186#0: *127783 close http connection: 746
2007/10/27 00:05:27 [debug] 15186#0: *127783 event timer del: 746: 3726876150
2007/10/27 00:05:27 [debug] 15186#0: *127783 free: 08A79AB8
2007/10/27 00:05:27 [debug] 15186#0: *127783 free: 08A79830
2007/10/27 00:05:27 [debug] 15186#0: *127783 free: 08A79728, unused: 64
-----

> Date: Sat, 27 Oct 2007 00:27:54 +0400
> From: Igor Sysoev <is at rambler-co.ru>
> Reply-To: nginx-ru at sysoev.ru
> To: nginx-ru at sysoev.ru
> Subject: Re: замирает скачивание файлов
> 
> On Fri, Oct 26, 2007 at 11:12:44PM +0300, tswiah at innovativemarketing.com.ua wrote:
>
>> On Fri, 26 Oct 2007, Igor Sysoev wrote:
>>
>>> Date: Fri, 26 Oct 2007 23:44:49 +0400
>>> From: Igor Sysoev <is at rambler-co.ru>
>>> Reply-To: nginx-ru at sysoev.ru
>>> To: nginx-ru at sysoev.ru
>>> Subject: Re: замирает скачивание файлов
>>>
>>> On Fri, Oct 26, 2007 at 10:35:16PM +0300,
>>> tswiah at innovativemarketing.com.ua wrote:
>>>
>>>> On Thu, 25 Oct 2007, umask wrote:
>>>>
>>>>> Date: Thu, 25 Oct 2007 19:57:14 +0400
>>>>> From: umask <umask at yandex.ru>
>>>>> Reply-To: nginx-ru at sysoev.ru
>>>>> To: nginx-ru at sysoev.ru
>>>>> Subject: Re: замирает скачивание файлов
>>>>>
>>>>>
>>>>>
>>>>>
>>>>>
>>>>> 25.10.07, 19:22, tswiah at innovativemarketing.com.ua:
>>>>>
>>>>>
>>>>>
>>>>>>> Что если включить debug, в логах что-то меняется?
>>>>
>>>> включение дебага указывает на вот такой симптом:
>>>>
>>>> readv() not ready (11: Resource temporarily unavailable)
>>>>
>>>> Как это можно лечить?
>>>
>>> Это нормально.
>>>
>> Возможно, однако после большого количества сообщений о недоступности
>> ресурса я вижу вот такие сроки:
>
> Если бы "readv() not ready (11: Resource temporarily unavailable)"
> имел хоть какое-то отношение к ошибке, то он бы логировался хотя бы на
> уровне info. Но никакого отношения к ошибам данная ситуация не имеет -
> просто вот так вот устроен epoll в Линуксе, что приходиться читать
> до ошибки EAGAIN, иначе можно пропустить конец файла.
>
>> -----
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 http write filter: l:0 f:0
>> s:47596090
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 http write filter limit
>> 1048576
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 http write filter 082A41EC
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 copy filter: -2
>> "/linux-source-2.6.20.tar.bz2?"
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 pipe write downstream done
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 event timer: 342, old:
>> 3723285152, new: 3723285408
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 event timer: 45, old:
>> 3723285182, new: 3723285408
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 http upstream exit: 00000000
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 finalize http upstream
>> request: 0
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 finalize http proxy request
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 free rr peer 1 0
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 close http upstream
>> connection: 342
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 event timer del: 342:
>> 3723285152
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 http upstream temp fd: 98
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 http output filter
>> "/linux-source-2.6.20.tar.bz2?"
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 copy filter:
>> "/linux-source-2.6.20.tar.bz2?"
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 http postpone filter
>> "/linux-source-2.6.20.tar.bz2?" 08485F58
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 http postpone filter out
>> "/linux-source-2.6.20.tar.bz2?"
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 write old buf t:1 f:0
>> 08889DD0, pos 08896DE8, size: 471016 file: 0, size: 0
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 write old buf t:0 f:1
>> 087F6970, pos 087F6970, size: 65536 file: 0, size: 65536
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 write old buf t:0 f:1
>> B7694008, pos B7694008, size: 524288 file: 65536, size: 524
>> <...>
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 http write filter: l:1 f:0
>> s:47596090
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 http write filter limit
>> 1048576
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 http write filter 082A41EC
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 copy filter: -2
>> "/linux-source-2.6.20.tar.bz2?"
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 http finalize request: -2,
>> "/linux-source-2.6.20.tar.bz2?"
>> 2007/10/26 23:04:06 [debug] 12897#0: *123551 event timer: 45, old:
>> 3723285182, new: 3723285408
>> -----
>>
>> но при этом файл не продолжает отдаваться и через некоторое время
>> соединение обрывается.
>>
>> Подскажите, пожалуйста, куда копать.
>
> Я правильно понимаю, что /linux-source-2.6.20.tar.bz2 проксируется
> с бэкенда ?
>
>
>

-- 
Best,
 	Yaroslav Tarasenko aka Taras Tswiah

More information about the nginx-ru mailing list