Rails app going nuts at 100% cpu

rubyonrails-talk
#1

Hi,

My rails app has been growing in LOC, everything was running fine, until
someday (one or two weeks ago) where I pushed an update to my server:
after a random period of time, my ruby processes eat 100% of the cpu,
and the app becomes unresponsive. The problem is that I am unable to
tell which update started giving troubles.

$ netstat -anp shows connections not being properly closed between my
rails process and postgresql database, the rails app certainly is
hanging there.

I have yet been unable to identify the source of the problem even after:
- reinstalling on a fresh operating system (debian lenny)
- switching from connecting to postgresql through remote tcp to local
unix sockets
- updating nginx
- updating Rails and other gems
- updating plugins, and removing some that are not so useful
- moving from Thin instances to Nginx+Passenger
- removing suspicious and most recent lines of code that could be the
problem

Everything works fine on my dev machine. On the production server, after
a random amount of time, it suddenly goes crazy. It's terribly painful
to hunt down and I don't see any new potential areas to investigate.

Recently I have been seeing a new error message from time to time but
which disappears on the next request:

#2

Houston we have a problem!

I wanted to stress test my website in order to make it fail faster. But
using ab (apache bench) I get the following error:

$ ab http://www.digiprof.fr/
This is ApacheBench, Version 1.3d <$Revision: 1.73 $> apache-1.3
Copyright (c) 1996 Adam Twiss, Zeus Technology Ltd,
http://www.zeustech.net/
Copyright (c) 2006 The Apache Software Foundation,
http://www.apache.org/

Benchmarking www.digiprof.fr (be patient)...
Test aborted after 10 failures

: Operation now in progress

#3

My munin graph show that when the rails app goes out of control, there
is a raise in the number of interrupt and context switches.

#4

Hi Fernandez,

#5

Fernando Perez wrote:

My munin graph show that when the rails app goes out of control, there
is a raise in the number of interrupt and context switches.

When you say 100%, do you mean the usage goes up and then bounces around,
say between 95% and 100%?

Or do you mean it flatlines at exactly 100%, with no bouncing?

The former means an infinite loop that accesses some IO resource, such as
the wire or the database. You could also have some kind of endless
conversation, where event A (such as an Ajax hit) triggers event B (such as
a page refresh), which triggers A again.

The latter means you have a simple infinite loop that is busy doing only
Ruby statements, such as "nil while true".

How are your unit tests doing? Do they cover all this logic, so they might
show a similar loop or dead spot?

Can you "comment out" entire blocks of your app, such as entire controller
actions, and then run the app and see if the problem goes away? If it does,
the problem is in the last action you clobbered, so put it back in and then
clobber half of it. Keep clobbering until you find the region of coding
doing it.

All generic techniques - no I don't know the difference here between Webrick
and Passenger - but they generally can't hurt!

#6

Excellent investigation and evidence. I hope you continue, and then do
something with it (i.e., a bug report to the appropriate forum).

I will report any progress here.

When you say 100%, do you mean the usage goes up and then bounces
around, say between 95% and 100%?
Or do you mean it flatlines at exactly 100%, with no bouncing?

$ top shows that it's locked at 100% From time to time anew ruby1.8
process pops in then goes away, but all locked ruby1.8 processes are at
16.7 to 17% in cpu usage and 8.4 to 8.5 memory usage.

How are your unit tests doing? Do they cover all this logic, so they
might show a similar loop or dead spot?

Nearly 99% of the code is covered and they all pass.

Can you "comment out" entire blocks of your app

Yes that's what I am doing right now. I have commented out 100% of my
models code, unloaded a few not frequently updated plugins, and
commented out all model calls in my controllers, so only empty pages
will get returned.

I'll see how it works out. The problem is that the last failure happened
after 8 hours of working perfectly, so I can't tell if it worked or not
unless I wait at least that amount of time if it doesn't fail before.

Total shot in the dark: resource acquisition deadlock? I seem to recall
that Passenger runs a cluter of Mongrels

I switched from Thin, to pure mongrel to Passenger, and they all failed
pretty much the same way, but I'll keep that in mind just in case, and
try with one Webrick running alone.

Thank you all for your assistance, I need new eyes on this problem as I
am sure I'm not looking in the correct place.

#7

Passenger uses mongrel? Is that really true? I have no idea but on
the modrails.com site it lists Passenger as being faster than mongrel
while running a couple apps. I'd almost have to say this isn't true,
if not because of the performance difference, then because it shares
none of the configuration settings of Mongrel. If those files are
sitting around they are cleverly hidden.

#8

Commenting out almost all my application yielded a 10hr run without any
problem, so I added in the latest pieces of code I thought the bug(s)
would be in, and still I got 10hr continuous run without any problem!

