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

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

先日、[ichiji.social](https://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](https://github.com/tootsuite/mastodon/pull/12886)

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

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

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

<img width="336" alt="スクリーンショット 2020-01-21 10.02.07.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/65644/ca354247-eb0b-a633-e5ba-57c5f6d7cae4.png">

<img width="582" alt="スクリーンショット 2020-01-17 12.43.53のコピー.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/65644/72674747-2d31-a4a3-50e0-5861bcd05c49.png">

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

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

## 何が起こっていた？

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

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

<img width="781" alt="スクリーンショット 2020-01-17 13.37.12.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/65644/04f080cd-650a-2e7a-43b2-22942cfdbc9d.png">



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

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

<img width="1047" alt="スクリーンショット 2020-01-17 12.53.54のコピー.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/65644/3fc38e8c-a786-315c-231d-e23e10f7bfb5.png">

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


## 解決策を見つけるまで

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

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

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

* [LTL is not displayed after applying #11623 in some instance · Issue #11643 · tootsuite/mastodon](https://github.com/tootsuite/mastodon/issues/11643)
* [Fix slow local timeline query by Gargron · Pull Request #11648 · tootsuite/mastodon](https://github.com/tootsuite/mastodon/pull/11648)

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

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

```ruby
    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]。

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

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

<img width="588" alt="スクリーンショット 2020-01-17 20.12.32.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/65644/b4392658-9d1a-33d5-1777-54dca4d62be0.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](https://github.com/tootsuite/mastodon/pull/12886)

実は、外部の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: