Rails Instrumentation API へのアクセスを少しだけ簡単にする

先日、 Kaigi on Rails 2021 というイベントで登壇をする機会をいただきました。緊張しましたがいい体験になりました。

このイベントで Rails の Instrumentation API について触れました。

この API を使うことで Rails が内部で hook しているイベントにアクセスしてログを出力する、などのコードを書くことができます。

Instrumentation API は ActiveSupport::Notifications.instrument を通じてイベントが発行されます。このメソッドで計測したい箇所をブロックでラップすることによって、以下のようなメトリクスを取得できます。

• duration: そのブロック内の処理にかかった時間
• cpu_time: CPU 使用時間（ clock_gettime(3) によって取得できる CPU 時間から算出したもの）
• idle_time: アイドル時間（処理にかかった時間 − CPU 使用時間）
• allocations: オブジェクトアロケーション（処理開始時の GC.stat(:total_allocated_objects) − 処理終了時の GC.stat(:total_allocated_objects)）

これに加えて、 ActiveSupport::Notifications.instrument に任意のペイロードを渡すことによって、 Instrumentation API の subscriber はそのペイロードを利用することができます。たとえば、 Rails で利用されている redirect_to.action_controller というイベントでは、ステータスコードと Location ヘッダーに指定した値がそれぞれ status と location という名前でペイロードに含まれています。

Instrumentation API の情報をもっと活用できないか？

Rails ではすでに、 Instrumentation API を通じて基本的なメトリクスに加えて様々なペイロードがイベントごとに発行されています。ということは、実際にこれらの情報を活用することで、文字通り計測が可能になります。実際のところ、 Rails では各コアコンポーネントごとに LogSubscriber というクラスを用意して、イベント発行時にログ出力を行う、ということが行われています。このログ出力はデフォルトで有効になり、 rails new した直後に、ログに関する設定を何もしていなくても Instrumentation API の情報に基づいたログが出力されます。

もちろん、デフォルトの LogSubscriber の出力で十分ですし、開発ではあまり困ることはないでしょう。しかし、 Rails のアプリケーションを長く運用していくと、ログのフォーマットを変えたい、デフォルトのログ出力にプラスして「これ」もほしい、などログに関して新たなニーズが出てくると思います。そんなときに、 Instrumentation API を活用して、ログ出力を変更しようとすると、デフォルトで subscribe している subscriber を unsubscribe させて、自前の subscriber を attach させないといけません。

subscriberのunsubscribeとsubscribe

# 既存の subscriber を unsubscribe
require "action_controller/log_subscriber"
ActionController::LogSubscriber.detach_from :action_controller

# 自前の subscriber を定義
class MyActionControllerSubscriber < ActiveSupport::LogSubscriber
 def process_action(event)
   info do
     path = event.payload[:path]&.split('?', 2)&.first || '-'
     "🚀 path=#{path}"
   end
 end
end

# 自前の subscriber を attach
MyActionControllerSubscriber.attach_to :action_controller

Kaigi on Rails 2021 の発表以降、こういった若干の面倒臭さを取り除けないだろうか？ということを考えていました。そこで、たどり着いた戦略が「subscribe と unsubscribe の処理を自動的に行い、 Instrumentation API のイベントペイロードへのアクセスを簡単にする」ような Gem をつくることでした。

rails_band で Instrumentation API へのアクセスを簡単にする

rails_band という Gem をつくりました。この Gem を require すると、 Rails がデフォルトで subscribe している subscriber が unsubscribe されます。 Instrumentation API のイベントには config で proc を指定することでアクセスできます。

実際、この Gem を使って Rails アプリケーションの運用も行っています。開発環境ではデフォルトのログ出力で十分と判断して、 production と staging 環境でのみこの Gem を require しています。もしかしたら、デフォルトの subscriber を unsubscribe するかどうかの設定を用意してもいいかもしれません（ご要望があればぜひ pull request を！）。

Gemfile

group :production, :staging do
  # Replace Instrumentation API
  gem 'rails_band'
end

config/environments/production.rb と config/environments/staging.rb で以下のような設定を書いています。

config/environments/production.rb

  config.rails_band.consumers = {
    'process_action.action_controller': lambda { |event|
      record = event.slice(:name, :method, :path, :status, :controller, :action, :duration, :allocation, :cpu_time, :view_runtime, :db_runtime)
      record[:message] = <<~MSG.squish
        #{event.method.upcase} #{event.path} #{event.status}, with `#{event.params.to_h.inspect}` consumed by #{event.controller}##{event.action}
      MSG
      Rails.logger.info(record)
    },
    'sql.active_record': ->(event) { Rails.logger.debug(event.slice(:name, :duration, :allocation, :cpu_time).merge!(message: "SQL: #{event.sql}")) },
    default: ->(event) { Rails.logger.info(event.slice(:name, :duration, :allocation, :cpu_time).merge!(message: "Event #{event.name} has finished.")) },
  }

この Rails アプリケーションですが、基本的には ActionController と ActiveRecord ぐらいしか使わないので process_action.action_controller と sql.active_record だけ、ログ出力を特別扱いしています。それ以外のイベントについては default という特別な指定により、すべて雑にログ出力する設定にしています。

自分でつくったものなので「簡単」だとは思っているのですが、「簡単」かどうかは個人の感想ですね。もしもっとよいアイディアがありましたら issue や pull request をオープンしていただけると嬉しいです。

rails_band の今後

実は rails_band はすべての Instrumentation API のイベントを網羅していません。たとえば、 Active Storage のイベントは一つもサポートできていません。まずは、すべてのイベントを網羅していくことを目指しています。加えて、それぞれのイベント（たとえば、 RailsBand::ActionController::Event::ProcessAction）でアクセス可能なペイロードをメソッドとして定義していますが、それぞれのメソッドに十分なドキュメントがないので、これらを充実させていく必要があると考えています。そして、 Rails は今も進化を続けているので既存の Instrumentation API に新しいペイロードが追加されていないか？新しいイベントが追加されていないか？などに気を配って行こうと考えております。

みなさんも Rails Instrumentation API で楽しい計測を行ってみませんか？