Railsの計測を支えるActiveSupport::Notificationsについて

rails

2014/12/18

こんにちは、技術推進室の篠崎（前回より5ヶ月ぶり）です。

Ruby on Rails（以下Rails）にはイベント（SQLを実行する、テンプレートを描画するなど）に対してフック（計測）できる仕組みがあるのはご存じですか？

おなじみのログもこのフックの仕組みを利用して出力されています。（1行目除く）

Started GET "/samples/1.json" for 127.0.0.1 at 2014-12-10 12:35:30 +0900
Processing by SamplesController#show as JSON
  Parameters: {"id"=>"1"}
  Sample Load (0.5ms)  SELECT `samples`.* FROM `samples` WHERE `samples`.`id` = 1 LIMIT 1
  Sample Load (0.5ms)  SELECT `samples`.* FROM `samples`
  Rendered samples/_simple.json.jbuilder (1005.6ms)
  Rendered samples/show.json.jbuilder (1014.4ms)
Completed 200 OK in 1027ms (Views: 1019.9ms | ActiveRecord: 1.0ms)

このようなRailsのフックはActiveSupport::Notificationsライブラリを利用して構築されています。

今回はこのActiveSupport::Notificationsとそれを利用して出力されるRailsのログについて調べてみました。

確認したバージョン

以下の環境で確認しました。

Rails 4.0.12
Ruby 2.1.5

ActiveSupport::Notificationsとは？

イベントを計測するためのライブラリで以下のAPIを提供します。

イベントを購読する
イベントを計測する

イベントを購読する

計測された情報で何か処理をする場合にこのAPIを利用します。

購読したイベントが計測されると通知されるようになります。（正確にはイベント開始、終了時に通知がくる）

通知時にはイベント情報が引数として渡され、そのイベント情報の中には処理時間なども含まれます。

以後、イベントを購読する者をSubscriberと呼びます。

イベントを計測する

そのままでイベントを計測する時に利用されるAPIです。

計測するとSubscriber「たち」に通知されます。

計測時に情報を付与する事もでき、独自の情報（以後payload）もSubscriberに渡せるようになります。

サンプル

イベント購読、計測のサンプルです、実行するとoutput.sampleを購読したSubscriberにだけ通知され、payload（name）とブロックの処理時間が出力されます。

class SampleScriber < ActiveSupport::Subscriber
  def output(event)
    payload = event.payload
    puts "#{payload[:name]} 処理時間: #{event.duration}ms"
  end
end

# output.sampleを購読する
SampleScriber.attach_to :sample

# output.sampleを計測する
ActiveSupport::Notifications.instrument('output.sample', name: 'aaa') do
  sleep(0.1)
end

# output.sampleを計測する
ActiveSupport::Notifications.instrument('output.sample', name: 'bbb') do
  sleep(0.2)
end

# output.exampleを計測する
ActiveSupport::Notifications.instrument('output.example', name: 'ccc') do
  sleep(0.3)
end

実行するとaaaとbbbのname、処理時間が表示されます。cccはoutput.sampleではなくoutput.exampleを計測しているのでSubscriberには通知されません。

$ bundle exec ruby sample.rb
aaa 処理時間: 100.28ms
bbb 処理時間: 200.24900000000002ms

イベント（output.sample）を購読する

ActiveSupport::Subscriberを継承したクラスを作成しoutput.sampleを購読しています。

class SampleScriber < ActiveSupport::Subscriber
  def output(event)
    payload = event.payload
    puts "#{payload[:name]} 処理時間: #{event.duration}ms"
  end
end

# output.sampleを購読する
SampleScriber.attach_to :sample

ActiveSupport::Subscriber

基本、このクラスを継承してSubscriberを作成します。

ActiveSupportではSubscriberクラスとそれを継承したログ用のLogSubscriberが用意されています。

attach_toメソッド

ActiveSupport::Subscriberに実装されているメソッドでattachしたクラスのパブリックなメソッド名を自動で購読（メソッド名.名前空間）します。（start、finishを除く）

このサンプルではメソッド名output、名前空間:sampleなのでoutput.sample計測時にoutputメソッドに通知されるようになります。

イベント（output.sample）を計測する

計測はActiveSupport::Notifications.instrumentメソッドで行います。

ブロック内の処理を計測してoutput.sampleを購読しているSubscriberに通知されます。

# output.sampleを計測する
ActiveSupport::Notifications.instrument('output.sample', name: 'aaa') do
  sleep(0.1)
end

ActiveSupport::Notifications.instrument

Subscriberが存在する場合、内部ではActiveSupport::Notifications::Instrumentor.instrumentを呼んでいます。実質な処理はこのメソッドです。

def instrument(name, payload={})
  start name, payload
  begin
    yield payload
  rescue Exception => e
    payload[:exception] = [e.class.name, e.message]
    raise e
  ensure
    finish name, payload
  end
end

instrumentメソッドに渡されたブロックを実行します。あわせて前後処理（ActiveSupport::Subscriber.start、ActiveSupport::Subscriber.finish）も実行します。

def start(name, id, payload)
  e = ActiveSupport::Notifications::Event.new(name, Time.now, nil, id, payload)
  parent = event_stack.last
  parent << e if parent

  event_stack.push e
end

def finish(name, id, payload)
  finished  = Time.now
  event     = event_stack.pop
  event.end = finished
  event.payload.merge!(payload)

  method = name.split('.').first
  send(method, event)
end

startとfinishで計測し、finishの最後でイベントを購読しているSubscriberに処理時間含むイベント情報を引数にして通知されます。

