Lock in $30 Savings on PRO—Offer Ends Soon! ⏳

Is Rails Slow?

Is Rails Slow?

Slides for Rails Israel 2014 talk "Is Rails Slow?" http://railsisrael2014.events.co.il/

Akira Matsuda

November 04, 2014
Tweet

More Decks by Akira Matsuda

Other Decks in Programming

Transcript

  1. pp self •name: Akira Matsuda •from: Tokyo, Japan •GitHub: amatsuda

    •Twitter: @a_matsuda https://www.flickr.com/photos/mobyrock/308887106/
  2. log/production.log I, [2014-11-02T00:06:33.728902 #54125] INFO -- : Started GET "/hello"

    for ::1 at 2014-11-02 00:06:33 +0900 I, [2014-11-02T00:06:33.729765 #54125] INFO -- : Processing by HelloController#index as HTML I, [2014-11-02T00:06:33.730733 #54125] INFO -- : Rendered text template (0.0ms) I, [2014-11-02T00:06:33.730917 #54125] INFO -- : Completed 200 OK in 1ms (Views: 0.3ms | ActiveRecord: 0.0ms) I, [2014-11-02T00:06:35.626889 #54125] INFO -- : Started GET "/hello" for ::1 at 2014-11-02 00:06:35 +0900 I, [2014-11-02T00:06:35.627652 #54125] INFO -- : Processing by HelloController#index as HTML I, [2014-11-02T00:06:35.628726 #54125] INFO -- : Rendered text template (0.0ms) I, [2014-11-02T00:06:35.628968 #54125] INFO -- : Completed 200 OK in 1ms (Views: 0.4ms | ActiveRecord: 0.0ms) I, [2014-11-02T00:06:37.267414 #54125] INFO -- : Started GET "/hello" for ::1 at 2014-11-02 00:06:37 +0900 I, [2014-11-02T00:06:37.268206 #54125] INFO -- : Processing by HelloController#index as HTML I, [2014-11-02T00:06:37.269261 #54125] INFO -- : Rendered text template (0.0ms) I, [2014-11-02T00:06:37.269509 #54125] INFO -- : Completed 200 OK in 1ms (Views: 0.3ms | ActiveRecord: 0.0ms) I, [2014-11-02T00:06:38.952585 #54125] INFO -- : Started GET "/hello" for ::1 at 2014-11-02 00:06:38 +0900 I, [2014-11-02T00:06:38.953367 #54125] INFO -- : Processing by HelloController#index as HTML I, [2014-11-02T00:06:38.954396 #54125] INFO -- : Rendered text template (0.0ms) I, [2014-11-02T00:06:38.954621 #54125] INFO -- : Completed 200 OK in 1ms (Views: 0.3ms | ActiveRecord: 0.0ms) I, [2014-11-02T00:06:40.761535 #54125] INFO -- : Started GET "/hello" for ::1 at 2014-11-02 00:06:40 +0900 I, [2014-11-02T00:06:40.762368 #54125] INFO -- : Processing by HelloController#index as HTML I, [2014-11-02T00:06:40.763489 #54125] INFO -- : Rendered text template (0.0ms) I, [2014-11-02T00:06:40.763722 #54125] INFO -- : Completed 200 OK in 1ms (Views: 0.4ms | ActiveRecord: 0.0ms)
  3. log/production.log I, [2014-11-02T00:06:33.728902 #54125] INFO -- : Started GET "/hello"

    for ::1 at 2014-11-02 00:06:33 +0900 I, [2014-11-02T00:06:33.729765 #54125] INFO -- : Processing by HelloController#index as HTML I, [2014-11-02T00:06:33.730733 #54125] INFO -- : Rendered text template (0.0ms) I, [2014-11-02T00:06:33.730917 #54125] INFO -- : Completed 200 OK in 1ms (Views: 0.3ms | ActiveRecord: 0.0ms) I, [2014-11-02T00:06:35.626889 #54125] INFO -- : Started GET "/hello" for ::1 at 2014-11-02 00:06:35 +0900 I, [2014-11-02T00:06:35.627652 #54125] INFO -- : Processing by HelloController#index as HTML I, [2014-11-02T00:06:35.628726 #54125] INFO -- : Rendered text template (0.0ms) I, [2014-11-02T00:06:35.628968 #54125] INFO -- : Completed 200 OK in 1ms (Views: 0.4ms | ActiveRecord: 0.0ms) I, [2014-11-02T00:06:37.267414 #54125] INFO -- : Started GET "/hello" for ::1 at 2014-11-02 00:06:37 +0900 I, [2014-11-02T00:06:37.268206 #54125] INFO -- : Processing by HelloController#index as HTML I, [2014-11-02T00:06:37.269261 #54125] INFO -- : Rendered text template (0.0ms) I, [2014-11-02T00:06:37.269509 #54125] INFO -- : Completed 200 OK in 1ms (Views: 0.3ms | ActiveRecord: 0.0ms) I, [2014-11-02T00:06:38.952585 #54125] INFO -- : Started GET "/hello" for ::1 at 2014-11-02 00:06:38 +0900 I, [2014-11-02T00:06:38.953367 #54125] INFO -- : Processing by HelloController#index as HTML I, [2014-11-02T00:06:38.954396 #54125] INFO -- : Rendered text template (0.0ms) I, [2014-11-02T00:06:38.954621 #54125] INFO -- : Completed 200 OK in 1ms (Views: 0.3ms | ActiveRecord: 0.0ms) I, [2014-11-02T00:06:40.761535 #54125] INFO -- : Started GET "/hello" for ::1 at 2014-11-02 00:06:40 +0900 I, [2014-11-02T00:06:40.762368 #54125] INFO -- : Processing by HelloController#index as HTML I, [2014-11-02T00:06:40.763489 #54125] INFO -- : Rendered text template (0.0ms) I, [2014-11-02T00:06:40.763722 #54125] INFO -- : Completed 200 OK in 1ms (Views: 0.4ms | ActiveRecord: 0.0ms)
  4. end

  5. I have 30 minutes today. •I think I still have

    time to do one more benchmarking.
  6. generate scaffold % rails g scaffold user name account email

    phone zip address birthday:datetime age:integer company bio:text admin:boolean % RAILS_ENV=production rake db:migrate
  7. seeds date_range = Date.parse('1960/1/1').. (10000.days.since(Date.parse('1960/1/1'))) [*1..10000].each do |i| User.create! name:

    "User %05d" % i, account: "user_%05d" % i, email: "user%[email protected]" % i, phone: "%011d" % i, zip: "%03d" % (i / 10), address: "#{i}-#{i} Tokyo, Japan" % i, birthday: rand(date_range), age: i / 365, company: "#{i} Signals", bio: 'Lorem ipsum dolor sit amet, consectetur adipisicing elit, sed do eiusmod tempor incididunt ut labore et dolore magna aliqua. Ut enim ad minim veniam, quis nostrud exerci tation ullamco laboris nisi ut aliquip ex ea commodo consequat. Duis aute irure dolor in reprehenderit in voluptate velit esse cillum dolore eu fugiat nulla pariatur. Excepteur sint occaecat cupidatat non proiden t, sunt in culpa qui officia deserunt mollit anim id est laborum.', admin: true end
  8. % tail -f log/production.log | grep Completed • 4378ms (Views:

    4297.7ms | ActiveRecord: 71.5ms) • 4548ms (Views: 4492.5ms | ActiveRecord: 55.0ms) • 4768ms (Views: 4686.3ms | ActiveRecord: 81.2ms) • 4708ms (Views: 4629.7ms | ActiveRecord: 77.7ms) • 4625ms (Views: 4566.1ms | ActiveRecord: 58.3ms)
  9. Getting rid of the layout and assets class UsersController <

    ApplicationController before_action :set_user, only: [:show, :edit, :update, :destroy] + layout :false ...
  10. Without layout • 4807ms (Views: 4730.6ms | ActiveRecord: 75.4ms) •

    4712ms (Views: 4638.6ms | ActiveRecord: 72.8ms) • 4453ms (Views: 4378.3ms | ActiveRecord: 74.2ms) • 4665ms (Views: 4575.6ms | ActiveRecord: 88.5ms) • 4785ms (Views: 4691.0ms | ActiveRecord: 93.1ms)
  11. Takes so much time for rendering the view (?) •@users.each

    is called in the view •So the query execution time was included in the view rendering time
  12. to_a the relation in the controller def index - @users

    = User.all + @users = User.all.to_a end
  13. to_a in the controller • 4513ms (Views: 4280.1ms | ActiveRecord:

    82.9ms) • 5050ms (Views: 4808.8ms | ActiveRecord: 84.6ms) • 4668ms (Views: 4416.8ms | ActiveRecord: 88.7ms) • 4405ms (Views: 4169.9ms | ActiveRecord: 79.0ms) • 4419ms (Views: 4183.9ms | ActiveRecord: 81.6ms)
  14. Copying files from the Rails app % cp RAILS_APP/db/ production.sqlite3

    SINATRA_APP/ % cp RAILS_APP/app/views/users/ index.html.haml SINATRA_APP/views/ index.haml
  15. views/index.haml %td= user.company %td= user.bio %td= user.admin - %td= link_to

    'Show', user - %td= link_to 'Edit', edit_user_path(user) - %td= link_to 'Destroy', user, :method => :delete, :data => { :confirm => 'Are you sure?' } - -%br - -= link_to 'New User', new_user_path
  16. Result D, [2014-11-03T17:14:49.041718 #36502] DEBUG -- : User Load (52.4ms)

    SELECT "users".* FROM "users" ::1 - - [03/Nov/2014 17:14:49] "GET /users HTTP/1.1" 200 7318342 0.9010 localhost - - [03/Nov/2014:17:14:48 JST] "GET /users HTTP/1.1" 200 7318342 - -> /users D, [2014-11-03T17:15:15.876042 #36502] DEBUG -- : User Load (54.9ms) SELECT "users".* FROM "users" ::1 - - [03/Nov/2014 17:15:16] "GET /users HTTP/1.1" 200 7318342 0.8763 localhost - - [03/Nov/2014:17:15:15 JST] "GET /users HTTP/1.1" 200 7318342 - -> /users D, [2014-11-03T17:15:18.832111 #36502] DEBUG -- : User Load (51.4ms) SELECT "users".* FROM "users" ::1 - - [03/Nov/2014 17:15:19] "GET /users HTTP/1.1" 200 7318342 1.0335 localhost - - [03/Nov/2014:17:15:18 JST] "GET /users HTTP/1.1" 200 7318342
  17. Copying the modified template back to the Rails version %

    cp SINATRA_APP/views/index.haml RAILS_APP/app/views/users/ index.html.haml
  18. Rails without the links • 1642ms (Views: 1411.0ms | ActiveRecord:

    73.6ms) • 1712ms (Views: 1500.6ms | ActiveRecord: 59.8ms) • 1644ms (Views: 1432.0ms | ActiveRecord: 55.6ms) • 1751ms (Views: 1503.9ms | ActiveRecord: 72.1ms) • 1741ms (Views: 1465.9ms | ActiveRecord: 83.0ms)
  19. Rails without the links •1.6 ʙ 1.8 seconds •Used to

    be 4.4ʙ 5.0 seconds with the links
  20. GC

  21. I heard Ruby GC is slow •Is the GC happening

    here? •How does it impact the performance?
  22. Tracing the AR query and the view rendering def index

    - @users = User.all.to_a + GC::Tracer.start_logging(Rails.root.join('tmp/gc.txt').to_s) do + @users = User.all.to_a + render + end end
  23. You'll get an output like this each time when GC

    happens • 550643500349 gc_end_s 56 2734 2734 0 1114375 0 0 457777 2734 0 8743696 7629321 6319200 27416576 40 16 10739 9754 641697 1017174 10477472 21452666 0 newobj 0 0 8971240 528767 230092800 0 0 0 65924 3 0 1 10 186 47 5 1317 625 • 550643568591 gc_start 57 2734 2734 0 1114375 0 0 457777 2734 0 8743696 7629321 6319200 27416576 40 16 10739 9754 641697 1017174 10477472 21452666 shady newobj 0 0 8971257 528772 230092800 0 0 0 65924 3 0 1 10 186 47 5 1317 625 • 550867572379 gc_end_m 57 2734 2734 0 1114375 0 0 457777 2734 0 8743696 7629321 6319200 27416576 40 17 13485 9754 664601 1017174 10477472 21452666 shady newobj 0 0 9057429 528841 230092800 0 0 0 65924 3 0 1 10 186 47 5 1317 634
  24. Results(GC.disable) • 1524ms (Views: 1319.9ms | ActiveRecord: 60.4ms) • 1568ms

    (Views: 1363.6ms | ActiveRecord: 58.8ms) • 1547ms (Views: 1342.0ms | ActiveRecord: 60.9ms) • 1597ms (Views: 1389.1ms | ActiveRecord: 62.0ms) • 1650ms (Views: 1437.1ms | ActiveRecord: 66.5ms)
  25. Fact •Disabling Ruby GC improves the Rails app performance about

    10% •The GC overhead used to be like 30% •It's really getting better recently
  26. Recent GC improvements •1.9.3: Lazy Sweep (@nari3) •2.0 : Bitmap

    Marking (@nari3) •2.1 : RGen GC (@ko1) •2.2 : Incremental GC (@ko1), 2 age RGenGC (@ko1), Symbol GC (@nari3)
  27. At RubyKaigi this year "Rails 4.2 is going to be

    the fastest Rails ever." @tenderlove
  28. Results • 1842ms (Views: 1450.1ms | ActiveRecord: 61.5ms) • 1908ms

    (Views: 1505.3ms | ActiveRecord: 60.8ms) • 1998ms (Views: 1590.2ms | ActiveRecord: 62.8ms) • 1948ms (Views: 1531.7ms | ActiveRecord: 63.2ms) • 1984ms (Views: 1561.9ms | ActiveRecord: 65.9ms)
  29. Let's see what's happening •Aaron said he changed AR a

    lot, but what's actually happening when calling User.all.to_a ? •Let's see which methods were called.
  30. Tracing the AR query def index - @users = User.all.to_a

    + calls = [] + trace = TracePoint.new(:call) do |tp| + calls << [tp.defined_class, tp.method_id, tp.lineno] + end + trace.enable + @users = User.all.to_a + trace.disable + pp calls.group_by(&:itself).map {|k, v| {k => v.length}}.sort_by {|h| -h.values.first} end
  31. trace output (4.2) {[ActiveRecord::Attribute, :initialize, 25]=>140000}, {[#<Class:ActiveRecord::Attribute>, :from_database, 4]=>140000}, {[ActiveRecord::AttributeMethods::ClassMethods,

    :de ne_attribute_methods, 79]=>20000}, {[ActiveRecord::ModelSchema::ClassMethods, :inheritance_column, 186]=>20000}, {[ActiveSupport::Callbacks, :_run_callbacks, 86]=>20000}, {[ActiveSupport::Callbacks::CallbackChain, :empty?, 488]=>20000}, {[ActiveRecord::AttributeMethods::PrimaryKey::ClassMethods, :primary_key, 72]=>10014}, {[Object, :present?, 23]=>10001}, {[ActiveRecord::Persistence::ClassMethods, :instantiate, 66]=>10000}, {[#<Class:ActiveRecord::Base>, :_ nd_callbacks, 86]=>10000}, {[ActiveRecord::AttributeSet::Builder, :add_uninitialized_attributes, 25]=>10000}, {[ActiveRecord::AttributeSet, :initialize, 7]=>10000},
  32. trace output (4.1) {[ActiveSupport::Callbacks, :run_callbacks, 79]=>20001}, {[ActiveSupport::Callbacks::CallbackChain, :empty?, 485]=>20001}, {[ActiveRecord::ModelSchema::ClassMethods,

    :inheritance_column, 165]=>20000}, {[ActiveRecord::AttributeMethods::PrimaryKey::ClassMethods, :primary_key, 71]=>10028}, {[Object, :present?, 23]=>10001}, {[ActiveRecord::ModelSchema::ClassMethods, :decorate_columns, 230]=>10001}, {[ActiveRecord::Persistence::ClassMethods, :instantiate, 49]=>10000}, {[#<Class:ActiveRecord::Base>, :_ nd_callbacks, 86]=>10000}, {[ActiveRecord::Base, :_ nd_callbacks, 106]=>10000}, {[ActiveRecord::AttributeMethods::ClassMethods, :de ne_attribute_methods, 70]=>10000}, {[ActiveRecord::Core, :init_internals, 431]=>10000}, {[ActiveRecord::Persistence::ClassMethods, :discriminate_class_for_record,
  33. trace output (4.2) {[ActiveRecord::Attribute, :initialize, 25]=>140000}, {[#<Class:ActiveRecord::Attribute>, :from_database, 4]=>140000}, {[ActiveRecord::AttributeMethods::ClassMethods,

    :de ne_attribute_methods, 79]=>20000}, {[ActiveRecord::ModelSchema::ClassMethods, :inheritance_column, 186]=>20000}, {[ActiveSupport::Callbacks, :_run_callbacks, 86]=>20000}, {[ActiveSupport::Callbacks::CallbackChain, :empty?, 488]=>20000}, {[ActiveRecord::AttributeMethods::PrimaryKey::ClassMethods, :primary_key, 72]=>10014}, {[Object, :present?, 23]=>10001}, {[ActiveRecord::Persistence::ClassMethods, :instantiate, 66]=>10000}, {[#<Class:ActiveRecord::Base>, :_ nd_callbacks, 86]=>10000}, {[ActiveRecord::AttributeSet::Builder, :add_uninitialized_attributes, 25]=>10000}, {[ActiveRecord::AttributeSet, :initialize, 7]=>10000},
  34. app/controllers/ users_controller.rb def index - @users = User.all.to_a + StackProf.run(mode:

    :cpu, out: 'tmp/ stackprof-cpu-ar.dump') do + @users = User.all.to_a + end end
  35. Rails 4.2 (GC.disabled) ================================== Mode: cpu(1000) Samples: 376 (0.00% miss

    rate) GC: 0 (0.00%) ================================== TOTAL (pct) SAMPLES (pct) FRAME 131 (34.8%) 131 (34.8%) ActiveRecord::Attribute#initialize 58 (15.4%) 58 (15.4%) block in SQLite3::Statement#each 176 (46.8%) 42 (11.2%) block in ActiveRecord::AttributeSet::Builder#build_attributes_from_values 39 (10.4%) 39 (10.4%) block in ActiveRecord::Result#hash_rows 16 (4.3%) 16 (4.3%) block in ActiveRecord::AttributeSet::Builder#add_uninitialized_attributes 12 (3.2%) 12 (3.2%) NilClass#blank?
  36. So, I started creating "hamlx" •A faster Haml fork •Optimized

    for Rails •IOW requires Rails •(planning to be html_safe by default) •(still in progress) •(not published yet)
  37. hamlx • 1616ms (Views: 1386.4ms | ActiveRecord: 69.1ms) • 1606ms

    (Views: 1384.0ms | ActiveRecord: 77.5ms) • 1576ms (Views: 1303.2ms | ActiveRecord: 76.9ms) • 1545ms (Views: 1303.1ms | ActiveRecord: 68.5ms) • 1585ms (Views: 1341.6ms | ActiveRecord: 65.3ms)
  38. hamlx •Renderes 10ʙ20% faster than current haml gem • (still

    slower than slim, I guess...) •Will be shipped :soon:
  39. Conclusion • Ruby is getting faster • Rails is getting

    faster • Now we have tools to investigate what's slow • URL helpers are extremely slow • Haml is slow • A faster Haml fork is coming soon
  40. end