![Unicorn 工人间歇性超时](https://linux22.com/image/648740/Unicorn%20%E5%B7%A5%E4%BA%BA%E9%97%B4%E6%AD%87%E6%80%A7%E8%B6%85%E6%97%B6.png)
我收到来自 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
不再超时。