Merge pull request #46041 from Shopify/fix-ar-log-sub

Fix Active Record :db_runtime metric

actionview/test/activerecord/controller_runtime_test.rb

@@ -19,7 +19,7 @@ class ControllerRuntimeLogSubscriberTest < ActionController::TestCase
     end
 
     def create
-      ActiveRecord::LogSubscriber.runtime += 100
+      ActiveRecord::RuntimeRegistry.sql_runtime += 100.0
       Project.last
       redirect_to "/"
     end
@@ -32,7 +32,7 @@ class ControllerRuntimeLogSubscriberTest < ActionController::TestCase
     def db_after_render
       render inline: "Hello world"
       Project.all
-      ActiveRecord::LogSubscriber.runtime += 100
+      ActiveRecord::RuntimeRegistry.sql_runtime += 100.0
     end
   end
 
@@ -72,7 +72,7 @@ class ControllerRuntimeLogSubscriberTest < ActionController::TestCase
   end
 
   def test_runtime_reset_before_requests
-    ActiveRecord::LogSubscriber.runtime += 12345
+    ActiveRecord::RuntimeRegistry.sql_runtime += 12345.0
     get :zero
     wait
 

activerecord/lib/active_record/log_subscriber.rb

@@ -7,16 +7,24 @@ module ActiveRecord
     class_attribute :backtrace_cleaner, default: ActiveSupport::BacktraceCleaner.new
 
     def self.runtime=(value)
+      ActiveSupport::Deprecation.warn(<<-MSG.squish)
+        ActiveRecord::LogSubscriber.runtime= is deprecated and will be removed in Rails 7.2.
+      MSG
       ActiveRecord::RuntimeRegistry.sql_runtime = value
     end
 
     def self.runtime
-      ActiveRecord::RuntimeRegistry.sql_runtime ||= 0
+      ActiveSupport::Deprecation.warn(<<-MSG.squish)
+        ActiveRecord::LogSubscriber.runtime is deprecated and will be removed in Rails 7.2.
+      MSG
+      ActiveRecord::RuntimeRegistry.sql_runtime
     end
 
     def self.reset_runtime
-      rt, self.runtime = runtime, 0
+      ActiveSupport::Deprecation.warn(<<-MSG.squish)
-      rt
+        ActiveRecord::LogSubscriber.reset_runtime is deprecated and will be removed in Rails 7.2.
+      MSG
+      ActiveRecord::RuntimeRegistry.reset
     end
 
     def strict_loading_violation(event)
@@ -29,8 +37,6 @@ module ActiveRecord
     subscribe_log_level :strict_loading_violation, :debug
 
     def sql(event)
-      self.class.runtime += event.duration
-
       payload = event.payload
 
       return if IGNORE_PAYLOAD_NAMES.include?(payload[:name])

activerecord/lib/active_record/railties/controller_runtime.rb

@@ -1,7 +1,7 @@
 # frozen_string_literal: true
 
 require "active_support/core_ext/module/attr_internal"
-require "active_record/log_subscriber"
+require "active_record/runtime_registry"
 
 module ActiveRecord
   module Railties # :nodoc:
@@ -23,16 +23,16 @@ module ActiveRecord
           # We also need to reset the runtime before each action
           # because of queries in middleware or in cases we are streaming
           # and it won't be cleaned up by the method below.
-          ActiveRecord::LogSubscriber.reset_runtime
+          ActiveRecord::RuntimeRegistry.reset
           super
         end
 
         def cleanup_view_runtime
           if logger && logger.info? && ActiveRecord::Base.connected?
-            db_rt_before_render = ActiveRecord::LogSubscriber.reset_runtime
+            db_rt_before_render = ActiveRecord::RuntimeRegistry.reset
             self.db_runtime = (db_runtime || 0) + db_rt_before_render
             runtime = super
-            db_rt_after_render = ActiveRecord::LogSubscriber.reset_runtime
+            db_rt_after_render = ActiveRecord::RuntimeRegistry.reset
             self.db_runtime += db_rt_after_render
             runtime - db_rt_after_render
           else
