Railsでイベントの処理時間を計測したりログを出力する

RailsのログにはViewのレンダリングやSQLの処理時間が表示されています。
これらは [ActiveSupport::Notifications](http://api.rubyonrails.org/classes/ActiveSupport/Notifications.html) や [ActiveSupport::Subscriber](http://api.rubyonrails.org/classes/ActiveSupport/Subscriber.html) が使われています。
この仕組みを利用すると、自分のライブラリでも処理時間やログを出力することができます。

まずは、Notificationsってどんなものか見てみましょう。

## ActiveSupport::Notifications
### Instrumenters
通知するリスナーを登録します。

```message_notifications.rb
ActiveSupport::Notifications.instrument('message.sample', text: 'message') do
  sleep(0.1)
end

ActiveSupport::Notifications.instrument('test.sample', text: 'test') do
  sleep(0.2)
end
```

`instrument` の第1引数が名前で、第2引数がsubscriberに通知されるデータです。

## ActiveSupport::Subscriber
Subscriberを登録します。

```message_subscriber.rb
class MessageScriber < ActiveSupport::Subscriber
  def message(event)
    payload = event.payload
    puts "#{payload[:text]} %.1fms" %  event.duration
  end

  def test(event)
    payload = event.payload
    puts "#{payload[:text]} %.1fms" %  event.duration
  end
end

# Subscriberを登録
MessageScriber.attach_to :sample
```

実行してみましょう。

```
message 101.1ms
test 201.8ms
```

処理時間を計測できました。


## Example
[Faraday Middleware](https://github.com/lostisland/faraday_middleware)で[Instrumentation](https://github.com/lostisland/faraday_middleware/wiki/Instrumentation)が利用できるので、ちょっとRailsアプリケーションで実際に使ってみましょう。

この記事のサンプルコード [murajun1978/notification-sample](https://github.com/murajun1978/notification-sample)

まずは [Faraday Middleware](https://github.com/lostisland/faraday_middleware) の Instrumentation をチラ見してみましょう。

```faraday_middleware/lib/faraday_middleware/instrumentation.rb
require 'faraday'

module FaradayMiddleware
  # Public: Instruments requests using Active Support.
  #
  # Measures time spent only for synchronous requests.
  #
  # Examples
  #
  #   ActiveSupport::Notifications.subscribe('request.faraday') do |name, starts, ends, _, env|
  #     url = env[:url]
  #     http_method = env[:method].to_s.upcase
  #     duration = ends - starts
  #     $stderr.puts '[%s] %s %s (%.3f s)' % [url.host, http_method, url.request_uri, duration]
  #   end
  class Instrumentation < Faraday::Middleware
    dependency 'active_support/notifications'

    def initialize(app, options = {})
      super(app)
      @name = options.fetch(:name, 'request.faraday')
    end

    def call(env)
      ::ActiveSupport::Notifications.instrument(@name, env) do
        @app.call(env)
      end
    end
  end
end
```

ふむふむ、名前が `request.faraday` で、第2引数の env が subscriber に通知されるのですね。

### Faradayがリクエストにかかった処理時間を表示する
アクション内のリクエスト時間をログのcompletedに表示してみましょう。

![fish.png](https://qiita-image-store.s3.amazonaws.com/0/6470/0a4b30e9-33af-fd9e-9c19-97840c0d7fc3.png)

アクション内のリクエスト時間を集計するためのグローバルな変数が必要なので、レジストリを作成します。

```lib/faraday/runtime_registry.rb
module Faraday
  class RuntimeRegistry
    thread_mattr_accessor :api_runtime
  end
en
```

遠い昔に[ブログ](http://murajun1978.hatenadiary.com/entry/2015/03/30/010910)を書いたのですが、[ActiveSupport::PerThreadRegistry](http://api.rubyonrails.org/classes/ActiveSupport/PerThreadRegistry.html) はRails5から **deprecated** らしいので [Module#thread_mattr_accessor](http://www.rubydoc.info/gems/activesupport/Module%3Athread_mattr_accessor) を使いましょう。

次にSubscriberを作成します。

```lib/faraday/log_subscriber.rb
module Faraday
  class LogSubscriber < ActiveSupport::LogSubscriber
    class << self
      def runtime=(value)
        Faraday::RuntimeRegistry.api_runtime = value
      end

      def runtime
        Faraday::RuntimeRegistry.api_runtime ||= 0
      end

      def reset_runtime
        rt, self.runtime = runtime, 0
        rt
      end
    end

    def request(event)
      self.class.runtime += event.duration
    end
  end
end

Faraday::LogSubscriber.attach_to :faraday
```

最後にControllerRuntimeを作成します。

```lib/faraday/controller_runtime.rb
module Faraday
  module ControllerRuntime
    extend ActiveSupport::Concern

    protected

    attr_internal :faraday_runtime

    def process_action(action, *args)
      Faraday::LogSubscriber.reset_runtime
      super
    end

    def append_info_to_payload(payload)
      super
      payload[:faraday_runtime] = (faraday_runtime || 0) + Faraday::LogSubscriber.reset_runtime
    end

    module ClassMethods
      def log_process_action(payload)
        messages, faraday_runtime = super, payload[:faraday_runtime]
        messages << ("Faraday: %.1fms" % faraday_runtime.to_f) if faraday_runtime
        messages
      end
    end
  end
end

ActiveSupport.on_load(:action_controller) do
  include Faraday::ControllerRuntime
end
```

サンプルアプリにリクエストしてみましょう。

```zsh
$ curl http://localhost:3000/users/murajun1978/repositories
```

![fish_2.png](https://qiita-image-store.s3.amazonaws.com/0/6470/bf53de5b-0ead-8fa4-8a58-2396c35a4735.png)


### Faradayのリクエストをログに出力する
リクエストの内容をログに出力してみましょう。

Subscriberをログ出力できるように修正します。

```diff
module Faraday
  class LogSubscriber < ActiveSupport::LogSubscriber
    class << self
      def runtime=(value)
        Faraday::RuntimeRegistry.api_runtime = value
      end

      def runtime
        Faraday::RuntimeRegistry.api_runtime ||= 0
      end

      def reset_runtime
        rt, self.runtime = runtime, 0
        rt
      end
    end

    def request(event)
      self.class.runtime += event.duration
+     return unless logger.debug?+
+
+     env = event.payload
+
+     method = env[:method].to_s.upcase
+     status = env[:status]
+     request = env[:url]
+
+     debug " #{method} #{status} #{request} (#{duration_color(event.duration)}) "
    end
+
+   private
+
+     def duration_color(payload_duration)
+       display_duration = "%.1fms" % payload_duration
+       display_color    = payload_duration >= 1500 ? RED : GREEN
+       color(display_duration, display_color, true)
+     end
  end
end

Faraday::LogSubscriber.attach_to :faraday
```

`duration_color` で1500ms以上の場合は、赤文字で表示するようにしています。

colorメソッドや定数(RED や GREEN）は [ActiveSupport::LogSubscriber](https://github.com/rails/rails/blob/master/activesupport/lib/active_support/log_subscriber.rb) に定義されています。

もう一度サンプルアプリにリクエストしてみましょう。

![fish_4.png](https://qiita-image-store.s3.amazonaws.com/0/6470/f6402bd8-c26a-46da-6daa-26606033cdcd.png)

リクエストの詳細も表示できるようになりました :tada:

## まとめ
こうしてまとめてみると、やっぱりコンテキストで分離されていてRails良くできてるなーって改めて感じます。
この記事では一定の処理時間以上になると色を変えてログ出力しましたが、slackなどに通知することもできますね。

Happy Hacking٩( ‘ω’ )و