Instrument cached collection renders.

Augments the collection caching with some instrumentation that's logged.

For collections that have been cached like:

```ruby
<%= render partial: 'notifications/notification', collection: @notifications, cached: true %>
```

We'll output a line showing how many cache hits we had when rendering it:

```
  Rendered collection of notifications/_notification.html.erb [0 / 100 cache hits] (3396.5ms)
```

5 files changed, 55 insertions, 20 deletions

diff --git a/actionview/lib/action_view/log_subscriber.rb b/actionview/lib/action_view/log_subscriber.rb
index 9047dbdd85..aa38db2a3a 100644
--- a/actionview/lib/action_view/log_subscriber.rb
+++ b/actionview/lib/action_view/log_subscriber.rb
@@ -20,7 +20,15 @@ module ActionView
       end
     end
     alias :render_partial :render_template
-    alias :render_collection :render_template
+
+    def render_collection(event)
+      identifier = event.payload[:identifier] || 'templates'
+
+      info do
+        "  Rendered collection of #{from_rails_root(identifier)}" \
+        " #{render_count(event.payload)} (#{event.duration.round(1)}ms)"
+      end
+    end
 
     def logger
       ActionView::Base.logger
@@ -38,6 +46,14 @@ module ActionView
     def rails_root
       @root ||= "#{Rails.root}/"
     end
+
+    def render_count(payload)
+      if payload[:cache_hits]
+        "[#{payload[:cache_hits]} / #{payload[:count]} cache hits]"
+      else
+        "[#{payload[:count]} times]"
+      end
+    end
   end
 end
 
diff --git a/actionview/lib/action_view/renderer/abstract_renderer.rb b/actionview/lib/action_view/renderer/abstract_renderer.rb
index aa77a77acf..23e672a95f 100644
--- a/actionview/lib/action_view/renderer/abstract_renderer.rb
+++ b/actionview/lib/action_view/renderer/abstract_renderer.rb
@@ -35,8 +35,12 @@ module ActionView
       end
     end
 
-    def instrument(name, options={})
-      ActiveSupport::Notifications.instrument("render_#{name}.action_view", options){ yield }
+    def instrument(name, **options)
+      options[:identifier] ||= (@template && @template.identifier) || @path
+
+      ActiveSupport::Notifications.instrument("render_#{name}.action_view", options) do |payload|
+        yield payload
+      end
     end
 
     def prepend_formats(formats)
diff --git a/actionview/lib/action_view/renderer/partial_renderer.rb b/actionview/lib/action_view/renderer/partial_renderer.rb
index bdbf03191a..514804b08e 100644
--- a/actionview/lib/action_view/renderer/partial_renderer.rb
+++ b/actionview/lib/action_view/renderer/partial_renderer.rb
@@ -294,7 +294,7 @@ module ActionView
 
     def render(context, options, block)
       setup(context, options, block)
-      identifier = (@template = find_partial) ? @template.identifier : @path
+      @template = find_partial
 
       @lookup_context.rendered_format ||= begin
         if @template && @template.formats.present?
@@ -305,11 +305,9 @@ module ActionView
       end
 
       if @collection
-        instrument(:collection, :identifier => identifier || "collection", :count => @collection.size) do
-          render_collection
-        end
+        render_collection
       else
-        instrument(:partial, :identifier => identifier) do
+        instrument(:partial) do
           render_partial
         end
       end
@@ -318,15 +316,17 @@ module ActionView
     private
 
     def render_collection
-      return nil if @collection.blank?
+      instrument(:collection, count: @collection.size) do |payload|
+        return nil if @collection.blank?
 
-      if @options.key?(:spacer_template)
-        spacer = find_template(@options[:spacer_template], @locals.keys).render(@view, @locals)
-      end
+        if @options.key?(:spacer_template)
+          spacer = find_template(@options[:spacer_template], @locals.keys).render(@view, @locals)
+        end
 
-      cache_collection_render do
-        @template ? collection_with_template : collection_without_template
-      end.join(spacer).html_safe
+        cache_collection_render(payload) do
+          @template ? collection_with_template : collection_without_template
+        end.join(spacer).html_safe
+      end
     end
 
     def render_partial
diff --git a/actionview/lib/action_view/renderer/partial_renderer/collection_caching.rb b/actionview/lib/action_view/renderer/partial_renderer/collection_caching.rb
index debfcae870..f7deba94ce 100644
--- a/actionview/lib/action_view/renderer/partial_renderer/collection_caching.rb
+++ b/actionview/lib/action_view/renderer/partial_renderer/collection_caching.rb
@@ -9,11 +9,12 @@ module ActionView
     end
 
     private
-      def cache_collection_render
+      def cache_collection_render(instrumentation_payload)
         return yield unless @options[:cached]
 
         keyed_collection = collection_by_cache_keys
-        cached_partials = collection_cache.read_multi(*keyed_collection.keys)
+        cached_partials  = collection_cache.read_multi(*keyed_collection.keys)
+        instrumentation_payload[:cache_hits] = cached_partials.size
 
         @collection = keyed_collection.reject { |key, _| cached_partials.key?(key) }.values
         rendered_partials = @collection.empty? ? [] : yield
diff --git a/actionview/test/template/log_subscriber_test.rb b/actionview/test/template/log_subscriber_test.rb
index 4776c18b0b..93a0701dcc 100644
--- a/actionview/test/template/log_subscriber_test.rb
+++ b/actionview/test/template/log_subscriber_test.rb
@@ -86,7 +86,7 @@ class AVLogSubscriberTest < ActiveSupport::TestCase
       wait
 
       assert_equal 1, @logger.logged(:info).size
-      assert_match(/Rendered test\/_customer.erb/, @logger.logged(:info).last)
+      assert_match(/Rendered collection of test\/_customer.erb \[2 times\]/, @logger.logged(:info).last)
     end
   end
 
@@ -96,7 +96,7 @@ class AVLogSubscriberTest < ActiveSupport::TestCase
       wait
 
       assert_equal 1, @logger.logged(:info).size
-      assert_match(/Rendered customers\/_customer\.html\.erb/, @logger.logged(:info).last)
+      assert_match(/Rendered collection of customers\/_customer\.html\.erb \[2 times\]/, @logger.logged(:info).last)
     end
   end
 
@@ -106,7 +106,21 @@ class AVLogSubscriberTest < ActiveSupport::TestCase
       wait
 
       assert_equal 1, @logger.logged(:info).size
-      assert_match(/Rendered collection/, @logger.logged(:info).last)
+      assert_match(/Rendered collection of templates/, @logger.logged(:info).last)
+    end
+  end
+
+  def test_render_collection_with_cached_set
+    Rails.stub(:root, File.expand_path(FIXTURE_LOAD_PATH)) do
+      def @view.view_cache_dependencies; []; end
+      def @view.fragment_cache_key(*); 'ahoy `controller` dependency'; end
+
+      @view.render(partial: 'customers/customer', collection: [ Customer.new('david'), Customer.new('mary') ], cached: true,
+        locals: { greeting: 'hi' })
+      wait
+
+      assert_equal 1, @logger.logged(:info).size
+      assert_match(/Rendered collection of customers\/_customer\.html\.erb \[0 \/ 2 cache hits\]/, @logger.logged(:info).last)
     end
   end
 end