Inspecting and Crafting Rails

Inspecting and Crafting Rails

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

76a777ff80f30bd3b390e275cce625bc?s=128

Akira Matsuda

April 28, 2018
Tweet

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