Trabalhadores do unicórnio atingindo o tempo intermitentemente

Question

Estou obtendo tempos limite intermitentes de trabalhadores de unicórnio por aparentemente nenhum motivo, e gostaria de alguma ajuda para depurar o problema real. É pior porque funciona cerca de 10 - 20 pedidos, em seguida, 1 será o tempo limite, em seguida, outros 10 - 20 pedidos e a mesma coisa vai acontecer novamente.

Eu criei um ambiente de desenvolvimento para ilustrar esse problema em particular, portanto, NÃO há tráfego, exceto o meu.

A pilha é Ubuntu 14.04, Rails 3.2.21, PostgreSQL 9.3.4, Unicorn 4.8.3, Nginx 1.6.2.

O problema

Vou descrever em detalhes a hora em que isso não funciona.

Eu solicito uma URL pelo navegador.

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)

Como você pode ver, a solicitação foi concluída com êxito com um status de 200 respostas em apenas 10,3 ms.

No entanto, o navegador trava por cerca de 30 segundos e o Unicorn mata o trabalhador:

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

E o seguinte erro nos registros do 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"

novamente. Não há carga no servidor. As únicas solicitações que estão passando são as minhas e cada 10 a 20 pedidos aleatoriamente têm esse mesmo problema.

Não parece que o unicórnio esteja devorando a memória. Eu sei disso porque estou usando watch -n 0.5 free -m e esse é o resultado.

             total       used       free     shared    buffers     cached
Mem:          1995        765       1229          0         94        405
-/+ buffers/cache:        264       1730
Swap:          511          0        511

Portanto, o servidor não está ficando sem memória.

Existe mais alguma coisa que eu possa fazer para depurar esse problema? ou qualquer insight sobre o que está acontecendo?

    

Answer 1

Eu percebi isso com uma pequena ajuda dos caras do Unicorn.

O problema originou-se de uma consulta que estava sendo executada como parte do middleware personalizado. Por isso, ele não apareceu em nenhum registro.

Este é o código incorreto:

connection = PG::Connection.open(db_info)
query_result = connection.exec(sql)

O código abriu uma conexão com o banco de dados, executou uma consulta SQL, mas nunca fechou a conexão. Eu uso PG bouncer como um pool de conexão que tinha um limite máximo de 20 conexões.

Como o middleware gerava novas conexões o tempo todo, mas nunca as fechava, o PGBouncer achava que todas as conexões estavam em uso e impedia que mais conexões fossem abertas. Então, a solicitação foi interrompida aguardando uma conexão com o banco de dados.

Eu refatorei o código, adicionando as seguintes linhas para fechar a conexão e agora tudo corre bem.

connection.flush
connection.finish

Sem mais tempos limite.