Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Better logging of cached partial renders #25825

Merged
merged 1 commit into from Aug 7, 2016
Merged

Conversation

@st0012
Copy link
Contributor

@st0012 st0012 commented Jul 14, 2016

Summary

This is for #23879

To get the result of fragment caching, I added #log_payload to ActionView::Base to store the payload hash. So we can still update the payload when read/write fragment cache.

@rails-bot
Copy link

@rails-bot rails-bot commented Jul 14, 2016

r? @eileencodes

(@rails-bot has picked a reviewer for you, use r? to override)

@st0012
Copy link
Contributor Author

@st0012 st0012 commented Jul 14, 2016

r? @kaspth

@rails-bot rails-bot assigned kaspth and unassigned eileencodes Jul 14, 2016
@kaspth
Copy link
Member

@kaspth kaspth commented Jul 14, 2016

Got some quick thoughts 😄

This isn't quite what we're going for. Individual templates already have a cache method that the use to participate in fragment caching, cached: true is just for collections and shouldn't be added to individual partial renders.

#23879 just wants to have the logging improved in two ways:

  • Turn off fragment caching logging e.g. "Read fragment views/sha256". Provide a config option for older apps.
  • Enrich the existing template rendering log to say if the cache was hit. You've got this part down in the LogSubscriber, well done 👏

So we need a different way to find out if the rendering was a hit or miss through the existing cache method. You can see the documentation in ActionView::CacheHelper#cache.

Thanks!

@st0012
Copy link
Contributor Author

@st0012 st0012 commented Jul 14, 2016

@kaspth Thanks for the quick response!
I updated my implementation 😄
And I wonder that if Provide a config option for older apps. means I need to create some new branches base on older version of Rails?

@kaspth
kaspth reviewed Jul 14, 2016
View changes
actionpack/lib/abstract_controller/caching/fragments.rb Outdated
@@ -86,10 +84,8 @@ def read_fragment(key, options = nil)
return unless cache_configured?

key = fragment_cache_key(key)
instrument_fragment_cache :read_fragment, key do

This comment has been minimized.

@kaspth

kaspth Jul 14, 2016
Member

Sorry, "remove" was ambiguous wording, I should have said disable.

People should still be able to log fragment caching, we just don't want it on for new apps in Rails 5.1.

We need a config option on Action View, say, enable_fragment_cache_logging. It's important that we don't muck with the instrumentation, that is useful for benchmarks and data aggregation, but just turn off the logging within it.

If that flag is off, we set the cache store logger to nil to return early here

return unless logger && logger.debug? && !silence?

@dhh does that sound good to you?

@kaspth
kaspth reviewed Jul 14, 2016
View changes
actionpack/test/controller/caching_test.rb Outdated
assert_equal "functional_caching", payload[:controller]
assert_equal "inline_fragment_cached", payload[:action]
end

This comment has been minimized.

@kaspth

kaspth Jul 14, 2016
Member

We should also keep these deleted tests and the others.

@kaspth
kaspth reviewed Jul 14, 2016
View changes
actionview/lib/action_view/log_subscriber.rb Outdated
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[:cache_partial]
message

This comment has been minimized.

@kaspth

kaspth Jul 14, 2016
Member

I don't see log_payload referenced here, so how does this tie in with the Action View accessor you've added?

This comment has been minimized.

@kaspth

kaspth Jul 14, 2016
Member

We also want the cache hit when we've rendered a template.

This comment has been minimized.

@st0012

st0012 Jul 14, 2016
Author Contributor

You mean same log info for normal template rendering?

@kaspth
kaspth reviewed Jul 14, 2016
View changes
actionview/lib/action_view/log_subscriber.rb Outdated
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[:cache_partial]

This comment has been minimized.

@kaspth

kaspth Jul 14, 2016
Member

Could remove the need for the :cache_partial key with event.payload.key?(:cache_hit).

@kaspth
kaspth reviewed Jul 14, 2016
View changes
actionview/lib/action_view/helpers/cache_helper.rb Outdated
content
else
write_fragment_for(name, options, &block)
end

