# Has anyone noticed Rails abrubtly slows down for no reason? **URL:** \ **Category:** Rails\ **Created:** [October 19, 2006, 7:21am UTC](https://www.ruby-forum.com/t/has-anyone-noticed-rails-abrubtly-slows-down-for-no-reason/72827 "2006-10-19T07:21:49Z")\ **Posts on this page:** 4\ **Page:** 1
**Author:** ![tlianza](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/t/ce7236/32.png) [@tlianza](https://www.ruby-forum.com/u/tlianza)\ **Post date:** [October 19, 2006, 7:21am UTC](https://www.ruby-forum.com/t/has-anyone-noticed-rails-abrubtly-slows-down-for-no-reason/72827/1 "2006-10-19T07:21:49Z")
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](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 ---
**Author:** ![tlianza](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/t/ce7236/32.png) [@tlianza](https://www.ruby-forum.com/u/tlianza)\ **Post date:** [October 19, 2006, 7:43am UTC](https://www.ruby-forum.com/t/has-anyone-noticed-rails-abrubtly-slows-down-for-no-reason/72827/2 "2006-10-19T07:43:51Z")
On Thu, 19 Oct 2006 05:19:58 -0000 “Tom” [removed\_email\_address@domain.invalid](mailto:removed_email_address@domain.invalid) wrote: \> \> 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 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 > **[Zed A. shaw](https://zedshaw.com/)** > > Personal essays and writings by Zed A. Shaw. [http://mongrel.rubyforge.org/](http://mongrel.rubyforge.org/) [http://www.lingr.com/room/3yXhqKbfPy8](http://www.lingr.com/room/3yXhqKbfPy8) – Come get help. ---
**Author:** ![tlianza](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/t/ce7236/32.png) [@tlianza](https://www.ruby-forum.com/u/tlianza)\ **Post date:** [October 19, 2006, 7:29pm UTC](https://www.ruby-forum.com/t/has-anyone-noticed-rails-abrubtly-slows-down-for-no-reason/72827/3 "2006-10-19T19:29:36Z")
Zed A. Shaw wrote: > > 23.00 31.22 31.22 143 218.32 318.67 Kernel.sleep > > 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 ---
**Author:** ![tlianza](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/t/ce7236/32.png) [@tlianza](https://www.ruby-forum.com/u/tlianza)\ **Post date:** [October 19, 2006, 8:13pm UTC](https://www.ruby-forum.com/t/has-anyone-noticed-rails-abrubtly-slows-down-for-no-reason/72827/4 "2006-10-19T20:13:43Z")
Tom wrote: > 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