This project is archived and is in readonly mode.

#5098 ✓ resolved
drjoke

Rails 3 Beta 4 ActiveRecord 5X slower than Rails 2.3.5

Reported by drjoke | July 12th, 2010 @ 05:37 PM | in 3.0.2

I have finished converting my live app to Rails 3.

I am using Ruby Enterprise 1.8.7 and Passenger 2.2.15 on Ubuntu 10.4

I go from 5.31 trans/sec to 3.05 trans/sec per AWS EC2 instance.

$ siege -c 5 -t 1M http://localhost

RAILS 2.3.5
Transactions:             320 hits
Availability:          100.00 %
Elapsed time:           60.26 secs
Data transferred:          6.76 MB
Response time:            0.45 secs
Transaction rate:          5.31 trans/sec
Throughput:            0.11 MB/sec
Concurrency:            2.41
Successful transactions:         320
Failed transactions:             0
Longest transaction:          1.05
Shortest transaction:          0.25

RAILS 3
Transactions:             169 hits
Availability:          100.00 %
Elapsed time:           55.38 secs
Data transferred:          3.72 MB
Response time:            1.06 secs
Transaction rate:          3.05 trans/sec
Throughput:            0.07 MB/sec
Concurrency:            3.23
Successful transactions:         169
Failed transactions:             0
Longest transaction:          1.74
Shortest transaction:          0.58

After removing Passenger from the equation and let this be script/server -e
production (Rails 2.3.5) vs. rails server -e production (Rails 3).


RAILS 2.3.5
Transactions:             312 hits
Availability:          100.00 %
Elapsed time:           60.32 secs
Data transferred:         68.81 MB
Response time:            0.44 secs
Transaction rate:          5.17 trans/sec
Throughput:            1.14 MB/sec
Concurrency:            2.29
Successful transactions:         312
Failed transactions:             0
Longest transaction:          0.99
Shortest transaction:          0.10

RAILS 3
Transactions:             109 hits
Availability:          100.00 %
Elapsed time:           59.77 secs
Data transferred:         23.80 MB
Response time:            2.20 secs
Transaction rate:          1.82 trans/sec
Throughput:            0.40 MB/sec
Concurrency:            4.01
Successful transactions:         109
Failed transactions:             0
Longest transaction:          2.99
Shortest transaction:          0.53

And now benchmarking ActiveRecord

Rails 2.3.5

