4

I've developed a small Rails app, using Rails 3.0.0 and Ruby 1.9.2. During test, on my personal computer, it's performance is fine. I put it on my VPS for production, using Apache and mod_rails, and sometimes the performance is horrible.

Here's an example from the production.log:

Started GET "/tracker" for XX.XX.XX.XX at 2010-11-21 21:49:56 -0500
Processing by FleetsController#index as HTML
Rendered layouts/_stylesheets.html.haml (0.8ms)
Rendered layouts/_header.html.haml (1.0ms)
Rendered layouts/_footer.html.haml (0.0ms)
Rendered pages/about.html.haml within layouts/application (4.5ms)
Completed 200 OK in 15ms (Views: 14.3ms | ActiveRecord: 0.0ms)

Started GET "/tracker/" for XX.XX.XX.XX at 2010-11-21 21:50:02 -0500
Processing by FleetsController#index as HTML
Rendered layouts/_stylesheets.html.haml (0.7ms)
Rendered layouts/_header.html.haml (1.1ms)
Rendered layouts/_footer.html.haml (0.0ms)
Rendered fleets/index.html.haml within layouts/application (7.8ms)
Completed 200 OK in 1901ms (Views: 7.8ms | ActiveRecord: 1.5ms)

Started GET "/tracker/fleets/XXXXXXXXX" for XX.XX.XX.XX at 2010-11-21 21:50:06 -0500
Processing by FleetsController#show as HTML
Parameters: {"id"=>"XXXXXXXXX"}
Rendered fleets/_details_inner.html.haml (1.2ms)
Rendered fleets/_details.html.haml (2.1ms)
Rendered fleets/_summary.html.haml (3.5ms)
Rendered fleets/_scouts_inner.html.haml (1.3ms)
Rendered fleets/_scouts.html.haml (3.5ms)
Rendered reports/_report.html.haml (0.5ms)
Rendered fleets/_reports.html.haml (3.0ms)
Rendered fleets/_recon_form.html.haml (39.9ms)
Rendered fleets/_recon.html.haml (40.8ms)
Rendered users/_user.html.haml (1.2ms)
Rendered fleets/_pilots.html.haml (1.9ms)
Rendered layouts/_stylesheets.html.haml (0.5ms)
Rendered layouts/_header.html.haml (0.9ms)
Rendered layouts/_footer.html.haml (0.0ms)
Rendered fleets/show.html.haml within layouts/application (60.2ms)
Completed 200 OK in 495ms (Views: 59.1ms | ActiveRecord: 2.9ms)

The first hit didn't have any database access. The second does have a database access, but the views only took 7.8ms to generate, and the database only 1.5ms, yet the entire page wasn't complete for almost 2 minutes! This is a pretty common example, but I've got some log entries with 14+ seconds for a page response. And no, this is not during the initial rails load after a reboot.

What could possibly be taking up that time?

1) Have I misinterpreted the ActiveRecord time reports and that's really just the code time, but the realtime database time is where the time is going?

2) I'm using sqlite. I know eventually I'll probably have to switch to MySQL since I will have concurrency issues since (most) every page hit does cause a database write. But right now, I have barely any traffic; at most perhaps 15 people on the site at the same time. In the log example above, there was only 1 hit at a time, with 4-6 seconds between each hits. I'd think sqlite could handle that...

3) I'm on a shared VPS. This means it's possible some other user on the VPS was doing something at the same time that caused the server to slow down. Most of the time, my VPS has very low CPU load, but it's possible that I got unlucky and something was going on at that exact moment. But I've seen this happen often enough that I don't buy that as an answer.

4) The VPS only has 512+512MB of memory. I'm showing there's 150MB free, but is it possible that I'm just hitting memory limits and this is page swapping or something?

5) I've also seen a few BusyException's in the log. I upped the database.yml timeout to 15 seconds (from 5) to see if that helps. Haven't done a real test since to see if it did.

I know I probably haven't provided enough information for you to actually tell me what's going on, so the real question is, how do I even start trying to track this down?

Mark Pundsack
  • 186
  • 1
  • 4

2 Answers2

2

So two things..

  1. Use New Relic to help diagnose code that's slow
  2. Based on the logging, I would bet that you are doing some array manipulation or returning a large array of items in FleetsController#index ... it looks like your application code is doing stuff there.

http://www.newrelic.com/

If that looks wrong, post the code in FleetsController#index. But NewRelic can help you figure out where exactly you are spending your cycles in slow web requests.

Jesse Wolgamott
  • 40,197
  • 4
  • 83
  • 109
  • I'll take a look at New Relic. – Mark Pundsack Nov 23 '10 at 02:11
  • The code is on github at: https://github.com/markpundsack/fleet-tracker/blob/master/app/controllers/fleets_controller.rb. – Mark Pundsack Nov 23 '10 at 02:13
  • FleetsController#index shouldn't really be doing much. There's a call to update the database with info about the current user (which happens for all views), then a lookup to see which Fleets they have access to. The .visible scope has a slightly convoluted where clause, but the set of data is not very large at all. Usually only 1-2 fleets in existence at a time so far, and only maybe 40 users in the entire database. FleetsController#show has more going on, which accounts for the view taking almost 10 times longer to process than #index. – Mark Pundsack Nov 23 '10 at 02:21
  • So I would try removing your before_filters and seeing if that speeds things up. Also, your Fleet.visible might be slowing things down as well. – Jesse Wolgamott Nov 23 '10 at 15:18
  • To SOLVE the problem, you should probably do any fancy manipulation and calculation offline --- precalc what they can see and then its a simple query. – Jesse Wolgamott Nov 23 '10 at 15:19
  • So New Relic's RPM isn't as granular as I'd like it to be, but after some custom traces, I was able to exhaust any obvious issues. The site was just slow. Then caught an exceptionally slow response, >10 seconds, that was sitting in one transaction. No concurrency issue, just plain slow response. I decided to bite the bullet and switch to MySQL instead of Sqlite. Wow, what a difference! Average responses are <200ms and simple ones are now <10ms! Still catching responses >2s so I'll keep trying to figure out what's going on. It's random, so I don't think it's related to my app code. – Mark Pundsack Nov 23 '10 at 23:43
0

SQLite doesn't do concurrency at all. I think that perhaps connections are being blocked on the database. The actual queries are fine, but I suspect that the SQLite db file is locked while another query is running.

You really need to move to an actual server database like MySQL or PostgreSQL.

Toby Hede
  • 36,755
  • 28
  • 133
  • 162
  • I'm prepared to move to MySQL when needed, but in the above example, there didn't happen to be any concurrency yet. There was a single user hitting the site during that time. Elsewhere, I have noticed a concurrency issue. But, my gut says that something else is wrong, and if I can fix that, the amount of database time should be so small that I won't be bumping up against concurrency issues til the site gets much busier. – Mark Pundsack Nov 23 '10 at 02:08