@@ -43,7 +43,7 @@ module ActiveRecord
         def append_info_to_payload(payload)
           super
           if ActiveRecord::Base.connected?
-            payload[:db_runtime] = (db_runtime || 0) + ActiveRecord::LogSubscriber.reset_runtime
+            payload[:db_runtime] = (db_runtime || 0) + ActiveRecord::RuntimeRegistry.reset
           end
         end
     end

activerecord/lib/active_record/railties/job_runtime.rb

@@ -1,6 +1,6 @@
 # frozen_string_literal: true
 
-require "active_record/log_subscriber"
+require "active_record/runtime_registry"
 
 module ActiveRecord
   module Railties # :nodoc:
@@ -9,9 +9,9 @@ module ActiveRecord
         def instrument(operation, payload = {}, &block)
           if operation == :perform && block
             super(operation, payload) do
-              db_runtime_before_perform = ActiveRecord::LogSubscriber.runtime
+              db_runtime_before_perform = ActiveRecord::RuntimeRegistry.sql_runtime
               result = block.call
-              payload[:db_runtime] = ActiveRecord::LogSubscriber.runtime - db_runtime_before_perform
+              payload[:db_runtime] = ActiveRecord::RuntimeRegistry.sql_runtime - db_runtime_before_perform
               result
             end
           else

activerecord/lib/active_record/runtime_registry.rb

@@ -10,11 +10,20 @@ module ActiveRecord
     extend self
 
     def sql_runtime
-      ActiveSupport::IsolatedExecutionState[:active_record_sql_runtime]
+      ActiveSupport::IsolatedExecutionState[:active_record_sql_runtime] ||= 0.0
     end
 
     def sql_runtime=(runtime)
       ActiveSupport::IsolatedExecutionState[:active_record_sql_runtime] = runtime
     end
+
+    def reset
+      rt, self.sql_runtime = sql_runtime, 0.0
+      rt
+    end
   end
 end
+
+ActiveSupport::Notifications.monotonic_subscribe("sql.active_record") do |name, start, finish, id, payload|
+  ActiveRecord::RuntimeRegistry.sql_runtime += (finish - start) * 1_000.0
+end

activerecord/test/activejob/job_runtime_test.rb

@@ -8,21 +8,21 @@ class JobRuntimeTest < ActiveSupport::TestCase
     include ActiveRecord::Railties::JobRuntime
 
     def perform(*)
-      ActiveRecord::LogSubscriber.runtime += 42
+      ActiveRecord::RuntimeRegistry.sql_runtime += 42.0
     end
   end
 
   test "job notification payload includes db_runtime" do
-    ActiveRecord::LogSubscriber.runtime = 0
+    ActiveRecord::RuntimeRegistry.sql_runtime = 0.0
 
     assert_equal 42, notification_payload[:db_runtime]
   end
 
   test "db_runtime tracks database runtime for job only" do
-    ActiveRecord::LogSubscriber.runtime = 100
+    ActiveRecord::RuntimeRegistry.sql_runtime = 100.0
 
-    assert_equal 42, notification_payload[:db_runtime]
+    assert_equal 42.0, notification_payload[:db_runtime]
-    assert_equal 142, ActiveRecord::LogSubscriber.runtime
+    assert_equal 142.0, ActiveRecord::RuntimeRegistry.sql_runtime
   end
 
   private

activerecord/test/cases/log_subscriber_test.rb

@@ -247,10 +247,6 @@ class LogSubscriberTest < ActiveRecord::TestCase
     assert_equal 0, @logger.logged(:debug).size
   end
 
-  def test_initializes_runtime
-    Thread.new { assert_equal 0, ActiveRecord::LogSubscriber.runtime }.join
-  end
-
   if ActiveRecord::Base.connection.prepared_statements
     def test_where_in_binds_logging_include_attribute_names
       Developer.where(id: [1, 2, 3, 4, 5]).load