This comment has been minimized.

@kaspth

kaspth Jul 14, 2016
Member

I think this would be simpler if we just had the branches mirror each other:

if content = read_fragment_for(name, options)
  log_payload[:cache_hit] = true if respond_to?(:log_payload)
  content
else
  log_payload[:cache_hit] = false if respond_to?(:log_payload)
  write_fragment_for(name, options, &block)
end

(We don't need to check that log_payload is a hash, let's just duck-type it.)

@kaspth
kaspth reviewed Jul 14, 2016
View changes
actionview/lib/action_view/renderer/partial_renderer.rb Outdated
@@ -330,22 +328,25 @@ def render_collection
end

def render_partial
view, locals, block = @view, @locals, @block
object, as = @object, @variable
instrument(:partial) do |payload|

This comment has been minimized.

@kaspth

kaspth Jul 14, 2016
Member

Let's leave the instrument call to where it was.

@kaspth
kaspth reviewed Jul 14, 2016
View changes
actionview/test/template/log_subscriber_test.rb Outdated

@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") })

This comment has been minimized.

@kaspth

kaspth Jul 14, 2016
Member

Your tests need to use new hash syntax on the :partial key 😁

This comment has been minimized.

@st0012

st0012 Jul 14, 2016
Author Contributor

Should I also update other tests' hash syntax?

@@ -307,9 +307,7 @@ def render(context, options, block)
if @collection
render_collection
else
instrument(:partial) do

This comment has been minimized.

@kaspth

kaspth Jul 14, 2016
Member

Let's yield the payload like we do in the collection rendering instead of defining log_payload. It would look like this:

instrument(:partial) do |payload|
  @log_payload_for_partial_render = payload
  render_partial
end

Then the code in the cache helper would look like:

if content = ...
  @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(...)
end
@st0012
st0012 reviewed Jul 16, 2016
View changes
actionpack/lib/abstract_controller/caching/fragments.rb Outdated
@@ -135,6 +135,7 @@ def expire_fragment(key, options = nil)
end

def instrument_fragment_cache(name, key) # :nodoc:
return unless ActionView::Base.enable_fragment_cache_logging

This comment has been minimized.

@st0012

st0012 Jul 16, 2016
Author Contributor

@kaspth I found that fragment caching's log is not at debug level, so we can't early return at the place you said. And I think we should do that in here instead.

@st0012
Copy link
Contributor Author

@st0012 st0012 commented Jul 16, 2016

@kaspth I did some changes base on your advice, please take a look. Thanks 😁

@st0012 st0012 force-pushed the st0012:partial-cache branch 2 times, most recently Jul 17, 2016
@kaspth kaspth added this to the 5.1.0 milestone Jul 20, 2016
@kaspth
kaspth reviewed Jul 20, 2016
View changes
actionpack/lib/abstract_controller/caching/fragments.rb Outdated
@@ -135,6 +135,7 @@ def expire_fragment(key, options = nil)
end

def instrument_fragment_cache(name, key) # :nodoc:
return yield unless ActionView::Base.enable_fragment_cache_logging

This comment has been minimized.

@kaspth

kaspth Jul 20, 2016
Member

When I said I config on Action View I didn't remember the fragment caches were in Action Pack. So we can't do this, it couples Action Pack to Action View.

Look to where perform_caching is defined in Action Pack, and move the config itself there.

@kaspth
kaspth reviewed Jul 20, 2016
View changes
actionview/lib/action_view/renderer/partial_renderer.rb Outdated
@@ -307,7 +307,8 @@ def render(context, options, block)
if @collection
render_collection
else
instrument(:partial) do
instrument(:partial) do |payload|
@view.instance_variable_set(:@log_payload_for_partial_render, payload)

This comment has been minimized.

@kaspth

kaspth Jul 20, 2016
Member

Thinking about this some more, if we are to provide fine grained [cache hit] misses per partial render will this do?

