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 ?