Inspecting and Crafting Rails

Slides for my keynote at Ruby X Elixir Conf Taiwan 2018 in Taipei https://2018.rubyconf.tw/#akira-matsuda

Transcript

1. Inspecting and Crafting Rails Akira Matsuda
2. Have You Heard a Rumour That Rails Is Slow?
3. For Example I Recently Saw This Page https://github.com/tbrand/whichisthe_fastest Rails is ranked at the 36th on the speed ranking out of 36 web frameworks
4. Let's See If It's True or Not
5. By Comparing with Something Else That Is Not Slow
6. I Heard Another Rumour About the Fastest Programming Language in the World
7. Of Course I'm Talking About
8. Of Course I'm Talking About
9. Let's Take Benchmarks and See How Slow (or Not Slow) Our Framework Is
10. Hello from Elixir & Phoenix % brew install elixir % mix archive.install https://github.com/phoenixframework/archives/raw/master/phx_new.ez % mix phx.new hello % cd hello % mix deps.get
11. The Action # lib/hello_web/controllers/page_controller.ex use HelloWeb, :controller def index(conn, _params) do - render conn, "index.html" + send_resp conn, 200, "" end end
12. Result % curl http://localhost:4000/ => [info] GET / [debug] Processing with HelloWeb.PageController.index/2 Parameters: %{} Pipelines: [:browser] [info] Sent 200 in 109µs
13. OMG! This Is Really Fast! Even in development mode
14. The Log Looks Super Cool I've never seen µs logs in Rails A fast framework needs this, I guess
15. Rails' Turn % rails new rails_hello --skip-bootsnap --skip-spring --skip-listen --skip-puma --skip-active-record --skip- action-cable --skip-active-storage --skip-action-mailer --skip-sprockets --skip-javascript -B % cd rails_hello % git add .
16. Remove Unneeded Gems # Gemfile source 'https://rubygems.org' gem 'rails', '~> 5.2.0'
17. Bundle # So that we can easily patch the framework and the bundled gems % bundle --path vendor/bundle
18. The Action # app/controllers/hello_controller.rb class HelloController < ApplicationController def index render plain: 'Hello, Taipei!' end end # config/routes.rb Rails.application.routes.draw do root 'hello#index' end
19. Run the Server and Show the Hello Page % rails s -e production # We don't want to be bothered by the browser cookies % curl http://localhost:3000/
20. Result Started GET "/" for 127.0.0.1 at 2018-04-27 19:18:34 +0900 Processing by HelloController#index as */* Rendering text template Rendered text template (0.0ms) Completed 200 OK in 1ms (Views: 0.7ms)
21. Not That Bad Maybe we need a little bit more accurate number We want to see µs logs like Phoenix!
22. The Patch (Our First Patch Today!) # vendor/bundle/ruby/2.6.0/gems/actionpack-5.2.0/lib/action_controller/log_subscriber.rb - message = "Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in #{event.duration.round} ms".dup + message = "Completed #{status} #{Rack::Utils::HTTP_STATUS_CODES[status]} in #{(event.duration * 1000).round}µs".dup
23. Result (µs) Completed 200 OK in 652μs (Views: 0.5ms)
24. The Fact Production mode Rails app is 5x Slower than development mode Phoenix app!
25. Phoenix Is So Impressive Great work, José!
26. How Can We Make Rails As Fast As Phoenix?
27. Let's Find Out Which Part of Rails Takes Time
28. There're Several Approaches to Find Performance Hot Spots Elapsed time Method calls Object allocations Memory usage
29. Measuring Elapsed Time # Just put something like this in your code p Benchmark.realtime { # do something }
30. It's a Quite Common Approach Nothing new here So I'm not going to explain this today
31. Object Allocations I heard that Rails allocates too much objects per each request That would cause memory bloat, GC pressure, etc. and so would largely impact on the total performance How can we measure this?
32. ObjectSpace The easiest way to see object allocations is to investigate
 ObjectSpace.count_objects
 before and after processing the request
