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

@@ -67,6 +67,7 @@ module ActionDispatch
     autoload :PublicExceptions
     autoload :Reloader
     autoload :RemoteIp
+    autoload :ServerTiming
     autoload :ShowExceptions
     autoload :SSL
     autoload :Static

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

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

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].

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

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?

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",