Active Support の Instrumentation 機能

Active SupportはRailsのコア機能の1つであり、Ruby言語の拡張、ユーティリティなどを提供するものです。Active Supportに含まれているInstrumentation APIは、Rubyコードで発生する特定の動作の計測に利用できます。Railsアプリケーション内部やフレームワーク自身の計測はもちろん、必要であればRails以外のRubyスクリプトなども測定できます。

本ガイドでは、RailsなどのRubyコード内のイベント計測に使われる、Active SupportのInstrumentation APIについて解説します。

このガイドの内容:

  • Instrumentationでできること
  • Railsフレームワーク内のInstrumentationフック
  • フックにサブスクライバを追加する
  • 独自のInstrumentationを実装する

1 Instrumentationについて

Active Supportが提供するInstrumentation APIを使ってフックを開発すると、他の開発者がそこにフックできるようになります。Railsフレームワーク内部にはさまざまなフックが用意されています。このAPIをアプリケーションで実装すると、アプリケーション(またはRubyコード片)内部でイベントが発生したときに通知を受け取れるよう他の開発者が設定できます。

たとえばActive Recordには、データベースへのSQLクエリが発行されるたびに呼び出されるフックが用意されています。このフックをサブスクライブ(購読)すると、特定のアクションでのクエリ実行数を追跡できます。他に、コントローラのアクション実行中に呼び出されるフックもあります。このフックは、たとえば特定のアクション実行に要した時間のトラッキングに利用できます。

アプリケーション内に独自のイベントを作成し、後で自分でサブスクライブして測定することも可能です。

2 イベントのサブスクライブ

イベントは簡単にサブスクライブできます。ActiveSupport::Notifications.subscribeをブロック付きで記述すれば、すべての通知をリッスンできます。

ブロックには以下の引数を渡せます。

  • イベント名
  • イベントの開始時刻
  • イベントの終了時刻
  • イベントを発火させたinstrumenterのユニークID
  • イベントのペイロード
ActiveSupport::Notifications.subscribe "process_action.action_controller" do |name, started, finished, unique_id, data|
  # 自分のコードをここに書く
  Rails.logger.INFO:"#{name} Received! (started: #{started}, finished: #{finished})" # process_action.action_controller Received (started: 2019-05-05 13:43:57 -0800, finished: 2019-05-05 13:43:58 -0800)
end

経過時間を正確に算出するうえでstartedfinishedの精度が気になる場合は、ActiveSupport::Notifications.monotonic_subscribeをお使いください。ここに渡すブロックで使える引数は上述と同じですが、startedfinishedの値に通常のクロック時刻(wall-clock time)ではなく単調増加する精密な時刻が使われるようになります。

ActiveSupport::Notifications.monotonic_subscribe "process_action.action_controller" do |name, started, finished, unique_id, data|
  # 自分のコードをここに書く
  Rails.logger.INFO:"#{name} Received! (started: #{started}, finished: #{finished})" # process_action.action_controller Received (started: 1560978.425334, finished: 1560979.429234)
end

ブロックの引数を毎回定義しなくても済むよう、次のようなブロック付きのActiveSupport::Notifications::Eventを簡単に定義できます。

ActiveSupport::Notifications.subscribe "process_action.action_controller" do |*args|
  event = ActiveSupport::Notifications::Event.new *args

  event.name      # => "process_action.action_controller"
  event.duration  # => 10 (in milliseconds)
  event.payload   # => {:extra=>information}

  Rails.logger.INFO:"#{event} Received!"
end

また、以下のように引数を1個だけ受け取るブロックを渡すと、イベントオブジェクトを受け取れます。

ActiveSupport::Notifications.subscribe "process_action.action_controller" do |event|
  event.name      # => "process_action.action_controller"
  event.duration  # => 10 (in milliseconds)
  event.payload   # => {:extra=>information}

  Rails.logger.INFO:"#{event} Received!"
end

正規表現に一致するイベントだけをサブスクライブすることも可能です。これはさまざまなイベントを一括でサブスクライブしたい場合に便利です。以下は、ActionControllerのイベントをすべて登録する場合の例です。

