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
--
Posted via http://www.ruby-forum.com/.
--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk?hl=en
-~----------~----~----~----~------~----~------~--~---
Hi Jonathan, On Tue, Apr 15, 2008 at 2:45 PM, Jonathan Rochkind <rails-mailing-list-ARtvInVfO7ksV2N9l4h3zg@public.gmane.org> 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. --~--~---------~--~----~------------~-------~--~----~ You received this message because you are subscribed to the Google Groups "Ruby on Rails: Talk" group. To post to this group, send email to rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org To unsubscribe from this group, send email to rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org For more options, visit this group at http://groups.google.com/group/rubyonrails-talk?hl=en -~----------~----~----~----~------~----~------~--~---
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:> Hi Jonathan, > > On Tue, Apr 15, 2008 at 2:45 PM, Jonathan Rochkind > <rails-mailing-list-ARtvInVfO7ksV2N9l4h3zg@public.gmane.org> 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.-- Posted via http://www.ruby-forum.com/. --~--~---------~--~----~------------~-------~--~----~ You received this message because you are subscribed to the Google Groups "Ruby on Rails: Talk" group. To post to this group, send email to rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org To unsubscribe from this group, send email to rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org For more options, visit this group at http://groups.google.com/group/rubyonrails-talk?hl=en -~----------~----~----~----~------~----~------~--~---
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:> 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:
>> Hi Jonathan,
>>
>> On Tue, Apr 15, 2008 at 2:45 PM, Jonathan Rochkind
>> <rails-mailing-list-ARtvInVfO7ksV2N9l4h3zg@public.gmane.org>
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.
--
Posted via http://www.ruby-forum.com/.
--~--~---------~--~----~------------~-------~--~----~
You received this message because you are subscribed to the Google Groups
"Ruby on Rails: Talk" group.
To post to this group, send email to
rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
To unsubscribe from this group, send email to
rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org
For more options, visit this group at
http://groups.google.com/group/rubyonrails-talk?hl=en
-~----------~----~----~----~------~----~------~--~---
On 15 Apr 2008, at 23:11, Jonathan Rochkind wrote:> > 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 ?> > > > Jonathan Rochkind 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 Barnette wrote: >>> Hi Jonathan, >>> >>> On Tue, Apr 15, 2008 at 2:45 PM, Jonathan Rochkind >>> <rails-mailing-list-ARtvInVfO7ksV2N9l4h3zg@public.gmane.org> 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. > > -- > Posted via http://www.ruby-forum.com/. > > >--~--~---------~--~----~------------~-------~--~----~ You received this message because you are subscribed to the Google Groups "Ruby on Rails: Talk" group. To post to this group, send email to rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org To unsubscribe from this group, send email to rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org For more options, visit this group at http://groups.google.com/group/rubyonrails-talk?hl=en -~----------~----~----~----~------~----~------~--~---
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:> On 15 Apr 2008, at 23:11, Jonathan Rochkind 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 ?-- Posted via http://www.ruby-forum.com/. --~--~---------~--~----~------------~-------~--~----~ You received this message because you are subscribed to the Google Groups "Ruby on Rails: Talk" group. To post to this group, send email to rubyonrails-talk-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org To unsubscribe from this group, send email to rubyonrails-talk-unsubscribe-/JYPxA39Uh5TLH3MbocFFw@public.gmane.org For more options, visit this group at http://groups.google.com/group/rubyonrails-talk?hl=en -~----------~----~----~----~------~----~------~--~---