In other words what's the life span of both @view and @log_payload_for_partial_render? If one variable sticks around after the other, then we will generate wrong information. Consider:

# app/views/customers/show.html.erb
render :customer # => [cache hit]
render :todo_list  # => Does this render inherit the [cache hit] from the previous render?
def @view.fragment_cache_key(*); 'ahoy `controller` dependency'; end
set_cache_controller

@view.render(partial: "test/cached_customer", locals: { cached_customer: Customer.new("david") })

This comment has been minimized.

@kaspth

kaspth Jul 20, 2016
Member

Think it's okay if we merge the above assertion into here and then kill the above test. We're testing the integration here after all, so fine with some lifecycle to it.

@kaspth
kaspth reviewed Jul 20, 2016
View changes
actionview/lib/action_view/base.rb Outdated
@@ -185,6 +189,7 @@ def xss_safe? #:nodoc:
end

attr_accessor :view_renderer

This comment has been minimized.

@kaspth

kaspth Jul 20, 2016
Member

✂️

@kaspth
kaspth reviewed Jul 20, 2016
View changes
actionpack/test/controller/log_subscriber_test.rb Outdated
ensure
@controller.config.perform_caching = true
ActionView::Base.enable_fragment_cache_logging = false
end

This comment has been minimized.

@kaspth

kaspth Jul 20, 2016
Member

What is this testing?

This comment has been minimized.

@st0012

st0012 Jul 21, 2016
Author Contributor

This is testing that the config can really mute to log.

@kaspth
kaspth reviewed Jul 20, 2016
View changes
actionpack/test/controller/log_subscriber_test.rb Outdated
@@ -92,6 +92,7 @@ class ACLogSubscriberTest < ActionController::TestCase

def setup
super
ActionView::Base.enable_fragment_cache_logging = true

This comment has been minimized.

@kaspth

kaspth Jul 20, 2016
Member

Reads a bit like a smell that we have to touch this config here as well as in the other tests. Perhaps there's a lower level of cache logging we can hook into?

This comment has been minimized.

@st0012

st0012 Jul 21, 2016
Author Contributor

After we move the config into ActionPack, the config will look like this

@controller.config.perform_caching = true
@controller.enable_fragment_cache_logging = true

And I think it's just the setup step in tests, like @controller.config.perform_caching = true

@kaspth
Copy link
Member

@kaspth kaspth commented Jul 20, 2016

There's also a mute method on the cache stores, which could be of interest:

@st0012
st0012 reviewed Jul 21, 2016
View changes
actionview/test/template/log_subscriber_test.rb Outdated

assert_equal 3, @logger.logged(:info).size
assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache hit\]/, @logger.logged(:info).second)
assert_match(/Rendered test\/_cached_customer\.erb (.*) \[cache miss\]/, @logger.logged(:info).last)

This comment has been minimized.

@st0012

st0012 Jul 21, 2016
Author Contributor

@kaspth I use this to test if the log payload would be affected by previous rendering. And it seems that it won't be affected.

This comment has been minimized.

@kaspth

kaspth Jul 22, 2016
Member

Okay, I think this test would be much clearer if we interspersed the assertions:

@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).first)

@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)[1])

@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)

assert_equal 3, @logger.logged(:info).size

We also shouldn't use second in the tests, [1] is fine here.

This comment has been minimized.

@kaspth

kaspth Jul 22, 2016
Member

Also great that you managed to test that past renders won't leak :cache_hit states 👏

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)

This comment has been minimized.

@kaspth

kaspth Jul 22, 2016
Member

I'm not too kind on us just removing the old test. Why do we need to?

This comment has been minimized.

@st0012

st0012 Jul 23, 2016
Author Contributor

Because this is testing if we pass a customer object and the renderer can still find the right template. I think we don't cover this kind of situation in our new tests.

@kaspth
kaspth reviewed Jul 22, 2016
View changes
actionview/lib/action_view/renderer/partial_renderer.rb Outdated
@@ -307,7 +307,8 @@ def render(context, options, block)
if @collection
render_collection
else
instrument(:partial) do
instrument(:partial) do |payload|
@view.instance_variable_set(:@log_payload_for_partial_render, payload)
render_partial

