Skip to content

db_runtime metric in requests logs is double counted #273

@jeromepl

Description

@jeromepl

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
end

This 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?

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions