Inspecting and Crafting Rails

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