Comments and changes to this ticket

• You flagged this item as spam.
  

  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.

• You flagged this item as spam.
  

  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?

• You flagged this item as spam.
  

  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)

• You flagged this item as spam.
  

  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.

• You flagged this item as spam.
  

  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.

• You flagged this item as spam.
  

  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)
  

• You flagged this item as spam.
  

  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)
  

• You flagged this item as spam.
  

  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?

• You flagged this item as spam.
  

  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)
  

• You flagged this item as spam.
  

  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?

• You flagged this item as spam.
  

  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.

• You flagged this item as spam.
  

  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

• You flagged this item as spam.
  

  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?

• You flagged this item as spam.
  

  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"
  

• You flagged this item as spam.
  

  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.

• You flagged this item as spam.
  

  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)
  

• You flagged this item as spam.
  

  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 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?

• You flagged this item as spam.
  

  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.

  • prof2.txt 38.6 KB
  • prof3.txt 65.6 KB
• 

  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.

• You flagged this item as spam.
  

  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.

• You flagged this item as spam.
  

  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?

• You flagged this item as spam.
  

  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.

  • rails3_rails2_find_profile.xls 98.5 KB

• You flagged this item as spam.
  

  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

• You flagged this item as spam.
  

  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
  

• You flagged this item as spam.
  

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

  • Assigned user set to “Emilio Tagua”
• 

  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 :)

• You flagged this item as spam.
  

  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)
  

  • fanout.patch 1 KB

• You flagged this item as spam.
  

  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)
  

  • log_subscriber.patch 475 Bytes
• 

  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!

• You flagged this item as spam.
  

  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)
  

  • minor_performance_improvement.patch 2 KB

• You flagged this item as spam.
  

  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 July 19th, 2010 @ 07:20 PM

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

• You flagged this item as spam.
  

  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

  • minor_performance_improvement.patch 2 KB
• 

  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...

• You flagged this item as spam.
  

  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 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.

• You flagged this item as spam.
  

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

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

• You flagged this item as spam.
  

  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.

• You flagged this item as spam.
  

  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.

• You flagged this item as spam.
  

  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 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...

• You flagged this item as spam.
  

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

  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?

• You flagged this item as spam.
  

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

• You flagged this item as spam.
  

  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 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.

• You flagged this item as spam.
  

  drjoke July 23rd, 2010 @ 12:29 PM

  Been few days. Any updates?

• 

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

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

• 

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

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

  @drjoke I'm still working on it.

• You flagged this item as spam.
  

  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 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.

• You flagged this item as spam.
  

  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 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!

• You flagged this item as spam.
  

  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 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.

• You flagged this item as spam.
  

  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) 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.

• You flagged this item as spam.
  

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

  • Tag set to “performace”
• 

  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.

  

  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

• You flagged this item as spam.
  

  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.

• You flagged this item as spam.
  

  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.

• You flagged this item as spam.
  

  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 August 25th, 2010 @ 11:56 AM

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

• You flagged this item as spam.
  

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

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

• 

  Jeremy Kemper August 30th, 2010 @ 04:10 AM

  • Milestone cleared.

  [bulk edit]

• You flagged this item as spam.
  

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

  

  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.

• You flagged this item as spam.
  

  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 September 27th, 2010 @ 06:23 PM

  • State changed from “open” to “resolved”

• You flagged this item as spam.
  

  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 October 15th, 2010 @ 11:01 PM

  • Milestone set to “3.0.2”

  [bulk edit]