5

I'm getting intermittent timeouts from unicorn workers for seemingly no reason, and I'd like some help to debug the actual problem. It's worse because it works about 10 - 20 requests then 1 will timeout, then another 10 - 20 requests and the same thing will happen again.

I've created a dev environment to illustrate this particular problem, so there is NO traffic except mine.

The stack is Ubuntu 14.04, Rails 3.2.21, PostgreSQL 9.3.4, Unicorn 4.8.3, Nginx 1.6.2.

The Problem

I'll describe in detail the time that it doesn't work.

I request a url through the browser.

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)

As you can see, the request completed successfully with a 200 response status in just 10.3ms.

However, the browser hangs for about 30 seconds and Unicorn kills the 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

And the following error in the Nginx logs:

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"

Again. There's no load on the server at all. The only requests going through are my own and every 10 - 20 requests at random have this same problem.

It doesn't look like unicorn is eating memory at all. I know this because I'm using watch -n 0.5 free -m and this is the result.

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

So the server isn't running out of memory.

Is there anything further I can do to debug this issue? or any insight into what's happening?

1 Answer 1

0

I figured this out with a little help from the guys over at Unicorn.

The problem originated from a query that was being run as part of custom middleware. Which is why it didn't show up in any logs.

Here's the offending code:

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

The code opened a connection to the database, performed an sql query, but never closed the connection. I use PG bouncer as a connection pool which had a maximum limit of 20 connections.

Since the middleware was spawning up new connections all the time, but never closing them, PGBouncer thought that all connections were in use and prevented more connections being opened. So the request was hung waiting for a connection to the database.

I refactored the code, adding the following lines to close the connection and now everything runs smoothly.

connection.flush
connection.finish

No more timeouts.

2
  • I've checked this issue whole afternoon, have exactly the same symptoms, where do I find that middleware code? and where do I put those lines to close the connection? Thanks! Feb 22, 2016 at 23:54
  • This Unicorn monkey-patch may help to locate where the code is timing out varaneckas.com/blog/ruby-tracing-threads-unicorn
    – mahemoff
    Aug 31, 2016 at 7:19

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .