Merge pull request rails#51457 from fatkodima/add-sql-queries-to-log

Add queries count to template rendering instrumentation

Author: byroot

actionview/CHANGELOG.md

@@ -1,3 +1,15 @@
+*   Add queries count to template rendering instrumentation
+
+    ```
+    # Before
+    Completed 200 OK in 3804ms (Views: 41.0ms | ActiveRecord: 33.5ms | Allocations: 112788)
+
+    # After
+    Completed 200 OK in 3804ms (Views: 41.0ms | ActiveRecord: 33.5ms (2 queries, 1 cached) | Allocations: 112788)
+    ```
+
+    *fatkodima*
+
 *   Raise `ArgumentError` if `:renderable` object does not respond to `#render_in`
 
     *Sean Doyle*

actionview/test/activerecord/controller_runtime_test.rb

@@ -31,7 +31,7 @@ def redirect
 
     def db_after_render
       render inline: "Hello world"
-      Project.all
+      Project.all.to_a
       ActiveRecord::RuntimeRegistry.sql_runtime += 100.0
     end
   end
@@ -68,7 +68,7 @@ def test_log_with_active_record
     wait
 
     assert_equal 2, @logger.logged(:info).size
-    assert_match(/\(Views: [\d.]+ms \| ActiveRecord: [\d.]+ms \| Allocations: [\d.]+\)/, @logger.logged(:info)[1])
+    assert_match(/\(Views: [\d.]+ms \| ActiveRecord: [\d.]+ms \(0 queries, 0 cached\) \| Allocations: [\d.]+\)/, @logger.logged(:info)[1])
   end
 
   def test_runtime_reset_before_requests
@@ -77,27 +77,27 @@ def test_runtime_reset_before_requests
     wait
 
     assert_equal 2, @logger.logged(:info).size
-    assert_match(/\(Views: [\d.]+ms \| ActiveRecord: [\d.]+ms \| Allocations: [\d.]+\)/, @logger.logged(:info)[1])
+    assert_match(/\(Views: [\d.]+ms \| ActiveRecord: [\d.]+ms \(0 queries, 0 cached\) \| Allocations: [\d.]+\)/, @logger.logged(:info)[1])
   end
 
   def test_log_with_active_record_when_post
     post :create
     wait
-    assert_match(/ActiveRecord: ([1-9][\d.]+)ms \| Allocations: [\d.]+\)/, @logger.logged(:info)[2])
+    assert_match(/ActiveRecord: ([1-9][\d.]+)ms \(1 query, 0 cached\) \| Allocations: [\d.]+\)/, @logger.logged(:info)[2])
   end
 
   def test_log_with_active_record_when_redirecting
     get :redirect
     wait
     assert_equal 3, @logger.logged(:info).size
-    assert_match(/\(ActiveRecord: [\d.]+ms \| Allocations: [\d.]+\)/, @logger.logged(:info)[2])
+    assert_match(/\(ActiveRecord: [\d.]+ms \(0 queries, 0 cached\) \| Allocations: [\d.]+\)/, @logger.logged(:info)[2])
   end
 
   def test_include_time_query_time_after_rendering
     get :db_after_render
     wait
 
     assert_equal 2, @logger.logged(:info).size
-    assert_match(/\(Views: [\d.]+ms \| ActiveRecord: ([1-9][\d.]+)ms \| Allocations: [\d.]+\)/, @logger.logged(:info)[1])
+    assert_match(/\(Views: [\d.]+ms \| ActiveRecord: ([1-9][\d.]+)ms \(1 query, 0 cached\) \| Allocations: [\d.]+\)/, @logger.logged(:info)[1])
   end
 end

activerecord/lib/active_record/railties/controller_runtime.rb

@@ -11,7 +11,14 @@ module ControllerRuntime # :nodoc:
       module ClassMethods # :nodoc:
         def log_process_action(payload)
           messages, db_runtime = super, payload[:db_runtime]
-          messages << ("ActiveRecord: %.1fms" % db_runtime.to_f) if db_runtime
+
+          if db_runtime
+            queries_count = payload[:queries_count] || 0
+            cached_queries_count = payload[:cached_queries_count] || 0
+            messages << ("ActiveRecord: %.1fms (%d %s, %d cached)" % [db_runtime.to_f, queries_count,
+                                                                      "query".pluralize(queries_count), cached_queries_count])
+          end
+
           messages
         end
       end
@@ -34,11 +41,11 @@ def process_action(action, *args)
 
         def cleanup_view_runtime
           if logger && logger.info?
-            db_rt_before_render = ActiveRecord::RuntimeRegistry.reset
+            db_rt_before_render = ActiveRecord::RuntimeRegistry.reset_runtimes
             self.db_runtime = (db_runtime || 0) + db_rt_before_render
             runtime = super
             queries_rt = ActiveRecord::RuntimeRegistry.sql_runtime - ActiveRecord::RuntimeRegistry.async_sql_runtime
-            db_rt_after_render = ActiveRecord::RuntimeRegistry.reset
+            db_rt_after_render = ActiveRecord::RuntimeRegistry.reset_runtimes
             self.db_runtime += db_rt_after_render
             runtime - queries_rt
           else
@@ -49,7 +56,9 @@ def cleanup_view_runtime
         def append_info_to_payload(payload)
           super
 
-          payload[:db_runtime] = (db_runtime || 0) + ActiveRecord::RuntimeRegistry.reset
+          payload[:db_runtime] = (db_runtime || 0) + ActiveRecord::RuntimeRegistry.reset_runtimes
+          payload[:queries_count] = ActiveRecord::RuntimeRegistry.reset_queries_count
+          payload[:cached_queries_count] = ActiveRecord::RuntimeRegistry.reset_cached_queries_count
         end
     end
   end

activerecord/lib/active_record/runtime_registry.rb

@@ -25,15 +25,54 @@ def async_sql_runtime=(runtime)
       ActiveSupport::IsolatedExecutionState[:active_record_async_sql_runtime] = runtime
     end
 
+    def queries_count
+      ActiveSupport::IsolatedExecutionState[:active_record_queries_count] ||= 0
+    end
+
+    def queries_count=(count)
+      ActiveSupport::IsolatedExecutionState[:active_record_queries_count] = count
+    end
+
+    def cached_queries_count
+      ActiveSupport::IsolatedExecutionState[:active_record_cached_queries_count] ||= 0
+    end
+
+    def cached_queries_count=(count)
+      ActiveSupport::IsolatedExecutionState[:active_record_cached_queries_count] = count
+    end
+
     def reset
+      reset_runtimes
+      reset_queries_count
+      reset_cached_queries_count
+    end
+
+    def reset_runtimes
       rt, self.sql_runtime = sql_runtime, 0.0
       self.async_sql_runtime = 0.0
       rt
     end
+
+    def reset_queries_count
+      qc = queries_count
+      self.queries_count = 0
+      qc
+    end
+
+    def reset_cached_queries_count
+      qc = cached_queries_count
+      self.cached_queries_count = 0
+      qc
+    end
   end
 end
 
 ActiveSupport::Notifications.monotonic_subscribe("sql.active_record") do |name, start, finish, id, payload|
+  unless ["SCHEMA", "TRANSACTION"].include?(payload[:name])
+    ActiveRecord::RuntimeRegistry.queries_count += 1
+    ActiveRecord::RuntimeRegistry.cached_queries_count += 1 if payload[:cached]
+  end
+
   runtime = (finish - start) * 1_000.0
 
   if payload[:async]