Visualize Rails server processing time using Server Timing

Introduction

As an easy way to visualize the processing time of the Rails server in the development environment, we will introduce a method of measuring the processing speed of the server using ActiveSupport :: Notifications and visualizing it using Server Timing.

Target audience

--Using Rails --Using a verification tool such as Chrome --I want to easily measure and visualize the processing speed of the server.

The finished product

Select the target communication from Chrome's verification tool and select the Timing tab to display Server Timing as shown in the figure below.

This means that it took 4.26ms to process the database query, 22.63ms to build the view, and 35.22ms in total for UserController # index.

What is ActiveSupport :: Notifications?

A library that provides a measurement API for Ruby. There is a mechanism to measure events and subscribe to measurement results, and you can easily use it like this.

#Subscribe
ActiveSupport::Notifications.subscribe("my.event") do |name, start, finish, id, payload|
  name    # =>event name: "my.event"
  start   # =>Measurement start time: 2020-10-18 12:34:56 +0900
  finish  # =>Measurement end time: 2020-10-18 12:34:56 +0900
  id      # =>Unique event ID: "xxxxxxxxxxxxx"
  payload # =>Payload / additional information(hash): {data: :hoge}
end

#measurement
ActiveSupport::Notifications.instrument("my.event", data: :hoge) do
  #Run event
end

What is Server Timing?

It is a mechanism to communicate the processing time on the server side through the HTTP header. By adding information such as measurement time to the Server-Timing header field of the response header, the verification tool will automatically visualize it.

notation

--Basic form: name; desc = description; dur = measurement time --Name the name total to represent the total measurement time --If there are multiple, separate them with commas.

combine

First of all, it is necessary to measure the processing time of the server, but in fact Rails already measures it with the name process_action.action_controller. Therefore, you can create it from the part you subscribe to.

Create a file like the following in config / initializer.

config/initializers/server_timing.rb

ActiveSupport::Notifications.subscribe "process_action.action_controller" do |*args|
  # ActiveSupport::Notifications::Event will process the data nicely if you pass the argument as it is
  event = ActiveSupport::Notifications::Event.new(*args)

  duration = event.duration   #processing time
  payload = event.payload     #payload

  controller_name = payload.controller #Controller name
  action_name = payload.action         #Action name
  db_runtime = payload.db_runtime      #Time taken to query the database
  view_runtime = payload.view_runtime  #Total time taken for view
  server_timing = "total;desc=\"#{controller_name}\##{action_name}\";dur=#{duration}, " \
           "db;dur=#{db_runtime}" \
           "view;dur=#{view_runtime}"
end

The contents of the payload of "process_action.action_controller" are described below. https://railsguides.jp/active_support_instrumentation.html#process-action-action-controller

This completes the acquisition of the processing time on the server. All you have to do now is register server_timing in the Server-Timing header.

Rails doesn't use global variables very much, but I don't know any other good way, so I will use global variables this time. Store the response object that can be obtained from the controller in a global variable, and add Server-Timing header to the response object in the previous subscription process.

app/controllers/application_controller.rb

class ApplicationController < ActionController::Base
  prepend_before_action { $response = response }
end

config/initializers/server_timing.rb

ActiveSupport::Notifications.subscribe "process_action.action_controller" do |*args|
  # ...
  #abridgement
  # ...
  response = $response
  response.headers["Server-Timing"] = server_timing
end

That's all for the implementation.

Now the Server-Timing header field will be given a value similar to the following, and Chrome's validation tool will give you a nice visualization.

Server-Timing: total;desc="UsersController#index";dur=17.167, db;dur=0.5440000677481294, view;dur=15.272999997250736

Finally

I used ActiveSupport :: Notifications and Server Timing for the first time, and found it useful because I could easily visualize where the server was taking time. ActiveSupport :: Notifications also tells you how many instances were created in ActiveRecord and whether the cache was used in SQL, so you can get more detailed information depending on your ingenuity. Also, if I have the opportunity, I would like to visualize detailed information.

reference

• ActiveSupport::Notifications -Active Support Instrumentation Function
• Server-Timing - MDN
• Server Timing - W3C