33. Using ObjectSpace # config/application.rb or somewhere like that class AllocationTracerMiddleware def initialize(app) @app = app; end def call(env) before = ObjectSpace.count_objects result = @app.call env after = ObjectSpace.count_objects pp after.each_pair {|k, v| after[k] = v - (before[k] || 0)}.select {|_k, v| v.positive?}. sort_by {|_k, v| -v} result ennd config.middleware.insert_before 0, AllocationTracerMiddleware
34. Maybe We'd Better Disable the GC Before Running This? # config.ru run Rails.application +GC.disable
35. The Result [[:T_ARRAY, 197], [:T_STRING, 159], [:T_HASH, 71], [:T_IMEMO, 52], [:T_OBJECT, 49], [:T_DATA, 31], [:T_MATCH, 8], [:T_STRUCT, 5], [:T_REGEXP, 1], [:T_CLASS, 1]]
36. Or For This Purpose, There's a Handy Gem Called allocation_tracer
37. GH/ko1/allocation_tracer
38. Just Bundle allocation_tracer Gem
39. Then Rewrite the Middleware to Be Something Like This class AllocationTracerMiddleware ObjectSpace::AllocationTracer.setup(%i{type}) def initialize(app) @app = app; end def call(env) result = nil allocations = ObjectSpace::AllocationTracer.trace { result = @app.call env } pp allocations.sort_by {|_k, v| -v.first} result end end
40. Result # We got a very similar result from the ObjectSpace one [[[:T_ARRAY], [197, 0, 0, 0, 0, 0]], [[:T_STRING], [164, 0, 0, 0, 0, 0]], [[:T_HASH], [72, 0, 0, 0, 0, 0]], [[:T_IMEMO], [52, 0, 0, 0, 0, 0]], [[:T_OBJECT], [49, 0, 0, 0, 0, 0]], [[:T_DATA], [31, 0, 0, 0, 0, 0]], [[:T_MATCH], [8, 0, 0, 0, 0, 0]], [[:T_STRUCT], [5, 0, 0, 0, 0, 0]], [[:T_CLASS], [1, 0, 0, 0, 0, 0]], [[:T_REGEXP], [1, 0, 0, 0, 0, 0]]]
41. Where in Our Code Do These Allocations Happen?
42. allocation_tracer Can Report Where the Objects Are Allocated class AllocationTracerMiddleware - ObjectSpace::AllocationTracer.setup(%i{type}) + ObjectSpace::AllocationTracer.setup(%i{path type}) def initialize(app) @app = app; end def call(env) result = nil allocations = ObjectSpace::AllocationTracer.trace { result = @app.call env } - pp allocations.sort_by {|_k, v| -v.first} + bundle_path = Rails.root.join('vendor/bundle/ruby/2.6.0/gems/').to_s + pp allocations.each_pair {|k, _v| k.first.sub!(bundle_path, '')}.sort_by {|_k, v| -v.first} result end end
43. Result [[["/Users/a_matsuda/.rbenv/versions/2.6.0-dev/lib/ruby/2.6.0/logger.rb", :T_STRING], [25, 0, 0, 0, 0, 0]], [["actionpack-5.2.0/lib/action_dispatch/http/response.rb", :T_ARRAY], [25, 0, 0, 0, 0, 0]], [["activesupport-5.2.0/lib/active_support/inflector/methods.rb", :T_STRING], [15, 0, 0, 0, 0, 0]], [["activesupport-5.2.0/lib/active_support/tagged_logging.rb", :T_ARRAY], [15, 0, 0, 0, 0, 0]], [["activesupport-5.2.0/lib/active_support/tagged_logging.rb", :T_STRING], [15, 0, 0, 0, 0, 0]], [["rack-2.0.5/lib/rack/utils.rb", :T_STRING], [13, 0, 0, 0, 0, 0]], [["activesupport-5.2.0/lib/active_support/hash_with_indifferent_access.rb", :T_HASH], [11, 0, 0, 0, 0, 0]], [["activesupport-5.2.0/lib/active_support/hash_with_indifferent_access.rb", :T_ARRAY], [11, 0, 0, 0, 0, 0]], [["actionpack-5.2.0/lib/action_dispatch/http/response.rb", :T_STRING], [11, 0, 0, 0, 0, 0]], [["/Users/a_matsuda/.rbenv/versions/2.6.0-dev/lib/ruby/2.6.0/securerandom.rb", :T_STRING], [10, 0, 0, 0, 0, 0]], [["actionpack-5.2.0/lib/action_dispatch/http/parameter_filter.rb", :T_ARRAY], [10, 0, 0, 0, 0, 0]], [["rack-2.0.5/lib/rack/request.rb", :T_STRING], [10, 0, 0, 0, 0, 0]],
44. active_support/tagged_logging.rb Creates 30 Objects
45. Because of This Code Where tags.size == 1 Is Almost Always 1 def tags_text tags = current_tags if tags.any? tags.collect { |tag| "[#{tag}] " }.join end end
46. This Can Be Very Easily Improved for the Majority Case Where tags.size == 1 def tags_text tags = current_tags - if tags.any? + if tags.one? + "[#{tags[0]}] " + elsif tags.any? tags.collect { |tag| "[#{tag}] " }.join end end
47. And So I Did So Yesterday https://github.com/rails/rails/commit/ ac93e7b5
48. Current Result [[["actionpack-5.2.0/lib/action_dispatch/http/response.rb", :T_ARRAY], [25, 0, 0, 0, 0, 0]], [["/Users/a_matsuda/.rbenv/versions/2.6.0-dev/lib/ruby/2.6.0/logger.rb", :T_STRING], [25, 0, 0, 0, 0, 0]], [["activesupport-5.2.0/lib/active_support/inflector/methods.rb", :T_STRING], [15, 0, 0, 0, 0, 0]], [["rack-2.0.5/lib/rack/utils.rb", :T_STRING], [13, 0, 0, 0, 0, 0]], [["activesupport-5.2.0/lib/active_support/hash_with_indifferent_access.rb", :T_HASH], [11, 0, 0, 0, 0, 0]], [["actionpack-5.2.0/lib/action_dispatch/http/response.rb", :T_STRING], [11, 0, 0, 0, 0, 0]], [["activesupport-5.2.0/lib/active_support/hash_with_indifferent_access.rb", :T_ARRAY], [11, 0, 0, 0, 0, 0]], [["activesupport-5.2.0/lib/active_support/tagged_logging.rb", :T_STRING], [10, 0, 0, 0, 0, 0]], [["actionpack-5.2.0/lib/action_dispatch/http/parameter_filter.rb", :T_ARRAY], [10, 0, 0, 0, 0, 0]], [["/Users/a_matsuda/.rbenv/versions/2.6.0-dev/lib/ruby/2.6.0/securerandom.rb", :T_STRING], [10, 0, 0, 0, 0, 0]], [["activesupport-5.2.0/lib/active_support/tagged_logging.rb", :T_ARRAY], [10, 0, 0, 0, 0, 0]], [["rack-2.0.5/lib/rack/request.rb", :T_STRING], [10, 0, 0, 0, 0, 0]], [["activesupport-5.2.0/lib/active_support/tagged_logging.rb", :T_IMEMO], [10, 0, 0, 0, 0, 0]],
49. hash_with_indifferent_access.rb A major culprit for Rails' too many object allocations Historically, we needed this because we could not create dynamic Hash instances with Symbol keys Since Ruby did not GC Symbols, if we create Symbols from user-input data, that would cause symbol-fixation vulnerability
50. But Recent Versions of Ruby GCs Dynamic Symbols! Maybe it's time to throw HWIA away, and let all Hashs be simply Symbol-based?
51. Assuming that We Get the env instance as a Symbol-based Hash class EnvSymbolizer def initialize(app) @app = app; end def call(env) env.symbolize_keys! @app.call env ennd config.middleware.insert_before 0, EnvSymbolizer
52. ERROR ActionController::UnknownHttpMethod: , accepted HTTP methods are OPTIONS, GET, HEAD, POST, PUT, DELETE, TRACE, CONNECT, PROPFIND, PROPPATCH, MKCOL, COPY, MOVE, LOCK, UNLOCK, VERSION-CONTROL, REPORT, CHECKOUT, CHECKIN, UNCHECKOUT, MKWORKSPACE, UPDATE, LABEL, MERGE, BASELINE-CONTROL, MKACTIVITY, ORDERPATCH, ACL, SEARCH, MKCALENDAR, and PATCH
53. Of Course It Doesn't Work, So Let's Make This Work
54. And So I Tried I needed to patch 89 files in actionpack, actionview, activesupport, rack, webrick, etc. I don't think the patch is completely done, but I could make it return some kind of
 "200 OK" response
55. Result [[[:T_ARRAY], [178, 0, 0, 0, 0, 0]], [[:T_STRING], [162, 0, 0, 0, 0, 0]], [[:T_HASH], [63, 0, 0, 0, 0, 0]], [[:T_IMEMO], [62, 0, 0, 0, 0, 0]], [[:T_OBJECT], [48, 0, 0, 0, 0, 0]], [[:T_DATA], [32, 0, 0, 0, 0, 0]], [[:T_MATCH], [8, 0, 0, 0, 0, 0]], [[:T_STRUCT], [5, 0, 0, 0, 0, 0]], [[:T_CLASS], [1, 0, 0, 0, 0, 0]], [[:T_REGEXP], [1, 0, 0, 0, 0, 0]]]
56. Result Before (Reprise) [[[:T_ARRAY], [197, 0, 0, 0, 0, 0]], [[:T_STRING], [164, 0, 0, 0, 0, 0]], [[:T_HASH], [72, 0, 0, 0, 0, 0]], [[:T_IMEMO], [52, 0, 0, 0, 0, 0]], [[:T_OBJECT], [49, 0, 0, 0, 0, 0]], [[:T_DATA], [31, 0, 0, 0, 0, 0]], [[:T_MATCH], [8, 0, 0, 0, 0, 0]], [[:T_STRUCT], [5, 0, 0, 0, 0, 0]], [[:T_CLASS], [1, 0, 0, 0, 0, 0]], [[:T_REGEXP], [1, 0, 0, 0, 0, 0]]]
57. Result I could reduce some object allocations
58. Speed Completed 200 OK in 663µs (Views: 0.5ms) Completed 200 OK in 559µs (Views: 0.4ms) Completed 200 OK in 619µs (Views: 0.5ms) Completed 200 OK in 567µs (Views: 0.4ms) Completed 200 OK in 597µs (Views: 0.5ms)
59. 10%-ish Faster Than Before? Still needs more work
60. Speed (Reprise) Completed 200 OK in 663µs (Views: 0.5ms) Completed 200 OK in 559µs (Views: 0.4ms) Completed 200 OK in 619µs (Views: 0.5ms) Completed 200 OK in 567µs (Views: 0.4ms) Completed 200 OK in 597µs (Views: 0.5ms)
61. You See, Most of The Time Is Spent for Views But what exactly the "view" does when we're not rendering a template?
62. What Is Displayed Here As the "Views:" Runtime? module ActionController module Instrumentation module ClassMethods # A hook which allows other frameworks to log what happened during # controller process action. This method should return an array # with the messages to be added. def log_process_action(payload) #:nodoc: messages, view_runtime = [], payload[:view_runtime] messages << ("Views: %.1fms" % view_runtime.to_f) if view_runtime messages ennnnd
63. How Is the view_runtime Value Set? module ActionController module Instrumentation def render(*args) render_output = nil self.view_runtime = cleanup_view_runtime do Benchmark.ms { render_output = super } end render_output ennnd
64. So, the view_runtime Should Be Almost Equivalent to the Time Spent for `render` Method
65. We Can Make This Sure by Adding Our Own Benchmark class HelloController < ApplicationController def index p Benchmark.realtime { render plain: 'Hello, Taipei!' } end end
66. Results # logfile Completed 200 OK in 581µs (Views: 0.4ms) # Benchmark.realtime 0.0004210001789033413
67. What Is Measured When We Don't Explicitly Call `render` in the Contrller?
68. The Framework Calls `default_render` module ActionController module BasicImplicitRender # :nodoc: def send_action(method, *args) super.tap { default_render unless performed? } ennnd
69. Then `default_render` Finds a Template from the Controller Class Name and the Action Name So basically it's a quick template lookup + render
70. Now Let's Go Back to This Code and See What Ruby Is Doing class HelloController < ApplicationController def index render plain: 'Hello, Taipei!' end end
71. Tracing Method Calls with TracePoint def index trace = TracePoint.new(:call) {|t| p "#{t.defined_class}##{t.method_id}"} trace.enable render plain: 'Hello, Taipei!' trace.disable end
72. Result "ActionController::Instrumentation#render" "ActionController::Instrumentation#cleanup_view_runtime" "#<Class:Benchmark>#ms" "#<Class:Benchmark>#realtime" "ActionController::Rendering#render" "AbstractController::Rendering#render" "AbstractController::Rendering#_normalize_render" "ActionController::Rendering#_normalize_args" "ActionView::Rendering#_normalize_args" "AbstractController::Rendering#_normalize_args" "ActionController::Rendering#_process_variant" "ActionDispatch::Http::MimeNegotiation#variant" "Object#present?" "ActionController::Rendering#_normalize_options" "ActionController::Rendering#_normalize_text" "ActionView::Layouts#_normalize_options" "ActionView::Rendering#_normalize_options" "AbstractController::Rendering#_normalize_options" "ActionView::ViewPaths#_prefixes" "ActionView::ViewPaths::ClassMethods#_prefixes" "ActionView::Layouts#_include_layout?" "ActionController::Renderers#render_to_body" "ActionController::Renderers#_render_to_body_with_renderer" "ActionController::Base#_renderers" "#<Class:ActionController::Base>#_renderers" "Set#each" "ActionController::Rendering#render_to_body" "ActionView::Rendering#render_to_body" "ActionController::Streaming#_process_options" "ActionController::Rendering#_process_options" "AbstractController::Rendering#_process_options" "ActionController::Streaming#_render_template" "ActionView::Rendering#_render_template" "ActionView::Rendering#view_context" "ActionView::Rendering#view_context_class" "ActionView::Rendering::ClassMethods#view_context_class" "ActionView::Rendering#view_renderer" "ActionView::ViewPaths#lookup_context" "ActionView::Renderer#initialize" "AbstractController::Rendering#view_assigns" "ActionController::Base#_protected_ivars" "Set#include?" "Set#include?" "Set#include?" "Set#include?" "Set#include?" "Set#include?" "Set#include?" "Set#include?" "Set#include?" "Set#include?" "Set#include?" "ActionDispatch::Routing::UrlFor#initialize" "ActionView::Base#initialize" "ActiveSupport::InheritableOptions#initialize" "ActionView::Base#assign" "ActionView::Helpers::ControllerHelper#assign_controller" "ActiveSupport::Configurable#config" "ActiveSupport::InheritableOptions#inheritable_copy" "ActiveSupport::InheritableOptions#initialize" "ActionController::FormBuilder#default_form_builder" "#<Class:ActionController::Base>#_default_form_builder" "ActionView::Context#_prepare_context" "ActionView::OutputFlow#initialize" "ActionView::Rendering#view_renderer" "ActionView::Renderer#render" "ActionView::Renderer#render_template" "ActionView::AbstractRenderer#initialize" "ActionView::TemplateRenderer#render" "ActionView::AbstractRenderer#extract_details" "ActionView::LookupContext#registered_details" "ActionView::TemplateRenderer#determine_template" "ActionView::Template::Text#initialize" "#<Class:ActionView::Template::Types>#[]" "#<Class:ActionView::Template::Types>#type_klass" "#<Class:Mime>#[]" "#<Class:Mime::Type>#lookup_by_extension" "ActionView::Template::Text#formats" "Mime::Type#ref" "ActionView::AbstractRenderer#prepend_formats" "ActionView::LookupContext::Accessors#formats" "ActionView::LookupContext#formats=" "ActionView::LookupContext::Accessors#formats=" "Object#present?" "ActionView::LookupContext::DetailsCache#_set_detail" "ActionView::Template::Text#formats" "Mime::Type#ref" "ActionView::TemplateRenderer#render_template" "ActionView::TemplateRenderer#render_with_layout" "ActionView::Template::Text#identifier" "NilClass#try" "ActionView::AbstractRenderer#instrument" "#<Class:ActiveSupport::Notifications>#instrument" "ActiveSupport::Notifications::Fanout#listening?" "ActiveSupport::Notifications::Fanout#listeners_for" "Concurrent::Map#[]" "Concurrent::Collection::NonConcurrentMapBackend#[]" "#<Class:ActiveSupport::Notifications>#instrumenter" "ActiveSupport::PerThreadRegistry#instance" "ActiveSupport::Notifications::InstrumentationRegistry#instrumenter_for" "ActiveSupport::Notifications::Instrumenter#instrument" "ActiveSupport::Notifications::Instrumenter#start" "ActiveSupport::Notifications::Fanout#start" "ActiveSupport::Notifications::Fanout#listeners_for" "Concurrent::Map#[]" "Concurrent::Collection::NonConcurrentMapBackend#[]" "ActiveSupport::Notifications::Fanout::Subscribers::Evented#start" "ActionView::LogSubscriber#start" "ActionView::LogSubscriber#log_rendering_start" "ActiveSupport::LogSubscriber#info" "ActionView::LogSubscriber#logger" "#<Class:ActionView::Base>#logger" "ActionView::LogSubscriber#logger" "#<Class:ActionView::Base>#logger" "Logger#info" "ActiveSupport::Logger#add" "ActiveSupport::LoggerThreadSafeLevel#level" "ActiveSupport::LoggerThreadSafeLevel#local_level" "ActiveSupport::LoggerThreadSafeLevel#local_log_id" "Concurrent::Map#[]" "Concurrent::Collection::NonConcurrentMapBackend#[]" "Logger#add" "ActionView::LogSubscriber#from_rails_root" "ActionView::LogSubscriber#rails_root" "Logger#format_severity" "Logger#format_message" "ActiveSupport::TaggedLogging::Formatter#call" "ActiveSupport::TaggedLogging::Formatter#tags_text" "ActiveSupport::TaggedLogging::Formatter#current_tags" "Logger::Formatter#call" "Logger::Formatter#format_datetime" "Logger::Formatter#msg2str" "Logger::LogDevice#write" "MonitorMixin#mon_synchronize" "MonitorMixin#mon_enter" "MonitorMixin#mon_exit" "MonitorMixin#mon_check_owner" "ActiveSupport::LogSubscriber#start" "ActionView::LogSubscriber#logger" "#<Class:ActionView::Base>#logger" "ActiveSupport::Subscriber#start" "ActiveSupport::Notifications::Event#initialize" "ActiveSupport::Subscriber#event_stack" "ActiveSupport::PerThreadRegistry#instance" "ActiveSupport::SubscriberQueueRegistry#get_queue" "ActiveSupport::Subscriber#event_stack" "ActiveSupport::PerThreadRegistry#instance" "ActiveSupport::SubscriberQueueRegistry#get_queue" "ActionView::Template::Text#render" "ActionView::Template::Text#to_str" "ActiveSupport::Notifications::Instrumenter#finish_with_state" "ActiveSupport::Notifications::Fanout#finish" "ActiveSupport::Notifications::Fanout::Subscribers::Evented#finish" "ActiveSupport::LogSubscriber#finish" "ActionView::LogSubscriber#logger" "#<Class:ActionView::Base>#logger" "ActiveSupport::Subscriber#finish" "ActiveSupport::Subscriber#event_stack" "ActiveSupport::PerThreadRegistry#instance" "ActiveSupport::SubscriberQueueRegistry#get_queue" "ActionView::LogSubscriber#render_template" "ActiveSupport::LogSubscriber#info" "ActionView::LogSubscriber#logger" "#<Class:ActionView::Base>#logger" "ActionView::LogSubscriber#logger" "#<Class:ActionView::Base>#logger" "Logger#info" "ActiveSupport::Logger#add" "ActiveSupport::LoggerThreadSafeLevel#level" "ActiveSupport::LoggerThreadSafeLevel#local_level" "ActiveSupport::LoggerThreadSafeLevel#local_log_id" "Concurrent::Map#[]" "Concurrent::Collection::NonConcurrentMapBackend#[]" "Logger#add" "ActionView::LogSubscriber#from_rails_root" "ActionView::LogSubscriber#rails_root" "ActiveSupport::Notifications::Event#duration" "Time#minus_with_coercion" "Time#minus_with_duration" "#<Class:ActiveSupport::Duration>#===" "ActiveSupport::NumericWithFormat#to_s" "Logger#format_severity" "Logger#format_message" "ActiveSupport::TaggedLogging::Formatter#call" "ActiveSupport::TaggedLogging::Formatter#tags_text" "ActiveSupport::TaggedLogging::Formatter#current_tags" "Logger::Formatter#call" "Logger::Formatter#format_datetime" "Logger::Formatter#msg2str" "Logger::LogDevice#write" "MonitorMixin#mon_synchronize" "MonitorMixin#mon_enter" "MonitorMixin#mon_exit" "MonitorMixin#mon_check_owner" "ActionView::Rendering#rendered_format" "ActionView::ViewPaths#lookup_context" "#<Class:ActionView::Template::Types>#[]" "#<Class:ActionView::Template::Types>#type_klass" "#<Class:Mime>#[]" "#<Class:Mime::Type>#lookup_by_extension" "ActionController::Rendering#_set_rendered_content_type" "ActionDispatch::Response#content_type" "ActionDispatch::Response#parsed_content_type_header" "ActionDispatch::Response#get_header" "#<Class:0x00007fe95526e288>#[]" "#<Class:0x00007fe95526e288>#__getobj__" "ActionDispatch::Response#parse_content_type" "Mime::Type#to_s" "ActionController::Metal#content_type=" "ActionDispatch::Response#content_type=" "ActionDispatch::Response#parse_content_type" "ActionDispatch::Response#parsed_content_type_header" "ActionDispatch::Response#get_header" "#<Class:0x00007fe95526e288>#[]" "#<Class:0x00007fe95526e288>#__getobj__" "ActionDispatch::Response#parse_content_type" "#<Class:ActionDispatch::Response>#default_charset" "ActionDispatch::Response#set_content_type" "ActionDispatch::Response#set_header" "ActionDispatch::Response::Header#[]=" "ActionDispatch::Response#sending?" "MonitorMixin#mon_synchronize" "MonitorMixin#mon_enter" "MonitorMixin#mon_exit" "MonitorMixin#mon_check_owner" "ActionDispatch::Response#sent?" "MonitorMixin#mon_synchronize" "MonitorMixin#mon_enter" "MonitorMixin#mon_exit" "MonitorMixin#mon_check_owner" "#<Class:0x00007fe95526e288>#[]=" "#<Class:0x00007fe95526e288>#__getobj__" "ActionController::Metal#response_body=" "ActionDispatch::Response#reset_body!" "ActionDispatch::Response#build_buffer" "ActionDispatch::Response::Buffer#initialize" "ActionDispatch::Response#body=" "MonitorMixin#mon_synchronize" "MonitorMixin#mon_enter" "ActionDispatch::Response#munge_body_object" "ActionDispatch::Response#build_buffer" "ActionDispatch::Response::Buffer#initialize" "MonitorMixin#mon_exit" "MonitorMixin#mon_check_owner"
73. Turned Out That a Simple `render :plain` Call Invokes 244 Methods I'm not going to step into this deeper, but there has to be a room for improvements Somebody please improve this!
74. Investigating More Details
75. Investigating More Details Use memory_profiler gem
76. GH/SamSaffron/memory_profiler Shows more detailed report with memory usage, allocated objects by gem, etc.
77. Result Total allocated: 36487 bytes (501 objects) Total retained: 9984 bytes (110 objects) ... allocated memory by location ----------------------------------- 1440 (gem_path)/activesupport-5.2.0/lib/active_support/inflector/methods.rb:72 1248 (ruby_path)/logger.rb:597 1194 (gem_path)/rack-2.0.5/lib/rack/utils.rb:469 1008 (gem_path)/activesupport-5.2.0/lib/active_support/tagged_logging.rb:23 968 (gem_path)/actionpack-5.2.0/lib/action_dispatch/http/response.rb:413 960 (gem_path)/activesupport-5.2.0/lib/active_support/notifications/instrumenter.rb:60 ... Allocated String Report ----------------------------------- 9 "" 6 (ruby_path)/logger.rb:597 2 (gem_path)/actionpack-5.2.0/lib/action_dispatch/http/request.rb:255 1 (gem_path)/actionpack-5.2.0/lib/action_dispatch/journey/router/utils.rb:20 9 "Hello" 9 (gem_path)/activesupport-5.2.0/lib/active_support/inflector/methods.rb:72 6 "/" 2 (gem_path)/rack-2.0.5/lib/rack/request.rb:404 1 (gem_path)/actionpack-5.2.0/lib/action_dispatch/journey/gtg/simulator.rb:26 1 (gem_path)/actionpack-5.2.0/lib/action_dispatch/journey/path/pattern.rb:158 1 (gem_path)/actionpack-5.2.0/lib/action_dispatch/journey/router/utils.rb:22
78. Why Don't We Try a Little Bit More Real-world-ish Use Case?
79. Same "Hello, Taipei!" Using Action View # app/controllers/hello_controller.rb class HelloController < ApplicationController def index - render plain: 'Hello, Taipei!' end end # app/views/hello/index.html.erb (new) +Hello, Taipei!
80. Result Total allocated: 68099 bytes (889 objects) Total retained: 14543 bytes (139 objects)
81. Very Interesting Part in the Report Allocated String Report ----------------------------------- ... 5 "/stylesheets/application.css" 1 (gem_path)/actionview-5.2.0/lib/action_view/helpers/asset_url_helper.rb:213 1 (gem_path)/actionview-5.2.0/lib/action_view/helpers/asset_url_helper.rb:264 1 (gem_path)/actionview-5.2.0/lib/action_view/helpers/tag_helper.rb:93 1 (gem_path)/activesupport-5.2.0/lib/active_support/core_ext/string/output_safety.rb:39 1 (gem_path)/activesupport-5.2.0/lib/active_support/multibyte/unicode.rb:229 ... 3 "<link rel=\"stylesheet\" media=\"all\" href=\"/stylesheets/application.css\" />" 1 (gem_path)/actionview-5.2.0/lib/action_view/helpers/asset_tag_helper.rb:143 1 (gem_path)/actionview-5.2.0/lib/action_view/helpers/tag_helper.rb:239 1 (gem_path)/activesupport-5.2.0/lib/active_support/core_ext/string/output_safety.rb:174
82. Why Does Action View Duplicates the Same Strings So Many Times? Let's see actionview-5.2.0/lib/action_view/ helpers/tag_helper.rb:93 as an example
83. The Code def tag_option(key, value, escape) if value.is_a?(Array) value = escape ? safe_join(value, " ".freeze) : value.join(" ".freeze) else value = escape ? ERB::Util.unwrapped_html_escape(value) : value.to_s end %(#{key}="#{value.gsub('"'.freeze, '&quot;'.freeze)}") # the line 93 end
84. Do You See What's Wrong with the Line 93?
85. The Answer String#gsub here duplicates the String instance, so we'd better use gsub! here We usually don't have to care about such a small difference, but this method is called against all tags' all attributes, so this gsub would create so many String objects
86. The Patch def tag_option(key, value, escape) if value.is_a?(Array) value = escape ? safe_join(value, " ".freeze) : value.join(" ".freeze) else - value = escape ? ERB::Util.unwrapped_html_escape(value) : value.to_s + value = escape ? ERB::Util.unwrapped_html_escape(value) : value.to_s.dup end - %(#{key}="#{value.gsub('"'.freeze, '&quot;'.freeze)}") + value.gsub!('"'.freeze, '&quot;'.freeze) + %(#{key}="#{value}") end
87. The Patch https://github.com/rails/rails/commit/ 9276ea89d2b0be9fdd1ad6590857f8d45a38 c267 https://github.com/rails/rails/commit/ 7d2400ab61c8e3ed95e14d03ba3844e8ba2e 36e4
88. Result Total allocated: 67740 bytes (878 objects) Total retained: 14543 bytes (139 objects)
89. Another String Duplication # action_view/helpers/asset_tag_helper.rb def stylesheet_link_tag(*sources) options = sources.extract_options!.stringify_keys path_options = options.extract!("protocol", "host", "skip_pipeline").symbolize_keys early_hints_links = [] sources_tags = sources.uniq.map { |source| href = path_to_stylesheet(source, path_options) early_hints_links << "<#{href}>; rel=preload; as=style" tag_options = { "rel" => "stylesheet", "media" => "screen", "href" => href }.merge!(options) tag(:link, tag_options) }.join("\n").html_safe request.send_early_hints("Link" => early_hints_links.join("\n")) if respond_to?(:request) && request sources_tags end
90. What's Happening Here tag() Returns an HTML safe String join("\n") makes the String unsafe even if the collection has only one element ['a'.html_safe].join("\n").html_safe? #=> false Then we need to call html_safe against it again
91. But This Method Won't Be That Serious Performance Hot Spot Because it's just a public helper method
92. Possible Patch path_options = options.extract!("protocol", "host", "skip_pipeline").symbolize_keys early_hints_links = [] - sources_tags = sources.uniq.map { |source| + sources_tags = sources.uniq.each_with_object("".html_safe) { |source, result| href = path_to_stylesheet(source, path_options) early_hints_links << "<#{href}>; rel=preload; as=style" tag_options = { "rel" => "stylesheet", "media" => "screen", "href" => href }.merge!(options) - tag(:link, tag_options) - }.join("\n").html_safe + result << "\n" unless result.empty? + result << tag(:link, tag_options) + }
93. But I Didn't Commit This Because I Couldn't See Any Significant Performance Change
94. I'm Rather Interested in active_support/ core_ext/string/output_safety.rb So many String duplications are happening in this file When creating a new SafeBuffer Or via ActiveSupport::Multibyte::Unicode.tidy_bytes
95. Maybe We Can Create tidy_bytes! Method Using String#scrub! But I'm not sure how to deal with the Rubinius implementation
96. Or Maybe It's Time to Think About Totally Newly Designed SafeBuffer?
97. (Time for Showing More Hacks If Time Allows) Tuning the template more A JSON API for the next benchmark Dealing with the database, and making it faster And so on...
98. So, I Hope You Got Some Ideas for Your Weekend Hack
99. And I Hope You Got Some Tools in Your Hands Now
100. There're So Many Problems and Rooms for Improvement in Rails
101. (We Need to Get Rid of the Reputation of "the Slowest Framework"...)
102. Ruby Is Getting Faster and Faster, So Let's Make Rails Faster Too!
103. Go Ahead and Do Your Hack!
104. end
105. end Name: Akira Matsuda GitHub: @amatsuda Twitter: @a_matsuda