How to findout what cause unicorn workers timeout

Question

People keeps claiming that my website always hang out at some pages. I checked the unicorn stderr log, and found many timeout errors like:

E, [2013-08-14T09:27:32.236478 #30027] ERROR -- : worker=5 PID:11619 timeout (601s > 600s), killing
E, [2013-08-14T09:27:32.252252 #30027] ERROR -- : reaped #<Process::Status: pid=11619,signaled(SIGKILL=9)> worker=5
I, [2013-08-14T09:27:32.266141 #4720]  INFO -- : worker=5 ready

There are many error messages like that.

Then I go to the rails production log, find the exact requests by searching the unicorn error time minus 601s. These timeout request, all choked at the page rendering phase. The sql of these requests are done already. It just never gets an end:

Processing by XXXController#index as HTML
  Rendered xxx/index.html.erb within layouts/application (41.4ms)
  Rendered shared/_sidebar.html.erb (200.9ms)

No complete. Most of these requests served successfully. I don't know why at random time, it hang out there.

I have no idea what may cause this. Can anybody give me a clue of how to find the real reason that cause the unicorn workers to timeout?

Update:

We used NSC to transfer request and response to unicorn. And to try to improve the timeout issue, we added nginx between NSC and unicorn. It turns out the unicorn worker timeout still happens, and each timeout matches a nginx upstream timeout in nginx error log.

Does anyone knows whether there is some kind of bottle neck in TCP connection of unicorn?

Answer 1

I'm using Rack::Timeout to time out before unicorn. Unicorn timeout uses kill -9, and I don't think that gives you any way to do anything.