Rails6 のちょい足しな新機能を試す88（ActiveSupport Instrumentation events編）

# はじめに

Rails 6 に追加された新機能を試す第88段。 今回は、 `ActiveSupport Instrumentation events` 編です。
Rails 6 では、ActiveSupport Instrumentation で event の情報として、 cpu_time, duration, allocations (アロケートされたオブジェクトの数) が取得できるようになりました。

Ruby 2.6.4, Rails 6.0.0 で確認しました。

```shell
$ rails --version
Rails 6.0.0
```

今回は、User の CRUD を作り、各コントローラのアクションを実行したときの情報を取得してログに出力してみます。

# プロジェクトを作る

```shell
$ rails new rails_sandbox
$ cd rails_sandbox
```

# User の CRUD を作る

name をもつ User の CRUD を作ります

```shell
$ bin/rails g scaffold User name
```

# Subscriber を作る

`ActiveSupport::Subscriber` クラスから派生した、`ActionControllerSubscriber` クラスを作成し、ログに各アクション毎に、 `cpu_time`, `duration`, `allocations` を出力するようにします。

```ruby:app/subscribers/action_controller_subscriber.rb
class ActionControllerSubscriber < ActiveSupport::Subscriber
  attach_to :action_controller

  def process_action(event)
    action = "#{event.payload[:controller]}##{event.payload[:action]}"
    Rails.logger.info("#{action} cpu_time=#{event.cpu_time} duration=#{event.duration} allocations=#{event.allocations}")
  end
end
```

# 明示的に require する

ActionControllerSubscriber が動作するように、 application_controller.rb の中で require しておきます。

```ruby:app/controllers/application_controller.rb
class ApplicationController < ActionController::Base
end

require 'action_controller_subscriber'
```

# User の登録などをしてログを確認する

実際に `rails server` を実行してブラウザから User の登録などをしてログを確認します。
ログを確認すると以下のような情報が出力されていることがわかります。

```log:log/development.log
...
UsersController#index cpu_time=834.3827130000001 duration=838.4368330007419 allocations=1237659
...
UsersController#new cpu_time=15.012763999999956 duration=15.109344996744767 allocations=8648
...
UsersController#create cpu_time=9.577076000000018 duration=11.577429017052054 allocations=2932
...
UsersController#show cpu_time=12.707243000000146 duration=13.30683400738053 allocations=7172
...
UsersController#edit cpu_time=11.627590999999882 duration=11.854875017888844 allocations=7326
...
UsersController#update cpu_time=7.077903999999968 duration=9.087090991670266 allocations=3338
...
UsersController#show cpu_time=9.279210999999954 duration=11.935491987969726 allocations=6453
...
UsersController#index cpu_time=11.08482700000013 duration=12.24463598919101 allocations=6671
...
UsersController#destroy cpu_time=10.467926000000016 duration=23.146274004830047 allocations=2771
...
UsersController#index cpu_time=15.835581000000154 duration=17.571506003150716 allocations=6597
```

# 試したソース

試したソースは以下にあります。
https://github.com/suketa/rails_sandbox/tree/try088_add_info_of_subscriber_events

# 参考情報

* [What is new in Rails 6.0](https://bogdanvlviv.com/posts/ruby/rails/what-is-new-in-rails-6_0.html)
* [Add cpu time, idle time, and allocations features to log subscriber events](https://github.com/rails/rails/pull/33449)
* [Active Support Instrumentation](https://edgeguides.rubyonrails.org/active_support_instrumentation.html)
* [ActiveSupport::Subscriber](https://api.rubyonrails.org/classes/ActiveSupport/Subscriber.html)
* [Instrumenting Ruby on Rails with Prometheus](https://www.firehydrant.io/blog/instrumenting-ruby-on-rails-with-prometheus/)

もしかしたら以下の記事と関係しているかもです。

* [Rails6 のちょい足しな新機能を試す45（Allocations 編）](https://qiita.com/suketa/items/835119ddc3e611e1b334)