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
--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk
-~----------~----~----~----~------~----~------~--~---
Zed A. Shaw
2006-Oct-19 08:37 UTC
Re: Has anyone noticed Rails abrubtly slows down for no reason?
On Thu, 19 Oct 2006 05:19:58 -0000 "Tom" <tlianza-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org> 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. --~--~---------~--~----~------------~-------~--~----~ You received this message because you are subscribed to the Google Groups "Ruby on Rails: Talk" group. To post to this group, send email to rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org To unsubscribe from this group, send email to rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org For more options, visit this group at http://groups.google.com/group/rubyonrails-talk -~----------~----~----~----~------~----~------~--~---
Zed A. Shaw wrote:> On Thu, 19 Oct 2006 05:19:58 -0000 > "Tom" <tlianza-Re5JQEeQqe8AvxtiuMwx3w@public.gmane.org> 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 --~--~---------~--~----~------------~-------~--~----~ You received this message because you are subscribed to the Google Groups "Ruby on Rails: Talk" group. To post to this group, send email to rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org To unsubscribe from this group, send email to rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org For more options, visit this group at http://groups.google.com/group/rubyonrails-talk -~----------~----~----~----~------~----~------~--~---
Long
2006-Oct-19 18:04 UTC
Re: Has anyone noticed Rails abrubtly slows down for no reason?
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 --~--~---------~--~----~------------~-------~--~----~ You received this message because you are subscribed to the Google Groups "Ruby on Rails: Talk" group. To post to this group, send email to rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org To unsubscribe from this group, send email to rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org For more options, visit this group at http://groups.google.com/group/rubyonrails-talk -~----------~----~----~----~------~----~------~--~---