This comment has been minimized.

@kaspth

kaspth Jul 22, 2016
Member

Okay, you we're right before. Moving the instrument to render_partial is better such that we only touch the @view from in there and have more consistency with render_collection.

@kaspth
kaspth reviewed Jul 22, 2016
View changes
actionpack/test/controller/log_subscriber_test.rb Outdated
@@ -258,6 +259,18 @@ def test_with_fragment_cache
@controller.config.perform_caching = true
end

def test_with_fragment_cache_when_log_disabled
@controller.config.perform_caching = true
@controller.enable_fragment_cache_logging = false

This comment has been minimized.

@kaspth

kaspth Jul 22, 2016
Member

We should capture the previous values here and reset them in ensure. Otherwise we're potentially leaking state.

This comment has been minimized.

@st0012

st0012 Jul 23, 2016
Author Contributor

Sorry, I don't really understand the situation you are saying. Can you explain more?

@kaspth
kaspth reviewed Jul 22, 2016
View changes
actionpack/lib/abstract_controller/caching/fragments.rb Outdated
@@ -135,6 +135,7 @@ def expire_fragment(key, options = nil)
end

def instrument_fragment_cache(name, key) # :nodoc:
return yield unless enable_fragment_cache_logging

This comment has been minimized.

@kaspth

kaspth Jul 22, 2016
Member

This isn't right. We don't want to disable instrumentation of fragment caches. We just don't want to show the logs, that's why I think we should look into using stuff like Rails.logger.silence or cache_store.logger.mute if the config is set.

This comment has been minimized.

@st0012

st0012 Jul 23, 2016
Author Contributor

Ok, I think I don't very understand the differences between instrumentation and logging. I thought they are the same thing 😓

@kaspth
kaspth reviewed Jul 22, 2016
View changes
actionview/CHANGELOG.md Outdated
Rendered recordings/threads/_thread.html.erb in 1.5 ms
```

*Stan Lo*

This comment has been minimized.

@kaspth

kaspth Jul 22, 2016
Member

Think we should just explain this as one change. How about:

*   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.enabled_fragment_cache_logging = true`.

    *Stan Lo*

This comment has been minimized.

@st0012

st0012 Jul 23, 2016
Author Contributor

Sure, thanks!

@kaspth
Copy link
Member

@kaspth kaspth commented Jul 22, 2016

Great job figuring out where to add documentation for this! Are there places in our docs that mention read fragment (and write) that we need to update after this? Same with rendered some/partial?

This is starting to get real good, we're getting closer every day! 😁

@st0012 st0012 force-pushed the st0012:partial-cache branch Jul 23, 2016
@st0012
st0012 reviewed Jul 23, 2016
View changes
actionpack/lib/action_controller/log_subscriber.rb Outdated
%w(write_fragment read_fragment).each do |method|
class_eval <<-METHOD, __FILE__, __LINE__ + 1
def #{method}(event)
return unless logger.info? && ActionController::Base.enable_fragment_cache_logging

This comment has been minimized.

@st0012

st0012 Jul 23, 2016
Author Contributor

@kaspth I think this is the best place to mute the logging. I mute the event subscriber instead of instrumentation. Is this what you mean?

This comment has been minimized.

@kaspth

kaspth Aug 2, 2016
Member

Yup, it looks like this will remove messages like:

Read fragment views/v1/2914079/v1/2914079/recordings/70182313-20160225015037000000/d0bdf2974e1ef6d31685c3b392ad0b74 (0.6ms)

I think we should just let the config work for every one of these methods. The config name communicates as much.

This comment has been minimized.

@kaspth

kaspth Aug 7, 2016
Member

What do you think about using the config for every one of these fragment cache log methods?

This comment has been minimized.

@st0012

st0012 Aug 7, 2016
Author Contributor

I am not sure, but it make sense to me

This comment has been minimized.

@st0012