Now I am adding back the code little by little, I have no idea where the
bug is, but I'm sure I'll be very surprised once I nail it! The worse
thing is that I'm probably looking at it right now and I don't know yet
it's him.

#9

Fernando Perez wrote:

I'm nailing it down more and more.

We all forgot to ask...

  - how many CPUs on your motherboard?
  - can you reproduce on another machine?
    - how many CPUs on it?

(Sometimes a threaded application can abuse semaphores and turn an SMP into a single-threaded multi-CPU process...)

#10

I have reactivated my whole application, except rcov_plugin for which I
had not installed the gem on the production server. I don't if that's
the cause, but now my app has been running flawlessly as if nothing ever
happenned...

#11

Sorry, should read: acts_as_tree might be the trouble maker.

#12

Fernando Perez wrote:

Sorry, should read: acts_as_tree might be the trouble maker.

<soapbox>
You probably want awesome_nested_set anyway.
</soapbox>

Good luck with the rest of the tracking. I'm not sure I'd have the
patience for all the stuff you've done!

Best,

#13

Nailed! It was acts_as_tree the problem. He has been sentenced to an
unlimited time ban from my app.

Marnen Laibow-Koser wrote:

<soapbox>
You probably want awesome_nested_set anyway.
</soapbox>

At the time I was reviewing various options, I should have taken
awesome_blabla instead of acts_as_messy_tree. Damn!

I'm not sure I'd have the patience for all the stuff you've done!

I have no other choice, as this rails app is my business :wink:

So remember, acts_as_tree doesn't seem to play nicely with other stuff
(acts_as_list?), so be careful. I hope this thread wil lsave other
people days of work.

Best regards,

#14

Nailed! It was acts_as_tree the problem. He has been sentenced to an
unlimited time ban from my app.

That seems surprising as there is so little in acts_as_tree. Unless
it is an interaction with something else that you have. Is there a
possibility you could be setting up a loop in the tree somehow? I
don't know whether that would give the symptom described. If there is
a flaw in your design that allows a loop to be setup you could get the
same issue with another acts_as..

Colin

#15

Hi, my app got fucked again!

So it might not be acts_as_tree's fault. Reading my log book and my
repository commits, I am now having high doubts about rcov_plugin: even
though it's not loaded in production.rb, it's still sitting in
vendor/plugins and it might be causing a problem.

I'll report tomorrow morning.

#16

A copy of XX has been removed from the module tree but is still active!

Usually [for me] that means "you're running in development node not
production"

Could that be related to some memory leak that will eventually lock a
rails process at 100% cpu after some time?

might be related to
http://redmine.ruby-lang.org/issues/show/1484

#17

Hi Fernando,

My app is still failing. I installed the MemoryLogic plugin to check the
memory usage after each request, but it's stable.

I noted that it's a single request that locks the app as it doesn't get
printed in the production.log file. Is it possible to debug a live
running Rails app? I looked at LiveConsole but it's only for ruby apps
not rails.

Sorry to hear you haven't gotten this sorted out yet.

By way of alternatives, here's a potentially productive debugging
approach.

Put production logging into debug mode by uncommenting the following
line in environment.rb:

# config.log_level = :debug

Your logs will be much bigger so you'll want to clear them on a daily
basis. But do not just delete them. Save them somewhere first.

You say "it doesn't get printed in the production.log file". That's ok.
My guess is that the problem you're having is almost surely
state-related. The next time your app fails, walk the log backwards to
figure out what state your app was in just prior to the failure. It's
not what we're shooting for, but in general most Rails apps aren't
stateless. You can narrow the list of requests that *might* be the
problem by figuring out what state the app was in prior to the
failure.

You're in production mode so I assume you've got multiple users on the
system. That means you'll have to sort them out. Write a little script
to do that by IP. Then start doing your analysis. Do it on *both* sets
of logs: ones where the app failed, but *especially* the ones where the
app did *not* fail. Your analysis needs to ask: "what's the
difference?" What was each user doing just before the problem. Were
all the users in one part of the app? Or did one just do something new
while all the rest were doing X and Y ?

Debugging a running production app is not impossible, but it's damn
close to impossible IME. The best I can suggest is start gathering as
much info as possible and doing some heavy analysis to narrow down the
possibilities.

Best of luck,
Bill

#18

Hi,

I finally solved my problem. It was a regular expression that failed on
a specific URL which locked the process! I never thought such thing
could happen!

Thank you all for your support and debugging ideas.

Best regards,

#19

I've been reading all along but had nothing to offer to help. I'm very
glad you got it solved. :slight_smile:

#20

check your yml config files

maybe you mixed ident spaces with a tab ?