-
-
Notifications
You must be signed in to change notification settings - Fork 134
Description
I was investigating an issue with our request logs where the db_runtime could sometimes be larger than the total request time and it looks like the issue originates from this gem or from our configuration of it.
I was able to narrow down the issue to a case of "double counting" of the sql query times. We are on Rails 8.0.3 and I monkey-patched ActiveRecord's RuntimeRegistry like so to find out that the #sql_runtime= method was being called twice for each query.
ActiveSupport::Notifications.monotonic_subscribe("sql.active_record") do |name, start, finish, id, payload|
Rails.logger.info "DB: start: #{start}, finish: #{finish}, dur: #{(finish - start) * 1_000.0} -- #{payload[:name]}"
end
# Monkey-patch:
module ActiveRecord
module RuntimeRegistry
def self.sql_runtime=(runtime)
Rails.logger.warn "Setting sql_runtime to #{runtime} -- #{caller(1..1).first}"
ActiveSupport::IsolatedExecutionState[:active_record_sql_runtime] = runtime
end
end
endThis results in logs like this when hitting the Rails server with a new request:
2025-09-26 18:25:56.172296 W [1:puma srv tp 005] Rails -- Setting sql_runtime to 1.8534999981056899 -- /usr/local/bundle/gems/activerecord-8.0.3/lib/active_record/runtime_registry.rb:81:in 'block in <main>'
2025-09-26 18:25:56.172322 W [1:puma srv tp 005] Rails -- DB: start: 191623.069111467, finish: 191623.070964967, dur: 1.8534999981056899 -- User Load
2025-09-26 18:25:56.172342 W [1:puma srv tp 005] Rails -- Setting sql_runtime to 3.7675830021034926 -- /usr/local/bundle/gems/rails_semantic_logger-4.18.0/lib/rails_semantic_logger/active_record/log_subscriber.rb:11:in 'RailsSemanticLogger::ActiveRecord::LogSubscriber.runtime='
Here the "User Load" query took 1.85ms, but the sql_runtime was set to 3.76ms as a result of adding 1.85ms twice. Once by the ActiveRecord::RuntimeRegistry internals and once by the rails_semantic_logger ActiveRecord::LogSubscriber.
Is it possible that since the first implementation of the ActiveRecord::LogSubscriber Rails has changed the way it registers sql runtime to use ActiveSupport::Instrumentation but those changes have not yet been reflected in rails_semantic_logger?