add additional instrumentation block for ActionView layout rendering

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*

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)}" \
+        message = +"  Rendered collection of #{from_rails_root(identifier)}"
-        " #{render_count(event.payload)} (Duration: #{event.duration.round(1)}ms | Allocations: #{event.allocations})"
+        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, name)
-        log_rendering_start(payload)
-      end
 
       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

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)

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)

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)
+          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

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