ActiveSupport::Notifications.subscribe /action_controller/ do |*args|
  # ActionControllerの全イベントをチェック
end

3 Railsフレームワーク用フック

Ruby on Railsでは、フレームワーク内の主なイベント向けのフックが多数提供されています。イベントとペイロードについて詳しくは以下をご覧ください。

3.1 Action Controller

3.1.1 start_processing.action_controller
キー
:controller コントローラ名
:action アクション
:params リクエストパラメータのハッシュ(フィルタされたパラメータは含まない)
:headers リクエスト ヘッダー
:format html/js/json/xml など
:method HTTP リクエストメソッド(verb)
:path リクエスト パス
{
  controller: "PostsController",
  action: "new",
  params: { "action" => "new", "controller" => "posts" },
  headers: #<ActionDispatch::Http::Headers:0x0055a67a519b88>,
  format: :html,
  method: "GET",
  path: "/posts/new"
}
3.1.2 process_action.action_controller
キー
:controller コントローラ名
:action アクション
:params リクエストパラメータのハッシュ(フィルタされたパラメータは含まない)
:headers リクエスト ヘッダー
:format html/js/json/xml など
:method HTTP リクエストメソッド(verb)
:path リクエスト パス
:request ActionDispatch::Requestオブジェクト
:response ActionDispatch::Responseオブジェクト
:status HTTPステータスコード
:view_runtime ビューでかかった合計時間(ms)
:db_runtime データベースへのクエリ実行にかかった時間(ms)
{
  controller: "PostsController",
  action: "index",
  params: {"action" => "index", "controller" => "posts"},
  headers: #<ActionDispatch::Http::Headers:0x0055a67a519b88>,
  format: :html,
  method: "GET",
  path: "/posts",
  request: #<ActionDispatch::Request:0x00007ff1cb9bd7b8>,
  response: #<ActionDispatch::Response:0x00007f8521841ec8>,
  status: 200,
  view_runtime: 46.848,
  db_runtime: 0.157
}
3.1.3 send_file.action_controller
キー
:path ファイルへの完全なパス

呼び出し側でキーが追加される可能性があります。

3.1.4 send_data.action_controller

ActionControllerはペイロードに特定の情報を追加しません。オプションは、すべてペイロード経由で渡されます。

3.1.5 redirect_to.action_controller
キー
:status HTTP レスポンス コード
:location リダイレクト先URL
:request ActionDispatch::Requestオブジェクト
{
  status: 302,
  location: "http://localhost:3000/posts/new"
}
3.1.6 halted_callback.action_controller
キー
:filter アクションを停止させたフィルタ
{
  filter: ":halting_filter"
}
3.1.7 unpermitted_parameters.action_controller
キー
:keys 許可されていないキー
:context 以下のキーを持つハッシュ: :controller:action:params:request

3.2 Action Controller — キャッシング

3.2.1 write_fragment.action_controller
キー
:key 完全なキー
{
  key: 'posts/1-dashboard-view'
}
3.2.2 read_fragment.action_controller
キー
:key 完全なキー
{
  key: 'posts/1-dashboard-view'
}
3.2.3 expire_fragment.action_controller
キー
:key 完全なキー
{
  key: 'posts/1-dashboard-view'
}
3.2.4 exist_fragment?.action_controller
キー
:key 完全なキー
{
  key: 'posts/1-dashboard-view'
}

3.3 Action Dispatch

3.3.1 process_middleware.action_dispatch
キー
:middleware ミドルウェア名

3.4 Action View

3.4.1 render_template.action_view
キー
:identifier テンプレートへの完全なパス
:layout 該当のレイアウト
{
  identifier: "/Users/adam/projects/notifications/app/views/posts/index.html.erb",
  layout: "layouts/application"
}
3.4.2 render_partial.action_view
キー
:identifier テンプレートへの完全なパス
{
  identifier: "/Users/adam/projects/notifications/app/views/posts/_form.html.erb"
}
3.4.3 render_collection.action_view
キー
:identifier テンプレートへのフルパス
:count コレクションのサイズ
:cache_hits キャッシュからフェッチしたパーシャルの個数

