LiBz Tech Blog

LiBの開発者ブログ

【Rails】Sidekiqの監視で工夫したこと

はじめに

最近SREだのDevOpsだの開発と運用にフォーカスがあたることが多いようで、
弊社でもDevOpsチームというものが発足されました。

開発しているエンジニア全体に、しっかりサービスの監視をしてもらえるようにインフラからアプリケーション層のエラー等の見える化を進めています。

それからどうした?

そこでタイトルにもあるように、はじめに着手したのがsidekiqの監視になります。
sidekiqは非同期で処理を実行できるため、メールの送信など時間差で処理が行われて良いものを実行させたりしてます。

f:id:kazuhisa_o:20190704114847p:plain

そんな中、sidekiqのエラーってちゃんと追えるのか?実行時間大丈夫?キュー溜まってない?と監視しなくてはいけない点がいくつかあるかと思います。
いくつかみんなに見てもらうために着手したものがあるので書いていきます。

やったこと

何を見えるようにするか?

今回は下記の点を監視できるようにしました。

  • sidekiqが失敗しているかを知りたい
    • なぜ?失敗したか?
    • sidekiqがどこから呼ばれたか?
    • どんな引数だったか?
  • 実行時間にどれくらい費やしているか
    • キューが溜まってないか?
    • キューを独占しがちのコードはないか?
    • 実行回数が多すぎるものはないか?

sidekiqの実行監視

まず導入したものがsidekiqのモニタリングサイトです。
Monitoring · mperham/sidekiq Wiki · GitHub

これを導入して見れる内容

  • sidekiqが失敗しているかを知りたい
    • なぜ?失敗したか?
    • どんな引数だったか?
  • 実行時間にどれくらい費やしているか
    • キューが溜まってないか?
    • キューを独占しがちのコードはないか?

いろんなことが一気に解決します!!すごい!!

sidekiqのモニタリングサイト

実行状況や失敗の様子を簡単に見ることができます。
f:id:kazuhisa_o:20190703211423p:plain

特に死亡したもの(リトライ回数上限まで失敗したもの)は、どんな原因で失敗したか引数は何だったかなど明確に表示されます
f:id:kazuhisa_o:20190703211700p:plain

上記の画面だと、HogehogeWorkerというJobで引数が足りずに失敗していることがわかります。

詳細を確認すると具体的にいつどんなJID(ジョブが発行されたときに発行されるユニークなID)のものが失敗したかまでわかります。
f:id:kazuhisa_o:20190703211852p:plain

やり方

sidekiqのgithubページを見ればだいたい書いてあります。
Monitoring · mperham/sidekiq Wiki · GitHub

基本的に既存のroutesに下記を記載すればOKです。

require 'sidekiq/web'
mount Sidekiq::Web => '/sidekiq'

認証が通るところに合わせて入れれるので、管理画面等に一緒に入れると良いかと思います。
詳しい書き方はsidekiqのwikiを見てください。

ジョブの実行元の調査

sidekiqのモニタリングサイトを入れることができましたが、
もし、このHogehogeWorkerが複数箇所から呼ばれている場合は、どこから呼ばれたかわかりません。
失敗したジョブはわかっても、そのJIDを見てもどこから呼ばれたのか特定ができませ。

実際に出ているエラーコードを見てもsidekiqからの呼び出しはわかっても、どのコードから呼ばれたものかは特定できません。