サンプルではsleepの処理時間を含んだイベント情報eventを引数にしてSampleSubscriber.outputに通知され、output内でその情報を出力しているわけです。

すごく簡単なサンプルですが概要を理解できるのではないかと思います。

Railsのログ出力

冒頭でRailsにはフックの仕組みがあり、その仕組みはActiveSupport::Notificationsで構築されログ出力はその仕組みを利用していると書きました。

サンプルが理解できればRailsではどのようにフックを提供しているか想像できるのではないでしょうか？

例えばActiveRecordなら以下のような感じです。

Sample Load (0.5ms)  SELECT `samples`.* FROM `samples

SubscriberがSQL実行（イベント）を購読する
SQL実行を計測する
Subscriberに通知されログ出力される

SubscriberがSQL実行（イベント）を購読する

ActiveRecordのSubscriberはActiveRecord::LogSubscriberでログ出力に特化したActiveSupport::LogSubscriberを継承しているクラスです。

ログ出力はsqlメソッドで行われます。

payloadで実行するSQLなども渡され、処理時間や色情報などとあわせてメッセージを作成しデバッグログを出力しています。

def sql(event)
  self.class.runtime += event.duration
  return unless logger.debug?

  payload = event.payload

  return if IGNORE_PAYLOAD_NAMES.include?(payload[:name])

  name  = "#{payload[:name]} (#{event.duration.round(1)}ms)"
  sql   = payload[:sql].squeeze(' ')
  binds = nil

  unless (payload[:binds] || []).empty?
    binds = "  " + payload[:binds].map { |col,v|
      render_bind(col, v)
    }.inspect
  end

  if odd?
    name = color(name, CYAN, true)
    sql  = color(sql, nil, true)
  else
    name = color(name, MAGENTA, true)
  end

  debug "  #{name}  #{sql}#{binds}"
end

名前空間active_recordで購読しているのでSQL実行（sql.active_record）が計測された時に通知されます。

ActiveRecord::LogSubscriber.attach_to :active_record

SQL実行（sql.active_record）を計測する

SQL実行（sql.active_record）はActiveRecord::ConnectionAdapters::AbstractAdapterクラスのlogメソッドで計測されます。

def log(sql, name = "SQL", binds = [])
  @instrumenter.instrument(
    "sql.active_record",
    :sql           => sql,
    :name          => name,
    :connection_id => object_id,
    :binds         => binds) { yield }
rescue => e
  message = "#{e.class.name}: #{e.message}: #{sql}"
  @logger.error message if @logger
  exception = translate_exception(e, message)
  exception.set_backtrace e.backtrace
  raise exception
end

このlogメソッドは2カ所から呼ばれます、SQLの結果をDB、キャッシュから取得した場合です。

ActiveRecord::ConnectionAdapters::MySQL2Adapterのexecuteメソッド ※ MySQLの場合
ActiveRecord::ConnectionAdapters::QueryCacheのcache_sqlメソッド

executeメソッドを見るとブロックで@connection.query(sql)を渡しています。

def execute(sql, name = nil)
  if name == :skip_logging
    @connection.query(sql)
  else
    log(sql, name) { @connection.query(sql) }
  end
rescue ActiveRecord::StatementInvalid => exception
  if exception.message.split(":").first =~ /Packets out of order/
    raise ActiveRecord::StatementInvalid.new("'Packets out of order' error was received from the database. Please update your mysql bindings (gem install mysql) and read http://dev.mysql.com/doc/mysql/en/password-hashing.html for more information. If you're on Windows, use the Instant Rails installer to get the updated mysql bindings.", exception.original_exception)
  else
    raise
  end
end

つまり以下のActiveRecordログの0.5msは@connection.query(sql)の処理時間なんだとかわかります。

Sample Load (0.5ms)  SELECT `samples`.* FROM `samples

ActiveRecordのログはSQL実行時（DB or キャッシュ）に以下の情報を出力する事がわかりました。

モデル
取得方法（検索、キャッシュ）
@connection.query(sql)の処理時間
実施されるSQL

他のLogSubscriber

Railsには他にもLogSubscriberがあります。

ここからたどっていくと、どのログがなんのイベント時に出力され、何の情報を出力しているかわかります。

ActionController::LogSubscriber
ActionView::LogSubscriber
ActionMailer::LogSubscriber
など

独自Subscriber

仕組みさえ理解できれば独自のSubscriberを作成するのは難しくないと思います。

特定のSQLにだけExplainしてログ出力するLogSubscriberや処理時間が50msを超えたSQLだけログ出力するLogSubscriberなど便利なものが作成できるかもしれません。（既にあるかもしれません）

また独自のイベントを計測する箇所とそのイベントを購読するSubscriberを用意すればアプリケーションの特定部分の処理を計測したりする事もできます。

ただのフックとしても利用できるので他にも色々出来るのではないでしょうか？

※ Railsでフックできる箇所はactive_support_instrumentaionで確認できます。

最後に

ActiveSupport::Notifications、利用したRailsのログ出力について概要は理解できたでしょうか？

他のLogSubscriberも調べて頂いて「出力されるログのmsは何の処理時間なんだろう？、Renderedの処理時間合計とViewsの処理時間はあわないけどなんでだろう？」など質問された時に回答できるとかっこいいかもしれません。

今回書かせて頂いた内容、実はここ見れば一発だぞとか全然間違っているとかあれば @ryshinoz にご連絡頂けると助かります。

以上

名無しのエンジニア

HOGE株式会社　エンジニアブログ