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 --- actionmailer/test/caching_test.rb | 3 ++ actionpack/lib/abstract_controller/caching.rb | 3 ++ actionpack/lib/action_controller/log_subscriber.rb | 3 +- actionpack/test/controller/caching_test.rb | 1 + actionpack/test/controller/log_subscriber_test.rb | 16 ++++++ 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 +++++++++++++++++++--- guides/source/configuring.md | 8 +++ 11 files changed, 151 insertions(+), 25 deletions(-) diff --git a/actionmailer/test/caching_test.rb b/actionmailer/test/caching_test.rb index 17267667aa..d7e21d4c8e 100644 --- a/actionmailer/test/caching_test.rb +++ b/actionmailer/test/caching_test.rb @@ -172,6 +172,7 @@ class FunctionalFragmentCachingTest < BaseCachingTest end def test_fragment_cache_instrumentation + @mailer.enable_fragment_cache_logging = true payload = nil subscriber = proc do |*args| @@ -185,6 +186,8 @@ class FunctionalFragmentCachingTest < BaseCachingTest assert_equal "caching_mailer", payload[:mailer] assert_equal "views/caching/#{template_digest("caching_mailer/fragment_cache")}", payload[:key] + ensure + @mailer.enable_fragment_cache_logging = true end private diff --git a/actionpack/lib/abstract_controller/caching.rb b/actionpack/lib/abstract_controller/caching.rb index a37ee9ec97..d222880922 100644 --- a/actionpack/lib/abstract_controller/caching.rb +++ b/actionpack/lib/abstract_controller/caching.rb @@ -34,6 +34,9 @@ module AbstractController config_accessor :perform_caching self.perform_caching = true if perform_caching.nil? + config_accessor :enable_fragment_cache_logging + self.enable_fragment_cache_logging = false + class_attribute :_view_cache_dependencies self._view_cache_dependencies = [] helper_method :view_cache_dependencies if respond_to?(:helper_method) diff --git a/actionpack/lib/action_controller/log_subscriber.rb b/actionpack/lib/action_controller/log_subscriber.rb index a0917b4fdb..739a11679b 100644 --- a/actionpack/lib/action_controller/log_subscriber.rb +++ b/actionpack/lib/action_controller/log_subscriber.rb @@ -59,14 +59,13 @@ module ActionController expire_fragment expire_page write_page).each do |method| class_eval <<-METHOD, __FILE__, __LINE__ + 1 def #{method}(event) - return unless logger.info? + return unless logger.info? && ActionController::Base.enable_fragment_cache_logging key_or_path = event.payload[:key] || event.payload[:path] human_name = #{method.to_s.humanize.inspect} info("\#{human_name} \#{key_or_path} (\#{event.duration.round(1)}ms)") end METHOD end - def logger ActionController::Base.logger end diff --git a/actionpack/test/controller/caching_test.rb b/actionpack/test/controller/caching_test.rb index 08aa383886..5f4857c553 100644 --- a/actionpack/test/controller/caching_test.rb +++ b/actionpack/test/controller/caching_test.rb @@ -184,6 +184,7 @@ class FunctionalFragmentCachingTest < ActionController::TestCase @controller = FunctionalCachingController.new @controller.perform_caching = true @controller.cache_store = @store + @controller.enable_fragment_cache_logging = true end def test_fragment_caching diff --git a/actionpack/test/controller/log_subscriber_test.rb b/actionpack/test/controller/log_subscriber_test.rb index dfc0edea69..0deeb3865d 100644 --- a/actionpack/test/controller/log_subscriber_test.rb +++ b/actionpack/test/controller/log_subscriber_test.rb @@ -92,6 +92,7 @@ class ACLogSubscriberTest < ActionController::TestCase def setup super + @controller.enable_fragment_cache_logging = true @old_logger = ActionController::Base.logger @@ -105,6 +106,7 @@ class ACLogSubscriberTest < ActionController::TestCase ActiveSupport::LogSubscriber.log_subscribers.clear FileUtils.rm_rf(@cache_path) ActionController::Base.logger = @old_logger + ActionController::Base.enable_fragment_cache_logging = true end def set_logger(logger) @@ -258,6 +260,20 @@ class ACLogSubscriberTest < ActionController::TestCase @controller.config.perform_caching = true end + def test_with_fragment_cache_when_log_disabled + @controller.config.perform_caching = true + ActionController::Base.enable_fragment_cache_logging = false + get :with_fragment_cache + wait + + assert_equal 2, logs.size + assert_equal "Processing by Another::LogSubscribersController#with_fragment_cache as HTML", logs[0] + assert_match(/Completed 200 OK in \d+ms/, logs[1]) + ensure + @controller.config.perform_caching = true + ActionController::Base.enable_fragment_cache_logging = true + end + def test_with_fragment_cache_if_with_true @controller.config.perform_caching = true get :with_fragment_cache_if_with_true_condition 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 diff --git a/guides/source/configuring.md b/guides/source/configuring.md index 572993a36b..48cbbe1f7d 100644 --- a/guides/source/configuring.md +++ b/guides/source/configuring.md @@ -516,6 +516,14 @@ encrypted cookies salt value. Defaults to `'signed encrypted cookie'`. * `config.action_view.debug_missing_translation` determines whether to wrap the missing translations key in a `` tag or not. This defaults to `true`. +* `config.action_view.enable_fragment_cache_logging` determines whether to log fragment cache reads and writes like: + + ``` + Read fragment views/v1/2914079/v1/2914079/recordings/70182313-20160225015037000000/d0bdf2974e1ef6d31685c3b392ad0b74 (0.6ms) + ``` + + Default value is false. + ### Configuring Action Mailer There are a number of settings available on `config.action_mailer`: -- cgit v1.2.3