Welcome! Log In Create A New Profile

Advanced

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

August 10, 2011 12:45PM
Добавили 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 секунд?
Subject Author Posted

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

urri August 08, 2011 12:45PM

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

Alexandr Gomoliako August 08, 2011 01:10PM

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

Никита Козлов August 08, 2011 01:18PM

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

urri August 09, 2011 03:49AM

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

Никита Козлов August 09, 2011 10:08AM

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

urri August 10, 2011 12:45PM

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

urri August 15, 2011 04:44AM



Sorry, only registered users may post in this forum.

Click here to login

Online Users

Guests: 62
Record Number of Users: 6 on February 13, 2018
Record Number of Guests: 185 on January 31, 2018
Powered by nginx      Powered by FreeBSD      PHP Powered      Powered by MariaDB      ipv6 ready