Add Server Timing middleware by sogamoso · Pull Request #36289 · rails/rails

sogamoso · 2019-05-15T22:57:44Z

Summary

What is server timing?

It's a specification that defines how the server can communicate the
user agent performance metrics about the request it is responding to.

Here's the official specification: https://www.w3.org/TR/server-timing/

How does it work?

This introduces a new ServerTiming middleware only on development by
default, this is done using the config.server_timing setting.

It works by subscribing to all ActiveSupport::Notifications and adding
their duration to the Server-Timing header.

Why is this useful?

It makes looking at performance metrics in development much easier,
especially when using Chrome dev tools which include the metrics in the
Network Inspector. Here's an example:

Paired on this with @guilleiguaran

guilleiguaran · 2019-05-15T23:05:42Z

FYI, This was originally planned for GSoC but it wasn't completed so I asked to @sebasoga to work on this.

https://github.com/railsgsoc/ideas/wiki/2018-Ideas#server-timing-middleware

/cc @gsamokovarov

actionpack/lib/action_dispatch/middleware/server_timing.rb

jeremy · 2019-05-16T03:29:27Z

See also #36220

rafaelfranca · 2019-05-16T15:25:58Z

I think we should be merging efforts on #36220 given it is an older PR and the contributor is still active.

guilleiguaran · 2019-05-16T15:26:16Z

actionpack/test/dispatch/server_timing_test.rb

Since we really don't care about what we are doing here we can just use true instead

sogamoso · 2019-05-16T23:46:41Z

@guilleiguaran, @jeremy, @rafaelfranca: happy to merge the efforts. I think we both took a different approach so a little bit of direction of how you think the API should look like might help us know what the best way to merge efforts is.

Maybe making the events and opt-in the app config could help reduce potential noise:

config.server_timing = ["process_action.action_controller"]

Would be great if ActiveSupport::Notifications::Event also had a #description that we could use and include in the header. I'd be happy to work on that as well, maybe on a separate branch.

/cc @itsWill

jonathanhefner · 2019-11-04T18:47:22Z

actionpack/lib/action_dispatch/middleware/server_timing.rb

This could be events_collection.sum(&:duration) instead of duration_sum(events_collection).

Nice suggestion, done in 45c9631.

igorkasyanchuk · 2020-01-03T20:11:56Z

It looks like a cool feature. Maybe try to backport it to the older version of Rails?

@guilleiguaran

What is server timing? It's an specification that defines how the server can communicate the user agent performance metrics about the request it is responding to. Here's the oficinal specification: https://www.w3.org/TR/server-timing/#dfn-server-timing-header-field How does it work? This introduces a new `ServerTiming` middleware only on `development` by default, this is done using the `config.server_timing` setting. It works by subscribing to all `ActiveSupport::Notifications` and adding their duration to the `Server-Timing` header. Why is this useful? It makes looking at perfomance metrics in development much easier, especially when using Chrime devtools which includes the metrics in the Network Inspector. Here's an example: ![](https://d3vv6lp55qjaqc.cloudfront.net/items/371h2y3B3a0U470j040u/Image%202019-05-15%20at%205.40.37%20PM.png?) Paired on this with @guilleiguaran

We only want to be subscribed for the life span of the middleware execution.

We don't really care about what's going on in the block as long as it gets executed.

sogamoso · 2020-01-08T21:57:00Z

@igorkasyanchuk I'd be glad to give that a try once we settle on an API for this.

