LoginSignup
6
2

More than 3 years have passed since last update.

@notozeki(notozeki)inフィフス・フロア株式会社

Mastodonをv3系に上げたらDB負荷が激増した話（と解消してコントリビュートした話）

Last updated at Posted at 2020-01-21

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

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

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

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

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

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

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

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

スクリーンショット 2020-01-21 10.02.07.png

スクリーンショット 2020-01-17 12.43.53のコピー.png

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

何が起こっていた？

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

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

スクリーンショット 2020-01-17 13.37.12.png

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

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

スクリーンショット 2020-01-17 12.53.54のコピー.png

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

解決策を見つけるまで

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

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

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

上記の問題は、ローカル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に発行して、インデックスを作ってみました3。

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の負荷が一瞬にして下がりました！

スクリーンショット 2020-01-17 20.12.32.png

インデックスすごい…

本家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時間ほどでレビューが付いていてビビりました:eyes:

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

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

まとめ

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

  1. 正確には、11:30くらいまでは、アップグレード作業に伴うDBのマイグレーションを回していたので、負荷が高いのは正しい挙動です。しかし、その後もCPU使用率が高いままなのは異常です。 ↩

  2. このIssueには「連合TLは前と同じくらい早い」ということが書かれていて、最初は「じゃあ今回の件とは関係ないか…」と一旦除外していたのですが、結局このIssueと原因は同じことがわかりました。 ↩

  3. CONCURRENTLYをつけると、テーブルをロックせずにインデックスを作ることができるため、稼働中のサービスへの影響を最小限に抑えられます。ただし、CREATE INDEXに少し時間がかかります。これは#11648でも使われていたのを真似しました。 ↩

6
2
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
6
2