Logging Render Times in Development Mode

[Aesthetikx]

Feature request

Hello, I am currently enjoying rewriting some partials et. al. as components. However, when checking on performance and optimizing, I miss the ability that you have with partials to see the render time of the individual partial in the server output. I see that instrumentation was recently implemented which I believe is a prerequisite for this. After enabling instrumentation in configurations, I was thinking that magically I would start to see render times in the logs, but after looking at the instrumentation framework briefly I understand that that is only something that instrumentation could enable, not something that it does out of the box.

Motivation

I am hoping that we could work towards enabling the logging of render times as a configuration setting, or otherwise demonstrate how to do this on the instrumentation page of the view component documentation. After a brief amount of time I was unable to see how to use instrumentation to log render times (I didn't try that hard) but if it is simple enough I think that would be worth adding to the documentation. Also, I understand that some shops are using view component for literally everything and that by default this would not be necessarily a desirable default behavior as it would pollute logs, but I think it should be something that can easily be toggled on when working on optimization.

[BlakeWilliams]

I think an addition to the documentation that shows how to use the instrumentation config option to log would be great. I'd also likely accept a PR that adds Rails style logging as an optional module that can be used with ActiveSupport::Notifications.

[Aesthetikx]

Cool. Leaving this https://github.com/rails/rails/blob/24189390074049ca16da003dc796f1f64622173a/actionview/lib/action_view/log_subscriber.rb here for myself or someone else at a later date, as this appears to be how Rails is using instrumentation and log subscriber to log partial render duration etc. If I get some Free Time ™️ I will have a go at a module / implementation, as it will be either usable as a configured option or otherwise simple enough to go into the documentation.

[Aesthetikx]

Made some progress.

module ViewComponent
  class LogSubscriber < ActiveSupport::LogSubscriber
    define_method :'!render' do |event|
      info do
        message = +"  Rendered #{event.payload[:name]}"
        message << " (Duration: #{event.duration.round(1)}ms"
        message << " | Allocations: #{event.allocations})"
      end
    end
  end
end

ViewComponent::LogSubscriber.attach_to :view_component

Note that I had to use define_method because you cannot def !render. See #910 (review) for a brief discussion on the leading !, I am thinking perhaps that was a mistake but I'm not sure of the full context. As an aside, whoever came up with that idea was rather clever.

There is also the option of using #{event.payload[:identifer]} (the path on disk to the component) or #{event.payload[:name]} (the class name of the view component.) Partials and templates use the path, so perhaps that is more consistent.

This is what it looks like using name:

  Rendered ModalComponent (Duration: 9.2ms | Allocations: 12458)

and identifier:

  Rendered /home/aesthetikx/thing/app/components/modal_component.rb (Duration: 8.7ms | Allocations: 12458)

I would appreciate if someone who knows better could chime in on the ! situation, and then after that we could either put this into the documentation or include the module in the library and hide the attach_to behind like a config.view_component.logging_enabled or something.

[Aesthetikx]

The plot thickens. #435 already introduced a LogSubscriber which was later reverted here 5f15ed3 (not sure why.) It looks like at the time there was both render_template and render_collection, so the log subscriber implementation was actually a bit more fancy then the one I came up with. In my current codebase I don't have any collections to test with, so I am not sure (I guess I assume it would) if it would print out 100 lines of render log for a collection. In that case, it seems that the instrumentation module would have to be updated to instrument both render and render collection, and then somehow skip the render log in the context of a render_collection log?

[Spone]

The revert of #435 was due to performance concerns (see the last comments on the PR), I'm not sure what can be done to improve on this front.

[danielnc]

Looking at this too, it would be helpful to get an idea if a specific component render time is potentially a bottleneck or could be optimized

[MyklClason]

Perhaps a different approach would be useful?

Might there be a quick way to do this as a hack to get a rough estimate of the render time? Is there something we can add the the ApplicationViewComponent and maybe do some convention that we define that could hook into it and allow us to say:

1. Set "@start_render_at" time during initializing
2. Add "@end_render_at" time after render.
3. Estimate render time as the difference of the two?

Perhaps even store at the class level so we can just have it give us the total time spent rendering a specific component. Then we can just do something like:

around_action :print_view_component_statistics

def print_view_component_statistics
  ApplicationViewComponent.reset_render_time_statistics if Rails.env.development?
  yield
  ApplicationViewComponent.print_render_time_statistics if Rails.env.development?
end

The data might be something like this:

SomethingComponent - 100ms total, 3 renders, 33.33 ms average.
SomethingElseComponent - 20ms total, 1 render
ViewComponent Overall - 120ms total, 4 renders, 30.00 ms average.

We could also wrap each component in something to allow for collecting those statistics if there's a suitable existing library for it. Right now I'm just looking for a good solution for collecting render time data for components.

Edit: I'm now recalling Dry::Effects gem as a potential solution for this. Use it to keep a hash that can be used to cache that data. Currently using the gem for passing current_user, as per this article: https://evilmartians.com/chronicles/viewcomponent-in-the-wild-supercharging-your-components.
https://github.com/dry-rb/dry-effects

[tgaff]

Just want to toss out a slightly alternate approach if you're OK with just seeing totals:

Getting the render times, at least broadly in total via the Server-Timings header is already built-into rails. But it excludes any Notification that begins with ! such as !render.view_component. It appears when Instrumentation was added there was a little discussion about whether it should or should not have a ! prefixed. It might be worth re-opening that discussion?

[joelhawksley]

@tgaff that's interesting. Do you know if those server timings are used in production? I'd be hesitant turn these on outside of development for performance reasons.

[Aesthetikx]

I may try to take a look at this again this week/end. I remember that I had answers to some of the questions raised above, but now I have totally forgotten.

[tgaff]

@tgaff that's interesting. Do you know if those server timings are used in production? I'd be hesitant turn these on outside of development for performance reasons.

They are not used in production. They're enabled by default in development only. They can be manually enabled via production.rb:

  config.server_timing = ENV["SERVER_TIMING"].present?

(but one may want to restrict this to a staging/UAT/etc environment when needed)

[joelhawksley]

@tgaff oh, that's fantastic then. I think it will be an easy PR to remove the ! 😄 Want to do the honors?

[tgaff]

Sure, I'd be happy to. I'm pretty focused on this feature right now anyway.

[tgaff]

Making the change was straightforward.

However its a breaking change for anyone already subscribing to the existing ActiveSupport::Notification. I don't see a way to publish under 2 names other than to instrument both.

I think we have a choice of either:

1. wait for a major release to include this change
2. publish both events: !render.view_component and render.view_component. The overhead is low assuming no one subscribes to both events (in which case its double the current).
3. another config flag + maybe a deprecation

Thoughts?
I'm leaning towards 2 but we'd also want to deprecate and clean it up for the next major release. I may open a PR so we can discuss there.
(Note: I'm leaving on vacation tomorrow so I may not respond until the 22nd of this month.)