# AR performance weirdness

**URL:** <https://www.ruby-forum.com/t/ar-performance-weirdness/134893>\
**Category:** Rails\
**Created:** [April 15, 2008, 11:45pm UTC](https://www.ruby-forum.com/t/ar-performance-weirdness/134893 "2008-04-15T23:45:30Z")\
**Posts on this page:** 6\
**Page:** 1

<div class="post-metadata">

**Author:** ![jrochkind](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/j/779978/32.png) [@jrochkind](https://www.ruby-forum.com/u/jrochkind)\
**Post date:** [April 15, 2008, 11:45pm UTC](https://www.ruby-forum.com/t/ar-performance-weirdness/134893/1 "2008-04-15T23:45:30Z")

</div>

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](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](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

---

<div class="post-metadata">

**Author:** ![jrochkind](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/j/779978/32.png) [@jrochkind](https://www.ruby-forum.com/u/jrochkind)\
**Post date:** [April 15, 2008, 11:58pm UTC](https://www.ruby-forum.com/t/ar-performance-weirdness/134893/2 "2008-04-15T23:58:16Z")

</div>

Hi Jonathan,

On Tue, Apr 15, 2008 at 2:45 PM, Jonathan R.  
[removed\_email\_address@domain.invalid](mailto:removed_email_address@domain.invalid) 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.

---

<div class="post-metadata">

**Author:** ![jrochkind](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/j/779978/32.png) [@jrochkind](https://www.ruby-forum.com/u/jrochkind)\
**Post date:** [April 16, 2008, 12:07am UTC](https://www.ruby-forum.com/t/ar-performance-weirdness/134893/3 "2008-04-16T00:07:08Z")

</div>

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.  
> [removed\_email\_address@domain.invalid](mailto:removed_email_address@domain.invalid) 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.

---

<div class="post-metadata">

**Author:** ![jrochkind](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/j/779978/32.png) [@jrochkind](https://www.ruby-forum.com/u/jrochkind)\
**Post date:** [April 16, 2008, 12:35am UTC](https://www.ruby-forum.com/t/ar-performance-weirdness/134893/4 "2008-04-16T00:35:45Z")

</div>

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 ?

---

<div class="post-metadata">

**Author:** ![jrochkind](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/j/779978/32.png) [@jrochkind](https://www.ruby-forum.com/u/jrochkind)\
**Post date:** [April 16, 2008, 12:11am UTC](https://www.ruby-forum.com/t/ar-performance-weirdness/134893/5 "2008-04-16T00:11:23Z")

</div>

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](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.  
> > [removed\_email\_address@domain.invalid](mailto:removed_email_address@domain.invalid) 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.

---

<div class="post-metadata">

**Author:** ![jrochkind](https://www.ruby-forum.com/letter_avatar_proxy/v4/letter/j/779978/32.png) [@jrochkind](https://www.ruby-forum.com/u/jrochkind)\
**Post date:** [April 16, 2008, 12:48am UTC](https://www.ruby-forum.com/t/ar-performance-weirdness/134893/6 "2008-04-16T00:48:13Z")

</div>

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 ?