So I’ve tracked down a mal-performing query in my app, and I can’t
figure out why it’s behaving so poorly. I’m getting 5-10 seconds of
response time in Rails for the same query that in MySQL directly takes
only .01 seconds. And the query only returns one row!
I have isolated this in a test controller that does nothing but try this
query:
rft_val = ReferentValue.find(:first,
:conditions=> { :key_name => 'identifier',
:value =>
'‘http://www.fin.ntu.edu.tw/~kchan/Handouts/Fama-French_1993.pdf’} )
This produces SQL trace from AR like this:
SELECT * FROM referent_values WHERE (referent_values.value =
‘http://www.fin.ntu.edu.tw/~kchan/Handouts/Fama-French_1993.pdf’ AND
referent_values.key_name = ‘identifier’) LIMIT 1
Now, granted, this table has 5 million rows in it. Yeah, that’s a lot.
But both those columns are indexed. And i went to mysql explain to make
sure the indexes were being used… and found that thsi query was no
problem in mysql. .01 seconds. But back in Rails, 9 seconds.
Anyone got any ideas? I’m at my wits end.
Jonathan
Hi Jonathan,
On Tue, Apr 15, 2008 at 2:45 PM, Jonathan R.
[email protected] wrote:
Now, granted, this table has 5 million rows in it. Yeah, that’s a lot.
But both those columns are indexed. And i went to mysql explain to make
sure the indexes were being used… and found that thsi query was no
problem in mysql. .01 seconds. But back in Rails, 9 seconds.
Have you tried this from the console? Same result as the test
controller? What about running the query through the AR connection?
Are these all just as slow?
~ j.
Good ideas, thanks. Let’s try em. From the console… yes, same slow
result.
I’m not sure how to “run the query through the AR connection”. You mean
issue manually constructed SQL via AR? Need to look up how to od that.
Now, this table DOES have 5 million rows in it. Maybe that’s a
distraction. But I keep thinking that it can’t be a coincidence, Rails
must be doing something behind the scenes that’s NOT showing up in the
query trace, that the 5 million rows is effecting? (MySQL has no problem
with 5 million rows when the same query found in the trace is given to
it directly; that’s what indexes are for).
Hmm. Very frustrating.
[And yes, that extra ’ in my example was a typo entering it here, not in
my actual code. That would have been a syntax error, but I’m talking
about a 9 second query.]
Jonathan
John B. wrote:
Hi Jonathan,
On Tue, Apr 15, 2008 at 2:45 PM, Jonathan R.
[email protected] wrote:
Now, granted, this table has 5 million rows in it. Yeah, that’s a lot.
But both those columns are indexed. And i went to mysql explain to make
sure the indexes were being used… and found that thsi query was no
problem in mysql. .01 seconds. But back in Rails, 9 seconds.
Have you tried this from the console? Same result as the test
controller? What about running the query through the AR connection?
Are these all just as slow?
~ j.
On 15 Apr 2008, at 23:11, Jonathan R. wrote:
6-19 seconds to return. The very same query (the one in that string)
issued directly to MySQL—.01 seconds.
This makes no sense to me. What the heck is going on?
If you run the explain through this (ie
ReferentValue.connection.select_all “EXPLAIN …”), do you get a
different answer from when you ran explain … in the mysql console/
query browser ?
Okay, here we go, raw query through AR:
ReferentValue.connection.select_all(“SELECT * FROM referent_values WHERE
(referent_values.value =
‘http://www.fin.ntu.edu.tw/~kchan/Handouts/Fama-French_1993.pdf’ AND
referent_values.key_name = ‘identifier’) LIMIT 1”)
6-19 seconds to return. The very same query (the one in that string)
issued directly to MySQL—.01 seconds.
This makes no sense to me. What the heck is going on?
Jonathan R. wrote:
Good ideas, thanks. Let’s try em. From the console… yes, same slow
result.
I’m not sure how to “run the query through the AR connection”. You mean
issue manually constructed SQL via AR? Need to look up how to od that.
Now, this table DOES have 5 million rows in it. Maybe that’s a
distraction. But I keep thinking that it can’t be a coincidence, Rails
must be doing something behind the scenes that’s NOT showing up in the
query trace, that the 5 million rows is effecting? (MySQL has no problem
with 5 million rows when the same query found in the trace is given to
it directly; that’s what indexes are for).
Hmm. Very frustrating.
[And yes, that extra ’ in my example was a typo entering it here, not in
my actual code. That would have been a syntax error, but I’m talking
about a 9 second query.]
Jonathan
John B. wrote:
Hi Jonathan,
On Tue, Apr 15, 2008 at 2:45 PM, Jonathan R.
[email protected] wrote:
Now, granted, this table has 5 million rows in it. Yeah, that’s a lot.
But both those columns are indexed. And i went to mysql explain to make
sure the indexes were being used… and found that thsi query was no
problem in mysql. .01 seconds. But back in Rails, 9 seconds.
Have you tried this from the console? Same result as the test
controller? What about running the query through the AR connection?
Are these all just as slow?
~ j.
Ooh, what an ingenius idea, thanks, I didn’t know you could do that.
Oops, I think I figured it out. It’s rather too embaressing to admit
publically. As usual, the problem is somewhere else. But going through
this helped me figure out what it WAS, thanks so much to the advice.
Frederick C. wrote:
On 15 Apr 2008, at 23:11, Jonathan R. wrote:
6-19 seconds to return. The very same query (the one in that string)
issued directly to MySQL—.01 seconds.
This makes no sense to me. What the heck is going on?
If you run the explain through this (ie
ReferentValue.connection.select_all “EXPLAIN …”), do you get a
different answer from when you ran explain … in the mysql console/
query browser ?