Rails でイベントの処理数や処理時間を計測して Datadog や Mackerel で監視する

Kaizen Platform で Product Manager / Engineering Group Manager をしている @takus です。

Kaizen Platform では多くのアプリケーションで Ruby on Rails を採用しています。Rails には Active Support の Instrumentation 機能というものがあり、これを利用するとアプリケーション内でのイベント処理数や処理時間を計測して Datadog や Mackerel といった監視システムに送ることが簡単にできるので、その話を紹介したいと思います。

TL;DR

Rails でイベント処理数や処理時間を計測して監視システムに送りたい
Active Support の Instrumentation 機能を使うと簡単にできる
試しに Delayed::Job の Job 処理数と処理時間を計測して可視化してみた

背景

Kaizen Platform は非同期処理で Delayed::Job というライブラリを利用しています。Rails の世界では Sidekiq、Resque などの選択肢もありますが、3~4 年前にライブラリ選定した時点においてシンプルで十分な機能を持っていたために採用されたようです。

安定稼働している Delayed::Job ですが、先日、Delayed::Job で実行している一部のジョブのバグに起因する障害が発生してしまったため、SRE 主導の元、障害振り返り会が開催されました。

再発防止や復旧時間の短縮する方法を議論する中で、障害発生の前に、徐々に遅くなっている Job を検知したり、障害発生時にどの Job が原因か素早く特定できるようにするために、Delayed::Job の Job 処理数と処理時間を計測したいという提案があったので、その実現方法を検討することになりました。

Active Support の Instrumentation 機能

Rails においてイベントの計測をする方法は色々あると思いますが、自分が調べた限りでは Active Support の Instrumentation 機能を利用するのが王道のようでした。(他によい仕組みがあれば教えてください)

Active Support の Instrumentation 機能とは？

Active Support の Instrumentation 機能については、Railsガイドにも詳しい解説がありますが、一言でいうと、アプリケーション内で発生したイベントを計測するための仕組み で、イベントを購読する処理とイベントを通知する処理を分離して実装することができます。

f:id:kaizenplatform:20180525025634p:plain — つながりをゆるふわにしよう ActiveSupprt::Notifications

これによって、オブジェクト間が疎結合になり、本来のアプリケーションのロジックと関係のない計測用のコードを後から追加しやすくなります。

利用方法

利用するのは簡単で、 ActiveSupport::Notifications.subscribe でイベントを購読する処理を記述して、ActiveSupport::Notifications.instrument でイベントを発生させるだけです。

f:id:kaizenplatform:20180525025954j:plain — Digging Deep with ActiveSupport::Notifications

下記のようにブロックを利用することで、ブロック内の処理にかかった時間を計測して、イベントに含めてくれるので、処理時間の計測も簡単に行うことができます。

f:id:kaizenplatform:20180525030019j:plain — Digging Deep with ActiveSupport::Notifications

参考リンク

詳しい説明は下記の資料を参考にしてください。

Delayed::Job の処理数と処理時間を Datadog に送信する

実装例として Delayed::Job の処理数と処理時間を Datadog に送信してみます。全て記述するのは面倒なので Gemfile などは省略します。ちなみに ActiveJob の場合は Rails の公式なフックが実装されているため、これを利用するとよさそうです。

イベントを購読する処理

config/initializers/datadog.rb に DelayedJobSubscriber を定義して dogstatsd 経由で Datadog にメトリクスを送信するようにしています。Mackerel に送信する場合は Mackerel に送信するための Subscriber を定義することで同じようにメトリクスを送信することができます。

require 'datadog/statsd'

