aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorStan Lo <a22301613@yahoo.com.tw>2016-07-14 18:38:16 +0800
committerStan Lo <a22301613@yahoo.com.tw>2016-08-08 00:24:39 +0800
commitab2af4dfcb61b568a9753b97dc55f1b45e3a824e (patch)
tree2e94a186941b1b890492828cefcaba1144b70836
parentc4f8c45ba57e97e8dfc99f8bf6c2fbfd39abd58b (diff)
downloadrails-ab2af4dfcb61b568a9753b97dc55f1b45e3a824e.tar.gz
rails-ab2af4dfcb61b568a9753b97dc55f1b45e3a824e.tar.bz2
rails-ab2af4dfcb61b568a9753b97dc55f1b45e3a824e.zip
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
-rw-r--r--actionmailer/test/caching_test.rb3
-rw-r--r--actionpack/lib/abstract_controller/caching.rb3
-rw-r--r--actionpack/lib/action_controller/log_subscriber.rb3
-rw-r--r--actionpack/test/controller/caching_test.rb1
-rw-r--r--actionpack/test/controller/log_subscriber_test.rb16
-rw-r--r--actionview/CHANGELOG.md24
-rw-r--r--actionview/lib/action_view/helpers/cache_helper.rb8
-rw-r--r--actionview/lib/action_view/log_subscriber.rb19
-rw-r--r--actionview/lib/action_view/renderer/partial_renderer.rb32
-rw-r--r--actionview/test/template/log_subscriber_test.rb59
-rw-r--r--guides/source/configuring.md8
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 `<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`: