Has anyone noticed Rails abrubtly slows down for no reason?

[Tom]

I've noticed this on various pages, both in development mode (which I
do with Mongrel) and in production mode under FastCGI. I've seen it on
Mac and on Linux. It's really bizarre. I'll pull up a random page,
one that typically takes under a second to return, and it will crawl
for an obscene amount of time. For example, I just pulled up a
straightforward "edit profile page" and the mongrel output is:

----------------------------------------
Processing GiftaliciousController#edit_profile (for 127.0.0.1 at
2006-10-18 22:07:21) [GET]
Session ID: 761a324c8ef63d038daf53f528ad2445
Parameters: {"action"=>"edit_profile", "id"=>"tlianza",
"controller"=>"giftalicious"}
User Load (0.001185) SELECT * FROM users WHERE (users.id = 1) LIMIT
1
User Load (0.001237) SELECT * FROM users WHERE (users.id = 1) LIMIT
1
User Columns (0.074004) SHOW FIELDS FROM users
Rendering giftalicious/edit_profile
Rendered giftalicious/_friend_banner (1.19412)
Rendered giftalicious/_user_form (7.61455)
Rendered giftalicious/_edit_profile (9.66085)
Completed in 106.69851 (0 reqs/sec) | Rendering: 104.38216 (97%) | DB:
0.07728 (0%) | 200 OK
[http://localhost/person/tlianza/section/edit_profile]
----------------------------------------

A few queries that are directly against a primary key, and a few
partials, and it took 106 seconds to come back, with almost no database
time. Then it seems like, after that point, everything is slow. All
the pages take many seconds to load until I kill and restart the
server.

Occasionally when I kill Mongrel, I get messages about waiting for
threads, and most recently this dumped out after killing mongrel:

% cumulative self self total
time seconds seconds calls ms/call ms/call name
23.00 31.22 31.22 143 218.32 318.67 Kernel.sleep
6.51 40.06 8.84 2158 4.10 45.39 Array#each
6.49 48.87 8.81 98958 0.09 0.09 String#==
3.40 53.48 4.61 427 10.80 16.81 String#scan
1.78 55.90 2.42 51 47.45 780.59
ActionView::Base::CompiledTemplates._run_rhtml_giftalicious__list_item
1.75 58.28 2.38 750 3.17 15.65 Hash#each
1.62 60.48 2.20 15174 0.14 0.20 Hash#[]
1.61 62.67 2.19 14570 0.15 11.46 Kernel.send
1.60 64.84 2.17 2955 0.73 8.34 Class#new
1.50 66.87 2.03 6936 0.29 0.49 Kernel.dup
1.49 68.89 2.02 1091
/usr/local/lib/ruby/1.8/pathname.rb:195: [BUG] Bus Error

Does anyone have any idea what might be going on? How might I begin
troubleshooting this thing?

Thanks!
Tom

[Zed A. Shaw]

On Thu, 19 Oct 2006 05:19:58 -0000
"Tom" <tli...@gmail.com> wrote:

<snip>

>
> Occasionally when I kill Mongrel, I get messages about waiting for
> threads, and most recently this dumped out after killing mongrel:
>
> % cumulative self self total
> time seconds seconds calls ms/call ms/call name
> 23.00 31.22 31.22 143 218.32 318.67 Kernel.sleep

<snip>

Uh, am I crazy or is that output from the "profile" library? Are you accidentally loading a "Profile" class and it's actually loading the ruby library (which absolutely crawls, crawls, crawls).

That's not normal output for Mongrel, so you've gotta be loading it somehow.

--
Zed A. Shaw, MUDCRAP-CE Master Black Belt Sifu
http://www.zedshaw.com/
http://mongrel.rubyforge.org/
http://www.lingr.com/room/3yXhqKbfPy8 -- Come get help.

[Tom]

Zed A. Shaw wrote:
> On Thu, 19 Oct 2006 05:19:58 -0000
> "Tom" <tli...@gmail.com> wrote:
>
> <snip>
> >
> > Occasionally when I kill Mongrel, I get messages about waiting for
> > threads, and most recently this dumped out after killing mongrel:
> >
> > % cumulative self self total
> > time seconds seconds calls ms/call ms/call name
> > 23.00 31.22 31.22 143 218.32 318.67 Kernel.sleep
> <snip>
>
> Uh, am I crazy or is that output from the "profile" library? Are you accidentally loading a "Profile" class and it's actually loading the ruby library (which absolutely crawls, crawls, crawls).
>
> That's not normal output for Mongrel, so you've gotta be loading it somehow.

Hi Zed - thank you for the response.

I grep'ed my code for "profiler", "benchmark", and "report" but the
only results I turned up were in my tests, not the application code.
That said, when that particluar dump happened I was running in
development mode. Is there a chance that something in the Rails stack
loads up the profiler when you're running in development mode?

I haven't seen that output under production mode, but I have seen the
kind of abrupt slowdowns that seem to linger until the ruby processes
are killed. Perhaps I linked the two (the abrupts slowdowns and that
output) incorrectly. Note also that I haven't been running Mongrel in
production mode (yet). I've been using FastCGI. So, I'd say it's
unlikely this is a Mongrel issue... which is in some ways unfortunate,
because you're among the most responsive people in the Ruby community
:).

In production mode, what I've been doing is throwing httperf at a
particular part of my app that does a db query returning @50 things,
and the view iterates them to build the page. What I often see is that
this page can take a second to run:

Completed in 1.09736 (0 reqs/sec) | Rendering: 0.99119 (90%) | DB:
0.02663 (2%) | 200 OK

But after say 10-15 requests, it can take almost 40 seconds to run:

Completed in 37.74147 (0 reqs/sec) | Rendering: 37.69804 (99%) | DB:
0.02693 (0%) | 200 OK

I understand that if my box is heavily loaded that things will take
longer - in this particular case at 3 connections per second it seeems
to spike the CPU after a few seconds. I know that makes this page a
good place to opimize or cache. The part that concerns me is when I
see the breakdown of the execution time spending nearly zero time in
the database and 37 seconds rendering the page. My database and web
server are on the same machine (right now) contending for the same
resources. The fact that the database seems to be processing things
quickly but the rendering takes a nosedive makes me wonder if something
is wrong in the app. It just doesn't smell right, as they say.

Or... is this common in Rails apps? What are other people seeing?

Tom

[Long]

Tom wrote:
>
> <snip>

>
> I understand that if my box is heavily loaded that things will take
> longer - in this particular case at 3 connections per second it seeems
> to spike the CPU after a few seconds. I know that makes this page a
> good place to opimize or cache. The part that concerns me is when I
> see the breakdown of the execution time spending nearly zero time in
> the database and 37 seconds rendering the page. My database and web
> server are on the same machine (right now) contending for the same
> resources. The fact that the database seems to be processing things
> quickly but the rendering takes a nosedive makes me wonder if something
> is wrong in the app. It just doesn't smell right, as they say.
>
> Or... is this common in Rails apps? What are other people seeing?
>

I am running three different apps on Apache 1.3+FCGI+Slackware and have
not experience any problem in production, so far. It seems 3 requests/sec is
slow but I don't know what is the average. Is 10 req/sec a good measure?

During development, sometimes due to an Exception (self inflicted) WEBrick
just doesn't recover. Subsequent request just takes forever and not get any result.
CTRL+C on WEBrick had no effect. I checked the server memory usage (free)
and can see available mem reducing then in memory stuff gets swapped out. By the
time I finish killing (kill -9) WEBrick and checked free memory again the
swap-space had grew and there was more free mem available.

Just thought I'd share in case you can see any similarities.

Long
www.edgesoft.ca