class DelayedJobSubscriber < ActiveSupport::Subscriber

  def initialize
    super()
    host = ENV['DATADOG_STATSD_HOST'] || 'localhost'
    port = ENV['DATADOG_STATSD_PORT'] || '8125'
    @statsd = Datadog::Statsd.new(host, port, tags:["app_name:#{Rails.application.class.parent.to_s.underscore}", "app_env:#{Rails.env}"])
  end

  def enqueue_at(event)
    job = event.payload[:job]
    @statsd.increment("app.delayed_job.enqueue", tags: ["job:#{job.name.underscore}", "queue:#{job.queue}"])
  end

  def dequeue_at(event)
    job = event.payload[:job]
    @statsd.increment("app.delayed_job.dequeue", tags: ["job:#{job.name.underscore}", "queue:#{job.queue}"])
  end

  def perform(event)
    job = event.payload[:job]
    @statsd.histogram("app.delayed_job.perform", event.duration, tags: ["job:#{job.name.underscore}", "queue:#{job.queue}"])
  end

  def error(event)
    job = event.payload[:job]
    @statsd.increment("app.delayed_job.error", tags: ["job:#{job.name.underscore}", "queue:#{job.queue}"])
  end

  def failure(event)
    job = event.payload[:job]
    @statsd.increment("app.delayed_job.failure", tags: ["job:#{job.name.underscore}", "queue:#{job.queue}"])
  end
end

if Rails.env == "production"
  DelayedJobSubscriber.attach_to :delayed_job
end

イベントを送信する処理

config/initializers/delayed_job.rb に Delayed::Job のプラグイン機構を利用して Delayed::Plugins::Notification を定義して、イベントを送信する処理を記述します。

module Delayed
  module Plugins
    class Notification < Plugin
      callbacks do |lifecycle|
        lifecycle.before(:enqueue) do |job|
          ActiveSupport::Notifications.instrument "enqueue_at.delayed_job", job: job
        end

        lifecycle.before(:perform) do |worker, job|
          ActiveSupport::Notifications.instrument "dequeue_at.delayed_job", job: job
        end

        lifecycle.around(:perform) do |worker, job, &block|
          ActiveSupport::Notifications.instrument "perform.delayed_job", job: job do
            block.call(worker, job)
          end
        end

        lifecycle.after(:error) do |worker, job|
          ActiveSupport::Notifications.instrument "error.delayed_job", job: job
        end

        lifecycle.after(:failure) do |worker, job|
          ActiveSupport::Notifications.instrument "failure.delayed_job", job: job
        end
      end
    end
  end
end
Delayed::Worker.plugins << Delayed::Plugins::Notification

Job を実行してみる

app/jobs/sleep_job.rb に sleep するだけの SleepJob を定義します。

class SleepJob
  def initialize(duration)
    @duration = duration || 5
  end

  def perform
    sleep @duration
  end

  def max_attempts
    3
  end
end

lib/tasks/jobs.rake にタスクを記述します。

namespace :jobs do
  desc "enqueue a sleep_job"
  task :enqueue => :environment do
    Delayed::Job.enqueue SleepJob.new(1)
  end
end

Rake で実行してみます。

# enqueue
bundle exec rake jobs:enqueue

# dequeue
bundle exec rake jobs:workoff

Datadog 側ではこのように処理数や処理時間をグラフ化したり、処理時間に対してアラートを設定したりできます。

f:id:kaizenplatform:20180525030055j:plain — Datadog

利用上の注意

Subscriber ではブロッキング処理を避ける

デフォルトでは Subscriber は instrument した thread 上で実行されるようなので、Subscriber で時間がかかる処理をすることは避けた方がよさそうです。Dogstatsd を利用する場合はローカルで起動している Dogstatsd のデーモンに対して UDP でメトリクスを送信してバッファリングし、Dogstatsd から Datadog のサーバーにメトリクスを送信するため、問題はないです。

ビジネスロジックは扱わない

本来のビジネスロジックと関係のない計測用のコードを後から追加しやすくなる仕組みとしての利用を想定しているので、特筆すべき理由がない限り、ビジネスロジックを担う処理を扱うのは避けた方がよいです。

まとめ

Rails でアプリケーション内でのイベント処理数や処理時間を計測する仕組みとして Active Support の Instrumentation 機能を紹介しました。計測は Kaizen の基本中の基本なので今後も様々なメトリクスを計測できるようにしていきたいと思います。