Got [this message](https://github.com/rails/rails/commit/45c9631614437b32af264c3fea3dad0333222456/checks?check_suite_id=390902272): ``` Offenses: actionpack/test/dispatch/server_timing_test.rb:41:3: C: Layout/EmptyLinesAroundAccessModifier: Remove a blank line after private. private ^^^^^^^ 2826 files inspected, 1 offense detected ```

gsamokovarov · 2020-01-09T12:50:42Z

actionpack/lib/action_dispatch/middleware/server_timing.rb

+      end
+
+      status, headers, body = @app.call(env)
+      ActiveSupport::Notifications.unsubscribe(subscriber)


Should we unsubscribe in an ensure block, to ensure we don't leak subscriptions if the @app crashes? 🤔

@gsamokovarov that makes sense. Are you thinking about something along these lines?

status, headers, body = begin @app.call(env) ensure ActiveSupport::Notifications.unsubscribe(subscriber) end

Yes, something like this should work.

Done in 6d9ce6e.

simi · 2020-01-09T13:17:05Z

railties/lib/rails/generators/rails/app/templates/config/environments/development.rb.tt

  config.consider_all_requests_local = true

+  # Enable server timing
+  config.server_timing = true


What about to make this default for development (also default for framework defaults "6.1" )? That will make it easier to use (it will kick-in on its own once "6.1" defaults are loaded) for upgraded apps as well.

rails/railties/lib/rails/application/configuration.rb

Line 159 in 61306d7

when "6.1"

@simi I think the most sensible is to make this the default on development only. I agree this would be a nice default for apps upgrading to 6.1+. Let's see what people in the core and committers team think about it.

My idea is to make it default in development only, but without need of explicit configuration entry.

Avoid instantiating an empty array and inserting items into it by using `map`.

We want to make sure that if the application during crashes the Server Timing middleware unsubscribes before continuing.

rails-bot · 2020-04-09T09:43:19Z

This pull request has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs.
Thank you for your contributions.

ahorek · 2020-04-09T09:50:04Z

I would like to see this feature in a future version of Rails, what else needs to be done?

n-rodriguez · 2020-12-02T19:45:26Z

Hi there! Any news?

sogamoso · 2020-12-10T14:08:18Z

@jeremy, @guilleiguaran is there anything I can do to move forward with this?

p8 · 2021-07-12T10:39:55Z

@SebastianS Could you resolve the merge conflicts and add a changelog entry?

sogamoso · 2021-09-20T04:07:04Z

@p8 will do.

guilleiguaran · 2021-09-20T04:43:00Z

@SebastianS sorry for the super-late reply, I've merged this and added the CHANGELOG entry in 54707cb

I think we should explain the new configuration variable added to the Configuring Guide: https://guides.rubyonrails.org/configuring.html

* main: [ci skip] Add Bootstrap and Bulma to the CSS processors' list (#43254) Add missing configuration to middleware test Add ActionDispatch::ServerTiming to the list of middlewares in test Add CHANGELOG entry for ServerTiming middleware [ci skip] Add Server Timing middleware (#36289) Don't overwrite default opts in rich_text_area_tag (#43156) Only call `wrap_parameters` if it's defined (#43259) Suggest a CSP that's compatible with Turbo + import map (#43227) Fix app generator tests Fix docs spacing Fix typo: integer numbers (not integral) Add `beginning_of_week` option to `weekday_options_for_select` Pluralize the heading on the index page generated with scaffold Move the parameter wrapper code to the ActionController::Railtie class Add explicit rendering to DiskController#update Fix update & destroy queries when default_scope is nillable with all_queries: true

rails-bot bot added actionpack railties labels May 15, 2019

guilleiguaran self-assigned this May 15, 2019

guilleiguaran added this to the 6.1.0 milestone May 15, 2019

jeremy reviewed May 16, 2019

View reviewed changes

actionpack/lib/action_dispatch/middleware/server_timing.rb Outdated Show resolved Hide resolved

guilleiguaran reviewed May 16, 2019

View reviewed changes

guilleiguaran mentioned this pull request May 16, 2019

Add server timing middleware #36220

Closed

sogamoso force-pushed the server-timing branch from e96bf54 to c8eb8ac Compare May 17, 2019 06:55

jonathanhefner reviewed Nov 4, 2019

View reviewed changes

sogamoso added 4 commits January 8, 2020 16:51

Unsuscribe from ActiveSupport notifications

db283e1

We only want to be subscribed for the life span of the middleware execution.

No need to sleep

917c695

We don't really care about what's going on in the block as long as it gets executed.

Use sum with symbol to proc instead of inject

45c9631

sogamoso force-pushed the server-timing branch from c8eb8ac to 45c9631 Compare January 8, 2020 21:51

gsamokovarov reviewed Jan 9, 2020

View reviewed changes

simi reviewed Jan 9, 2020

View reviewed changes

Use #map instead of #each

93a67cd

Avoid instantiating an empty array and inserting items into it by using `map`.

sogamoso force-pushed the server-timing branch 2 times, most recently from f8c6119 to f888f68 Compare January 9, 2020 23:15

Ensure we don't leak subscriptions when the app crashes

6d9ce6e

We want to make sure that if the application during crashes the Server Timing middleware unsubscribes before continuing.

sogamoso force-pushed the server-timing branch from f888f68 to 6d9ce6e Compare January 10, 2020 00:23

rails-bot bot added the stale label Apr 9, 2020

rails-bot bot removed the stale label Apr 9, 2020

jeremy modified the milestones: 6.1.0, 6.x Nov 2, 2020

Base automatically changed from master to main January 14, 2021 17:01

georgeclaghorn modified the milestones: 6.x, 7.0 Mar 27, 2021

guilleiguaran merged commit 0547b16 into rails:main Sep 20, 2021

tagliala mentioned this pull request Dec 31, 2021

Add Rails 7 Support activeadmin/activeadmin#7235

Merged

11 tasks

jonathanhefner mentioned this pull request Jan 17, 2022

doc: ActionDispatch::ServerTiming & rails_on_rack guide update [ci-skip] #44186

Merged

cwrw mentioned this pull request Mar 23, 2022

Upgrade rails version DFE-Digital/apply-for-teacher-training#6699

Merged

bibendi mentioned this pull request May 22, 2022

fix compatibility with Rails 7 palkan/downstream#8

Merged

3 tasks

sogamoso deleted the server-timing branch June 5, 2022 21:34

This was referenced Jun 12, 2023

Logging Render Times in Development Mode ViewComponent/view_component#1490

Closed

Allow Rails to provide timing data in browser dev-tools via Server-Timing header ViewComponent/view_component#1771

Merged

mjankowski mentioned this pull request Jun 20, 2023

Rails 7 update mastodon/mastodon#24241

Merged

Conversation

sogamoso commented May 15, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Summary

What is server timing?

How does it work?

Why is this useful?

Uh oh!

guilleiguaran commented May 15, 2019

Uh oh!

Uh oh!

jeremy commented May 16, 2019

Uh oh!

rafaelfranca commented May 16, 2019

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

sogamoso commented May 16, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

sogamoso Jan 8, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

igorkasyanchuk commented Jan 3, 2020

Uh oh!

sogamoso commented Jan 8, 2020

Uh oh!

Choose a reason for hiding this comment

Uh oh!

sogamoso Jan 9, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

sogamoso Jan 9, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

rails-bot bot commented Apr 9, 2020

Uh oh!

ahorek commented Apr 9, 2020

Uh oh!

n-rodriguez commented Dec 2, 2020

Uh oh!

sogamoso commented Dec 10, 2020

Uh oh!

p8 commented Jul 12, 2021

Uh oh!

sogamoso commented Sep 20, 2021

Uh oh!

guilleiguaran commented Sep 20, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

12 participants

sogamoso commented May 15, 2019 •

edited

Loading

sogamoso commented May 16, 2019 •

edited

Loading

sogamoso Jan 8, 2020 •

edited

Loading

sogamoso Jan 9, 2020 •

edited

Loading

sogamoso Jan 9, 2020 •

edited

Loading