この記事はGMOペパボエンジニアアドベントカレンダー2021の3日目の記事です。
昨日はyammerさんの「複数の環境に適応する、階層構造のdotfiles」でした。私は例年長期休暇中にdotfileを整理しているのですが、仕事用、家庭用、家庭用、家庭用がある我が家にピッタリで非常に参考になる記事でしたので冬休みの楽しみにしようと思います。
3日目の記事では、最近行ったMackerel公式pluginへのコントリビュートした際の経緯や実装にあたり調べたことや考えたことをご紹介します。
背景
sidekiqはredisをqueueに使う非同期処理を実現するgemです。
これの運用においてはキューがスタックしていないか知りたいケースがあるかと思います。私が所属するGMOペパボの多くのサービスではMacekrelを利用しており、Sidekiqの監視もMackerelで公式プラグインや自作プラグインなどを用いて行われています。キューのjob数を監視していたのですが、短期間にjobが追加された場合などに問題ない速度でjobが処理できているのですが一時的に閾値を超え誤報が頻発しておりました。
上記のようにSidekiqの監視は単純にはenqueueされたjobの数を監視する方法などが考えられますが、たとえ閾値以上となっても許容時間内に処理できていれば問題になることは少ないでしょう。
これに関してはsidekiq公式wikiに記述があり、より誤検知が少ないQueue latencyを使うことが提案されてます。
If you throw a lot of jobs into the queue, you can get false positives when monitoring the queue backlog. Instead, monitor the queue latency.(https://github.com/mperham/sidekiq/wiki/Monitoring#using-a-custom-end-point)
既存のMackerel pluginにはSidekiqのQueue latencyを計測するものは調べた限り見つけられませんでした。これをMackerelで監視できるようにするには複数の方法が考えられました。
公式wikiのような方法でlatencyを公開しそれを投稿する方法や、sidekiq gemを用いて監視のためのrubyスクリプトを作成する方法などが考えられましたが、さまざまな環境に簡単に導入できるようmackerel-plugin-sidekiqに機能追加することにしました。
Queue latency
Queue latencyはqueue上の最も古いjobがpushされた時間と現在時刻の差です。
前述の公式wikiには次のような例が載っており、Queueにlatencyメソッドがあることがわかります。
# https://github.com/mperham/sidekiq/wiki/Monitoring#using-a-custom-end-point
require 'sidekiq/api'
match "queue-latency" => proc { [200, {"Content-Type" => "text/plain"}, [Sidekiq::Queue.new.latency < 30 ? "OK" : "UHOH" ]] }, via: :get 実装
GoにSidekiq互換の非同期処理ライブラリがあったので、簡単に実現できるかもと思いましたが残念ながらQueue latency計測は未実装のようでした。
そこでsidekiqのlatencyメソッドを参考にlatency計測を実装することにしました。
実装を見てみると、queue:#{name}のリストの最後のアイテムを取ってきてnilなら0を、そうでないならjobをjson loadして enqueed_atの値と現在時刻の差分を返しているようでした。
# https://github.com/mperham/sidekiq/blob/46f4c6bd9ee0b2f5502a1dc0d03414989ad65063/lib/sidekiq/api.rb#L226-L229
def initialize(name = "default")
@name = name.to_s
@rname = "queue:#{name}"
end
# (--- 省略 ---)
# https://github.com/mperham/sidekiq/blob/46f4c6bd9ee0b2f5502a1dc0d03414989ad65063/lib/sidekiq/api.rb#L240-L254
# Calculates this queue's latency, the difference in seconds since the oldest
# job in the queue was enqueued.
#
# @return Float
def latency
entry = Sidekiq.redis { |conn| conn.lrange(@rname, -1, -1) }.first
return 0 unless entry
job = Sidekiq.load_json(entry)
now = Time.now.to_f
thence = job["enqueued_at"] || now
now - thence
end実際どのような内容がredisに格納されているかを調べてみました。lrange(name, -1, -1)はリストの最後の要素を取得します。
keyに格納されているリストの指定された要素を返します。オフセット start と stop はゼロベースのインデックスです。0 はリストの最初の要素 (リストの先頭)、 1 は次の要素。これらのオフセットはリストの最後から始まるオフセットを示す負の数にすることもできます。例えば、1 はリストの最後の要素、2は最後から2番目の要素です。
> lrange queue:default -1 -1
1) “{\"retry\":true,\"queue\":\"default\",\"class\":\"HelloWorker\",\"args\":[],\"jid\":\"84378c279c51117f84dd5918\",\"created_at\":1637110549.0927832,\"enqueued_at\":1637110549.0927997}"見やすくしたのがこちらです。created_atとenqueued_atはfloat精度のUNIX timeになっていました。
{
"retry": true,
"queue": "default",
"class": "HelloWorker",
"args": [],
"jid": "84378c279c51117f84dd5918",
"created_at": 1637110549.0927832,
"enqueued_at": 1637110549.0927997
}このlatencyの計測部分はほぼそのままGoに書き換えて実装しました。実装詳細についてはPRをご覧ください。
さいごに
上記機能追加が先日無事リリースされました。早速弊社の環境にも導入し、監視の誤報を減らすことができ安眠を手に入れることができました。
Sidekiqの実装も知るきっかけとなり、なかなか面白い経験ができました。是非使っていただきフィードバックをいただければとおもいます。
明日のアドベントカレンダー4日目ははらちゃんです！よろしくお願いします🎄
