RailsのログにはViewのレンダリングやSQLの処理時間が表示されています。
これらは ActiveSupport::Notifications や ActiveSupport::Subscriber が使われています。
この仕組みを利用すると、自分のライブラリでも処理時間やログを出力することができます。
まずは、Notificationsってどんなものか見てみましょう。
ActiveSupport::Notifications
Instrumenters
通知するリスナーを登録します。
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を登録します。
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 をチラ見してみましょう。
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に表示してみましょう。
アクション内のリクエスト時間を集計するためのグローバルな変数が必要なので、レジストリを作成します。
module Faraday
class RuntimeRegistry
thread_mattr_accessor :api_runtime
end
en
遠い昔にブログを書いたのですが、ActiveSupport::PerThreadRegistry はRails5から deprecated らしいので Module#thread_mattr_accessor を使いましょう。
次に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
end
end
end
Faraday::LogSubscriber.attach_to :faraday
最後にControllerRuntimeを作成します。
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٩( ‘ω’ )و