From 0547b1646d09a80d0685a03c932fb0ba09c3e614 Mon Sep 17 00:00:00 2001 From: Sebastian Sogamoso Date: Sun, 19 Sep 2021 23:27:07 -0500 Subject: [PATCH] Add Server Timing middleware (#36289) * Add Server Timing middleware 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/#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 performance metrics in development much easier, especially when using Chrome dev tools 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 --- actionpack/lib/action_dispatch.rb | 1 + .../middleware/server_timing.rb | 33 +++++++++ .../test/dispatch/server_timing_test.rb | 70 +++++++++++++++++++ .../lib/rails/application/configuration.rb | 3 +- .../application/default_middleware_stack.rb | 1 + .../config/environments/development.rb.tt | 3 + railties/test/application/middleware_test.rb | 2 + 7 files changed, 112 insertions(+), 1 deletion(-) create mode 100644 actionpack/lib/action_dispatch/middleware/server_timing.rb create mode 100644 actionpack/test/dispatch/server_timing_test.rb diff --git a/actionpack/lib/action_dispatch.rb b/actionpack/lib/action_dispatch.rb index 76377984a6..7ffc6472b3 100644 --- a/actionpack/lib/action_dispatch.rb +++ b/actionpack/lib/action_dispatch.rb @@ -67,6 +67,7 @@ module ActionDispatch autoload :PublicExceptions autoload :Reloader autoload :RemoteIp + autoload :ServerTiming autoload :ShowExceptions autoload :SSL autoload :Static diff --git a/actionpack/lib/action_dispatch/middleware/server_timing.rb b/actionpack/lib/action_dispatch/middleware/server_timing.rb new file mode 100644 index 0000000000..258f3cdd9d --- /dev/null +++ b/actionpack/lib/action_dispatch/middleware/server_timing.rb @@ -0,0 +1,33 @@ +# frozen_string_literal: true + +require "active_support/notifications" + +module ActionDispatch + class ServerTiming + SERVER_TIMING_HEADER = "Server-Timing" + + def initialize(app) + @app = app + end + + def call(env) + events = [] + subscriber = ActiveSupport::Notifications.subscribe(/.*/) do |*args| + events << ActiveSupport::Notifications::Event.new(*args) + end + + status, headers, body = begin + @app.call(env) + ensure + ActiveSupport::Notifications.unsubscribe(subscriber) + end + + header_info = events.group_by(&:name).map do |event_name, events_collection| + "#{event_name};dur=#{events_collection.sum(&:duration)}" + end + headers[SERVER_TIMING_HEADER] = header_info.join(", ") + + [ status, headers, body ] + end + end +end diff --git a/actionpack/test/dispatch/server_timing_test.rb b/actionpack/test/dispatch/server_timing_test.rb new file mode 100644 index 0000000000..b66592fbc1 --- /dev/null +++ b/actionpack/test/dispatch/server_timing_test.rb @@ -0,0 +1,70 @@ +# frozen_string_literal: true + +require "abstract_unit" + +class ServerTimingTest < ActionDispatch::IntegrationTest + class TestController < ActionController::Base + def index + head :ok + end + + def show + ActiveSupport::Notifications.instrument("custom.event") do + true + end + head :ok + end + + def create + ActiveSupport::Notifications.instrument("custom.event") do + raise + end + end + end + + test "server timing header is included in the response" do + with_test_route_set do + get "/" + assert_match(/\w+/, @response.headers["Server-Timing"]) + end + end + + test "includes default action controller events duration" do + with_test_route_set do + get "/" + assert_match(/start_processing.action_controller;dur=\w+/, @response.headers["Server-Timing"]) + assert_match(/process_action.action_controller;dur=\w+/, @response.headers["Server-Timing"]) + end + end + + test "includes custom active support events duration" do + with_test_route_set do + get "/id" + assert_match(/custom.event;dur=\w+/, @response.headers["Server-Timing"]) + end + end + + test "ensures it doesn't leak subscriptions when the app crashes" do + with_test_route_set do + post "/" + assert_not ActiveSupport::Notifications.notifier.listening?("custom.event") + end + end + + private + def with_test_route_set + with_routing do |set| + set.draw do + get "/", to: ::ServerTimingTest::TestController.action(:index) + get "/id", to: ::ServerTimingTest::TestController.action(:show) + post "/", to: ::ServerTimingTest::TestController.action(:create) + end + + @app = self.class.build_app(set) do |middleware| + middleware.use ActionDispatch::ServerTiming + end + + yield + end + end +end diff --git a/railties/lib/rails/application/configuration.rb b/railties/lib/rails/application/configuration.rb index 4414d170c0..f83df20a8b 100644 --- a/railties/lib/rails/application/configuration.rb +++ b/railties/lib/rails/application/configuration.rb @@ -21,7 +21,7 @@ module Rails :read_encrypted_secrets, :log_level, :content_security_policy_report_only, :content_security_policy_nonce_generator, :content_security_policy_nonce_directives, :require_master_key, :credentials, :disable_sandbox, :add_autoload_paths_to_load_path, - :rake_eager_load + :rake_eager_load, :server_timing attr_reader :encoding, :api_only, :loaded_config_version @@ -74,6 +74,7 @@ module Rails @add_autoload_paths_to_load_path = true @permissions_policy = nil @rake_eager_load = false + @server_timing = false end # Loads default configurations. See {the result of the method for each version}[https://guides.rubyonrails.org/configuring.html#results-of-config-load-defaults]. diff --git a/railties/lib/rails/application/default_middleware_stack.rb b/railties/lib/rails/application/default_middleware_stack.rb index eddd3432c7..daaa009f69 100644 --- a/railties/lib/rails/application/default_middleware_stack.rb +++ b/railties/lib/rails/application/default_middleware_stack.rb @@ -42,6 +42,7 @@ module Rails middleware.use ::ActionDispatch::Executor, app.executor + middleware.use ::ActionDispatch::ServerTiming if config.server_timing middleware.use ::Rack::Runtime middleware.use ::Rack::MethodOverride unless config.api_only middleware.use ::ActionDispatch::RequestId, header: config.action_dispatch.request_id_header diff --git a/railties/lib/rails/generators/rails/app/templates/config/environments/development.rb.tt b/railties/lib/rails/generators/rails/app/templates/config/environments/development.rb.tt index 623070be48..fa1bd04579 100644 --- a/railties/lib/rails/generators/rails/app/templates/config/environments/development.rb.tt +++ b/railties/lib/rails/generators/rails/app/templates/config/environments/development.rb.tt @@ -14,6 +14,9 @@ Rails.application.configure do # Show full error reports. config.consider_all_requests_local = true + # Enable server timing + config.server_timing = true + # Enable/disable caching. By default caching is disabled. # Run rails dev:cache to toggle caching. if Rails.root.join("tmp/caching-dev.txt").exist? diff --git a/railties/test/application/middleware_test.rb b/railties/test/application/middleware_test.rb index f015938a19..fdc088f0a0 100644 --- a/railties/test/application/middleware_test.rb +++ b/railties/test/application/middleware_test.rb @@ -21,6 +21,7 @@ module ApplicationTests test "default middleware stack" do add_to_config "config.active_record.migration_error = :page_load" + add_to_config "config.server_timing = true" boot! @@ -63,6 +64,7 @@ module ApplicationTests "Rack::Sendfile", "ActionDispatch::Static", "ActionDispatch::Executor", + "ActionDispatch::ServerTiming", "ActiveSupport::Cache::Strategy::LocalCache", "Rack::Runtime", "Rack::MethodOverride",