unicorn Ruby/Rack server user+dev discussion/patches/pulls/bugs/help
 help / color / mirror / code / Atom feed
* Timeouts longer than expected.
@ 2015-01-29 13:06 Antony Gelberg
  2015-01-29 20:00 ` Eric Wong
  0 siblings, 1 reply; 2+ messages in thread
From: Antony Gelberg @ 2015-01-29 13:06 UTC (permalink / raw)
  To: unicorn-public

Hi all.  We use unicorn in production across four servers, behind
nginx and HAProxy (to load balance).  We set a 300s timeout in the
config file.  On an average day, we see something like:

E, [2015-01-22T17:01:24.335600 #4311] ERROR -- : worker=2 PID:21101
timeout (301s > 300s), killing

in our logs, ~60 times.  However, one day we noticed that production
had gone down with all the unicorns showing entries like the
following:

E, [2015-01-22T12:35:15.643020 #4311] ERROR -- : worker=1 PID:4605
timeout (451s > 300s), killing

(note the 451s before it was killed).

Any clues how we can better-understand the root cause, even if it's
something we'll put in place for the future?  We lack visibility here.

Thanks in advance,

Antony

^ permalink raw reply	[flat|nested] 2+ messages in thread

* Re: Timeouts longer than expected.
  2015-01-29 13:06 Timeouts longer than expected Antony Gelberg
@ 2015-01-29 20:00 ` Eric Wong
  0 siblings, 0 replies; 2+ messages in thread
From: Eric Wong @ 2015-01-29 20:00 UTC (permalink / raw)
  To: Antony Gelberg; +Cc: unicorn-public

Antony Gelberg <antony.gelberg@gmail.com> wrote:
> Hi all.  We use unicorn in production across four servers, behind
> nginx and HAProxy (to load balance).  We set a 300s timeout in the
> config file.  On an average day, we see something like:
> 
> E, [2015-01-22T17:01:24.335600 #4311] ERROR -- : worker=2 PID:21101
> timeout (301s > 300s), killing
> 
> in our logs, ~60 times.  However, one day we noticed that production
> had gone down with all the unicorns showing entries like the
> following:
> 
> E, [2015-01-22T12:35:15.643020 #4311] ERROR -- : worker=1 PID:4605
> timeout (451s > 300s), killing
> 
> (note the 451s before it was killed).

What other log entries appear in the 8 minutes leading up to the 451s
line?

Which version of unicorn is this?

There were some bugs fixed in ancient unicorn versions; and current
versions are still affected by big NTP adjustments due to the lack of
monotonic clock API in older Rubies.

I have a patch queued up for 5.x to use the monotonic clock, but
requires Ruby 2.1+ to be useful:
http://bogomips.org/unicorn-public/m/20150118033916.GA4478%40dcvr.yhbt.net.html

Maybe there's another sleep calculation bug, though.  Not many people
rely on giant timeouts and probably never notice it.

I'll take a closer look at the master sleep calculations (in
murder_lazy_workers) in a week or so and see if there's another problem
lurking in the current versions.

> Any clues how we can better-understand the root cause, even if it's
> something we'll put in place for the future?  We lack visibility here.

I'd use an in-process timeout to get backtraces.  The
Application_Timeouts doc in the source and online has more
tips on dealing with timeouts in general.

  http://unicorn.bogomips.org/Application_Timeouts.html

Also curious: you have users willing to wait 5 minutes for an
HTTP response?  Yikes!

^ permalink raw reply	[flat|nested] 2+ messages in thread

end of thread, other threads:[~2015-01-29 20:00 UTC | newest]

Thread overview: 2+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2015-01-29 13:06 Timeouts longer than expected Antony Gelberg
2015-01-29 20:00 ` Eric Wong

Code repositories for project(s) associated with this public inbox

	https://yhbt.net/unicorn.git

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).