st0012 Aug 7, 2016
Author Contributor

I think I would apply it to every methods.

@st0012 st0012 force-pushed the st0012:partial-cache branch 2 times, most recently Jul 25, 2016
@st0012
Copy link
Contributor Author

@st0012 st0012 commented Jul 27, 2016

I have rebased and didn't find other documents that need to be updated 😁

@st0012 st0012 force-pushed the st0012:partial-cache branch Jul 30, 2016
@kaspth
kaspth reviewed Aug 2, 2016
View changes
actionpack/lib/abstract_controller/caching.rb Outdated
@@ -34,6 +34,10 @@ def cache_configured?
config_accessor :perform_caching
self.perform_caching = true if perform_caching.nil?

# Specify whether fragment caching should be logged

This comment has been minimized.

@kaspth

kaspth Aug 2, 2016
Member

This comment doesn't really add anything, let's just remove it.

@@ -258,6 +260,18 @@ def test_with_fragment_cache
@controller.config.perform_caching = true
end

def test_with_fragment_cache_when_log_disabled
@controller.config.perform_caching = true

This comment has been minimized.

@kaspth

kaspth Aug 2, 2016
Member

Is the config going to be respected at this time? Won't it have been moved to another attribute by now?

This comment has been minimized.

@kaspth

kaspth Aug 2, 2016
Member

Yup, I see it in other tests.

get :with_fragment_cache
wait

assert_equal 2, logs.size

This comment has been minimized.

@kaspth

kaspth Aug 2, 2016
Member

We should also add some assert_match calls, only checking the size personally doesn't boost my confidence that things are working.

@kaspth
kaspth reviewed Aug 2, 2016
View changes
actionview/CHANGELOG.md Outdated
```

Though that full output can be reenabled with
`config.action_controller.enabled_fragment_cache_logging = true`.

This comment has been minimized.

@kaspth

kaspth Aug 2, 2016
Member

No d on enable.

@kaspth
kaspth reviewed Aug 2, 2016
View changes
actionview/test/template/log_subscriber_test.rb Outdated
Rails.stub(:root, File.expand_path(FIXTURE_LOAD_PATH)) do
@view.render(:partial => "test/customer")
@view.render(Customer.new("david"), :greeting => "hi")

This comment has been minimized.

@kaspth

kaspth Aug 2, 2016
Member

New hash syntax please 😁

@st0012
Copy link
Contributor Author

@st0012 st0012 commented Aug 3, 2016

@kaspth Just updated 😁

@kaspth
Copy link
Member

@kaspth kaspth commented Aug 7, 2016

Almost there! You need to rebase on master and squash your commits down to one.

@st0012 st0012 force-pushed the st0012:partial-cache branch Aug 7, 2016
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
@st0012 st0012 force-pushed the st0012:partial-cache branch to ab2af4d Aug 7, 2016
@st0012
Copy link
Contributor Author

@st0012 st0012 commented Aug 7, 2016

@kaspth done

@kaspth kaspth merged commit b35afdd into rails:master Aug 7, 2016
1 of 2 checks passed
1 of 2 checks passed
codeclimate Code Climate found 3 new issues.
Details
continuous-integration/travis-ci/pr The Travis CI build passed
Details
@kaspth
Copy link
Member

@kaspth kaspth commented Aug 7, 2016

Lovely! Well done, you must've logged a lot of fragmented hours for this, but I'm sure it will be a (cache) hit 😁

@st0012
Copy link
Contributor Author

@st0012 st0012 commented Aug 8, 2016

@kaspth thank you for your help, I learnt a lot from implementing this. And this is my second Rails feature, hope that I can contribute more in the future 😄

@kaspth
Copy link
Member

@kaspth kaspth commented Aug 8, 2016

@st0012 I'm glad you had fun and learned something! I hope you will contribute more 😁

@st0012 st0012 deleted the st0012:partial-cache branch Oct 20, 2016
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Linked issues

Successfully merging this pull request may close these issues.

None yet

5 participants
You can’t perform that action at this time.