AR performance weirdness

rubyonrails-talk
1

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

2

Hi Jonathan,

3

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 Barnette wrote:

4

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 Rochkind wrote:

5

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?

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 ?

6

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 Cheung wrote: