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

@@ -172,6 +172,7 @@ def test_multipart_fragment_caching
   end
 
   def test_fragment_cache_instrumentation
+    @mailer.enable_fragment_cache_logging = true
     payload = nil
 
     subscriber = proc do |*args|
@@ -185,6 +186,8 @@ def test_fragment_cache_instrumentation
 
     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

actionpack/lib/abstract_controller/caching.rb

@@ -34,6 +34,9 @@ def cache_configured?
       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)

actionpack/lib/action_controller/log_subscriber.rb

@@ -59,14 +59,13 @@ def unpermitted_parameters(event)
        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

actionpack/test/controller/caching_test.rb

@@ -184,6 +184,7 @@ def setup
     @controller = FunctionalCachingController.new
     @controller.perform_caching = true
     @controller.cache_store = @store
+    @controller.enable_fragment_cache_logging = true
   end
 
   def test_fragment_caching

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 @@ def teardown
     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 @@ def test_with_fragment_cache
     @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

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:
 

actionview/lib/action_view/helpers/cache_helper.rb

@@ -226,7 +226,13 @@ def fragment_name_with_digest(name, virtual_path) #:nodoc:
 
       # 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:

actionview/lib/action_view/log_subscriber.rb

@@ -19,7 +19,16 @@ def render_template(event)
         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 @@ def render_count(payload)
       end
     end
 
+    def cache_message(payload)
+      if payload[:cache_hit]
+        "[cache hit]"
+      else
+        "[cache miss]"
+      end
+    end
+
   private
 
     def log_rendering_start(payload)

actionview/lib/action_view/renderer/partial_renderer.rb

@@ -308,9 +308,7 @@ def render(context, options, block)
       if @collection
         render_collection
       else
-        instrument(:partial) do
-          render_partial
-        end
+        render_partial
       end
     end
 
@@ -331,22 +329,26 @@ def render_collection
       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

actionview/test/template/log_subscriber_test.rb

@@ -30,6 +30,13 @@ def set_logger(logger)
     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 @@ def test_render_inline_template
     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
 

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 `<span>` 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`: