(60: Operation timed out) while reading response header from upstream

[urri]

Добавили request_time (время обработки
запроса, от получения, до отправки
клиенту) в лог nginx.

368325 запросов из 389838 выполнились за 0.00X
секунд
17629 запросов из 389838 выполнились за 0.0X
секунд
2872 запросов из 389838 выполнились за 0.X
секунд

~ 300 запросов выполнялось 75 секунд
(время таймаута) и примерно столько же
записей в error.log (60: Operation timed out) while reading
response header from upstream.

Вот типичный таймаут, время выполнения
запроса 75.005, время когда таймаут был
зафиксирован 16:06:49:

95.95.95.95 - - [10/Aug/2011:16:06:49+0400] - 75.005 - "GET /XXX/YYY/
HTTP/1.1" 504 584

Время которое зафиксировал демон по
этому запросу, запрос пришел в 16:06:49 и
был обработан в эту же секунду:

2011.08.10 16:06:49 v[3] 	handler_input: id: 35071142
2011.08.10 16:06:49 v[3] 	handler: id: 35071142 ip: 95.95.95.95 uri:
/XXX/YYY/ 
2011.08.10 16:06:49 v[3]	handler_output: id: 35071142

То есть на пути nginx -> [( network -> libevent )] -> input
query было потеряно 75 секунд.

Я думаю это происходит из-за
недопонимания во взаимодействии по
протоколу HTTP, nginx отправляет запрос и
ждет ответ (response header), libevent получает
запрос, но думает что запрос получен не
полностью и продолжает ждать
оставшуюся часть, и только когда nginx
закрывает соединение по таймауту libevent
отправляет запрос на обработку к
демону.

Вот пример access лога по одну из ИП
который получил таймаут, 10 запросов
менее 1 секунды и 2 по 75 секунд.

96.96.96.96 - - [10/Aug/2011:16:05:26 +0400] - 0.080 -  "GET /XXX/ZZZ/
HTTP/1.1" 200 67
96.96.96.96 - - [10/Aug/2011:16:05:26 +0400] - 0.075 -  "GET /XXX/ZZZ/
HTTP/1.1" 200 67
96.96.96.96 - - [10/Aug/2011:16:05:26 +0400] - 0.012 -  "GET /XXX/ZZZ/
HTTP/1.1" 200 67
96.96.96.96 - - [10/Aug/2011:16:05:26 +0400] - 0.009 -  "GET /XXX/ZZZ/
HTTP/1.1" 200 1287
96.96.96.96 - - [10/Aug/2011:16:05:26 +0400] - 0.004 -  "GET /XXX/ZZZ/
HTTP/1.1" 200 67
96.96.96.96 - - [10/Aug/2011:16:05:26 +0400] - 0.003 -  "GET /XXX/ZZZ/
HTTP/1.1" 200 67
96.96.96.96 - - [10/Aug/2011:16:05:26 +0400] - 0.003 -  "GET /XXX/ZZZ/
HTTP/1.1" 200 67
96.96.96.96 - - [10/Aug/2011:16:05:26 +0400] - 0.002 -  "GET /XXX/ZZZ/
HTTP/1.1" 200 67
96.96.96.96 - - [10/Aug/2011:16:05:26 +0400] - 0.005 -  "GET /XXX/ZZZ/
HTTP/1.1" 200 67
96.96.96.96 - - [10/Aug/2011:16:05:26 +0400] - 0.003 -  "GET /XXX/ZZZ/
HTTP/1.1" 200 67
96.96.96.96 - - [10/Aug/2011:16:06:41 +0400] - 75.000 -  "GET /XXX/ZZZ/
HTTP/1.1" 504 182
96.96.96.96 - - [10/Aug/2011:16:06:41 +0400] - 75.000 -  "GET /XXX/ZZZ/
HTTP/1.1" 504 182

Где могут застревать запросы на 75
секунд?

Posted at Nginx Forum: http://forum.nginx.org/read.php?21,213520,213642#msg-213642