Добавили 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 секунд?