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 アクション
:request ActionDispatch::Requestオブジェクト
: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",
  request: <ActionDispatch::Request:0x00007ff1cb9bd7b8>
}
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.3.2 redirect.action_dispatch
キー
:status HTTPレスポンスコード
:location リダイレクト先URL
:request ActionDispatch::Requestオブジェクト
3.3.3 request.action_dispatch
キー
:request ActionDispatch::Requestオブジェクト

3.4 Action View

3.4.1 render_template.action_view
キー
:identifier テンプレートへの完全なパス
:layout 該当のレイアウト
:locals テンプレートに渡されるローカル変数
{
  identifier: "/Users/adam/projects/notifications/app/views/posts/index.html.erb",
  layout: "layouts/application",
  locals: { foo: "bar" }
}
3.4.2 render_partial.action_view
キー
:identifier テンプレートへの完全なパス
:locals テンプレートに渡されるローカル変数
{
  identifier: "/Users/adam/projects/notifications/app/views/posts/_form.html.erb",
  locals: { foo: "bar" }
}
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 strict_loading_violation.active_record

このイベントはconfig.active_record.action_on_strict_loading_violation:logに設定されている場合にのみ発火します。

キー
:owner strict_loadingが有効化されたモデル
:reflection 読み込もうとしている関連付けのリフレクション
3.5.3 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 ストアクラス名
:hits ヒットしたかどうか
: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 Support — Messages

3.8.1 message_serializer_fallback.active_support
キー
:serializer プライマリ(意図した)シリアライザ
:fallback フォールバック(実際の)シリアライザ
:serialized シリアライズされた文字列
:deserialized デシリアライズされた値
{
  serializer: :json_allow_marshal,
  fallback: :marshal,
  serialized: "\x04\b{\x06I\"\nHello\x06:\x06ETI\"\nWorld\x06;\x00T",
  deserialized: { "Hello" => "World" },
}

3.9 Active Job

3.9.1 enqueue_at.active_job
キー
:adapter ジョブを処理するQueueAdapterオブジェクト
:job Jobオブジェクト
3.9.2 enqueue.active_job
キー
:adapter ジョブを処理するQueueAdapterオブジェクト
:job Jobオブジェクト
3.9.3 enqueue_retry.active_job
キー
:job Jobオブジェクト
:adapter ジョブを処理するQueueAdapterオブジェクト
:error リトライが原因で発生したエラー
:wait リトライの遅延
3.9.4 enqueue_all.active_job
キー
:adapter ジョブを処理するQueueAdapterオブジェクト
:jobs Jobオブジェクトの配列
3.9.5 perform_start.active_job
キー
:adapter ジョブを処理するQueueAdapterオブジェクト
:job Jobオブジェクト
3.9.6 perform.active_job
キー
:adapter ジョブを処理するQueueAdapterオブジェクト
:job Jobオブジェクト
:db_runtime データベースクエリの総実行時間(ms)
3.9.7 retry_stopped.active_job
キー
:adapter ジョブを処理するQueueAdapterオブジェクト
:job Jobオブジェクト
:error リトライが原因で発生したエラー
3.9.8 discard.active_job
キー
:adapter ジョブを処理するQueueAdapterオブジェクト
:job Jobオブジェクト
:error リトライが原因で発生したエラー

3.10 Action Cable

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

3.11 Active Storage

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

3.12 Active Storage: ストレージサービス

3.12.1 service_upload.active_storage
キー
:key セキュアトークン
:service サービス名
:checksum 完全性を担保するチェックサム
3.12.2 service_streaming_download.active_storage
キー
:key セキュアトークン
:service サービス名
3.12.3 service_download_chunk.active_storage
キー
:key セキュアトークン
:service サービス名
:range 読み取りを試行するバイト範囲
3.12.4 service_download.active_storage
キー
:key セキュアトークン
:service サービス名
3.12.5 service_delete.active_storage
キー
:key セキュアトークン
:service サービス名
3.12.6 service_delete_prefixed.active_storage
キー
:prefix キーのプレフィックス
:service サービス名
3.12.7 service_exist.active_storage
キー
:key セキュアトークン
:service サービス名
:exist ファイルまたはblobが存在するかどうか
3.12.8 service_url.active_storage
キー
:key セキュアトークン
:service サービス名
:url 生成されたURL
3.12.9 service_update_metadata.active_storage

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

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

3.13 Action Mailbox

3.13.1 process.action_mailbox
Key Value
:mailbox ActionMailbox::Baseから継承したMailboxクラスのインスタンス
:inbound_email 処理中の受信メールに関するデータのハッシュ
{
  mailbox: #<RepliesMailbox:0x00007f9f7a8388>,
  inbound_email: {
    id: 1,
    message_id: "0CB459E0-0336-41DA-BC88-E6E28C697DDB@37signals.com",
    status: "processing"
  }
}

3.14 Railties

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

3.15 Rails

3.15.1 deprecation.rails
キー
:message 非推奨機能の警告メッセージ
:callstack 非推奨警告の発生元
:gem_name 非推奨警告で報告されたgem名
:deprecation_horizon 非推奨の振る舞いが削除されるバージョン

4 例外

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

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

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

独自のイベントを自由に追加できます。Active Supportは、面倒な作業を代行してくれます。イベント追加は、namepayload、ブロックを指定してActiveSupport::Notifications.instrumentを呼び出すだけで完了します。 通知は、ブロックが戻ってから送信されます。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. このエントリーをはてなブックマークに追加