Rails - Sep 2005 - Performance: is find slow or is it me?

I''m troubled by the it takes Rails to pass me the objects resulting
from
a find query. As I wrote in another message, I''m currently working on 
exporting data to CSV, but the same problem occurs for list views 
containing many objects.

For a sample query returning 4000 result items, running it through 
ActiveRecord takes about 10.1 seconds (with GC disabled it''s 0.6 
seconds less). There are two included associations, therefore, 
presumably AR has to instantiate on the order of 12000 objects.

For comparison, I took the generated SQL and ran it directly:

$ echo $query | time psql myapp_development > /dev/null
        Command being timed: "psql myapp_development"
        User time (seconds): 0.17
        System time (seconds): 0.02
        Percent of CPU this job got: 37%
        Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.52

Obviously the database is not the bottleneck. Even including the startup 
time for psql, it accounts for less than 1 second. Also, I made sure 
that I''m not running into an n+1 query trap. There''s just one
query.

Let''s see where AR is spending its time. So I removed the two included 
associations

  Klass.find(:all, :includes => [])

Now the time is down to about 1.7 seconds! Removing only one of the 
included associations gets the time to about 5 seconds.

There''s still room for improvement

  Klass.find(:all)

This only take 0.6 seconds. That''s the baseline for retrieving and 
instantiating 4000 objects. The two included associations add 4000 
objects each, but no additional time to access the database. Therefore, 
unless I''m missing something, finding with two included associations 
ought to take roughly 1.8 seconds, definitely not six times that.

My tentative conclusion is that AR#find with included associations has a 
serious performance problem.

(All Rails tests were run in production environment and with warm-up 
rounds.)


Michael

-- 
Michael Schuerig                                 Life is what happens 
mailto:michael-q5aiKMLteq4b1SvskN2V4Q@public.gmane.org                  While
you''re making plans
http://www.schuerig.de/michael/    --Kevin Gilbert, A Long Day''s Life

Michael Schuerig wrote:
> 
> I''m troubled by the it takes Rails to pass me the objects
resulting from
> a find query. As I wrote in another message, I''m currently working
on
> exporting data to CSV, but the same problem occurs for list views
> containing many objects.
> 
> For a sample query returning 4000 result items, running it through
> ActiveRecord takes about 10.1 seconds (with GC disabled it''s 0.6
> seconds less). There are two included associations, therefore,
> presumably AR has to instantiate on the order of 12000 objects.
> 
> For comparison, I took the generated SQL and ran it directly:
> 
> $ echo $query | time psql myapp_development > /dev/null
>         Command being timed: "psql myapp_development"
>         User time (seconds): 0.17
>         System time (seconds): 0.02
>         Percent of CPU this job got: 37%
>         Elapsed (wall clock) time (h:mm:ss or m:ss): 0:00.52
> 
> Obviously the database is not the bottleneck. Even including the startup
> time for psql, it accounts for less than 1 second. Also, I made sure
> that I''m not running into an n+1 query trap. There''s just
one query.
> 
> Let''s see where AR is spending its time. So I removed the two
included
> associations
> 
>   Klass.find(:all, :includes => [])
> 
> Now the time is down to about 1.7 seconds! Removing only one of the
> included associations gets the time to about 5 seconds.
> 
> There''s still room for improvement
> 
>   Klass.find(:all)
> 
> This only take 0.6 seconds. That''s the baseline for retrieving and
> instantiating 4000 objects. The two included associations add 4000
> objects each, but no additional time to access the database. Therefore,
> unless I''m missing something, finding with two included
associations
> ought to take roughly 1.8 seconds, definitely not six times that.
> 
> My tentative conclusion is that AR#find with included associations has a
> serious performance problem.
> 
> (All Rails tests were run in production environment and with warm-up
> rounds.)
> 
> 
> Michael
> 
What''s your server environment?  I''ve recently ported an
application from
PHP/Mysql to Rails and have been delighted by the performance - it''s
definitely quicker.  Can''t give you any real numbers, but to give you
an
idea, the app runs 53 tables many of which have 5 figure numbers of rows.

