Fast in MySQL console, slow in ActiveRecord

rubyonrails-talk
1

Has anyone experienced an ActiveRecord query being much much slower than running the equivalent

query in the MySql console?

I am running a simple “group by” query with one condition on a table with 7 million records. When

I run EXPLAIN it says that it will have to scan over all the records - well that’s OK. In the MySQL

query it takes 1min 40secs which is OK for me - this is not a web app. But when I run exactly

the same query in a ruby script using ActiveRecord it takes about 45 mins - far too long.

I am running all this on my work PC, 3 gig of memory. Windows PerfMon says I have 2 gig available

and 1 gig on standyby. I am using ruby 1.8.7; rails 3; mysql2 gem; Windows 7 and MySql 5.5.

I have also set the INNODB buffer pool size to 480M.

What seems to be happening is that the MySQL process uses all the memory up to 500M and

there is a lot of page swapping. PerfMon shows that the disk activity is very high (99%). So

that explains the bottleneck. But I still don’t know why this happens when I run the code from

Ruby and yet from the MySQL console it is fine.

I even tried just using the MySQL2 gem directly in my ruby code using MySql2::Client.new,

but still very very slow.

I know this probably doesn’t explain everything but I just wondered if anyone had a similar experience.

Thanks

William

p.s. also posed on StackOverflow.

http://stackoverflow.com/questions/5004204/query-is-fast-in-mysql-but-slow-when-run-from-rails-activerecord

2

Has anyone experienced an ActiveRecord query being much much slower than running the equivalent query in the MySql console?

I am running a simple "group by" query with one condition on a table with 7 million records. When I run EXPLAIN it says that it will have to scan over all the records - well that's OK. In the MySQL query it takes 1min 40secs which is OK for me - this is not a web app. But when I run exactly the same query in a ruby script using ActiveRecord it takes about 45 mins - far too long.

I'd try using ruby-prof to see where the time is being spent (bear in mind that ruby-prof does slow down the execution of ruby code, but it should still give you an idea)

Fred

3

Thanks, nice idea for installing ruby-prof. Never used it before and it’s extremely easy to install and use. I’m on Windows so I needed to install with this command:

gem install ruby-prof --platform=mswin32 -v 0.8.1

I tried it on a simpler query and I give the top lines of the profile here.
You can see that it takes 5.9 seconds with virtually all the time spend in
Mysql2::Client#query. When I run the same query through
the console it takes 812ms.

Thread ID: 25569168
Total: 5.910000

 %self total self wait child calls name
 99.14 5.86 5.86 0.00 0.00 1 Mysql2::Client#query (ruby_runtime:0}
  0.42 0.03 0.03 0.00 0.00 2 Kernel#require (ruby_runtime:0}
  0.32 0.04 0.02 0.00 0.03 1 ActiveRecord::ConnectionAdapters::Quoting#quote (C:/ruby187/lib/ruby/gems/1.8/gems/activerecord-3.0.4/lib/active_record/connection_adapters/abstract/quoting.rb:8}
  0.03 0.00 0.00 0.00 0.00 147 <Class::ActiveRecord::Base>#instantiate (C:/ruby187/lib/ruby/gems/1.8/gems/activerecord-3.0.4/lib/active_record/base.rb:907}
  0.02 0.00 0.00 0.00 0.00 28 Kernel#hash (ruby_runtime:0}
  0.02 0.00 0.00 0.00 0.00 5 Kernel#clone (ruby_runtime:0}
  0.02 0.00 0.00 0.00 0.00 147 ActiveRecord::Base#_run_initialize_callbacks (C:/ruby187/lib/ruby/gems/1.8/gems/activesupport-3.0.4/lib/active_support/callbacks.rb:401}
  ...

I'm still stuck to know why it takes so much longer :(

William
4

Dumb question: are you sure that it's exactly the same query that is being run and that there isn't something like a default_scope adding an order clause or anything like that ?

Fred

5

Hi Fred,

Yes I am pretty sure, because I write it out using to_sql before I run. At the moment is seems like a Windows memory problem rather than a ruby problem. As I commented on the StackOverflow thread I now have a solution for my immediate problem. Since I am calculating averages over a date range over three years - and since the dates are actually end-of-month dates - I am really calculating an overage over 36 distinct months. I therefore do my query in two steps. First, I calculate averages and counts per month. Second I aggregate up to get averages over 36 months. Runs pretty quick.

But I haven’t solved the problem and I haven’t been able to find comments from anyone else experiencing the same thing. So the mystery remains.

Ruby-prof, though. Thanks for that. You made me install it and its actually rather nice.

William

6

Do you have indexes on your database tables at all?

7

Yes I do. But still the problem is the difference in speed between running the query in the MySql console and using MySql2 gem. At the moment I think I might also be having a problem with a gem file. So slowly trying to remove them to see if I can see one causing a problem.

8

Is AR building models from the query's result set? Can you paste some relevant code?