:cache_hitsは、cached: trueをオンにしてレンダリングしたときだけ含まれます。

{
  identifier: "/Users/adam/projects/notifications/app/views/posts/_post.html.erb",
  count: 3,
  cache_hits: 0
}
3.4.4 render_layout.action_view
キー
:identifier テンプレートへのフルパス
{
  identifier: "/Users/adam/projects/notifications/app/views/layouts/application.html.erb"
}

3.5 Active Record

3.5.1 sql.active_record
キー
:sql SQL文
:name 操作の名前
:connection コネクションオブジェクト
:binds バインドするパラメータ
:type_casted_binds 型キャストされたバインドパラメータ
:statement_name SQL文の名前
:cached キャッシュされたクエリが使われるとtrueが追加される

アダプタが独自のデータを追加する可能性もあります。

{
  sql: "SELECT \"posts\".* FROM \"posts\" ",
  name: "Post Load",
  connection: #<ActiveRecord::ConnectionAdapters::SQLite3Adapter:0x00007f9f7a838850>,
  binds: [#<ActiveModel::Attribute::WithCastValue:0x00007fe19d15dc00>],
  type_casted_binds: [11],
  statement_name: nil
}
3.5.2 instantiation.active_record
キー
:record_count レコードのインスタンス数
:class_name レコードのクラス
{
  record_count: 1,
  class_name: "User"
}

3.6 Action Mailer

3.6.1 deliver.action_mailer
キー
:mailer メーラークラス名
:message_id Mail gemが生成したメッセージID
:subject メールの件名
:to メールの宛先(複数可)
:from メールの差出人
:bcc メールのBCCアドレス(複数可)
:cc メールのCCアドレス(複数可)
:date メールの日付
:mail メールのエンコード形式
:perform_deliveries このメッセージが配信されたかどうか
{
  mailer: "Notification",
  message_id: "4f5b5491f1774_181b23fc3d4434d38138e5@mba.local.mail",
  subject: "Rails Guides",
  to: ["users@rails.com", "dhh@rails.com"],
  from: ["me@rails.com"],
  date: Sat, 10 Mar 2012 14:18:09 +0100,
  mail: "...", # (省略)
  perform_deliveries: true
}
3.6.2 process.action_mailer
キー
:mailer メーラーのクラス名
:action アクション
:args 引数
{
  mailer: "Notification",
  action: "welcome_email",
  args: []
}

3.7 Active Support -- キャッシング

3.7.1 cache_read.active_support
キー
:key ストアで使われるキー
:store ストアクラス名
:hit ヒットしたかどうか
:super_operation 読み出しにfetchが使われる場合に:fetchを追加
3.7.2 cache_read_multi.active_support
キー
:key ストアで使われるキー
:store ストアクラス名
:hit ヒットしたかどうか
:super_operation 読み出しにfetch_multiが使われる場合に:fetch_multiを追加
3.7.3 cache_generate.active_support

このイベントは、fetchをブロック付きで呼び出した場合にのみ使われます。

キー
:key ストアで使われるキー
:store ストアクラス名

fetchに渡されたオプションは、ストアへの書き込み時にペイロードとマージされます。

{
  key: "name-of-complicated-computation",
  store: "ActiveSupport::Cache::MemCacheStore"
}
3.7.4 cache_fetch_hit.active_support

このイベントは、fetchをブロック付きで呼び出した場合にのみ使われます。

キー
:key ストアで使われるキー
:store ストアクラス名

fetchに渡されたオプションは、ペイロードとマージされます。

{
  key: "name-of-complicated-computation",
  store: "ActiveSupport::Cache::MemCacheStore"
}
3.7.5 cache_write.active_support
キー
:key ストアで使われるキー
:store ストアクラス名

キャッシュストアが独自のキーを追加することがあります。

{
  key: "name-of-complicated-computation",
  store: "ActiveSupport::Cache::MemCacheStore"
}
3.7.6 cache_write_multi.active_support
キー
:key ストアに書き込まれるキーと値
:store ストアクラス名
3.7.7 cache_increment.active_support

このイベントが発火するのは、MemCacheStoreまたはRedisCacheStoreを使っている場合のみです。

キー
:key ストアに書き込まれるキーと値
:store ストアクラス名
:amount インクリメントの総量
{
  key: "bottles-of-beer",
  store: "ActiveSupport::Cache::RedisCacheStore",
  amount: 99
}
3.7.8 cache_decrement.active_support

このイベントが発火するのは、MemCacheStoreまたはRedisCacheStoreを使っている場合のみです。

キー
:key ストアに書き込まれるキーと値
:store ストアクラス名
:amount デクリメントの総量
{
  key: "bottles-of-beer",
  store: "ActiveSupport::Cache::RedisCacheStore",
  amount: 1
}
3.7.9 cache_delete.active_support
キー
:key ストアで使われるキー
:store ストアクラス名
{
  key: "name-of-complicated-computation",
  store: "ActiveSupport::Cache::MemCacheStore"
}
3.7.10 cache_delete_multi.active_support
キー
:key ストアで使われるキー
:store ストアクラス名
3.7.11 cache_delete_matched.active_support

このイベントが発火するのは、RedisCacheStoreFileStore、またはMemoryStoreを使っている場合のみです。

キー
:key 使われるキーパターン
:store ストアクラス名
{
  key: "posts/*",
  store: "ActiveSupport::Cache::RedisCacheStore"
}
3.7.12 cache_cleanup.active_support

このイベントが発火するのは、MemoryStoreを使っている場合のみです。

キー
:store ストアクラス名
:size クリーンアップ前のキャッシュにあるエントリ数
{
  store: "ActiveSupport::Cache::MemoryStore",
  size: 9001
}
3.7.13 cache_prune.active_support

このイベントが発火するのは、MemoryStoreを使っている場合のみです。

キー
:store ストアクラス名
:key キャッシュのターゲットサイズ(バイト単位)
:from prune前のキャッシュサイズ(バイト単位)
{
  store: "ActiveSupport::Cache::MemoryStore",
  key: 5000,
  from: 9001
}
3.7.14 cache_exist?.active_support
キー
:key ストアで使われるキー
:store ストアクラス名
{
  key: "name-of-complicated-computation",
  store: "ActiveSupport::Cache::MemCacheStore"
}

3.8 Active Job

3.8.1 enqueue_at.active_job
キー
:adapter ジョブを処理するQueueAdapterオブジェクト
:job Jobオブジェクト
3.8.2 enqueue.active_job
キー
:adapter ジョブを処理するQueueAdapterオブジェクト
:job Jobオブジェクト
3.8.3 enqueue_retry.active_job
キー
:job Jobオブジェクト
:adapter ジョブを処理するQueueAdapterオブジェクト
:error リトライが原因で発生したエラー
:wait リトライの遅延
3.8.4 perform_start.active_job
キー
:adapter ジョブを処理するQueueAdapterオブジェクト
:job Jobオブジェクト
3.8.5 perform.active_job
キー
:adapter ジョブを処理するQueueAdapterオブジェクト
:job Jobオブジェクト
3.8.6 retry_stopped.active_job
キー
:adapter ジョブを処理するQueueAdapterオブジェクト
:job Jobオブジェクト
:error リトライが原因で発生したエラー
3.8.7 discard.active_job
キー
:adapter ジョブを処理するQueueAdapterオブジェクト
:job Jobオブジェクト
:error リトライが原因で発生したエラー

3.9 Action Cable

3.9.1 perform_action.action_cable
キー
:channel_class チャネルのクラス名
:action アクション
:data 日付(ハッシュ)
3.9.2 transmit.action_cable
キー
:channel_class チャネルのクラス名
:action アクション
:via 経由先
3.9.3 transmit_subscription_confirmation.action_cable
キー
:channel_class チャネルのクラス名
3.9.4 transmit_subscription_rejection.action_cable
キー
:channel_class チャネルのクラス名
3.9.5 broadcast.action_cable
キー
:broadcasting 名前付きブロードキャスト
:message メッセージ(ハッシュ)
:coder コーダー

3.10 Active Storage

3.10.1 preview.active_storage
キー
:key セキュアトークン
3.10.2 transform.active_storage
3.10.3 analyze.active_storage
キー
:analyzer アナライザ名(ffprobeなど)

3.11 Active Storage — ストレージサービス

3.11.1 service_upload.active_storage
キー
:key セキュアトークン
:service サービス名
:checksum 完全性を担保するチェックサム
3.11.2 service_streaming_download.active_storage
キー
:key セキュアトークン
:service サービス名
3.11.3 service_download_chunk.active_storage
キー
:key セキュアトークン
:service サービス名
:range 読み取りを試行するバイト範囲
3.11.4 service_download.active_storage
キー
:key セキュアトークン
:service サービス名
3.11.5 service_download.active_storage
キー
:key セキュアトークン
:service サービス名
3.11.6 service_delete_prefixed.active_storage
キー
:prefix キーのプレフィックス
:service サービス名
3.11.7 service_exist.active_storage
キー
:key セキュアトークン
:service サービス名
:exist ファイルまたはblobが存在するかどうか
3.11.8 service_url.active_storage
キー
:key セキュアトークン
:service サービス名
:url 生成されたURL
3.11.9 service_update_metadata.active_storage

このイベントが発火するのは、Google Cloud Storageサービスを使っている場合のみです。

キー
:key セキュアトークン
:service サービス名
:content_type HTTP Content-Typeフィールド
:disposition HTTP Content-Dispositionフィールド

3.12 Railties

3.12.1 load_config_initializer.railties
キー
:initializer config/initializersで読み込まれたイニシャライザへのパス

3.13 Rails

3.13.1 deprecation.rails
キー
:message 非推奨機能の警告メッセージ
:callstack 非推奨警告の発生元

4 例外

instrumentationの途中で例外が発生すると、ペイロードにその情報が含まれます。

キー
:exception 2個の要素(例外クラス名とメッセージ)を持つ配列
:exception_object 例外オブジェクト

5 カスタムイベントの作成

独自のイベントも手軽に追加できます。面倒な作業はActive Supportが代行するので、ActiveSupport::Notifications.instrumentnamepayload、およびブロックを指定して呼び出すだけでイベント追加が完了します。 通知は、ブロックから制御が戻った後で送信されます。Active Supportでは、開始時刻、終了時刻、およびinstrumenterのユニークIDが生成されます。instrument呼び出しに渡されるすべてのデータがペイロードに含まれます。

以下に例を示します。

ActiveSupport::Notifications.instrument "my.custom.event", this: :data do
  # 自分のコードをここに書く
end

これで、次のようにイベントをリッスンできるようになります。

ActiveSupport::Notifications.subscribe "my.custom.event" do |name, started, finished, unique_id, data|
  puts data.inspect # {:this=>:data}
end

以下のように、instrumentにブロックを渡さずに呼び出すことも可能です。これにより、instrumentationインフラストラクチャを他のメッセージング用途に活用できます。

ActiveSupport::Notifications.instrument "my.custom.event", this: :data

ActiveSupport::Notifications.subscribe "my.custom.event" do |name, started, finished, unique_id, data|
  puts data.inspect # {:this=>:data}
end

独自のイベントを作成するときは、Railsの規約に従ってください。形式は「event.library」を使います。 たとえば、アプリケーションがツイートを送信するのであれば、イベント名はtweet.twitterとなります。

フィードバックについて

Railsガイドは GitHub の yasslab/railsguides.jp で管理・公開されております。本ガイドを読んで気になる文章や間違ったコードを見かけたら、気軽に Pull Request を出して頂けると嬉しいです。Pull Request の送り方については GitHub の README をご参照ください。

原著における間違いを見つけたら『Rails のドキュメントに貢献する』を参考にしながらぜひ Rails コミュニティに貢献してみてください 🛠💨✨

本ガイドの品質向上に向けて、皆さまのご協力が得られれば嬉しいです。

Railsガイド運営チーム (@RailsGuidesJP)

支援・協賛

Railsガイドは下記の協賛企業から継続的な支援を受けています。支援・協賛にご興味あれば協賛プランからお問い合わせいただけると嬉しいです。

  1. Star
  2. このエントリーをはてなブックマークに追加