ActionCable logger.debug call optimisation

Gemfile

source "https://rubygems.org"

git_source(:github) { |repo| "https://github.com/#{repo}.git" }

gem "rails", path: "../" #github: "rails/rails"
gem "benchmark-ips"
gem "kalibera"

logger_performance_test.rb

require "ostruct"
require 'benchmark/ips'
require "active_support"
require_relative "lib/action_cable/server/broadcasting"
require_relative "lib/action_cable/server/connections"
require_relative "lib/action_cable/subscription_adapter/base"
require_relative "test/stubs/test_adapter"
require_relative "test/stubs/test_server"

module ActionCable
  module Server
    module Broadcasting
      class OptimizedBroadcaster < Broadcaster
        # Patch broadcast to wrap logger.debug to block to avoid evaluating it if log level isn't debug
        def broadcast(message)
          server.logger.debug { "[ActionCable] Broadcasting to #{broadcasting}: #{message.inspect}" }

          payload = { broadcasting: broadcasting, message: message, coder: coder }
          ActiveSupport::Notifications.instrument("broadcast.action_cable", payload) do
            encoded = coder ? coder.encode(message) : message
            server.pubsub.broadcast broadcasting, encoded
          end
        end
      end
    end
  end
end

# Enumerate some representative scenarios here.
#
# It is very easy to make an optimization that improves performance for a
# specific scenario you care about but regresses on other common cases.
# Therefore, you should test your change against a list of representative
# scenarios. Ideally, they should be based on real-world scenarios extracted
# from production applications.
SCENARIOS = {
  "small payload"  => { "id" => 123, "email" => "myemail@gmail.com", "name" => "Alex Emelyanov" },
  "large payload"  => 100.times.map do |i|
    { "id" => i, "cluster_id" => i, "kind" => "deploy_info", "data" => "Project eb354deb undeploy started", "created_at" => "2019-05-28T13:35:45.293Z", "updated_at" => "2019-05-28T13:35:45.293Z", "project_id" => i, "component_id" => nil }
  end
}

SCENARIOS.each_pair do |payload_name, payload|
  Benchmark.ips do |x|
    x.config(:stats => :bootstrap, :confidence => 99)

    [
      ActionCable::Server::Broadcasting::Broadcaster,
      ActionCable::Server::Broadcasting::OptimizedBroadcaster,
    ].each do |broadcaster_klass|
      [:debug, :info].each do |log_level|
        server = TestServer.new
        server.logger.level = log_level
        broadcaster = broadcaster_klass.new(server, 'test', coder: ActiveSupport::JSON)

        x.report("#{payload_name} with #{broadcaster_klass.to_s.split(':').last} log_level=#{log_level}") do
          broadcaster.broadcast(payload)
        end
      end
    end

    x.compare!
  end
end

results.log

$ ruby logger_performance_test.rb                                                                                                                                           2.6.2
Warming up --------------------------------------
small payload with Broadcaster log_level=debug
                         3.241k i/100ms
small payload with Broadcaster log_level=info
                         3.968k i/100ms
small payload with OptimizedBroadcaster log_level=debug
                         3.417k i/100ms
small payload with OptimizedBroadcaster log_level=info
                         4.954k i/100ms
Calculating -------------------------------------
small payload with Broadcaster log_level=debug
                         32.300k (± 4.0%) i/s -    158.809k in   5.015592s
small payload with Broadcaster log_level=info
                         40.454k (± 2.3%) i/s -    202.368k in   5.028088s
small payload with OptimizedBroadcaster log_level=debug
                         32.919k (± 2.9%) i/s -    164.016k in   5.019224s
small payload with OptimizedBroadcaster log_level=info
                         51.405k (± 1.1%) i/s -    257.608k in   5.016018s
                   with 99.0% confidence

Comparison:
small payload with OptimizedBroadcaster log_level=info:     51404.7 i/s
small payload with Broadcaster          log_level=info:     40453.9 i/s - 1.27x  (± 0.03) slower
small payload with OptimizedBroadcaster log_level=debug:    32918.8 i/s - 1.56x  (± 0.05) slower
small payload with Broadcaster          log_level=debug:    32299.8 i/s - 1.59x  (± 0.07) slower
                   with 99.0% confidence

Warming up --------------------------------------
large payload with Broadcaster log_level=debug
                        22.000  i/100ms
large payload with Broadcaster log_level=info
                        23.000  i/100ms
large payload with OptimizedBroadcaster log_level=debug
                        22.000  i/100ms
large payload with OptimizedBroadcaster log_level=info
                        28.000  i/100ms
Calculating -------------------------------------
large payload with Broadcaster log_level=debug
                        224.112  (± 1.9%) i/s -      1.122k in   5.023456s
large payload with Broadcaster log_level=info
                        221.001  (± 1.8%) i/s -      1.127k in   5.112207s
large payload with OptimizedBroadcaster log_level=debug
                        219.062  (± 2.2%) i/s -      1.100k in   5.042578s
large payload with OptimizedBroadcaster log_level=info
                        283.700  (± 1.7%) i/s -      1.428k in   5.045466s
                   with 99.0% confidence

Comparison:
large payload with OptimizedBroadcaster log_level=info:      283.7 i/s
large payload with Broadcaster          log_level=debug:     224.1 i/s - 1.27x  (± 0.03) slower
large payload with Broadcaster          log_level=info:      221.0 i/s - 1.28x  (± 0.03) slower
large payload with OptimizedBroadcaster log_level=debug:     219.1 i/s - 1.29x  (± 0.04) slower
                   with 99.0% confidence