Allow Rails to provide timing data in browser dev-tools via Server-Timing header

[tgaff]

What are you trying to accomplish?

Per this discussion:
#1490 (comment)

This may resolve in part #1490

This alters the key used for ActiveSupport Instrumentation so that Rails automatically picks it up and includes a sum total in the browser headers sent to the client (feature added to Rails here). By default the Server-Timing header is only enabled in development but can be turned on via config.server_timing = true. Rails excludes any notification key that starts with ! when setting the Server-Timing header.

All desktop browsers I've checked (FF, Chrome, Safari, Edge, Opera) will automatically add this data to the client-side timing data on the dev-tools Network tab. This makes for a quick "low-detail" look at what happened in a particular request.

Above is what you see in Firefox.

• marks the old key as deprecated
  • and avoids reporting this on every render
• adds a config setting to choose the deprecated key (default) or the new one

What approach did you choose and why?

I've gone with the simplest approach of just renaming the key for now as that's what was initially discussed in the issue. Please see discussion below.

Based on feedback, this now introduces a new config to avoid the breaking change.

Anything you want to highlight for special attention from reviewers?

the below "breaking change" issue has been resolved with an additional config option per @joelhawksley instruction

As I mentioned on the issue, this could be considered a breaking change for anyone currently subscribed to the current notification name. I proposed 3 ways of handling that, but could use guidance on what maintainers think is best.

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 to set which name to use + maybe a deprecation for the old ! name.

I have a slight preference towards 2 since it gets this in quickly, but not opposed to any of these.

Also I haven't proven it out yet, but I think there's a chance that nested components could also suffer from this bug that I reported over on the Rails repo: rails/rails#48375

[joelhawksley]

another config flag to set which name to use + maybe a deprecation for the old ! name.

Let's do that! Let's default the config to false.

[boardfish]

Looks good to me!

[joelhawksley]

👏🏻

[tgaff]

Not important but: specifying Chrome here is perhaps a little "chrome-centric". The feature works nearly the same in FF, Safari, Edge and Opera. The screenshot in the PR is from FF 113 IIRC.

[reeganviljoen]

Is there anyway you can add Firefox and safari instructions

[tgaff]

They are nearly identical aside from coloration, so I don't think it's necessary.

1. Network tab (refresh if its empty)
2. Click the request you're interested in.
3. on the right-side OR the bottom-side (depends on size of the dev-tools area) you'll see several tabs for that request; choose "Timing" or "Timings" (in FF)
4. Look for server timings at the bottom beneath the client-side data.

Biggest caveats with Server-Timings in general:

• It's not provided for every request. Normal MVC rails controllers in development mode will provide it (it's a middleware) - but assets won't. In production you won't see it without enabling it in production.rb.
• It does not give you the level of detail (or cross-request metrics) you can get from a product like Skylight or New Relic. I'd suggest using it for quick-checks mainly, e.g.: "huh active record is crazy on this one, maybe I should take a look at my queries."
• Does not exist prior to Rails 7.

From top-left going clockwise: Chrome, Firefox, Safari. You can see its pretty much the same.

[joelhawksley]

How about we just say "browser" here? Perhaps we should add this screenshot to the docs?

[tgaff]

I just added a smaller variant of the screenshot. When running the docs locally that path seems to work and display properly, but there may be some risk of a dead img src when deployed.

[joelhawksley]

@tgaff it looks like we might have some missing test coverage here. Care to investigate?

[tgaff]

I've been trying to get coverage on that deprecation warning and have run into a bit of a wall. Maybe someone has advice.

In engine_test.rb something like this works for testing it:

  def test_deprecation_notice_when_use_deprecated_instrumentation_name
    with_config_option(:instrumentation_enabled, true) do
      with_config_option(:use_deprecated_instrumentation_name, true) do
        assert_deprecated(/!render\.view_component/, ViewComponent::Deprecation) do
          ActiveSupport.run_load_hooks(:view_component, self)
        end
      end
    end
  end

  def test_no_deprecation_notice_when_not_using_deprecated_name
    with_config_option(:instrumentation_enabled, true) do
      with_config_option(:use_deprecated_instrumentation_name, false) do
        assert_not_deprecated(ViewComponent::Deprecation) do
          ActiveSupport.run_load_hooks(:view_component, self)
        end
      end
    end
  end

However it's got a pretty big down-side of causing the other instrumentation tests to fail in an order-dependent way and I suspect having all the initializer hooks (in engine.rb) run twice could also cause unexpected issues elsewhere in the test suite too (someday). More specifically: in the other instrumentation tests it finds more than one event - because with the initializer loaded twice it sends multiple events.

I've been trying to find a way to bind those initializers to another context to test but I haven't been able to come up with anything that actually works. I've even tried running just the two config and instrumentation hooks, bound to a fresh Rails app but it still poisons the suite.

Any ideas?

[joelhawksley]

I've been trying to find a way to bind those initializers to another context to test but I haven't been able to come up with anything that actually works. I've even tried running just the two config and instrumentation hooks, bound to a fresh Rails app but it still poisons the suite.

😅 sounds like we should :nodoc: this section then. Thanks for digging in so thoroughly. Perhaps you could include a summary comment of what you said here with the nodoc?

[tgaff]

😅 sounds like we should :nodoc: this section then. Thanks for digging in so thoroughly. Perhaps you could include a summary comment of what you said here with the nodoc?

I couldn't find a better alternative. 🙁 nocov added around that section - with comment.

[rmacklin]

It looks like this may have been inadvertently deleted by regenerating the API docs, which happened because it seems this part was manually added directly in api.md in #1773, rather than in the corresponding YARD comment.

[rmacklin]

I've opened a PR here to restore this example here: #1794

[oliverguenther]

Also I haven't proven it out yet, but I think there's a chance that nested components could also suffer from this bug that I reported over on the Rails repo: rails/rails#48375

I can confirm that this happens. The logged render statements for an exemplary stacked ViewComponent (lots of nested component calls) is

:I, [2023-09-14T11:04:59.370006 #44280] INFO -- : Rendered Meetings::ShowComponent within layouts/base (Duration: 226.1ms | Allocations: 215335)

The total browser reported time is somehwere in ~400ms. The reported timing is ~6s, which is the sum of all component instrumentation calls combined. But as they are nested, inner calls should be excluded.