2019-07-03T12:13:55.479Z 67303 TID-ow5skpx8k WARN: {"context":"Job raised exception","job":{"class":"HogehogeWorker","args":[],"retry":3,"queue":"priority_row","jid":"5d4ea1c8a60c1312f6d6d180","created_at":1562155835.218923,"enqueued_at":1562156035.4771168,"error_message":"wrong number of arguments (given 0, expected 1)","error_class":"ArgumentError","failed_at":1562155835.848227,"retry_count":3,"retried_at":1562156035.477864},"jobstr":"{\"class\":\"HogehogeWorker\",\"args\":[],\"retry\":3,\"queue\":\"priority_row\",\"jid\":\"5d4ea1c8a60c1312f6d6d180\",\"created_at\":1562155835.218923,\"enqueued_at\":1562156035.4771168,\"error_message\":\"wrong number of arguments (given 0, expected 1)\",\"error_class\":\"ArgumentError\",\"failed_at\":1562155835.848227,\"retry_count\":2,\"retried_at\":1562155939.789458}"}
2019-07-03T12:13:55.479Z 67303 TID-ow5skpx8k WARN: ArgumentError: wrong number of arguments (given 0, expected 1)
2019-07-03T12:13:55.479Z 67303 TID-ow5skpx8k WARN: /hogehoge/app/workers/hogehoge_worker.rb:4:in `perform'
/hogehoge/lib/sidekiq/processor.rb:199:in `execute_job'
/hogehoge/lib/sidekiq/processor.rb:170:in `block (2 levels) in process'
/hogehoge/lib/sidekiq/middleware/chain.rb:128:in `block in invoke'
/hogehoge/lib/sidekiq/middleware/chain.rb:133:in `invoke'
/hogehoge/lib/sidekiq/processor.rb:169:in `block in process'
/hogehoge/lib/sidekiq/processor.rb:141:in `block (6 levels) in dispatch'
/hogehoge/lib/sidekiq/job_retry.rb:97:in `local'
/hogehoge/lib/sidekiq/processor.rb:140:in `block (5 levels) in dispatch'
/hogehoge/lib/sidekiq/rails.rb:42:in `block in call'
/hogehoge/lib/active_support/execution_wrapper.rb:87:in `wrap'
/hogehoge/lib/active_support/reloader.rb:73:in `block in wrap'
/hogehoge/lib/active_support/execution_wrapper.rb:87:in `wrap'
/hogehoge/lib/active_support/reloader.rb:72:in `wrap'
/hogehoge/lib/sidekiq/rails.rb:41:in `call'
/hogehoge/lib/sidekiq/processor.rb:136:in `block (4 levels) in dispatch'
/hogehoge/lib/sidekiq/processor.rb:215:in `stats'
/hogehoge/lib/sidekiq/processor.rb:131:in `block (3 levels) in dispatch'
/hogehoge/lib/sidekiq/job_logger.rb:7:in `call'
/hogehoge/lib/sidekiq/processor.rb:130:in `block (2 levels) in dispatch'
/hogehoge/lib/sidekiq/job_retry.rb:72:in `global'
/hogehoge/lib/sidekiq/processor.rb:129:in `block in dispatch'
/hogehoge/lib/sidekiq/logging.rb:44:in `with_context'
/hogehoge/lib/sidekiq/logging.rb:38:in `with_job_hash_context'
/hogehoge/lib/sidekiq/processor.rb:128:in `dispatch'
/hogehoge/lib/sidekiq/processor.rb:168:in `process'
/hogehoge/lib/sidekiq/processor.rb:85:in `process_one'
/hogehoge/lib/sidekiq/processor.rb:73:in `run'
/hogehoge/lib/sidekiq/util.rb:16:in `watchdog'
/hogehoge/lib/sidekiq/util.rb:25:in `block in safe_thread'

内容を見てもSidekiq上で呼ばれたさいのトレースはあるが、どこから呼ばれかがわかりません。

なので、Worker実行時にログが残るようにしていきます!

これを導入して見れる内容

  • sidekiqが失敗しているかを知りたい
    • なぜ?失敗したか?
    • sidekiqがどこから呼ばれたか?

ログを残す

実行するperform_asyncの返り値はモニタリングサイトに出てくるJIDが返ってきます。

[1] pry(main)> HogehogeWorker.perform_async
=> "11f53888ddf4bcb39ed924c2"
[2] pry(main)>

これをログに残すことで調査しやすくなります。

ただ、1個1個に書くのはめんどくさいので、継承してWorker全部に反映させるようにしました。

変更前

hogehoge_worker.rb

class HogehogeWorker
  include Sidekiq::Worker
  sidekiq_options queue: :priority_row

  def perform(id)
    # ここに処理
  end
