Railsでイベントの処理時間を計測したりログを出力する

RailsのログにはViewのレンダリングやSQLの処理時間が表示されています。
これらは ActiveSupport::Notifications や ActiveSupport::Subscriber が使われています。
この仕組みを利用すると、自分のライブラリでも処理時間やログを出力することができます。

まずは、Notificationsってどんなものか見てみましょう。

ActiveSupport::Notifications

Instrumenters

通知するリスナーを登録します。

message_notifications.rb

ActiveSupport::Notifications.instrument('message.sample', text: 'message') do
  sleep(0.1)
end

ActiveSupport::Notifications.instrument('test.sample', text: 'test') do
  sleep(0.2)
end

instrument の第1引数が名前で、第2引数がsubscriberに通知されるデータです。

ActiveSupport::Subscriber

Subscriberを登録します。

message_subscriber.rb

class MessageScriber < ActiveSupport::Subscriber
  def message(event)
    payload = event.payload
    puts "#{payload[:text]} %.1fms" %  event.duration
  end

  def test(event)
    payload = event.payload
    puts "#{payload[:text]} %.1fms" %  event.duration
  end
end

# Subscriberを登録
MessageScriber.attach_to :sample

実行してみましょう。

message 101.1ms
test 201.8ms

処理時間を計測できました。

Example

Faraday MiddlewareでInstrumentationが利用できるので、ちょっとRailsアプリケーションで実際に使ってみましょう。

この記事のサンプルコード murajun1978/notification-sample

まずは Faraday Middleware の Instrumentation をチラ見してみましょう。

faraday_middleware/lib/faraday_middleware/instrumentation.rb

require 'faraday'

module FaradayMiddleware
  # Public: Instruments requests using Active Support.
  #
  # Measures time spent only for synchronous requests.
  #
  # Examples
  #
  #   ActiveSupport::Notifications.subscribe('request.faraday') do |name, starts, ends, _, env|
  #     url = env[:url]
  #     http_method = env[:method].to_s.upcase
  #     duration = ends - starts
  #     $stderr.puts '[%s] %s %s (%.3f s)' % [url.host, http_method, url.request_uri, duration]
  #   end
  class Instrumentation < Faraday::Middleware
    dependency 'active_support/notifications'

    def initialize(app, options = {})
      super(app)
      @name = options.fetch(:name, 'request.faraday')
    end

    def call(env)
      ::ActiveSupport::Notifications.instrument(@name, env) do
        @app.call(env)
      end
    end
  end
end

ふむふむ、名前が request.faraday で、第2引数の env が subscriber に通知されるのですね。

Faradayがリクエストにかかった処理時間を表示する

アクション内のリクエスト時間をログのcompletedに表示してみましょう。

アクション内のリクエスト時間を集計するためのグローバルな変数が必要なので、レジストリを作成します。

lib/faraday/runtime_registry.rb

module Faraday
  class RuntimeRegistry
    thread_mattr_accessor :api_runtime
  end
en

遠い昔にブログを書いたのですが、ActiveSupport::PerThreadRegistry はRails5から deprecated らしいので Module#thread_mattr_accessor を使いましょう。

次にSubscriberを作成します。

lib/faraday/log_subscriber.rb

module Faraday
  class LogSubscriber < ActiveSupport::LogSubscriber
    class << self
      def runtime=(value)
        Faraday::RuntimeRegistry.api_runtime = value
      end

      def runtime
        Faraday::RuntimeRegistry.api_runtime ||= 0
      end

      def reset_runtime
        rt, self.runtime = runtime, 0
        rt
      end
    end

    def request(event)
      self.class.runtime += event.duration
    end
  end
end

Faraday::LogSubscriber.attach_to :faraday

最後にControllerRuntimeを作成します。

lib/faraday/controller_runtime.rb

module Faraday
  module ControllerRuntime
    extend ActiveSupport::Concern

    protected

    attr_internal :faraday_runtime

    def process_action(action, *args)
      Faraday::LogSubscriber.reset_runtime
      super
    end

    def append_info_to_payload(payload)
      super
      payload[:faraday_runtime] = (faraday_runtime || 0) + Faraday::LogSubscriber.reset_runtime
    end

    module ClassMethods
      def log_process_action(payload)
        messages, faraday_runtime = super, payload[:faraday_runtime]
        messages << ("Faraday: %.1fms" % faraday_runtime.to_f) if faraday_runtime
        messages
      end
    end
  end
end

ActiveSupport.on_load(:action_controller) do
  include Faraday::ControllerRuntime
end

サンプルアプリにリクエストしてみましょう。

$ curl http://localhost:3000/users/murajun1978/repositories

Faradayのリクエストをログに出力する

リクエストの内容をログに出力してみましょう。

Subscriberをログ出力できるように修正します。

module Faraday
  class LogSubscriber < ActiveSupport::LogSubscriber
    class << self
      def runtime=(value)
        Faraday::RuntimeRegistry.api_runtime = value
      end

      def runtime
        Faraday::RuntimeRegistry.api_runtime ||= 0
      end

      def reset_runtime
        rt, self.runtime = runtime, 0
        rt
      end
    end

    def request(event)
      self.class.runtime += event.duration
+     return unless logger.debug?+
+
+     env = event.payload
+
+     method = env[:method].to_s.upcase
+     status = env[:status]
+     request = env[:url]
+
+     debug " #{method} #{status} #{request} (#{duration_color(event.duration)}) "
    end
+
+   private
+
+     def duration_color(payload_duration)
+       display_duration = "%.1fms" % payload_duration
+       display_color    = payload_duration >= 1500 ? RED : GREEN
+       color(display_duration, display_color, true)
+     end
  end
end

Faraday::LogSubscriber.attach_to :faraday

duration_color で1500ms以上の場合は、赤文字で表示するようにしています。

colorメソッドや定数(RED や GREEN）は ActiveSupport::LogSubscriber に定義されています。

もう一度サンプルアプリにリクエストしてみましょう。

リクエストの詳細も表示できるようになりました

まとめ

こうしてまとめてみると、やっぱりコンテキストで分離されていてRails良くできてるなーって改めて感じます。
この記事では一定の処理時間以上になると色を変えてログ出力しましたが、slackなどに通知することもできますね。

Happy Hacking٩( ‘ω’ )و