☰

Unicorn 工人间歇性超时

tag-icon • tag-icon nginx ruby-on-rails ubuntu-14.04 unicorn
Unicorn 工人间歇性超时

我收到来自 unicorn worker 的间歇性超时，似乎没有任何原因，我需要一些帮助来调试实际问题。情况更糟，因为它工作了大约 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)

可以看到，请求仅用了 10.3ms 就成功完成，响应状态为 200。

然而，浏览器挂起了大约 30 秒，并且 Unicorn 杀死了该 worker：

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 个随机请求都会出现同样的问题。

看起来 Unicorn 根本没有占用内存。我知道这一点，因为我正在使用，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

因此服务器不会耗尽内存。

我还能做些什么来调试这个问题？或者对正在发生的事情有任何了解吗？

答案1

在 Unicorn 的小伙子们的帮助下我解决了这个问题。

问题源于作为自定义中间件的一部分运行的查询。这就是它未显示在任何日志中的原因。

以下是有问题的代码：

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

代码打开了与数据库的连接，执行了 SQL 查询，但从未关闭连接。我使用 PG bouncer 作为连接池，其最大连接数限制为 20 个。

由于中间件一直在创建新连接，但从不关闭它们，因此 PGBouncer 认为所有连接都已在使用中，并阻止打开更多连接。因此请求被挂起，等待与数据库的连接。

我重构了代码，添加了以下几行来关闭连接，现在一切都运行顺利。

connection.flush
connection.finish

不再超时。

相关内容