end

変更後

hogehoge_worker.rb

class HogehogeWorker < ApplicationJobWorker
  sidekiq_options queue: :priority_row

  def perform(id)
    p 'hogehoge'
  end
end

application_job_worker.rb

class ApplicationJobWorker
  include Sidekiq::Worker
  sidekiq_options queue: :default

  class << self
    def perform_async(*args)
      job_id = super(*args)
      # Rails.logger.infoでもなんでも良い
      Ahoy::Tracker.new.track('sidekiq_backtrace', job_id: job_id, backtrace: caller)
      job_id
    end
  end
end

これでどこから呼ばれたか、わかるようになって死亡したジョブの原因を追うことができます。

実行時間

そろそろブログを書くのに飽きてきましたが、
各ジョブの実行時間を調べて、実行時間の遅いジョブを見つけれるようにしました。

これを導入して見れる内容

  • 実行時間にどれくらい費やしているか
    • キューが溜まってないか?
    • キューを独占しがちのコードはないか?
    • 実行回数が多すぎるものはないか?

sidekiqのログ

sidekiqのログには開始してから何秒かかったかのログがあったので集計するようにしました。

2019-07-04T00:45:30.349Z 67303 TID-ow5qq7z5k HogehogeWorker JID-627ab09d65a8e00b0c31a741 INFO: start
"hogehoge"
2019-07-04T00:45:30.857Z 67303 TID-ow5qq7z5k HogehogeWorker JID-627ab09d65a8e00b0c31a741 INFO: done: 0.508 sec

scriptを作成

ログを取るためにscriptを書きました。
ざっくりやっていることは下記です。

  • スケジュール実行
  • AWSのsidekiqが動いているサーバーをリストアップ
  • サーバーにあるsidekiq.logを収集する
  • 結果をslackに通知

railsとsidekiqに関係しているところだけピックアップしていきます。

スケジュール実行

定期実行として元々wheneverを使っていたのと、scriptも定期実行に入れることができたので使いました。
GitHub - javan/whenever: Cron jobs in Ruby

# #{Rails.root}/script/check_sidekiq_running_time.shを実行する
script 'check_sidekiq_running_time.sh'

サーバーにあるsidekiq.logを収集する

ログの収集方法としては、サーバーにsshしてsidekiq.logをawkで収集しています。

  server_log=$(ssh user_name@`echo $ip | sed 's/"//g'` 'awk '\'' { if ($7 == "done:") sum[$4] += $8; count[$4]++; } END {for (key in sum) { if (key) print ("\"title\":\"" key "\",\"value\":\"total=" sum[key] "s,avg=" (sum[key]/count[key]) "s,count=" count[key] "\"") } }'\'' /hogehoge/log/sidekiq.log')

awkは下記ページを参考にしてました。
[初心者向け]Awkの使い方 - Qiita

やっていることとしては、下記になります。

  • ssh
  • doneが記載されている行を取得
  • Jobの名前毎に実行にかかった時間と実行回数を保存していく
  • 最後に集計結果を出す

集計結果はこんな感じのものが並びます。

HogehogeWorker
total=74.804s, avg=0.13956s, count=536
  • total: 1日で何秒動いていたか
  • avg: 1回の処理時間が何秒くらいで動いていたか
  • count: 1日で何回実行されたか

sidekiqは独占すると他のキューの処理ができなくなるので、
実行時間をなるべく短くすることが大切です。
avgが1秒以上のものは、なるべく修正対象にしていきます。

countが多いものは基準を厳しくするなど、見えることで対応しなければいけないハードルが明確にできるのが良いかと思います。

さいごに

紹介したやり方では、sidekiqの死亡が通知されないなどあるので今のままでは不十分かと思います。
ただ、着手したタイミングでは死亡が日に何度も発生していたため通知自体は後回しにしています。

今のプロダクトの状態や工数なんかの折り合いで、良き着地どころで改善していくことが大切かと思います。

最後まで読んでくれてありがとうございました!