CGI is very slow, but Apache and FasCGI seems great to me.

-- 
Robert Jones

On Saturday 10 September 2005 17:27, Robert Jones wrote:
> What''s your server environment?  I''ve recently ported an
application
> from PHP/Mysql to Rails and have been delighted by the performance -
> it''s definitely quicker.  Can''t give you any real
numbers, but to
> give you an idea, the app runs 53 tables many of which have 5 figure
> numbers of rows.
>
> CGI is very slow, but Apache and FasCGI seems great to me.
I''ve run the tests on a P4 2.4GHz, but that''s not really
important. No
http server was involved in the testing, I have accessed the app 
directly from a script. Also, the problem is not at all related to the 
number of rows in a table.

Performance is bad specifically for AR#find with included associations. 
I have tested with 4000 objects returned from the query, I haven''t yet 
tried to pinpoint whether performance is just linearly bad or if some 
super-linear time-complexity is involved.

Michael

-- 
Michael Schuerig                  I am the sum total of the parts
mailto:michael-q5aiKMLteq4b1SvskN2V4Q@public.gmane.org        I control
directly.
http://www.schuerig.de/michael/   --Daniel C. Dennett, Elbow Room

On Saturday 10 September 2005 16:23, Michael Schuerig wrote:
> My tentative conclusion is that AR#find with included associations
> has a serious performance problem.
Recapitulating, finding a result set of 4000 objects takes about 1.6 
seconds on my machine. When two belongs_to associations are included, 
the time blows up to > 10 seconds. I''ve tried to narrow down where
the
time is spend and the single biggest culprit is 
ActiveRecord::Associations#extract_record. That method alone is 
responsible for about half the time the call to find takes.

  def extract_record(schema_abbreviations, table_name, row)
    record = {}
    row.each do |column, value|
      prefix, column_name = schema_abbreviations[column]
      record[column_name] = value if prefix == table_name
      record[column] = value unless schema_abbreviations.include?
(column) or record[column]
    end
    return record
  end

The inner loop is where it''s at. Commenting it out drops the response 
time by > 5 seconds. The decrease is *not* a side effect of returning 
an empty hash; running the loop and returning {} has only a minimal 
effect.

Michael

-- 
Michael Schuerig                 Not only does lightning not strike
mailto:michael-q5aiKMLteq4b1SvskN2V4Q@public.gmane.org       twice, it usually
doesn''t strike once.
http://www.schuerig.de/michael/  --Salman Rushdie, Fury

Hi Michael,

I just had a look, and the current revision of the rails trunk (2176)
looks like it has slightly different code - it does not include the
line:

     record[column] = value unless schema_abbreviations.include?
(column) or record[column]

Of all the code in there, I would guess that this was the most CPU
intensive (the .include? call specifically) - perhaps the problem was
noticed and has been fixed?

Cheers,

-David Felstead


On 9/11/05, Michael Schuerig
<michael-q5aiKMLteq4b1SvskN2V4Q@public.gmane.org>
wrote:
> On Saturday 10 September 2005 16:23, Michael Schuerig wrote:
> 
> > My tentative conclusion is that AR#find with included associations
> > has a serious performance problem.
> 
> Recapitulating, finding a result set of 4000 objects takes about 1.6
> seconds on my machine. When two belongs_to associations are included,
> the time blows up to > 10 seconds. I''ve tried to narrow down
where the
> time is spend and the single biggest culprit is
> ActiveRecord::Associations#extract_record. That method alone is
> responsible for about half the time the call to find takes.
> 
>   def extract_record(schema_abbreviations, table_name, row)
>     record = {}
>     row.each do |column, value|
>       prefix, column_name = schema_abbreviations[column]
>       record[column_name] = value if prefix == table_name
>       record[column] = value unless schema_abbreviations.include?
> (column) or record[column]
>     end
>     return record
>   end
> 
> The inner loop is where it''s at. Commenting it out drops the
response
> time by > 5 seconds. The decrease is *not* a side effect of returning
> an empty hash; running the loop and returning {} has only a minimal
> effect.
> 
> Michael
> 
> --
> Michael Schuerig                 Not only does lightning not strike
> mailto:michael-q5aiKMLteq4b1SvskN2V4Q@public.gmane.org       twice, it
usually doesn''t strike once.
> http://www.schuerig.de/michael/  --Salman Rushdie, Fury
> _______________________________________________
> Rails mailing list
> Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org
> http://lists.rubyonrails.org/mailman/listinfo/rails
>

