From ab2af4dfcb61b568a9753b97dc55f1b45e3a824e Mon Sep 17 00:00:00 2001 From: Stan Lo Date: Thu, 14 Jul 2016 18:38:16 +0800 Subject: Modify LogSubscriber for single partial's cache message. Implement naive partial caching mechanism. Add test for LogSubscriber Use ActionView::Base#log_payload to store log_subscriber's payload, so we can pass cache result into it. Fixed tests Remove useless settings Check if #log_payload exists before calling it. Because other classes also includes CacheHelper but don't have is attribute Use @log_payload_for_partial_reder instead of #log_payload to carry ActionView's payload. Update test's hash syntax Add configuration to enable/disable fragment caching logging Remove unless test and add new test to ensure cache info won't effect next rendering's log Move :enable_fragment_cache_logging config from ActionView to ActionPack Apply new config to tests Update actionview's changelog Update configuration guide Improve actionview's changelog Refactor PartialRenderer#render and log tests Mute subscriber's log instead of disabling instrumentation. Fix typo, remove useless comment and use new hash syntax Improve actionpack's log_subscriber test Fix rebase mistake Apply new config to all caching intstrument actions --- actionview/CHANGELOG.md | 24 +++++++++ actionview/lib/action_view/helpers/cache_helper.rb | 8 ++- actionview/lib/action_view/log_subscriber.rb | 19 ++++++- .../lib/action_view/renderer/partial_renderer.rb | 32 ++++++------ actionview/test/template/log_subscriber_test.rb | 59 +++++++++++++++++++--- 5 files changed, 119 insertions(+), 23 deletions(-) (limited to 'actionview') diff --git a/actionview/CHANGELOG.md b/actionview/CHANGELOG.md index 7754bd8dd9..bd6f2d788d 100644 --- a/actionview/CHANGELOG.md +++ b/actionview/CHANGELOG.md @@ -9,6 +9,30 @@ *Steven Harman* +* Show cache hits and misses when rendering partials. + + Partials using the `cache` helper will show whether a render hit or missed + the cache: + + ``` + Rendered messages/_message.html.erb in 1.2 ms [cache hit] + Rendered recordings/threads/_thread.html.erb in 1.5 ms [cache miss] + ``` + + This removes the need for the old fragment cache logging: + + ``` + Read fragment views/v1/2914079/v1/2914079/recordings/70182313-20160225015037000000/d0bdf2974e1ef6d31685c3b392ad0b74 (0.6ms) + Rendered messages/_message.html.erb in 1.2 ms [cache hit] + Write fragment views/v1/2914079/v1/2914079/recordings/70182313-20160225015037000000/3b4e249ac9d168c617e32e84b99218b5 (1.1ms) + Rendered recordings/threads/_thread.html.erb in 1.5 ms [cache miss] + ``` + + Though that full output can be reenabled with + `config.action_controller.enable_fragment_cache_logging = true`. + + *Stan Lo* + * New syntax for tag helpers. Avoid positional parameters and support HTML5 by default. Example usage of tag helpers before: diff --git a/actionview/lib/action_view/helpers/cache_helper.rb b/actionview/lib/action_view/helpers/cache_helper.rb index 6c3092cc46..b598469d01 100644 --- a/actionview/lib/action_view/helpers/cache_helper.rb +++ b/actionview/lib/action_view/helpers/cache_helper.rb @@ -226,7 +226,13 @@ module ActionView # TODO: Create an object that has caching read/write on it def fragment_for(name = {}, options = nil, &block) #:nodoc: - read_fragment_for(name, options) || write_fragment_for(name, options, &block) + if content = read_fragment_for(name, options) + @log_payload_for_partial_render[:cache_hit] = true if defined?(@log_payload_for_partial_render) + content + else + @log_payload_for_partial_render[:cache_hit] = false if defined?(@log_payload_for_partial_render) + write_fragment_for(name, options, &block) + end end def read_fragment_for(name, options) #:nodoc: diff --git a/actionview/lib/action_view/log_subscriber.rb b/actionview/lib/action_view/log_subscriber.rb index 34e1a35dc2..c9f308c2a2 100644 --- a/actionview/lib/action_view/log_subscriber.rb +++ b/actionview/lib/action_view/log_subscriber.rb @@ -19,7 +19,16 @@ module ActionView message << " (#{event.duration.round(1)}ms)" end end - alias :render_partial :render_template + + def render_partial(event) + info do + message = " Rendered #{from_rails_root(event.payload[:identifier])}" + message << " within #{from_rails_root(event.payload[:layout])}" if event.payload[:layout] + message << " (#{event.duration.round(1)}ms)" + message << " #{cache_message(event.payload)}" if event.payload.key?(:cache_hit) + message + end + end def render_collection(event) identifier = event.payload[:identifier] || "templates" @@ -63,6 +72,14 @@ module ActionView end end + def cache_message(payload) + if payload[:cache_hit] + "[cache hit]" + else + "[cache miss]" + end + end + private def log_rendering_start(payload) diff --git a/actionview/lib/action_view/renderer/partial_renderer.rb b/actionview/lib/action_view/renderer/partial_renderer.rb index 1509726a37..92bd0ccf91 100644 --- a/actionview/lib/action_view/renderer/partial_renderer.rb +++ b/actionview/lib/action_view/renderer/partial_renderer.rb @@ -308,9 +308,7 @@ module ActionView if @collection render_collection else - instrument(:partial) do - render_partial - end + render_partial end end @@ -331,22 +329,26 @@ module ActionView end def render_partial - view, locals, block = @view, @locals, @block - object, as = @object, @variable + instrument(:partial) do |payload| + view, locals, block = @view, @locals, @block + object, as = @object, @variable - if !block && (layout = @options[:layout]) - layout = find_template(layout.to_s, @template_keys) - end + view.instance_variable_set(:@log_payload_for_partial_render, payload) - object = locals[as] if object.nil? # Respect object when object is false - locals[as] = object if @has_object + if !block && (layout = @options[:layout]) + layout = find_template(layout.to_s, @template_keys) + end - content = @template.render(view, locals) do |*name| - view._layout_for(*name, &block) - end + object = locals[as] if object.nil? # Respect object when object is false + locals[as] = object if @has_object - content = layout.render(view, locals){ content } if layout - content + content = @template.render(view, locals) do |*name| + view._layout_for(*name, &block) + end + + content = layout.render(view, locals){ content } if layout + content + end end # Sets up instance variables needed for rendering a partial. This method diff --git a/actionview/test/template/log_subscriber_test.rb b/actionview/test/template/log_subscriber_test.rb index 565eee6628..3884807017 100644 --- a/actionview/test/template/log_subscriber_test.rb +++ b/actionview/test/template/log_subscriber_test.rb @@ -30,6 +30,13 @@ class AVLogSubscriberTest < ActiveSupport::TestCase ActionView::Base.logger = logger end + def set_cache_controller + controller = ActionController::Base.new + controller.perform_caching = true + controller.cache_store = ActiveSupport::Cache::MemoryStore.new + @view.controller = controller + end + def test_render_file_template Rails.stub(:root, File.expand_path(FIXTURE_LOAD_PATH)) do @view.render(file: "test/hello_world") @@ -63,23 +70,63 @@ class AVLogSubscriberTest < ActiveSupport::TestCase end end - def test_render_partial_template + def test_render_partial_with_implicit_path Rails.stub(:root, File.expand_path(FIXTURE_LOAD_PATH)) do - @view.render(partial: "test/customer") + @view.render(Customer.new("david"), greeting: "hi") wait assert_equal 1, @logger.logged(:info).size - assert_match(/Rendered test\/_customer.erb/, @logger.logged(:info).last) + assert_match(/Rendered customers\/_customer\.html\.erb/, @logger.logged(:info).last) end end - def test_render_partial_with_implicit_path + def test_render_partial_with_cache_missed Rails.stub(:root, File.expand_path(FIXTURE_LOAD_PATH)) do - @view.render(Customer.new("david"), greeting: "hi") + def @view.view_cache_dependencies; []; end + def @view.fragment_cache_key(*); 'ahoy `controller` dependency'; end + set_cache_controller + + @view.render(partial: "test/cached_customer", locals: { cached_customer: Customer.new("david") }) wait assert_equal 1, @logger.logged(:info).size - assert_match(/Rendered customers\/_customer\.html\.erb/, @logger.logged(:info).last) + assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, @logger.logged(:info).last) + end + end + + def test_render_partial_with_cache_hitted + 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 + set_cache_controller + + @view.render(partial: "test/cached_customer", locals: { cached_customer: Customer.new("david") }) + # Second render should hit cache. + @view.render(partial: "test/cached_customer", locals: { cached_customer: Customer.new("david") }) + wait + + assert_equal 2, @logger.logged(:info).size + assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache hit\]/, @logger.logged(:info).last) + end + end + + def test_render_partial_with_cache_hitted_and_missed + 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 + set_cache_controller + + @view.render(partial: "test/cached_customer", locals: { cached_customer: Customer.new("david") }) + wait + assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, @logger.logged(:info).last) + + @view.render(partial: "test/cached_customer", locals: { cached_customer: Customer.new("david") }) + wait + assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache hit\]/, @logger.logged(:info).last) + + @view.render(partial: "test/cached_customer", locals: { cached_customer: Customer.new("Stan") }) + wait + assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, @logger.logged(:info).last) end end -- cgit v1.2.3