Я получаю прерывистые тайм-ауты от рабочих-единорогов, казалось бы, без причины, и мне нужна помощь в устранении реальной проблемы. Хуже, потому что он работает с 10-20 запросами, затем 1 будет тайм-аут, затем еще 10-20 запросов и снова произойдет то же самое.
Я создал среду разработки, чтобы проиллюстрировать эту конкретную проблему, поэтому нет трафика, кроме моего.
Стек - это Ubuntu 14.04, Rails 3.2.21, PostgreSQL 9.3.4, Unicorn 4.8.3, Nginx 1.6.2.
Эта проблема
Подробно опишу время, когда не работает.
Я запрашиваю URL-адрес через браузер.
Started GET "/offers.xml?q%5bupdated_at_greater_than_or_equal_to%5d=2014-12-28T18:01:16Z&q%5bupdated_at_less_than_or_equal_to%5d=2014-12-28T19:30:21Z" for 127.0.0.1 at 2014-12-30 15:58:59 +0000
Completed 200 OK in 10.3ms (Views: 0.0ms | ActiveRecord: 2.1ms)
Как видите, запрос успешно завершился со статусом ответа 200 всего за 10,3 мс.
Однако браузер зависает примерно на 30 секунд, и Unicorn убивает воркера:
E, [2014-12-30T15:59:30.267605 #13678] ERROR -- : worker=0 PID:14594 timeout (31s > 30s), killing
E, [2014-12-30T15:59:30.279000 #13678] ERROR -- : reaped #<Process::Status: pid 14594 SIGKILL (signal 9)> worker=0
I, [2014-12-30T15:59:30.355085 #23533] INFO -- : worker=0 ready
И следующая ошибка в логах Nginx:
2014/12/30 15:59:30 [error] 23463#0: *27 upstream prematurely closed connection while reading response header from upstream, client: 127.0.0.1, server: localhost, request: "GET /offers.xml?q%5bupdated_at_greater_than_or_equal_to%5d=2014-12-28T18:01:16Z&q%5bupdated_at_less_than_or_equal_to%5d=2014-12-28T19:30:21Z HTTP/1.1", upstream: "http://unix:/app/shared/tmp/sockets/unicorn.sock:/offers.xml?q%5bupdated_at_greater_than_or_equal_to%5d=2014-12-28T18:01:16Z&q%5bupdated_at_less_than_or_equal_to%5d=2014-12-28T19:30:21Z", host: "localhost", referrer: "http://localhost/offers.xml?q%5bupdated_at_greater_than_or_equal_to%5d=2014-12-28T18:01:16Z&q%5bupdated_at_less_than_or_equal_to%5d=2014-12-28T19:30:21Z"
Очередной раз. На сервере вообще нет нагрузки. Единственные проходящие запросы - мои собственные, и каждые 10-20 случайных запросов имеют такую же проблему.
Не похоже, что единорог вообще пожирает память. Я знаю это, потому что использую watch -n 0.5 free -m и вот результат.
total used free shared buffers cached
Mem: 1995 765 1229 0 94 405
-/+ buffers/cache: 264 1730
Swap: 511 0 511
Таким образом, серверу не хватает памяти.
Могу ли я что-нибудь сделать для устранения этой проблемы? или любое понимание того, что происходит?
Я понял это с небольшой помощью ребят из Unicorn.
Проблема возникла из-за запроса, который выполнялся как часть настраиваемого промежуточного программного обеспечения. Вот почему он не отображается ни в одном журнале.
Вот оскорбительный код:
connection = PG::Connection.open(db_info)
query_result = connection.exec(sql)
Код открыл соединение с базой данных, выполнил запрос sql, но так и не закрыл соединение. Я использую PG bouncer в качестве пула соединений, у которого было максимальное ограничение в 20 соединений.
Поскольку промежуточное программное обеспечение постоянно порождает новые соединения, но никогда их не закрывает, PGBouncer считал, что все соединения используются, и предотвращал открытие новых соединений. Итак, запрос завис в ожидании подключения к базе данных.
Я изменил код, добавив следующие строки, чтобы закрыть соединение, и теперь все работает без сбоев.
connection.flush
connection.finish
Больше никаких тайм-аутов.