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

先日、 [Kaigi on Rails 2021](https://kaigionrails.org/2021/) というイベントで[登壇をする機会](https://kaigionrails.org/2021/talks/yykamei/)をいただきました。緊張しましたがいい体験になりました。

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

<a href="https://docs.google.com/presentation/d/e/2PACX-1vT7IpjvurfAeEatc0Nlq-eC9SXsmJcktxKBragCScJrfhCbudYKnOLtdHBchsqfK7EveHEE2bQS3UKf/pub?start=false&loop=false&delayms=3000&slide=id.gea744784cf_0_93"><img width="1634" alt="ActiveSupport::Notifications?" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/1451159/0a10b3e1-e7f7-4697-be7b-2721e728be30.png"></a>

この 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 させないといけません。

```ruby: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](https://github.com/yykamei/rails_band) という Gem をつくりました。この Gem を `require` すると、 Rails がデフォルトで subscribe している subscriber が unsubscribe されます。 Instrumentation API のイベントには config で `proc` を指定することでアクセスできます。

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

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

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

```ruby: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`](https://github.com/yykamei/rails_band/blob/main/lib/rails_band/action_controller/event/process_action.rb)）でアクセス可能なペイロードをメソッドとして定義していますが、それぞれのメソッドに十分なドキュメントがないので、これらを充実させていく必要があると考えています。そして、 Rails は今も進化を続けているので既存の Instrumentation API に新しいペイロードが追加されていないか？新しいイベントが追加されていないか？などに気を配って行こうと考えております。

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