こんにちは！　フィフス・フロアのnotozekiです。今年は記事書いてくイヤーにしたいと目論んでいます

先日、ichiji.socialというMastodonサーバーをv2.7.3から一気にv.3.0.1までアップグレードしました。

このアップグレード直後、DBサーバの負荷が異常に高まるという現象が発生し、解決に苦戦したので、そのときの知見を共有したいと思います

また、最後にも記載していますが、解決策を本家MastodonにPull Requestとして送っています。~~記事執筆時点ではまだマージされていませんが、~~もし同様の問題に悩んでいる方がいればこちらをお試しください（2020/01/22 追記: マージされました！）:

Fix slow query of federated timeline by notozeki · Pull Request #12886 · tootsuite/mastodon

v3にアップデート直後、DBのCPU使用率が跳ね上がる

最初に異変に気づいたのは、メンテ後にStackdriverで負荷状況を様子見していたときでした。

メンテナンス自体は大きな問題もなく終了したので、一件落着と思ってグラフを一通り追っていくと…

なんと、DBサーバーのCPU使用率が跳ね上がっています¹

何が起こっていた？

結論から言うと、「連合タイムライン」で発行されるSQLクエリの実行に非常に時間がかかるという現象でした。

以下が、この現象が起きていた時の実際のPgHeroの画面のスクリーンショットです。

このように、いくつもlong runningなクエリが走っている状態でした。この中で一番長いものでは、約1,200,000ms＝1200秒＝20分（20分）も走っているクエリがあります。これらのクエリがDBのCPUを喰い潰しているようでした。

このクエリは、連合TLで使われているAPI（GET /api/v1/timelines/public）で発行されていることがわかりました。ロードバランサのログにも、以下のように 504 (＝Gateway Timeout、つまりバックエンドサーバが一定時間内に応答できなかった) のログが並んでいました。

幸い、サービス全体が重くなったりすることはなく、また↑のエラーもすべての連合TLのAPI呼び出しで出ていたわけではなかったのですが、いずれにせよDBの負荷が高いまま放っておくわけにはいきません。

解決策を見つけるまで

ここまではわかったものの、解決策にたどり着くのに苦労しました。

経験上、このようなメジャーな不具合は、既にIssueとして報告されていたり、修正のPRがあることがほとんどです。今回もそうだろうと思ってMastodonのリポジトリのIssueやPRを追いかけたのですが、一向に同じ報告が見つからず焦りました。

かろうじて、以下のIssue（と解決のPR）が見つかりました。ほぼ同様の現象ですが、このIssueでは「ローカルタイムライン」のみが問題となっていました²。

上記の問題は、ローカルTLのAPIで発行される特定のSQLクエリの検索パフォーマンスが良くないことでした。それを改善するために、#11648では以下のようなマイグレーションで新たなインデックスを作成しています。

    add_index :statuses, [:id, :account_id], name: :index_statuses_local_20190824, algorithm: :concurrently, order: { id: :desc }, where: '(local OR (uri IS NULL)) AND deleted_at IS NULL AND visibility = 0 AND reblog_of_id IS NULL AND ((NOT reply) OR (in_reply_to_account_id = account_id))'

注目すべき点はwhereオプションです。これを指定すると「部分インデックス」が作られます。部分インデックスは、この条件に合致するレコードのみを対象とするインデックスで、上記のwhere条件はローカルTLのクエリに合わせて作られているようでした。

これを連合TL用にも作れば解消するのでは、というのが今回の解決策の着想です。つまり、上記のwhere条件を連合TL向けに少し緩くしたインデックスを作ってみます。

インデックスを作るとCPU使用率が劇的改善

幸い、インデックスを作るだけなら、アプリケーションコードをいじらなくても試すことができます。以下のSQLを本番DBに発行して、インデックスを作ってみました³。

CREATE INDEX CONCURRENTLY index_statuses_public_20200117 ON statuses USING btree (id DESC, account_id) WHERE ((deleted_at IS NULL) AND (visibility = 0) AND (reblog_of_id IS NULL) AND ((NOT reply) OR (in_reply_to_account_id = account_id)));

するとどうでしょう、あれだけ高かったDBの負荷が一瞬にして下がりました！

インデックスすごい…

本家MastodonにPull Requestを送る

直った！　ということでこれで終わりでもよいのですが、せっかく解決できたので、本家Mastodon (https://github.com/tootsuite/mastodon) にもコントリビュートしましょう。

というわけで、上記のインデックス作成をマイグレーション化して、Pull Requestにして送りました。

Fix slow query of federated timeline by notozeki · Pull Request #12886 · tootsuite/mastodon

実は、外部のOSSプロジェクトにPRを送るのはこれが初めてでした。送るまでは結構「内容はこんな感じでいいんだろうか…」とか「英語ちゃんと伝わるんだろうか…」とかドキドキしていたのですが、翌朝にはapproveされていてホッとしました。というか送って1時間ほどでレビューが付いていてビビりました

~~まだマージされていませんが、よしななタイミングでメンテナの方がマージするようなのでそれ待ちです。~~

2020/01/22 追記 マージされました
https://github.com/tootsuite/mastodon/pull/12886#event-2967198280

まとめ

インデックスはすごい
「IssueやPRが既にあるだろう」と思い込んで調べているとドツボにハマる
IssueやPRが無い問題を見つけたらせっかくならコントリビュートしよう

正確には、11:30くらいまでは、アップグレード作業に伴うDBのマイグレーションを回していたので、負荷が高いのは正しい挙動です。しかし、その後もCPU使用率が高いままなのは異常です。 ↩
このIssueには「連合TLは前と同じくらい早い」ということが書かれていて、最初は「じゃあ今回の件とは関係ないか…」と一旦除外していたのですが、結局このIssueと原因は同じことがわかりました。 ↩
CONCURRENTLYをつけると、テーブルをロックせずにインデックスを作ることができるため、稼働中のサービスへの影響を最小限に抑えられます。ただし、CREATE INDEXに少し時間がかかります。これは#11648でも使われていたのを真似しました。 ↩