puts Benchmark.measure{5000.times{User.find :first, :conditions => ["id 
= ?", (rand * 1000 + 1).to_i]}}
  1.500000   0.100000   1.600000 (  2.371361)

Rails 3.0

puts Benchmark.measure{5000.times{User.find :first, :conditions => ["id 
= ?", (rand * 1000 + 1).to_i]}}
  8.160000   0.160000   8.320000 ( 15.330955)

I can also reproduce this problem on my Macbook Pro using Snow Leopard
10.6.4

Rails 2.3.5
puts Benchmark.measure{5000.times{User.find :first, :conditions => ["id 
= ?", (rand * 1000 + 1).to_i]}}
  2.460000   0.440000   2.900000 ( 20.093052)

Rails 3.0
puts Benchmark.measure{5000.times{User.find :first, :conditions => ["id 
= ?", (rand * 1000 + 1).to_i]}}
  9.100000   0.810000   9.910000 ( 28.481634)

Comments and changes to this ticket

  • John McAliley

    John McAliley July 12th, 2010 @ 06:54 PM

    I am also seeing bad performance using similar find queries. Rails3beta 4 and Ruby 1.9.2preview3 (RVM) on my Mac.

    Something strange I noticed was this:

    RAILS 3. puts Benchmark.measure{5000.times{|i| User.find(i}}
    2.370000 0.160000 2.530000 ( 3.079710)

    RAILS 3. puts Benchmark.measure{5000.times{|i| User.where(:id=>i)}}
    0.200000 0.000000 0.200000 ( 0.206418)

    I ran these each 5 times with similar results. The new query API is faster than the 2.3x API if you use "where", but much slower if you use "find". Will try to run thru debugger if I get a chance today.

  • Miles Egan

    Miles Egan July 13th, 2010 @ 04:24 AM

    drjoke - I'm not seeing a similar performance difference on my Ubuntu laptop with postgresql. Rails 3 seems about 20% slower here. What hardware and db engine are you using?

    John - I see similar performance diffs between find() and where() in dev mode, but not in production mode. I suspect from looking at profiles that this is because find() is performing a more expensive query compilation than where but that this difference disappears in production mode due to query caching. Do you see the same performance delta when you run in development and production mode or only in development mode?

  • drjoke

    drjoke July 13th, 2010 @ 04:37 AM

    I am using MySQL, and am seeing this same problem both on Amazon EC2 running Ubuntu and Macbook Pro running snow leopard. The performance difference is similar in both instance.

    Now using the Rails 3 ActiveRecord API yield very very fast result.

    RAILS3

    OLD API
    puts Benchmark.measure{5000.times{User.find :first, :conditions => ["id
    = ?", (rand * 1000 + 1).to_i]}} 9.100000 0.810000 9.910000 ( 28.481634

    NEW API
    puts Benchmark.measure{ 5000.times { User.where(:id => (rand * 1000 + 1).to_i) } }

    I am in production mode.

    0.830000 0.000000 0.830000 ( 0.838565)

  • drjoke

    drjoke July 13th, 2010 @ 04:39 AM

    I am using MySQL, and am seeing this same problem both on Amazon EC2 running Ubuntu and Macbook Pro running snow leopard. The performance difference is similar in both instance.
    Now using the Rails 3 new ActiveRecord API yield very very fast result.

    BOTH are Rails 3

    OLD API
    puts Benchmark.measure{5000.times{User.find :first, :conditions => ["id = ?", (rand * 1000 + 1).to_i]}} 9.100000 0.810000 9.910000 ( 28.481634
    
    NEW API
    puts Benchmark.measure{ 5000.times { User.where(:id => (rand * 1000 + 1).to_i) } }
    0.830000 0.000000 0.830000 ( 0.838565)
    

    I am in production mode.

  • John McAliley

    John McAliley July 13th, 2010 @ 12:49 PM

    Rails3 beta4, Ruby 1.9.2 preview 3. This time on CentOS 5.5 instead of dev Mac.
    Production in console. I tested several models, 5 times each. Similar results in all cases:

    $ rails c production
    
    Loading production environment (Rails 3.0.0.beta4)
    irb(main):012:0> puts Benchmark.measure{5000.times{|i| SearchLog.find(i+1)}}
      4.690000   0.190000   4.880000 (  7.102072)
    => nil
    irb(main):013:0> puts Benchmark.measure{5000.times{|i| SearchLog.where(:id=>(i+1))}}
      0.310000   0.000000   0.310000 (  0.308452)
    => nil
    

    Production with Passenger

    puts Benchmark.measure{5000.times{|i| SearchLog.find(i+1)}}
    3.520000   0.260000   3.780000 (  6.031257)
    
    puts Benchmark.measure{5000.times{|i| SearchLog.where(:id=>(i+1))}}
    0.130000   0.000000   0.130000 (  0.131140)
    

    I am working on running this against edge to see if I get the same results.

  • John McAliley

    John McAliley July 13th, 2010 @ 01:32 PM

    I apologize, but that last test is incorrect. The queries were not even executed.. I did not realize it was lazy loaded. I added a print statement so the query gets executed and the results are about the same for both queries now. So "where" is not performing much different than "find" on Rails 3.

    puts Benchmark.measure{5000.times{|i| p SearchLog.where(:id=>(i+1));}}
    5.890000   0.480000   6.370000 (  8.860438)
    
    puts Benchmark.measure{5000.times{|i| p SearchLog.find(i+1);}}
    6.000000   0.440000   6.440000 (  8.965563)
    
  • John McAliley

    John McAliley July 13th, 2010 @ 02:54 PM

    Another test w/ Rails3 edge instead of beta4 gems. Performance is better in Rails 3 edge, but still not as good as 2.3.2. But acceptable for my app.

    @drjoke - Sorry about my earlier test with "where". It was incorrect b/c the queries were never executed... I hope you didn't start converting your queries as a result. Have you tried benchmarking your app with edge Rails?

    @Miles Egan - performance is slightly better in production mode in edge.

    Loading RAILS_ENV=production environment (Rails 2.3.2)
    puts Benchmark.measure{5000.times{|i| SearchLog.find(i+1)}}
      1.120000   0.140000   1.260000 (  1.788877)
    
    
    #rails 3b4 gem
    Loading production environment (Rails 3.0.0.beta4)
    puts Benchmark.measure{5000.times{|i| SearchLog.find(i+1)}}
      2.370000   0.100000   2.470000 (  3.006663)
    

    Rails 3 Edge in production mode w/ commit: b75fc... I added this to my Gemfile: gem 'rails', :git => 'git://github.com/rails/rails.git' and bundle install.

    puts Benchmark.measure{5000.times{|i| SearchLog.find(i+1);}}
      1.680000   0.090000   1.770000 (  2.282400)
    
  • drjoke

    drjoke July 13th, 2010 @ 04:01 PM

    I run production on Amazon AWS EC2. If Rails 3 is not going to be as fast as Rails 2.3.5, it means I will have to pay more $$$ for more EC2 instances.

    Until Rails 3 Edge performs as well as Rails 2.3.5, I will not be able to upgrade. I actually read a lot of blogs which tend to make me think that Rails 3 ActiveRecord improvement is all about speed.

    Is there any sign that the core developers are aware of this issue?

  • drjoke

    drjoke July 13th, 2010 @ 04:57 PM

    I am now trying Rails 3.0 Edge. It 33% faster than Rails 3.0 Beta 4, but over 100% slower than Rails 2.3.5.

    Rails 2.3.5
    puts Benchmark.measure{5000.times{User.find :first, :conditions => ["id = ?", (rand * 1000 + 1).to_i]}}
      2.460000   0.440000   2.900000 ( 20.093052)
    
    Rails 3.0 Beta 4
    puts Benchmark.measure{5000.times{User.find :first, :conditions => ["id = ?", (rand * 1000 + 1).to_i]}}
      9.100000   0.810000   9.910000 ( 28.481634)
    
    Rails 3.0 Edge
    puts Benchmark.measure{ 5000.times { User.where(:id => (rand * 1000 + 1).to_i)[0].id } }
      6.050000   0.670000   6.720000 ( 24.857868)
    
  • Miles Egan

    Miles Egan July 13th, 2010 @ 09:37 PM

    drjoke - I think the number we're interested in here is the last (real time) of the benchmark measure results, right?

  • Miles Egan

    Miles Egan July 13th, 2010 @ 10:10 PM

    Following up on this, I created a test set of data like this:

    >> 5000.times { User.create(:name => "name") }
    

    And a simple benchmark script like this:

    count = 0
    Benchmark.bm(10) do |x|
      x.report("find") { 10000.times { count += User.find(:first, :conditions => ["id = ?", rand(5000) + 1]).name.size } }
      puts count
      if Rails.version =~ /^3/
        count = 0
        x.report("where") { 10000.times { count += User.where(:id => rand(5000) + 1).name.size } }
        puts count
      end
    end
    

    Running this with rails 2 I get this:

    $ ./script/runner -e production ../bench.rb
                    user     system      total        real
    find        2.730000   0.090000   2.820000 (  3.629271)
    40000
    

    and with rails 3 I get this:

    $ bundle exec ~/c/rails/bin/rails runner -e production ../bench.rb
                    user     system      total        real
    find        5.320000   0.050000   5.370000 (  6.230500)
    40000
    where       0.610000   0.010000   0.620000 (  0.618468)
    40000
    

    So I'm seeing rails 3 as almost twice as slow doing a find() but significantly faster with a where(). This is on a desktop workstation though so the I/O characteristics might be very different from an EC2 instance.

  • Daniel Guettler

    Daniel Guettler July 14th, 2010 @ 01:13 AM

    Miles,

    keep in mind that User.where(:id => ... ) isn't actually hitting the database unless you try to access it. Which means User.find(...) is loading and instantiating 5000 records vs User.where(...) isn't loading anything. So you are comparing apples with oranges here...

    Best, Daniel

  • Miles Egan

    Miles Egan July 14th, 2010 @ 01:15 AM

    Daniel - if you look at the benchmark code I posted I access an attribute(name, in this case) of each instance returned by where() and use it to calculate a running total. So it looks to me as if it is actually performing the queries. Is this not the case?

  • John McAliley

    John McAliley July 14th, 2010 @ 03:33 AM

    @Miles - At first glance it appears that it executes the queries, but take a look at this:

    p User.where(:id => rand(5000) + 1).class
    ActiveRecord::Relation


    p User.where(:id => rand(5000) + 1).name "User"

    Your query returns an ActiveRecord::Relation object and coincidentally the name method returns a 4 character string ("User") also. Its just like calling User.name. You need to call .first or [0] to get the User model and execute the SQL query.

    p User.where(:id => rand(5000) + 1).first.name
    "some_user_name"
    
  • drjoke

    drjoke July 14th, 2010 @ 04:06 AM

    @miles I think we are looking at the third number from the left for benchmark result, which is also the last number when not counting the parenthesized one.

  • drjoke

    drjoke July 14th, 2010 @ 04:15 AM

    @miles please look at how I do my recent benchmark with the new API. I feel this is the correct way to get through the lazy loading feature.

    It is a bit faster than using the old API, but still 100% slower than Rails 2.3.5.

    Rails 3.0 Edge
    puts Benchmark.measure{ 5000.times { User.where(:id => (rand * 1000 + 1).to_i)[0].id } }
      6.050000   0.670000   6.720000 ( 24.857868)
    
  • Miles Egan

    Miles Egan July 14th, 2010 @ 04:23 AM

    John - good catch. I guess I chose a bad default value for my test data that masked the behavior of the where() method. Those low times meant that no queries were actually being run.

    drjoke - Using your syntax I reran my tests and I'm seeing essentially the same thing you're seeing. On this test at least rails3 seems to take about twice as long as rails2 to run the same query.

  • Rohit Arondekar

    Rohit Arondekar July 14th, 2010 @ 04:48 AM

    • State changed from “new” to “open”
    • Importance changed from “” to “Low”

    djroke: Why the (rand * 1000 + 1).to_i ? Float multiplication & conversion to integer will take it's own time imho. I tried the following on Rails master:

    puts Benchmark.measure { 5000.times { |i| Post.where(:id => 1).all } }
      3.220000   0.110000   3.330000 (  3.842138)
    

    I'm a benchmarking noob though so I might be totally wrong about this. Also is there any way to find out where Rails is spending it's time?

  • Miles Egan

    Miles Egan July 14th, 2010 @ 04:57 AM

    Rohit I've attached two traces from ruby-prof on this benchmark, prof2.txt for rails2 and prof3.txt for rails 3. I'm no expert at ruby profiling either but the calls to the Arel::SqlCompiler kind of jump out from the profile. It would be great if somebody more familiar with the arel/AR code could look at this.

  • José Valim

    José Valim July 14th, 2010 @ 01:12 PM

    • Milestone cleared.
    • Assigned user set to “Emilio Tagua”
    • Importance changed from “Low” to “Medium”

    In the benchmarks above, the value we should look at is (real). That said, we had a performance decrease by moving from 20s (2.3) to around 24s (using Rails master). This is expected since we moved to ARel and ActiveRecord today share both the old and new code (as soon as we deprecate and remove it, performance will likely improve).

    Also, notice we already have some benchmarks inside activerecord that we've been using extensively. Nonetheless, the profiling results helps, so I'm assigning to Emilio to see if there is something we can cache help in Arel::SqlCompiler.

  • drjoke

    drjoke July 14th, 2010 @ 01:56 PM

    @Jose, I have a different take on this.

    I feel we should look at total, which is the third number, because it signifies the total CPU consumed to process this request.

    In real deployment, especially in my case with AWS EC2, I am concern about the CPU consumed because I would have multiple ruby threads processing requests in parallel. All these threads will add up to the total CPU used by the EC2 instance.

    (real), the wall clock time, is influence by other factors like network latency or even MySQL delay. It makes the slowness in the Rails 3.0 code itself appear a lot less significant. Also, it would not signify the concern that people will have in real deployment with CPU cycles.

  • drjoke

    drjoke July 14th, 2010 @ 02:06 PM

    @Jose I have another question as well. Do you expect things to improve in Rails 3.0 final?

    When you said "(as soon as we deprecate and remove it, performance will likely improve)" are you talking about removing the old .find API before things start improving? If that is so, it will be in Rails 3.1 or after?

  • John McAliley

    John McAliley July 14th, 2010 @ 02:09 PM

    • Assigned user cleared.

    Here is another profile similar to Miles, if you need more data. OSX 10.5.8, Ruby 1.9.2 preview3, Rails Edge vs OSX 10.5.8, Ruby 1.8.6, Rails 2.3.2

    require 'ruby-prof'
    RubyProf.start
    1000.times{|i| User.find(i+1000)}
    result = RubyProf.stop
    printer = RubyProf::FlatPrinter.new(result)
    printer.print(STDOUT)
    

    Results are in the attached spreadsheet (2 sheets). I just included total time (self), total % of time (%self), and method calls. Rails 3 has significantly more method calls - 661,902 vs 399,990. And total time - 4.09 vs 2.39

    There are alot of calls to Class.new, #method_missing, etc.. Performance may be taking a hit from some of the meta stuff and arel in general.

  • John McAliley

    John McAliley July 14th, 2010 @ 02:12 PM

    • Assigned user set to “Emilio Tagua”

    oops.. looks like I accidentally wiped out assigned user.. setting it back to Emilio

  • Daniel Guettler

    Daniel Guettler July 14th, 2010 @ 02:44 PM

    • Assigned user cleared.

    I did some more testing and yes Arel::SqlCompiler adds to the total run time e.g.

    Test case: puts Benchmark.measure{5000.times{User.where(:id => (rand * 1000 + 1).to_i)[0] }}
    
    Rails 3 Edge & Ruby 1.9.1
    ========================================================
    Base case (unmodified code) total run time: 2.25
    Replace call to compiler with static sql:   1.33
    Replace to_a with static return value (this doesn't hit the database): 0.27
    

    However I also compared run time for basic calls to User.find_by_sql and ActiveRecord::Base.connection.execute and I'm already seeing almost twice as long runtimes there between Rails 2.3.5 and Rails 3 Edge. Note: my database is actually empty while running these tests.

    
    Rails 3 Edge
    ========================================================
    irb(main):007:0> puts Benchmark.measure{5000.times{User.find_by_sql("Select * from users where id = #{(rand * 1000 + 1).to_i}")[0] }}
      1.120000   0.080000   1.200000 (  1.212694)
    => nil
    irb(main):008:0> puts Benchmark.measure{5000.times{ActiveRecord::Base.connection.execute("Select * from users where id = #{(rand * 1000 + 1).to_i}") }}
      0.950000   0.080000   1.030000 (  1.037620)
    => nil
    
    
    Rails 2.3.5
    ========================================================
    >> puts Benchmark.measure{5000.times{User.find_by_sql("Select * from users where id = #{(rand * 1000 + 1).to_i}")[0] }}
      0.650000   0.080000   0.730000 (  0.750073)
    => nil
    >> puts Benchmark.measure{5000.times{ActiveRecord::Base.connection.execute("Select * from users where id = #{(rand * 1000 + 1).to_i}") }}
      0.490000   0.070000   0.560000 (  0.567267)
    => nil
    
  • Daniel Guettler

    Daniel Guettler July 14th, 2010 @ 02:45 PM

    • Assigned user set to “Emilio Tagua”
  • Pratik

    Pratik July 16th, 2010 @ 12:22 AM

    @drjoke : Removing the old API won't have any affect on the performance. Under the hood, old API is using the new finder methods already ( Check Relation#apply_finder_options ).

    @Daniel : Difference in find_by_sql time is because of an instrumentation call in AbstractAdapter#log. If you remove ActiveSupport::Notifications stuff from there, you'd see completely different results.

    Finder performance hit in AR 3 is mainly because of ARel and ActiveSupport::Notifications to a very minor extent. So, patches please :)

  • Daniel Guettler

    Daniel Guettler July 18th, 2010 @ 04:53 AM

    @Patrik : Unfortunately you're right. I could squeeze out a tiny performance gain by changing the code a little, but most of the remaining difference comes from @block.call(*args) in the Subscribers 'push' method.

    Test case & results:

    Base case Rails 2.3.5
    =================================================
    >> puts Benchmark.measure{50000.times{ActiveRecord::Base.connection.execute("Select * from users where id = 1") }}
      6.180000   0.760000   6.940000 (  7.126519)
    
    Rails 3 without modifications
    =================================================
    irb(main):001:0> puts Benchmark.measure{50000.times{ActiveRecord::Base.connection.execute("Select * from users where id = 1") }}
      9.110000   0.790000   9.900000 (  9.914706)
    
    Rails 3 with modified code
    =================================================
    irb(main):001:0> puts Benchmark.measure{50000.times{ActiveRecord::Base.connection.execute("Select * from users where id = 1") }}
      8.860000   0.780000   9.640000 (  9.661421)
    
    Rails 3 with commented @block.call(*args) and modified code
    =================================================
    irb(main):001:0> puts Benchmark.measure{50000.times{ActiveRecord::Base.connection.execute("Select * from users where id = 1") }}
      6.930000   0.780000   7.710000 (  7.718084)
    
  • Daniel Guettler

    Daniel Guettler July 18th, 2010 @ 05:14 AM

    Well you can get a little but more performance out of it if you modify the log_subscriber 'sql' method a tiny bit.

    Rails 3 with modified log_subscriber
    =================================================
    irb(main):001:0> puts Benchmark.measure{50000.times{ActiveRecord::Base.connection.execute("Select * from users where id = 1") }}
      7.540000   0.780000   8.320000 (  8.351694)
    
  • José Valim

    José Valim July 18th, 2010 @ 09:22 AM

    Daniel, could you wrap up these changes in a patch following the guidelines here: https://rails.lighthouseapp.com/projects/8994/sending-patches

    Thanks!

  • Daniel Guettler

    Daniel Guettler July 18th, 2010 @ 01:02 PM

    Ok, attached patch against the latest version of rails master following the above guidelines.
    Latest version now comes pretty close to the 2.3.5 base case:

    Rails 2.3.5
    =================================================
    >> puts Benchmark.measure{50000.times{ActiveRecord::Base.connection.execute("Select * from users where id = 1") }}
      6.100000   0.740000   6.840000 (  6.852199)
    
    Rails 3 without patch applied
    =================================================
    irb(main):002:0> puts Benchmark.measure{50000.times{ActiveRecord::Base.connection.execute("Select * from users where id = 1") }}
      7.560000   0.760000   8.320000 (  8.335182)
    
    Rails 3 with patch applied
    =================================================
    irb(main):001:0> puts Benchmark.measure{50000.times{ActiveRecord::Base.connection.execute("Select * from users where id = 1") }}
      6.370000   0.740000   7.110000 (  7.106953)
    
  • drjoke

    drjoke July 18th, 2010 @ 02:46 PM

    @daniel Can you please try the new patch on ActiveRecord.find rather than the pre-baked SQL statements? Would this change have any impact? For example, please try:

    puts Benchmark.measure{5000.times{User.find :first, :conditions => ["id = ?", (rand * 1000 + 1).to_i]}}
    
  • Aaron Patterson

    Aaron Patterson July 19th, 2010 @ 07:20 PM

    @daniel Can you rebase your patch against master, and I'll apply it?

  • Daniel Guettler

    Daniel Guettler July 19th, 2010 @ 07:34 PM

    @aaron : I attached updated patch.

    @drjoke : no this doesn't have any impact on find yet. Performance hit in find comes more or less completely from Arel

  • Repository

    Repository July 19th, 2010 @ 07:46 PM

    (from [38f0161aabb302550e1522cb62d19e54d448be9b]) Minor performance improvment in notifications/fanout and active_record/log_subscriber [#5098 state:open] http://github.com/rails/rails/commit/38f0161aabb302550e1522cb62d19e...

  • Miles Egan

    Miles Egan July 19th, 2010 @ 08:21 PM

    I was able to shave a little of the overhead off the arel code by explicitly defining all the methods that are called via method_missing in arel/lib/arel/engines/sql/relations/compiler.rb, but it didn't seem like it was enough to really make it worth it.

  • Pratik

    Pratik July 19th, 2010 @ 08:47 PM

    Miles, I think that'd still be a good patch. Could just use class_eval or delegate to declare those methods.

  • Miles Egan

    Miles Egan July 19th, 2010 @ 08:58 PM

    Ok I'll see if I can put together a good patch for that.

  • Daniel Guettler

    Daniel Guettler July 19th, 2010 @ 08:59 PM

    I don't think it is needed to define all the methods. What I tried to do before with little performance impact was to call the methods directly on the relation and change the method there from protected to public. e.g instead of

    
          def select_sql
            query = build_query \
              "SELECT     #{select_clauses.join(', ')}",
              "FROM       #{from_clauses}",
              (joins(self)                                   unless joins(self).blank? ),
              ("WHERE     #{where_clauses.join(' AND ')}"    unless wheres.blank?      ),
              ("GROUP BY  #{group_clauses.join(', ')}"       unless groupings.blank?   ),
              ("HAVING    #{having_clauses.join(' AND ')}"      unless havings.blank?     ),
              ("ORDER BY  #{order_clauses.join(', ')}"       unless orders.blank?      )
              engine.add_limit_offset!(query,{ :limit => taken, :offset => skipped }) if taken || skipped
              query << " #{locked}" unless locked.blank?
              query
          end
    

    you would get something like:

    
          def select_sql
            query = build_query \
              "SELECT     #{relation.select_clauses.join(', ')}",
              "FROM       #{relation.from_clauses}",
              (relation.joins(self)                                   unless relation.joins(self).blank? ),
              ("WHERE     #{relation.where_clauses.join(' AND ')}"    unless relation.wheres.blank?      ),
              ("GROUP BY  #{relation.group_clauses.join(', ')}"       unless relation.groupings.blank?   ),
              ("HAVING    #{relation.having_clauses.join(' AND ')}"   unless relation.havings.blank?     ),
              ("ORDER BY  #{relation.order_clauses.join(', ')}"       unless relation.orders.blank?      )
              engine.add_limit_offset!(query,{ :limit => relation.taken, :offset => relation.skipped }) if relation.taken || relation.skipped
              query << " #{locked}" unless locked.blank?
              query
          end
    

    which call all the functions directly on the relation which is what method_missing did before. It saves you the extra method call if you define each method in the compile.

  • Miles Egan

    Miles Egan July 19th, 2010 @ 09:09 PM

    I did basically the same thing Daniel. It seemed to shave a little overhead off but not much.

    As far as I can tell there's not a single big bottleneck in the Arel code. It's just operating at a higher level of abstraction than the old AR code and that comes at a price, at least in this case.

    I think it would be good to consider a few more benchmarks than just this one trivial case though. It's not clear to me how the performance of Rails 2 and Rails 3 compare in this respect over a lot of real-world use cases.

  • Daniel Guettler

    Daniel Guettler July 19th, 2010 @ 09:42 PM

    Follow up on my last post adding some benchmarks

    
    Base case Rails 2.3.5
    =================================================
    >> puts Benchmark.measure{5000.times{User.find(1)}}
      1.420000   0.130000   1.550000 (  2.498500)
    
    Rails 3 with method_missing
    =================================================
    irb(main):001:0> puts Benchmark.measure{5000.times{User.find(1)}}
      2.240000   0.110000   2.350000 (  2.441295)
    
    Rails 3 calling methods directly on relation
    =================================================
    irb(main):001:0> puts Benchmark.measure{5000.times{User.find(1)}}
      2.160000   0.110000   2.270000 (  2.298687)
    
    Rails 3 with compiler.select_sql return static sql
    =================================================
    irb(main):002:0> puts Benchmark.measure{5000.times{User.find(1)}}
      1.660000   0.080000   1.740000 (  1.820115)
    
  • Repository

    Repository July 19th, 2010 @ 09:44 PM

    (from [202fb79e8686ee127fe49497c979cfc9c9d985d5]) reusing the time instrumentation from the instrumenter rather than Benchmark. [#5098 state:open] http://github.com/rails/rails/commit/202fb79e8686ee127fe49497c979cf...

  • Miles Egan

    Miles Egan July 19th, 2010 @ 09:50 PM

    Daniel I think it's worthwhile to run each of your benchmark tests at least 10 times and take some averages. When I do this on my machine I get a fairly wide spread of results so I think one run isn't enough to judge the effectiveness of a patch.

  • Aaron Patterson

    Aaron Patterson July 19th, 2010 @ 09:53 PM

    I've just pushed a commit that should get the performance more in line with 2.3.x. Please test out your benchmarks!

    Here is the benchmark I've been using:

    require 'rubygems'
    require 'sqlite3'
    require 'active_support'
    require 'active_record'
    require 'benchmark'
    
    p ActiveRecord::VERSION::STRING
    
    ActiveRecord::Base.establish_connection(:adapter => 'sqlite3',
                                            :database => ':memory:')
    
    ActiveRecord::Base.connection.execute <<-eosql
    CREATE TABLE "posts" ("id" INTEGER PRIMARY KEY AUTOINCREMENT NOT NULL, "title" varchar(255), "body" text, "created_at" datetime, "updated_at" datetime);
    eosql
    
    class Post < ActiveRecord::Base; end
    class << Post.connection
      public :log
    end
    
    10_000.step(100_000, 10_000) do |n|
      puts "N: #{n}"
      puts "######################"
      Benchmark.bm(11) do |x|
        x.report("find_by_sql") do
          n.times do
            Post.find_by_sql(
              "Select * from posts where id = #{(rand * 1000 + 1).to_i}").first
          end
        end
    
        x.report("execute") do
          n.times do
            ActiveRecord::Base.connection.execute(
              "Select * from posts where id = #{(rand * 1000 + 1).to_i}").first
          end
        end
    
        x.report("log") do
          n.times do
            Post.connection.log("hello", "world") do
            end
          end
        end
      end
    end
    

    I've graphed the performance here:
    my graph

    After my refactor, the "log" method performs at the same speed as 2.3.x, and the find_by_sql() method performs faster than 2.3.x. I can't speak for the performance of arel, but maybe that should be a different ticket?

  • Daniel Guettler

    Daniel Guettler July 19th, 2010 @ 10:41 PM

    Aaron I can confirm even better performance after latest patches

    
    Rails 3 before 'Minor performance improvment in notifications/fanout and active_record/log_subscriber'
    =================================================
    irb(main):001:0> puts Benchmark.measure{50000.times{ActiveRecord::Base.connection.execute("Select * from users where id = 1") }}
      7.490000   0.800000   8.290000 (  8.292456)
    
    Rails 3 after 'Minor performance improvment in notifications/fanout and active_record/log_subscriber'
    =================================================
    irb(main):001:0> puts Benchmark.measure{50000.times{ActiveRecord::Base.connection.execute("Select * from users where id = 1") }}
      6.440000   0.740000   7.180000 (  7.182058)
    
    Rails 3 after 'reusing the time instrumentation from the instrumenter rather than Benchmark'
    =================================================
    irb(main):001:0> puts Benchmark.measure{50000.times{ActiveRecord::Base.connection.execute("Select * from users where id = 1") }}
      5.870000   0.720000   6.590000 (  6.605073)
    
  • Aaron Patterson

    Aaron Patterson July 19th, 2010 @ 10:51 PM

    @Daniel Can you compare against rails 2.3.x? I think we should close this ticket, but I want to get opinions from others first. :-D

  • Daniel Guettler

    Daniel Guettler July 19th, 2010 @ 11:01 PM

    My original tests for Rails 2.3.5 came out at 6.1 however today they ran slightly faster and come out at 5.0

    Rails 2.3.5
    =================================================
    >> puts Benchmark.measure{50000.times{ActiveRecord::Base.connection.execute("Select * from users where id = 1") }}
      5.000000   0.720000   5.720000 (  5.771005)
    

    I think this is pretty close. Definitely much better than the 7.x we had in the beginning.

    Also did some more testing against the latest version of Arel results come slightly closer to Rails 2.3.5

    Rails 2.3.5
    =================================================
    >> 1.upto(10) { puts Benchmark.measure{5000.times{User.find(1)}} }
      1.250000   0.080000   1.330000 (  1.333757)
      1.250000   0.080000   1.330000 (  1.327106)
      1.250000   0.070000   1.320000 (  1.321343)
      1.260000   0.080000   1.340000 (  1.343815)
      1.250000   0.080000   1.330000 (  1.329569)
      1.240000   0.080000   1.320000 (  1.321797)
      1.260000   0.070000   1.330000 (  1.330874)
      1.250000   0.080000   1.330000 (  1.331315)
      1.250000   0.080000   1.330000 (  1.326549)
      1.260000   0.080000   1.340000 (  1.344488)
    
    Rails 3 with latest Arel branch
    =================================================
    irb(main):004:0> 1.upto(10) { puts Benchmark.measure{5000.times{User.find(1)}} }
      2.030000   0.080000   2.110000 (  2.115218)
      2.020000   0.090000   2.110000 (  2.108246)
      1.990000   0.080000   2.070000 (  2.066324)
      2.030000   0.080000   2.110000 (  2.112565)
      2.020000   0.090000   2.110000 (  2.110026)
      2.030000   0.080000   2.110000 (  2.111698)
      1.980000   0.080000   2.060000 (  2.070301)
      2.040000   0.080000   2.120000 (  2.189787)
      2.020000   0.090000   2.110000 (  2.111094)
      1.980000   0.080000   2.060000 (  2.065495)
    
    Rails 3 with Arel 0.4.0 gem
    =================================================
    irb(main):001:0> puts Benchmark.measure{5000.times{User.find(1)}}
      2.240000   0.110000   2.350000 (  2.441295)
    
  • Aaron Patterson

    Aaron Patterson July 19th, 2010 @ 11:12 PM

    Guh. Okay. Still not acceptable speeds. I think we can cut logging out of the picture though and focus on arel. I'll see what I can do.

  • drjoke

    drjoke July 23rd, 2010 @ 12:29 PM

    Been few days. Any updates?

  • José Valim

    José Valim July 23rd, 2010 @ 12:41 PM

    Not beyond the ones already reported here. Patches are welcome.

  • Aaron Patterson

    Aaron Patterson July 23rd, 2010 @ 04:24 PM

    • Assigned user changed from “Emilio Tagua” to “Aaron Patterson”

    @drjoke I'm still working on it.

  • Christos Zisopoulos

    Christos Zisopoulos July 23rd, 2010 @ 11:38 PM

    Having just migrated my current project and seeing it run 4-6 times slower than in 2.3.8, I am a bit surprised Rails 3 is being pushed by the community as production ready.

    A vanilla Rails 3 @{master} app is roughly 3.5 times SLOWER than a 2.3.8 in just about every scenario. I did a side by side setup and comparison here:

    http://gist.github.com/487687

    Being unfamiliar with the internals of arel, I would like to ask if the more knowledgeable chaps here think that 2.3.8 speed is something that can be achieved before the (eventual) release of Rails 3.

    If not, I think that the speed issue should at least be communicated more widely, to prevent people from spending days trying to upgrade their apps only to find out that they go 3 times slower...

  • José Valim

    José Valim July 23rd, 2010 @ 11:45 PM

    Christos Zisopoulos,

    Rails 3 lazy loads a lot of stuff, this means that ActiveRecord and ActionController gets loaded just on the first request. This is why it takes longer (probably ActionView is being loaded).

    Second, benchmarks using development (with cache classes) and considering just one request, are very poor. You need to use benchmarking tools like httperf or apache benchmark to have an average result for a bunch of whole requests.

  • Christos Zisopoulos

    Christos Zisopoulos July 24th, 2010 @ 12:22 AM

    Hi José,

    Sorry. I should have mentioned that even production, and after multiple reloads, it is still as slow...

    I've updated the gist with some httperf results, run in production:

    http://gist.github.com/487687#file_rails3_vs_rails2_httperfd.sh

    Even with a smaller number of seeded posts/tags (200 posts/10 tags) I get this:

    Rails 2.3.8

    Connection time [ms]: min 252.5 avg 320.4 max 633.6 median 295.5 stddev 85.5

    Rails 3.0.0 (standard deviation is high, but tests would take too long for more conns)

    Connection time [ms]: min 826.6 avg 2240.9 max 6342.8 median 1349.5 stddev 2007.7

  • José Valim

    José Valim July 24th, 2010 @ 12:27 AM

    Thanks, this is already much better! Just one thing, be sure to leave the first request out (although I don't think it should change something, probably just the max) and use a good server, as thin/mongrel. We should not use Webrick in such benchmarks! :) Thanks!

  • Christos Zisopoulos

    Christos Zisopoulos July 24th, 2010 @ 12:33 AM

    José,

    Yeah, the important number is the median there.

    I used Webrick 1.3.1 for both environments because I wanted to be sure that no external factor, such as thin interfacing differently with Rack and Rails 3, skewed the results.

    When I get a chance I'll try and get the same version of thin/unicorn running in both environemnts and repeat the benchmarks.

    I still would like to know how serious/difficult to fix this performance issue is, if you have an idea :)

  • José Valim

    José Valim July 24th, 2010 @ 12:39 AM

    We already did a bunch of improvements since beta 4. The only way we can improve it even more is by profiling the app you generated and see if we find any hotspot.

    Btw, taking a look at your script, I saw you are using /posts/index in your requests to a Rails 3 app. Beware that Rails 3 does not include the defaults routes, so you may as well be rendering a 404 page.

  • Christos Zisopoulos

    Christos Zisopoulos July 24th, 2010 @ 12:46 AM

    The controller generator has created

    get 'posts/index'

    in routes.rb, so I am pretty sure I am not hitting a 404 (and I tried it in the browser)

    I can upload tarballs of the apps somewhere, if you need the to do some profiling, but it is probably quicker to follow the steps in the gists to recreate them locally.

    If you have any pointers as to how I could get ruby-prof working with rails 3, I could also give it a go...

  • Yehuda Katz (wycats)

    Yehuda Katz (wycats) July 24th, 2010 @ 02:27 AM

    We spent the past year and a half improving the internals of Rails. Because there is so much new code, there is also lots of obvious, low-hanging optimizations still to be done. We will continue to release pre-releases of Rails that might have unacceptable performance characteristics, and we will continue to improve the performance of the various systems as we move toward 3.0 final.

    Part of the reason for the performance issues are new systems like pervasive instrumentation and escaping by default. We have been able to reduce the impact of some (but not all) of these new systems to almost zero. ActiveRelation is a new system that still needs to undergo significant performance tuning.

    Make no mistake, though: we will not release Rails 3.0 final that is slower, for the common case, than Rails 2.3. In order to achieve this, we need the help of the community to provide us with repeatable benchmarks that demonstrate the specific performance problem that people are encountering. We have some of our own benchmarks and apps, but anything you guys can do would help.

  • Erik Michaels-Ober

    Erik Michaels-Ober August 3rd, 2010 @ 08:36 PM

    • Tag set to performace
  • Aaron Patterson

    Aaron Patterson August 24th, 2010 @ 05:33 AM

    The RC2 was released, so I figure I'd better update this ticket with progress.

    I am currently optimizing simple queries like Post.find(1). The currently release candidate of Arel is approximately 36% faster than before I started playing with it. I was able to get a 36% speed improvement through "superficial" performance improvements. Things like converting to attr_(reader|writer), removing unnecessary conditional tests, using faster methods, removing inject, reducing call stack, etc.

    There are a few issues with Arel that cause it to be slow. Unfortunately, these are due to a fundamental design problem with the current Arel implementation. The problem is kind of long to explain, so I may just blog about it rather than bury it in a ticket. There are probably other "superficial" speed increases I can do, but they are becoming more difficult to find.

    I think that the only real way we can see good improvements is through a fundamental design change. I've already put together an "experimental" branch of ARel to prove my theory. I believe this branch is the only way forward. I've included benchmarks from the experimental branch. It's slightly faster than Rails 2.3.x, and I believe after I've finished making the tests pass, we can improve it to be even faster than 2.3.x.

    performance

    Please help by sending me internet hugs, high fives, best wishes, and patches. I'll continue to move forward and update this ticket as I go along. Thanks for your patience and support! <3 <3 <3

  • Miles Egan

    Miles Egan August 24th, 2010 @ 05:55 AM

    Thanks for your work on this Aaron. I got the same impression from the profiling I did earlier. There's not a single bottleneck in Arel, there's overhead spread throughout the code.

  • iHiD

    iHiD August 24th, 2010 @ 09:19 AM

    • Tag changed from performace to performance

    Thanks for all your work Aaron. Is the experimental branch on GitHub and if so, which one is it? Look forward to reading your blog post on this and looking for patches etc.

  • Dr Nic Williams

    Dr Nic Williams August 25th, 2010 @ 11:54 AM

    Aaron is a champion of the people. I'm not sure exactly what the massive size of that set of people is, but the set includes me.

    Carry on my good man!

    Nic

  • Pratik

    Pratik August 25th, 2010 @ 11:56 AM

    Super awesome work Aaron! Can't wait to see this work in action :)

  • Miles Egan

    Miles Egan August 30th, 2010 @ 02:52 AM

    Did we decide to leave this as is for the 3.0 release?

  • Jeremy Kemper
  • Christos Zisopoulos

    Christos Zisopoulos August 30th, 2010 @ 06:22 PM

    For the record, using my simple app test outlined above, with Rails 3.0.0

      Connection rate: 0.2 conn/s (4849.7 ms/conn, <=1 concurrent connections)
      Connection time [ms]: min 2897.8 avg 4849.7 max 5219.0 median 5004.5 stddev 542.9
    

    And with Rails 2.3.8

      Connection rate: 0.4 conn/s (2745.8 ms/conn, <=1 concurrent connections)
      Connection time [ms]: min 1789.3 avg 2745.8 max 3115.9 median 2854.5 stddev 350.3
    

    Response time has improved since RC4 from 3.5x slower to just under 2x slower

  • Aaron Patterson

    Aaron Patterson September 27th, 2010 @ 05:39 PM

    I've pushed a new version of ARel to github:

    http://github.com/rails/arel

    From my benchmarks, it seems that the performance of ActiveRecord is nearly the same as 2.3.x:

    benchmark

    Unless there are objections, I'd like to close this ticket as "close enough". I will continue to improve the performance of ActiveRecord, but I think those performance improvements must be made inside AR rather than ARel.

  • Wincent Colaiuta

    Wincent Colaiuta September 27th, 2010 @ 06:09 PM

    Did you do any benchmarks for cases other than Post.find(1). Seems an incredibly narrow basis for declaring performance parity.

    Having said that, there's probably no harm in closing the ticket because as you say, performance work is going to continue regardless.

  • Jeremy Kemper

    Jeremy Kemper September 27th, 2010 @ 06:23 PM

    • State changed from “open” to “resolved”
  • Ken Collins

    Ken Collins September 27th, 2010 @ 07:55 PM

    Great news! Was just testing this out for the SQL Server compiler and noticed I could not bundle rails 3-0-stable and arel master using my ENV vars for the path due to the version in Arel still being 1.0.1. I changed lib/arel/version to 2.0.0 and got the local bundle working. Something you may want to change if indeed rails/arel at master is indeed the 2.0 version.

  • Jeremy Kemper

    Jeremy Kemper October 15th, 2010 @ 11:01 PM

    • Milestone set to 3.0.2

Create your profile

Help contribute to this project by taking a few moments to create your personal profile. Create your profile »

Tickets have moved to Github

The new ticket tracker is available at https://github.com/rails/rails/issues

Shared Ticket Bins

Referenced by

Pages