アラーム1つが1日の読み取り上限500万行を使い切った:Durable Objects 1101の追跡記録

まず数字から

エラー収集サーバーが止まったと気づいて最初にやったのは、数字を集めることでした。上限がいくつで、誰がどれだけ読んだのかから見ました。

最初は違うサーバーを疑った

症状はエラー収集サーバーに先に出ました。セッション一覧とイシュー一覧を呼ぶと500が返り、本文にはerror code: 1101とだけ書かれていました。同じ時間に、友達招待サーバーも同じコードで止まっていました。

緊急通知のバーには、招待サーバーが犯人として表示されました。止まったサーバーをそのまま犯人にしていたわけです。でも招待サーバーは1日のリクエストが数千件しかなく、それだけの読み取りは作れません。

エラー収集サーバーも同じでした。リクエストは1日2〜3千件なのに、読み取り行数は140万〜514万。リクエスト数と読み取り行数がここまで合わないなら、リクエスト以外の誰かが読んでいるということです。

犯人は5秒ごとのアラームだった

上限はアカウント全体で共有なので、サーバーごとの使用量を別々に見る必要がありました。Cloudflare APIでサーバー(Worker)ごとの読み取り行数を出すと、ほぼ全部が1か所でした。ドットクランのゲームサーバーです。

このサーバーは5秒ごとにアラームが動きます。アラームの中で、接続中の人数を数えたりボット名簿を読んだりするクエリが、usersとfeedのテーブルにインデックスがないせいで、毎回テーブルを頭から最後まで読んでいました。

1回290行は小さく見えます。でもアラームは1日17,280回動くので、掛けると498万になります。

直したこと

ドットクランのサーバーとエラー収集サーバーを、それぞれ直しました。原因はどちらも同じで、インデックスなしで範囲を読むクエリでした。

• 直したサーバーをデプロイしても、その日の上限はすでに使い切っていたのですぐには復旧しませんでした。エラー収集サーバーは次のリセット(00:00 UTC)で戻ります。
• インデックスを付けると、1回に読む行数がテーブル全体の大きさから、必要な行数まで減ります。

同じことを繰り返さないために

直すだけでは足りませんでした。今回は上限が尽きてから気づき、誰が使っているのかはだいぶ後でわかりました。そこで2つ足しました。

1つ目はテストです。アラームを400回動かす間に実行されたクエリを集め、EXPLAIN QUERY PLANでプランを見て、usersやfeedをインデックスなしで読むクエリが1つでもあればテストが失敗します。LIMITが付いて先頭で止まるクエリは除きます。

2つ目は監視です。毎時7分にサーバーごとの読み取り行数を合計し、上限の60%を超えたら、犯人サーバーの名前と行数を付けて通知を出します。招待サーバーとエラー収集サーバーを直接叩いて1101が返ってきたらそれも通知し、復旧したら消します。

私が間違えていたこと

間違いはクエリ1つではありませんでした。複数のサーバーが無料枠1つを分け合っているのに、サーバーごとにどれだけ読んでいるかを測る場所がありませんでした。1つのサーバーが上限を使い切ると、無関係なサーバーが代わりに止まり、止まった側だけが目に入ります。

そこでドットクランには、アラームの経路のクエリがインデックスを使うかを見るテストを入れました。上限がアカウント共有なら、先にサーバーごとの使用量の表が必要だと、今回学びました。