On Saturday 10 September 2005 23:56, David Felstead
wrote:
> Hi Michael,
>
> I just had a look, and the current revision of the rails trunk (2176)
> looks like it has slightly different code - it does not include the
> line:
>
>      record[column] = value unless schema_abbreviations.include?
> (column) or record[column]
Yes, you''re right. I''m using an earlier version of a patch
that allows
multiple associations to the same table 
(http://dev.rubyonrails.org/ticket/1562). I should have checked this 
before. Well, I did check now with a clean checkout and the patch 
doesn''t have an effect on performance.
> Of all the code in there, I would guess that this was the most CPU
> intensive (the .include? call specifically) - perhaps the problem was
> noticed and has been fixed?
No, that''s where intuition can go wrong. I''ve simply commented
out the
line and found that it accounts for only 1s of otherwise 11s.

I haven''t thought this through, but I''m pretty sure given an
result row,
there''s a way to extract the fields needed to instantiate an object 
that works without lots of iterating and hash lookups.

Michael

-- 
Michael Schuerig                   The Fifth Rider of the Apocalypse
mailto:michael-q5aiKMLteq4b1SvskN2V4Q@public.gmane.org         is a programmer.
http://www.schuerig.de/michael/

I''m quite keen for some kind of fix on this as well... I''m
getting
*REALLY* slow results from my rails app, and the way I want to write  
apps is going to use these multiple association loadings quite often.

Julian.

On 11/09/2005, at 9:25 AM, Michael Schuerig wrote:
> On Saturday 10 September 2005 23:56, David Felstead wrote:
>
>> Hi Michael,
>>
>> I just had a look, and the current revision of the rails trunk (2176)
>> looks like it has slightly different code - it does not include the
>> line:
>>
>>      record[column] = value unless schema_abbreviations.include?
>> (column) or record[column]
>>
>
> Yes, you''re right. I''m using an earlier version of a
patch that allows
> multiple associations to the same table
> (http://dev.rubyonrails.org/ticket/1562). I should have checked this
> before. Well, I did check now with a clean checkout and the patch
> doesn''t have an effect on performance.
>
>
>> Of all the code in there, I would guess that this was the most CPU
>> intensive (the .include? call specifically) - perhaps the problem was
>> noticed and has been fixed?
>>
>
> No, that''s where intuition can go wrong. I''ve simply
commented out the
> line and found that it accounts for only 1s of otherwise 11s.
>
> I haven''t thought this through, but I''m pretty sure given
an result
> row,
> there''s a way to extract the fields needed to instantiate an
object
> that works without lots of iterating and hash lookups.
>
> Michael
>
> -- 
> Michael Schuerig                   The Fifth Rider of the Apocalypse
> mailto:michael-q5aiKMLteq4b1SvskN2V4Q@public.gmane.org         is a
programmer.
> http://www.schuerig.de/michael/
> _______________________________________________
> Rails mailing list
> Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org
> http://lists.rubyonrails.org/mailman/listinfo/rails
>

Hello,

Does anybody know if there are plans to be able to include associations
that are more than one step away? For instance, if a project has many
clients and each client can have multiple contacts, it would be nice to
be able to

Project.find(:all, :include => [:clients, :contacts]

and have AR find the relationships and pull in contacts. Right now this
definitely doesn''t work, but it would be nice, and the SQL
isn''t that
much more complicated than it is with only a single join.

Thanks for the feedback,

Sean Wallace

Julian Leviston wrote:
> I''m quite keen for some kind of fix on this as well...
I''m getting
> *REALLY* slow results from my rails app, and the way I want to write 
> apps is going to use these multiple association loadings quite often.
> 
> Julian.
> 
> On 11/09/2005, at 9:25 AM, Michael Schuerig wrote:
> 
>> On Saturday 10 September 2005 23:56, David Felstead wrote:
>>
>>> Hi Michael,
>>>
>>> I just had a look, and the current revision of the rails trunk
(2176)
>>> looks like it has slightly different code - it does not include the
>>> line:
>>>
>>>      record[column] = value unless schema_abbreviations.include?
>>> (column) or record[column]
>>>
>>
>> Yes, you''re right. I''m using an earlier version of a
patch that allows
>> multiple associations to the same table
>> (http://dev.rubyonrails.org/ticket/1562). I should have checked this
>> before. Well, I did check now with a clean checkout and the patch
>> doesn''t have an effect on performance.
>>
>>
>>> Of all the code in there, I would guess that this was the most CPU
>>> intensive (the .include? call specifically) - perhaps the problem
was
>>> noticed and has been fixed?
>>>
>>
>> No, that''s where intuition can go wrong. I''ve simply
commented out the
>> line and found that it accounts for only 1s of otherwise 11s.
>>
>> I haven''t thought this through, but I''m pretty sure
given an result  row,
>> there''s a way to extract the fields needed to instantiate an
object
>> that works without lots of iterating and hash lookups.
>>
>> Michael
>>
>> -- 
>> Michael Schuerig                   The Fifth Rider of the Apocalypse
>> mailto:michael-q5aiKMLteq4b1SvskN2V4Q@public.gmane.org         is a
programmer.
>> http://www.schuerig.de/michael/
>> _______________________________________________
>> Rails mailing list
>> Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org
>> http://lists.rubyonrails.org/mailman/listinfo/rails
>>
> 
> _______________________________________________
> Rails mailing list
> Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org
> http://lists.rubyonrails.org/mailman/listinfo/rails

Take comfort in knowing that it used to be a lot, lot slower ;). But
I''m all ears for further optimizations. It''s not an entirely
trivial
matter to decipher the aliased result set and it does add considerably
overhead to the operation.

Thankfully, you don''t need to manipulate 12K records at once In most
every day use.

But since you do, there should be amble motivation for making it
faster. Do dig in!
-- 
David Heinemeier Hansson
http://www.loudthinking.com -- Broadcasting Brain
http://www.basecamphq.com   -- Online project management
http://www.backpackit.com   -- Personal information manager
http://www.rubyonrails.com  -- Web-application framework

I like to program Ruby by writing a few "puts statements" to check
rrsults.
This is a result of my limited Ruby skills
What is the easiest way to do this in Rails?
jb
PS - Seen p. 194 of AW

For basic debugging, I use the following:

In controllers, models etc...

logger.info @var

Then watch the logs, or

<%= debug(@var) %>

in views to see a debug output.

-- 
R.Livsey
http://livsey.org



John Brookes wrote:
> I like to program Ruby by writing a few "puts statements" to
check
> rrsults.
> This is a result of my limited Ruby skills
> What is the easiest way to do this in Rails?
> jb
> PS - Seen p. 194 of AW
>
> _______________________________________________
> Rails mailing list
> Rails-1W37MKcQCpIf0INCOvqR/iCwEArCW2h5@public.gmane.org
> http://lists.rubyonrails.org/mailman/listinfo/rails
>
>
>

How about avoiding debugging as much as possible by witting tests. This way
you''ll spend less time for extinguishing fire you caused in code
written last
week.

Richard Livsey wrote:
> For basic debugging, I use the following:
> 
> In controllers, models etc...
> 
> logger.info @var
> 
> Then watch the logs, or
> 
> <%= debug(@var) %>
> 
> in views to see a debug output.
> 
-- 
Company  - http://primalgrasp.com
Thoughts - http://deezsombor.blogspot.com