From 6380aee182a6acb4f5062c5aa377d290e696e4b7 Mon Sep 17 00:00:00 2001 From: zvkemp Date: Mon, 20 Apr 2020 13:28:35 -0700 Subject: [PATCH] add additional instrumentation block for ActionView layout rendering --- actionview/CHANGELOG.md | 4 ++ actionview/lib/action_view/log_subscriber.rb | 30 ++++++++--- .../renderer/collection_renderer.rb | 1 + .../action_view/renderer/partial_renderer.rb | 3 +- .../action_view/renderer/template_renderer.rb | 9 ++-- .../test/template/log_subscriber_test.rb | 52 +++++++++++++++++++ 6 files changed, 87 insertions(+), 12 deletions(-) diff --git a/actionview/CHANGELOG.md b/actionview/CHANGELOG.md index 398a7f2553..1eaebca45f 100644 --- a/actionview/CHANGELOG.md +++ b/actionview/CHANGELOG.md @@ -1,3 +1,7 @@ +* Instrument layout rendering in `TemplateRenderer#render_with_layout` as `render_layout.action_view`, and include (when necessary) the layout's virtual path in notification payloads for collection and partial renders. + + *Zach Kemp* + * `ActionView::Base.annotate_template_file_names` annotates HTML output with template file names. *Joel Hawksley*, *Aaron Patterson* diff --git a/actionview/lib/action_view/log_subscriber.rb b/actionview/lib/action_view/log_subscriber.rb index 2ce502ba9b..018830aaa3 100644 --- a/actionview/lib/action_view/log_subscriber.rb +++ b/actionview/lib/action_view/log_subscriber.rb @@ -32,19 +32,26 @@ module ActionView end end + def render_layout(event) + info do + message = +" Rendered layout #{from_rails_root(event.payload[:identifier])}" + message << " (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})" + end + end + def render_collection(event) identifier = event.payload[:identifier] || "templates" debug do - " Rendered collection of #{from_rails_root(identifier)}" \ - " #{render_count(event.payload)} (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})" + message = +" Rendered collection of #{from_rails_root(identifier)}" + message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout] + message << " #{render_count(event.payload)} (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})" + message end end def start(name, id, payload) - if name == "render_template.action_view" - log_rendering_start(payload) - end + log_rendering_start(payload, name) super end @@ -82,9 +89,18 @@ module ActionView end end - def log_rendering_start(payload) + def log_rendering_start(payload, name) debug do - message = +" Rendering #{from_rails_root(payload[:identifier])}" + qualifier = + if name == "render_template.action_view" + "" + elsif name == "render_layout.action_view" + "layout " + end + + return unless qualifier + + message = +" Rendering #{qualifier}#{from_rails_root(payload[:identifier])}" message << " within #{from_rails_root(payload[:layout])}" if payload[:layout] message end diff --git a/actionview/lib/action_view/renderer/collection_renderer.rb b/actionview/lib/action_view/renderer/collection_renderer.rb index bfd3aee838..d9c8361d86 100644 --- a/actionview/lib/action_view/renderer/collection_renderer.rb +++ b/actionview/lib/action_view/renderer/collection_renderer.rb @@ -144,6 +144,7 @@ module ActionView ActiveSupport::Notifications.instrument( "render_collection.action_view", identifier: identifier, + layout: layout && layout.virtual_path, count: collection.size ) do |payload| spacer = if @options.key?(:spacer_template) diff --git a/actionview/lib/action_view/renderer/partial_renderer.rb b/actionview/lib/action_view/renderer/partial_renderer.rb index cb68d0acdc..1503ba734d 100644 --- a/actionview/lib/action_view/renderer/partial_renderer.rb +++ b/actionview/lib/action_view/renderer/partial_renderer.rb @@ -279,7 +279,8 @@ module ActionView def render_partial_template(view, locals, template, layout, block) ActiveSupport::Notifications.instrument( "render_partial.action_view", - identifier: template.identifier + identifier: template.identifier, + layout: layout && layout.virtual_path ) do |payload| content = template.render(view, locals) do |*name| view._layout_for(*name, &block) diff --git a/actionview/lib/action_view/renderer/template_renderer.rb b/actionview/lib/action_view/renderer/template_renderer.rb index ebb3dc138f..f20e786b61 100644 --- a/actionview/lib/action_view/renderer/template_renderer.rb +++ b/actionview/lib/action_view/renderer/template_renderer.rb @@ -64,13 +64,14 @@ module ActionView def render_with_layout(view, template, path, locals) layout = path && find_layout(path, locals.keys, [formats.first]) - content = yield(layout) body = if layout - view.view_flow.set(:layout, content) - layout.render(view, locals) { |*name| view._layout_for(*name) } + ActiveSupport::Notifications.instrument("render_layout.action_view", identifier: layout.identifier) do + view.view_flow.set(:layout, yield(layout)) + layout.render(view, locals) { |*name| view._layout_for(*name) } + end else - content + yield end build_rendered_template(body, template) end diff --git a/actionview/test/template/log_subscriber_test.rb b/actionview/test/template/log_subscriber_test.rb index 129147b9d7..9e23bc8498 100644 --- a/actionview/test/template/log_subscriber_test.rb +++ b/actionview/test/template/log_subscriber_test.rb @@ -63,6 +63,21 @@ class AVLogSubscriberTest < ActiveSupport::TestCase end end + def test_render_template_with_layout + Rails.stub(:root, File.expand_path(FIXTURE_LOAD_PATH)) do + @view.render(template: "test/hello_world", layout: "layouts/yield") + wait + + assert_equal 2, @logger.logged(:debug).size + assert_equal 2, @logger.logged(:info).size + + assert_match(/Rendering layout layouts\/yield\.erb/, @logger.logged(:debug).first) + assert_match(/Rendering test\/hello_world\.erb within layouts\/yield/, @logger.logged(:debug).last) + assert_match(/Rendered test\/hello_world\.erb within layouts\/yield/, @logger.logged(:info).first) + assert_match(/Rendered layout layouts\/yield\.erb/, @logger.logged(:info).last) + end + end + def test_render_file_template Rails.stub(:root, File.expand_path(FIXTURE_LOAD_PATH)) do @view.render(file: "#{FIXTURE_LOAD_PATH}/test/hello_world.erb") @@ -137,6 +152,30 @@ class AVLogSubscriberTest < ActiveSupport::TestCase end end + def test_render_partial_as_layout + Rails.stub(:root, File.expand_path(FIXTURE_LOAD_PATH)) do + set_view_cache_dependencies + set_cache_controller + + @view.render(layout: "layouts/yield_only") { "hello" } + + assert_equal 1, @logger.logged(:debug).size + assert_match(/Rendered layouts\/_yield_only\.erb/, @logger.logged(:debug).first) + end + end + + def test_render_partial_with_layout + Rails.stub(:root, File.expand_path(FIXTURE_LOAD_PATH)) do + set_view_cache_dependencies + set_cache_controller + + @view.render(partial: "partial", layout: "layouts/yield_only") + + assert_equal 1, @logger.logged(:debug).size + assert_match(/Rendered test\/_partial\.html\.erb within layouts\/_yield_only/, @logger.logged(:debug).first) + end + end + def test_render_uncached_outer_partial_with_inner_cached_partial_wont_mix_cache_hits_or_misses Rails.stub(:root, File.expand_path(FIXTURE_LOAD_PATH)) do set_view_cache_dependencies @@ -208,6 +247,19 @@ class AVLogSubscriberTest < ActiveSupport::TestCase end end + def test_render_collection_template_with_layout + Rails.stub(:root, File.expand_path(FIXTURE_LOAD_PATH)) do + set_cache_controller + + @view.render(partial: "test/customer", layout: "layouts/yield_only", collection: [ Customer.new("david"), Customer.new("mary") ]) + wait + + assert_equal 1, @logger.logged(:debug).size + assert_match(/Rendered collection of test\/_customer.erb within layouts\/_yield_only \[2 times\]/, @logger.logged(:debug).last) + end + end + + def test_render_collection_with_implicit_path Rails.stub(:root, File.expand_path(FIXTURE_LOAD_PATH)) do set_cache_controller