From 6369e92fbbdd6d56cfd1bc5ac995ee5fc4fda8d6 Mon Sep 17 00:00:00 2001 From: fatkodima Date: Mon, 1 Apr 2024 03:25:32 +0300 Subject: [PATCH] Add queries count to template rendering instrumentation --- actionview/CHANGELOG.md | 12 ++++++ .../activerecord/controller_runtime_test.rb | 12 +++--- .../railties/controller_runtime.rb | 17 ++++++-- .../lib/active_record/runtime_registry.rb | 39 +++++++++++++++++++ 4 files changed, 70 insertions(+), 10 deletions(-) diff --git a/actionview/CHANGELOG.md b/actionview/CHANGELOG.md index de7146138a9e2..6ea40856e0fec 100644 --- a/actionview/CHANGELOG.md +++ b/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* diff --git a/actionview/test/activerecord/controller_runtime_test.rb b/actionview/test/activerecord/controller_runtime_test.rb index 334b2d02b3ef8..e19d3f349b92e 100644 --- a/actionview/test/activerecord/controller_runtime_test.rb +++ b/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,20 +77,20 @@ 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 @@ -98,6 +98,6 @@ def test_include_time_query_time_after_rendering 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 diff --git a/activerecord/lib/active_record/railties/controller_runtime.rb b/activerecord/lib/active_record/railties/controller_runtime.rb index 0acb366306138..a9ec0e70f049a 100644 --- a/activerecord/lib/active_record/railties/controller_runtime.rb +++ b/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 diff --git a/activerecord/lib/active_record/runtime_registry.rb b/activerecord/lib/active_record/runtime_registry.rb index 408b36c3aaa17..3b35779de2db4 100644 --- a/activerecord/lib/active_record/runtime_registry.rb +++ b/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]