Is Rails Slow?

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

Transcript

2. pp self •name: Akira Matsuda •from: Tokyo, Japan •GitHub: amatsuda •Twitter: @a_matsuda https://www.flickr.com/photos/mobyrock/308887106/
6. begin
7. Is Rails slow?
8. You may have heard a rumor that...
9. Rails is slow. https://www.flickr.com/photos/naturald/429267360
10. Really? Do you think it's true?
11. If so, •where is it slow? •how is it slow? •why is it slow?
12. Let's benchmark!
14. 'JHIUʂ Sinatra
15. Round 1
16. A very simple hello app
17. rails new % rails new rails_israel
18. config/secret.yml production: secret_key_base: something
19. generate controller % rails g controller hello index
20. app/controllers/ hello_controller.rb class HelloController < ApplicationController def index + render text: 'Hello, Israel!' end end
21. rails server % rails s -e production
22. How can we measure?
23. How can we measure? •Let's do it simple.
24. Requesting from the browser
25. The rule •Request 5 times and take the average
26. Results: Rails hello •10ms •9ms •8ms •9ms •9ms •=> 9.0ms
27. Gemfile source 'https://rubygems.org/' gem 'sinatra'
28. Hello from Sinatra require 'bundler/setup' Bundler.require get '/hello' do 'Hello, Israel!' end
29. Starting up Sinatra % RACK_ENV=production bundle ex ruby app.rb
30. Sinatra •9ms •8ms •8ms •7ms •8ms •=> 8.0ms
31. Fact •Rails is 1ms slower than Sinatra.
32. Full-stack vs Micro A micro-framework + 1ms = A full-stack framework
33. In Rails production.log
34. 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)
35. 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)
36. Only 1ms in the Rails land • 1ms (Views: 0.3ms | ActiveRecord: 0.0ms)
37. Acceptable?
38. Acceptable? •To me, yes.
39. Conclusion
40. Conclusion "Rails is NOT slow."
41. end
43. Actually,
44. I have 30 minutes today.
45. I have 30 minutes today. •I think I still have time to do one more benchmarking.
46. So, let's benchmark a little bit more realworld-ish app
47. Round 2
48. A scaffold app
49. The Rails scaffold •What we need to do rst before running the scaffold is...
50. To bundle haml •Of course everyone loves Haml, right?
51. Gemfile +gem 'haml-rails'
52. 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
53. Preparing 10,000 records •Via seeds
54. 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%05d@example.com" % 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
55. seeds % RAILS_ENV=production rake db:seed
56. Let's startup the server •And tail the log le
57. % 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)
58. But it causes some errors concerning the assets
59. Getting rid of the layout and assets class UsersController < ApplicationController before_action :set_user, only: [:show, :edit, :update, :destroy] + layout :false ...
60. 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)
61. No big difference
62. 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
63. to_a the relation in the controller def index - @users = User.all + @users = User.all.to_a end
64. 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)
65. Rails •4.4ʙ 5.0 seconds •In this case, 98% is consumed in Haml
66. Sinatra's turn
67. Enabling AR and Haml
68. Gemfile gem 'sinatra' +gem 'sinatra-activerecord' +gem 'sqlite3' +gem 'haml'
69. Connecting to DB +set :database, {adapter: 'sqlite3', database: 'production.sqlite3'} +class User < ActiveRecord::Base; end
70. Implementing /users + +get '/users' do + @users = User.all.to_a + haml :index +end
71. 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
72. Result NoMethodError - unde ned method `link_to' for #<Sinatra::Application: 0x007fa4b5405e50>:
73. Getting rid of url helpers •link_to •edit_user_path •new_user_path
74. 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
75. 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
76. Sinatra •0.9068s •0.9104s •1.0093s •0.9260s •0.9444s
77. Sinatra •0.9 ʙ 1.0 second
78. Rails •4.4ʙ 5.0 seconds
79. OMG! Sinatra is so fast! •Awesome work, Konstantin!
80. But, wait •The templates were little bit different
81. Copying the modified template back to the Rails version % cp SINATRA_APP/views/index.haml RAILS_APP/app/views/users/ index.html.haml
82. 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)
83. Rails without the links •1.6 ʙ 1.8 seconds •Used to be 4.4ʙ 5.0 seconds with the links
84. Fact •60%ʙ 70% of the response time was consumed for drawing links!
85. It's getting closer to Sinatra speed •But still a little bit slow
86. How can we make it faster?
87. GC
88. I heard Ruby GC is slow •Is the GC happening here? •How does it impact the performance?
89. Inspecting the GC •gc_tracer gem by @ko1 • https://github.com/ko1/gc_tracer •Just bundle the gem, and...
90. 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
91. 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
92. What if we totally stop the GC
93. GC.disable •Add GC.disable to somewhere in the con g le
94. The gc_tracer outputs nothing (but headers) now •Which means that the GC was not executed
95. 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)
96. 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
97. 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)
98. Newer Rails
99. At RubyKaigi this year "Rails 4.2 is going to be the fastest Rails ever." @tenderlove
100. Let's try Rails 4.2!
101. Creating the same app on current GH master
102. 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)
103. No big change •Or isn't it actually slower a little bit?
104. 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.
105. How could we know which methods were called? "Use the Tracepoint API." @ko1
106. Tracepoint •Introduced in the core since Ruby 2.0
107. 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
108. 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},
109. 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,
110. 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},
111. Confirming that this is actually consuming the CPU time
112. Stackprof •Use stackprof gem by @tmm1 •Available in Ruby 2.1+
113. 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
114. 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?
115. I guess this has to be fixed before the 4.2.0 release
116. Haml
117. Haml is consuming most of the response time •Can't we make it faster?
118. 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)
119. 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)
120. hamlx •Renderes 10ʙ20% faster than current haml gem • (still slower than slim, I guess...) •Will be shipped :soon:
121. 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
122. end