Edited at

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

More than 1 year has passed since last update.

RailsのログにはViewのレンダリングやSQLの処理時間が表示されています。

これらは ActiveSupport::NotificationsActiveSupport::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 MiddlewareInstrumentationが利用できるので、ちょっと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に表示してみましょう。

fish.png

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


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

fish_2.png


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 に定義されています。

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

fish_4.png

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


まとめ

こうしてまとめてみると、やっぱりコンテキストで分離されていてRails良くできてるなーって改めて感じます。

この記事では一定の処理時間以上になると色を変えてログ出力しましたが、slackなどに通知することもできますね。

Happy Hacking٩( ‘ω’ )و