diff --git a/lib/time_bandits/monkey_patches/active_record.rb b/lib/time_bandits/monkey_patches/active_record.rb index 2529d20..44bdd96 100644 --- a/lib/time_bandits/monkey_patches/active_record.rb +++ b/lib/time_bandits/monkey_patches/active_record.rb @@ -1,158 +1,6 @@ -# this file monkey patches class ActiveRecord::LogSubscriber -# to count the number of sql statements being executed -# and the number of query cache hits -# it needs to be adapted to each new rails version - -require "active_record/log_subscriber" - -module ActiveRecord - class LogSubscriber - IGNORE_PAYLOAD_NAMES = ["SCHEMA", "EXPLAIN"] unless defined?(IGNORE_PAYLOAD_NAMES) - - if Gem::Version.new(ActiveRecord::VERSION::STRING) >= Gem::Version.new("7.1.0") - def self.reset_runtime - ActiveRecord::RuntimeRegistry.reset - end - def self.runtime - ActiveRecord::RuntimeRegistry.sql_runtime - end - def self.runtime=(value) - ActiveRecord::RuntimeRegistry.sql_runtime = value - end - end - - def self.call_count=(value) - Thread.current.thread_variable_set(:active_record_sql_call_count, value) - end - - def self.call_count - Thread.current.thread_variable_get(:active_record_sql_call_count) || - Thread.current.thread_variable_set(:active_record_sql_call_count, 0) - end - - def self.query_cache_hits=(value) - Thread.current.thread_variable_set(:active_record_sql_query_cache_hits, value) - end - - def self.query_cache_hits - Thread.current.thread_variable_get(:active_record_sql_query_cache_hits) || - Thread.current.thread_variable_set(:active_record_sql_query_cache_hits, 0) - end - - def self.reset_call_count - calls = call_count - self.call_count = 0 - calls - end - - def self.reset_query_cache_hits - hits = query_cache_hits - self.query_cache_hits = 0 - hits - end - - remove_method :sql - def sql(event) - payload = event.payload - - self.class.runtime += event.duration - self.class.call_count += 1 - self.class.query_cache_hits += 1 if payload[:cached] || payload[:name] == "CACHE" - - return unless logger.debug? - - return if IGNORE_PAYLOAD_NAMES.include?(payload[:name]) - - log_sql_statement(payload, event) - end - - private - def log_sql_statement(payload, event) - name = if payload[:async] - "ASYNC #{payload[:name]} (#{payload[:lock_wait].round(1)}ms) (db time #{event.duration.round(1)}ms)" - else - "#{payload[:name]} (#{event.duration.round(1)}ms)" - end - name = "CACHE #{name}" if payload[:cached] - sql = payload[:sql] - binds = render_binds(payload) - - name = colorize_payload_name(name, payload[:name]) - sql = colorize_sql(sql) if colorize_logging - - debug " #{name} #{sql}#{binds}" - end - - if Gem::Version.new(ActiveRecord::VERSION::STRING) >= Gem::Version.new("7.1.0") - def render_binds(payload) - binds = nil - if payload[:binds]&.any? - casted_params = type_casted_binds(payload[:type_casted_binds]) - - binds = [] - payload[:binds].each_with_index do |attr, i| - attribute_name = if attr.respond_to?(:name) - attr.name - elsif attr.respond_to?(:[]) && attr[i].respond_to?(:name) - attr[i].name - else - nil - end - - filtered_params = filter(attribute_name, casted_params[i]) - - binds << render_bind(attr, filtered_params) - end - binds = binds.inspect - binds.prepend(" ") - end - return binds - end - def colorize_sql(sql) - color(sql, sql_color(sql), bold: true) - end - else - def render_binds(payload) - binds = nil - unless (payload[:binds] || []).empty? - casted_params = type_casted_binds(payload[:type_casted_binds]) - binds = " " + payload[:binds].zip(casted_params).map { |attr, value| - render_bind(attr, value) - }.inspect - end - return binds - end - def colorize_sql(sql) - color(sql, sql_color(sql), true) - end - end - end - - require "active_record/railties/controller_runtime" - - module Railties - module ControllerRuntime - remove_method :cleanup_view_runtime - def cleanup_view_runtime - # this method has been redefined to do nothing for activerecord on purpose - super - end - - remove_method :append_info_to_payload - def append_info_to_payload(payload) - super - if ActiveRecord::Base.connected? - payload[:db_runtime] = TimeBandits::TimeConsumers::Database.instance.consumed - end - end - - module ClassMethods - # this method has been redefined to do nothing for activerecord on purpose - remove_method :log_process_action - def log_process_action(payload) - super - end - end - end - end +if Gem::Version.new(ActiveRecord::VERSION::STRING) < Gem::Version.new("7.1.0") + require_relative "active_record/log_subscriber" +else + require_relative "active_record/runtime_registry" end +require_relative "active_record/railties/controller_runtime" diff --git a/lib/time_bandits/monkey_patches/active_record/log_subscriber.rb b/lib/time_bandits/monkey_patches/active_record/log_subscriber.rb new file mode 100644 index 0000000..5e82504 --- /dev/null +++ b/lib/time_bandits/monkey_patches/active_record/log_subscriber.rb @@ -0,0 +1,77 @@ +# This file monkey patches class ActiveRecord::LogSubscriber to count +# the number of sql statements being executed and the number of query +# cache hits, but is only used for Rails versions before 7.1.0. + +require "active_record/log_subscriber" + +module ActiveRecord + class LogSubscriber + IGNORE_PAYLOAD_NAMES = ["SCHEMA", "EXPLAIN"] unless defined?(IGNORE_PAYLOAD_NAMES) + + def self.call_count=(value) + Thread.current.thread_variable_set(:active_record_sql_call_count, value) + end + + def self.call_count + Thread.current.thread_variable_get(:active_record_sql_call_count) || + Thread.current.thread_variable_set(:active_record_sql_call_count, 0) + end + + def self.query_cache_hits=(value) + Thread.current.thread_variable_set(:active_record_sql_query_cache_hits, value) + end + + def self.query_cache_hits + Thread.current.thread_variable_get(:active_record_sql_query_cache_hits) || + Thread.current.thread_variable_set(:active_record_sql_query_cache_hits, 0) + end + + def self.reset_call_count + calls = call_count + self.call_count = 0 + calls + end + + def self.reset_query_cache_hits + hits = query_cache_hits + self.query_cache_hits = 0 + hits + end + + remove_method :sql + def sql(event) + payload = event.payload + + self.class.runtime += event.duration + self.class.call_count += 1 + self.class.query_cache_hits += 1 if payload[:cached] || payload[:name] == "CACHE" + + return unless logger.debug? + + return if IGNORE_PAYLOAD_NAMES.include?(payload[:name]) + + log_sql_statement(payload, event) + end + + private + def log_sql_statement(payload, event) + name = "#{payload[:name]} (#{event.duration.round(1)}ms)" + name = "CACHE #{name}" if payload[:cached] + sql = payload[:sql] + binds = nil + + unless (payload[:binds] || []).empty? + casted_params = type_casted_binds(payload[:type_casted_binds]) + binds = " " + payload[:binds].zip(casted_params).map { |attr, value| + render_bind(attr, value) + }.inspect + end + + name = colorize_payload_name(name, payload[:name]) + sql = color(sql, sql_color(sql), true) + + debug " #{name} #{sql}#{binds}" + end + end + +end diff --git a/lib/time_bandits/monkey_patches/active_record/railties/controller_runtime.rb b/lib/time_bandits/monkey_patches/active_record/railties/controller_runtime.rb new file mode 100644 index 0000000..48cd4de --- /dev/null +++ b/lib/time_bandits/monkey_patches/active_record/railties/controller_runtime.rb @@ -0,0 +1,29 @@ +require "active_record/railties/controller_runtime" + +module ActiveRecord + module Railties + module ControllerRuntime + remove_method :cleanup_view_runtime + def cleanup_view_runtime + # this method has been redefined to do nothing for activerecord on purpose + super + end + + remove_method :append_info_to_payload + def append_info_to_payload(payload) + super + if ActiveRecord::Base.connected? + payload[:db_runtime] = TimeBandits::TimeConsumers::Database.instance.consumed + end + end + + module ClassMethods + # this method has been redefined to do nothing for activerecord on purpose + remove_method :log_process_action + def log_process_action(payload) + super + end + end + end + end +end diff --git a/lib/time_bandits/monkey_patches/active_record/runtime_registry.rb b/lib/time_bandits/monkey_patches/active_record/runtime_registry.rb new file mode 100644 index 0000000..0a28831 --- /dev/null +++ b/lib/time_bandits/monkey_patches/active_record/runtime_registry.rb @@ -0,0 +1,50 @@ +# This file monkey patches class ActiveRecord::RuntimeRegistry to +# additionally store call counts and cache hits and subscribes an +# event listener to manage those counters. + +require "active_record/runtime_registry" + +module ActiveRecord + module RuntimeRegistry + + def self.call_count + ActiveSupport::IsolatedExecutionState[:active_record_sql_call_count] ||= 0 + end + + def self.call_count=(value) + ActiveSupport::IsolatedExecutionState[:active_record_sql_call_count] = value + end + + def self.query_cache_hits + ActiveSupport::IsolatedExecutionState[:active_record_sql_query_cache_hits] ||= 0 + end + + def self.query_cache_hits=(value) + ActiveSupport::IsolatedExecutionState[:active_record_sql_query_cache_hits] = value + end + + alias_method :reset_runtime, :reset + alias_method :runtime, :sql_runtime + alias_method :runtime=, :sql_runtime= + + def self.reset_call_count + calls = call_count + self.call_count = 0 + calls + end + + def self.reset_query_cache_hits + hits = query_cache_hits + self.query_cache_hits = 0 + hits + end + + end +end + +require "active_support/notifications" + +ActiveSupport::Notifications.subscribe("sql.active_record") do |event| + ActiveRecord::RuntimeRegistry.call_count += 1 + ActiveRecord::RuntimeRegistry.query_cache_hits += 1 if event.payload[:cached] +end diff --git a/lib/time_bandits/time_consumers/database.rb b/lib/time_bandits/time_consumers/database.rb index 412a867..6470c24 100644 --- a/lib/time_bandits/time_consumers/database.rb +++ b/lib/time_bandits/time_consumers/database.rb @@ -13,6 +13,18 @@ class Database < TimeBandits::TimeConsumers::BaseConsumer fields :time, :calls, :sql_query_cache_hits format "ActiveRecord: %.3fms(%dq,%dh)", :time, :calls, :sql_query_cache_hits + class << self + if Gem::Version.new(ActiveRecord::VERSION::STRING) >= Gem::Version.new("7.1.0") + def metrics_store + ActiveRecord::RuntimeRegistry + end + else + def metrics_store + ActiveRecord::LogSubscriber + end + end + end + def reset reset_stats super @@ -27,13 +39,13 @@ def consumed end def current_runtime - Database.instance.time + ActiveRecord::LogSubscriber.runtime + Database.instance.time + self.class.metrics_store.runtime end private def reset_stats - s = ActiveRecord::LogSubscriber + s = self.class.metrics_store hits = s.reset_query_cache_hits calls = s.reset_call_count time = s.reset_runtime diff --git a/test/unit/database_test.rb b/test/unit/database_test.rb index 78d48a0..a7da6e5 100644 --- a/test/unit/database_test.rb +++ b/test/unit/database_test.rb @@ -10,6 +10,15 @@ def setup TimeBandits.reset @old_logger = ActiveRecord::Base.logger ActiveRecord::Base.logger = Logger.new($stdout) + ActiveRecord::Base.logger.level = Logger::DEBUG + + ActiveRecord::Base.establish_connection( + adapter: "mysql2", + username: "root", + encoding: "utf8", + host: ENV['MYSQL_HOST'] || "127.0.0.1", + port: (ENV['MYSQL_PORT'] || 3601).to_i + ) end def teardown @@ -28,18 +37,18 @@ def teardown end test "formatting" do - log_subscriber.runtime += 1.234 - log_subscriber.call_count += 3 - log_subscriber.query_cache_hits += 1 + metrics_store.runtime += 1.234 + metrics_store.call_count += 3 + metrics_store.query_cache_hits += 1 TimeBandits.consumed assert_equal "ActiveRecord: 1.234ms(3q,1h)", TimeBandits.runtime end test "accessing current runtime" do - log_subscriber.runtime += 1.234 + metrics_store.runtime += 1.234 assert_equal 1.234, TimeBandits.consumed - assert_equal 0, log_subscriber.runtime - log_subscriber.runtime += 4.0 + assert_equal 0, metrics_store.runtime + metrics_store.runtime += 4.0 assert_equal 5.234, bandit.current_runtime assert_equal "ActiveRecord: 1.234ms(0q,0h)", TimeBandits.runtime end @@ -52,12 +61,38 @@ def teardown assert_nil log_subscriber.new.sql(event) end + test "instrumentation records runtimes at log level debug" do + ActiveRecord::Base.logger.stubs(:debug) + ActiveRecord::Base.connection.execute "SELECT 1" + bandit.consumed + assert(bandit.current_runtime > 0) + # 2 calls, because one configures the connection + assert_equal 2, bandit.calls + assert_equal 0, bandit.sql_query_cache_hits + end + + test "instrumentation records runtimes at log level error" do + skip if Gem::Version.new(ActiveRecord::VERSION::STRING) < Gem::Version.new("7.1.0") + ActiveRecord::Base.logger.level = Logger::ERROR + ActiveRecord::LogSubscriber.expects(:sql).never + ActiveRecord::Base.connection.execute "SELECT 1" + bandit.consumed + assert(bandit.current_runtime > 0) + # 2 calls, because one configures the connection + assert_equal 2, bandit.calls + assert_equal 0, bandit.sql_query_cache_hits + end + private def bandit TimeBandits::TimeConsumers::Database.instance end + def metrics_store + TimeBandits::TimeConsumers::Database.metrics_store + end + def log_subscriber ActiveRecord::LogSubscriber end