Inspecting and Crafting Rails Akira Matsuda

Have You Heard a Rumour That Rails Is Slow?

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

Let's See If It's True or Not

By Comparing with Something Else That Is Not Slow

I Heard Another Rumour About the Fastest Programming Language in the World

Of Course I'm Talking About

Of Course I'm Talking About

Let's Take Benchmarks and See How Slow (or Not Slow) Our Framework Is

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

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

Result % curl http://localhost:4000/ => [info] GET / [debug] Processing with HelloWeb.PageController.index/2 Parameters: %{} Pipelines: [:browser] [info] Sent 200 in 109µs

OMG! This Is Really Fast! Even in development mode

The Log Looks Super Cool I've never seen µs logs in Rails A fast framework needs this, I guess

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 .

Remove Unneeded Gems # Gemfile source 'https://rubygems.org' gem 'rails', '~> 5.2.0'

Bundle # So that we can easily patch the framework and the bundled gems % bundle --path vendor/bundle

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

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/

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)

Not That Bad Maybe we need a little bit more accurate number We want to see µs logs like Phoenix!

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

Result (µs) Completed 200 OK in 652μs (Views: 0.5ms)

The Fact Production mode Rails app is 5x Slower than development mode Phoenix app!

Phoenix Is So Impressive Great work, José!

How Can We Make Rails As Fast As Phoenix?

Let's Find Out Which Part of Rails Takes Time

There're Several Approaches to Find Performance Hot Spots Elapsed time Method calls Object allocations Memory usage

Measuring Elapsed Time # Just put something like this in your code p Benchmark.realtime { # do something }

It's a Quite Common Approach Nothing new here So I'm not going to explain this today

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?

ObjectSpace The easiest way to see object allocations is to investigate
 ObjectSpace.count_objects
 before and after processing the request

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

Maybe We'd Better Disable the GC Before Running This? # config.ru run Rails.application +GC.disable

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

Or For This Purpose, There's a Handy Gem Called allocation_tracer

GH/ko1/allocation_tracer

Just Bundle allocation_tracer Gem

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

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

Where in Our Code Do These Allocations Happen?

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

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

active_support/tagged_logging.rb Creates 30 Objects

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

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

And So I Did So Yesterday https://github.com/rails/rails/commit/ ac93e7b5

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

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

But Recent Versions of Ruby GCs Dynamic Symbols! Maybe it's time to throw HWIA away, and let all Hashs be simply Symbol-based?

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

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

Of Course It Doesn't Work, So Let's Make This Work

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

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

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

Result I could reduce some object allocations

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)

10%-ish Faster Than Before? Still needs more work

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)

You See, Most of The Time Is Spent for Views But what exactly the "view" does when we're not rendering a template?

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

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

So, the view_runtime Should Be Almost Equivalent to the Time Spent for `render` Method

We Can Make This Sure by Adding Our Own Benchmark class HelloController < ApplicationController def index p Benchmark.realtime { render plain: 'Hello, Taipei!' } end end

Results # logfile Completed 200 OK in 581µs (Views: 0.4ms) # Benchmark.realtime 0.0004210001789033413

What Is Measured When We Don't Explicitly Call `render` in the Contrller?

The Framework Calls `default_render` module ActionController module BasicImplicitRender # :nodoc: def send_action(method, *args) super.tap { default_render unless performed? } ennnd

Then `default_render` Finds a Template from the Controller Class Name and the Action Name So basically it's a quick template lookup + render

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

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

Result "ActionController::Instrumentation#render" "ActionController::Instrumentation#cleanup_view_runtime" "##ms" "##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" "##_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" "##_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" "##[]" "##type_klass" "##[]" "##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" "##instrument" "ActiveSupport::Notifications::Fanout#listening?" "ActiveSupport::Notifications::Fanout#listeners_for" "Concurrent::Map#[]" "Concurrent::Collection::NonConcurrentMapBackend#[]" "##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" "##logger" "ActionView::LogSubscriber#logger" "##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" "##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" "##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" "##logger" "ActionView::LogSubscriber#logger" "##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" "##===" "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" "##[]" "##type_klass" "##[]" "##lookup_by_extension" "ActionController::Rendering#_set_rendered_content_type" "ActionDispatch::Response#content_type" "ActionDispatch::Response#parsed_content_type_header" "ActionDispatch::Response#get_header" "##[]" "##__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" "##[]" "##__getobj__" "ActionDispatch::Response#parse_content_type" "##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" "##[]=" "##__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"

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!

Investigating More Details

Investigating More Details Use memory_profiler gem

GH/SamSaffron/memory_profiler Shows more detailed report with memory usage, allocated objects by gem, etc.

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

Why Don't We Try a Little Bit More Real-world-ish Use Case?

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!

Result Total allocated: 68099 bytes (889 objects) Total retained: 14543 bytes (139 objects)

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

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

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, '"'.freeze)}") # the line 93 end

Do You See What's Wrong with the Line 93?

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

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, '"'.freeze)}") + value.gsub!('"'.freeze, '"'.freeze) + %(#{key}="#{value}") end

The Patch https://github.com/rails/rails/commit/ 9276ea89d2b0be9fdd1ad6590857f8d45a38 c267 https://github.com/rails/rails/commit/ 7d2400ab61c8e3ed95e14d03ba3844e8ba2e 36e4

Result Total allocated: 67740 bytes (878 objects) Total retained: 14543 bytes (139 objects)

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

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

But This Method Won't Be That Serious Performance Hot Spot Because it's just a public helper method

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) + }

But I Didn't Commit This Because I Couldn't See Any Significant Performance Change

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

Maybe We Can Create tidy_bytes! Method Using String#scrub! But I'm not sure how to deal with the Rubinius implementation

Or Maybe It's Time to Think About Totally Newly Designed SafeBuffer?

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

So, I Hope You Got Some Ideas for Your Weekend Hack

And I Hope You Got Some Tools in Your Hands Now

There're So Many Problems and Rooms for Improvement in Rails

(We Need to Get Rid of the Reputation of "the Slowest Framework"...)

Ruby Is Getting Faster and Faster, So Let's Make Rails Faster Too!

Go Ahead and Do Your Hack!

end

end Name: Akira Matsuda GitHub: @amatsuda Twitter: @a_matsuda