From b4700de1ce21599b500d43d8138184ee7ae81407 Mon Sep 17 00:00:00 2001 From: Kasper Timm Hansen Date: Thu, 18 Feb 2016 21:55:42 +0100 Subject: [PATCH] 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) ``` --- actionview/lib/action_view/log_subscriber.rb | 18 +++++++++++++- .../action_view/renderer/abstract_renderer.rb | 8 +++++-- .../action_view/renderer/partial_renderer.rb | 24 +++++++++---------- .../partial_renderer/collection_caching.rb | 5 ++-- .../test/template/log_subscriber_test.rb | 20 +++++++++++++--- 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 @@ def render_template(event) 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 @@ def from_rails_root(string) 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 @@ def extract_details(options) 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 @@ def initialize(*) 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 @@ def render(context, options, block) 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 @@ def render(context, options, block) 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 CollectionCaching # :nodoc: 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 @@ def test_render_collection_template 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 @@ def test_render_collection_with_implicit_path 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 @@ def test_render_collection_template_without_path 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 -- GitLab