private-message-topic-tracking-state.json の読み込みが遅い

2.8.0.beta5 以降、グループ PM の受信トレイの読み込みに 4 秒以上を要し、その大部分(2〜3 秒)は private-message-topic-tracking-state.json の巨大な SQL クエリによるものです。

当サイトには約 80 万件のトピック、約 380 万ユーザーが存在し、未読 PM からユーザーへの大規模なグラフも存在すると思われますが、クエリ分析では特に目立つ点は見当たりません(読み方が下手なだけかもしれません)。

beta5 以前は問題なかったのですが、現在は PM の受信トレイの管理が非常に難しく、ストレスを感じるようになりました。

「いいね!」 1

ふむ、メタでは平均 200ms 程度です。

とはいえ、プロフィール内のメッセージに移動すると現在 3 つの異なるフェッチが発生しており、あなたが言及しているものが私にとって 900 個のオブジェクトを含む 92kB の JSON を返しているのはかなり怪しいですね :scream:

「いいね!」 2

どうやら miniprofiler の状態が途中で無効化されているようで、SQL クエリを取得して適切に EXPLAIN することもできません。

「いいね!」 2

はい、そのルート遷移が正常に動作していません。

ところで、ここに実行計画を抽出しました: ieWq | explain.depesz.com

「いいね!」 3

この修正により、約 13ms まで低下するはずです。

なお、未読の数が多いほど、クエリのコストは高くなります。

@sam 他にも修正が必要な点として、未読を既読として処理しても、通常トピックや PM トピック向けの first_unread_at の最適化が更新されないという問題があります。

「いいね!」 4

1.73 秒後にこの変更を cherry-pick し、Unicorn を再起動しましたが、自分自身とグループの「未読」時刻はだいぶ遅れているようです(この受信トレイでは、可視的な「新規」が 59 件、「未読」が 4 件です。このルートはユーザーごとに設定されているのでしょうか?「すべてのメッセージ」で見ても、新規が 61 件、未読が 7 件です)。

「いいね!」 1

既読未読の時刻は、あなたの受信トレイの未読メッセージ数と相関していますか?

「いいね!」 1
discourse=# select first_unread_pm_at from group_users where user_id = 2334 order by first_unread_pm_at asc;
     first_unread_pm_at
----------------------------
 2021-09-03 06:54:13.493514
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
(17 rows)
discourse=# select first_unread_pm_at from user_stats where user_id = 2334;
     first_unread_pm_at
----------------------------
 2021-09-03 07:05:00.565522
(1 row)

不思議なことに、その範囲はさほど大きくないため、別の条件が低速になっているようです(ただし、いくつかの未読を既読にした後、不思議なことに実行時間が 700ms に短縮され、許容できるレベルになりました。以前、私の first_unread_pm_at の範囲がどれくらいだったかはわかりませんが、数週間分だったかもしれません)。

メッセージページでミニプロファイラが更新され、古いリクエストがすべて削除された後、クエリを取得して EXPLAIN を実行する方法はありますか?

これは確かに奇妙ですが、開発環境では再現できませんでした。来週、この件について調査する時間を取ります。

「いいね!」 1

以下のプルリクエストで修正しました。

「いいね!」 1

ありがとうございます!次のビルド/再起動ウィンドウのときに、再度確認することを忘れないように努めます。

「いいね!」 1

クエリプラン/EXPLAIN ANALYZE の結果を取得しました(まだ 1.3 秒まで戻ってしまいます :confused:): CvUX | explain.depesz.com

reindex index concurrently index_topics_on_timestamps_private; を実行後、少し高速化されました (768ms)。これは、過去の DM が大量に溜まっていたことによる一時的な現象かもしれません(整理前のナラティブボットが DM テーブルをひどく汚染していました!)… しかし、同じインデックスではまだ遅いままです。

Rails コンソールで Topic.where(archetype: Archetype.private_message).count を実行していただけますか?

なお、このクエリは現在非同期で実行されるため、メッセージページやプライベートメッセージの読み込みをブロックすることはありません。

[1] pry(main)> Topic.where(archetype: Archetype.private_message).count
=> 543855

最悪の事態よりはマシですね。最近、残っていたナラティブボットのトピックをすべて整理しましたから :sweat_smile: それでも予想より多いです!

あ、それで miniprofiler にそのクエリが少し遅れて表示されるのかと思っていました。それは良いですね!

最近、この機能を取得するために再度アップデートしました(https://github.com/discourse/discourse/pull/13603、現在は 2.8.0beta6)。

ユーザーのすべての PM を取得する処理(最終的には FEATURE: New and Unread messages for user personal messages. by tgxworld · Pull Request #13603 · discourse/discourse · GitHub につながる箇所)が、以下のようなクエリを生成しているようです。

SELECT "topics"."id", "topics"."title", "topics"."last_posted_at", "topics"."created_at", "topics"."updated_at", "topics"."views", "topics"."posts_count", "topics"."user_id", "topics"."last_post_user_id", "topics"."reply_count", "topics"."featured_user1_id", "topics"."featured_user2_id", "topics"."featured_user3_id", "topics"."deleted_at", "topics"."highest_post_number", "topics"."like_count", "topics"."incoming_link_count", "topics"."category_id", "topics"."visible", "topics"."moderator_posts_count", "topics"."closed", "topics"."archived", "topics"."bumped_at", "topics"."has_summary", "topics"."archetype", "topics"."featured_user4_id", "topics"."notify_moderators_count", "topics"."spam_count", "topics"."pinned_at", "topics"."score", "topics"."percent_rank", "topics"."subtype", "topics"."slug", "topics"."deleted_by_id", "topics"."participant_count", "topics"."word_count", "topics"."excerpt", "topics"."pinned_globally", "topics"."pinned_until", "topics"."fancy_title", "topics"."highest_staff_post_number", "topics"."featured_link", "topics"."reviewable_score", "topics"."image_upload_id", "topics"."slow_mode_seconds" FROM "topics" LEFT OUTER JOIN topic_users AS tu ON (topics.id = tu.topic_id AND tu.user_id = 1234) LEFT JOIN group_archived_messages gm ON gm.topic_id = topics.id
LEFT JOIN user_archived_messages um
ON um.user_id = 1234
AND um.topic_id = topics.id WHERE "topics"."deleted_at" IS NULL AND (topics.id IN (
SELECT topic_id
FROM topic_allowed_users
WHERE user_id = 1234
 UNION ALL
SELECT topic_id FROM topic_allowed_groups
 WHERE group_id IN (
SELECT group_id FROM group_users WHERE user_id = 1234
  )
)) AND "topics"."archetype" = 'private_message' AND "topics"."visible" = TRUE AND (um.user_id IS NULL AND gm.topic_id IS NULL) ORDER BY topics.bumped_at DESC LIMIT 30;

このクエリが RDS サーバーを完全に停止させています。チームのメンバーの一人は、結合する前に利用可能なインデックスを使ってデータをフィルタリングすることを提案しました。この修正版クエリは 100ms 未満で実行されます。

SELECT "topics_filter"."id", "topics_filter"."title", "topics_filter"."last_posted_at", "topics_filter"."created_at", "topics_filter"."updated_at",
"topics_filter"."views", "topics_filter"."posts_count", "topics_filter"."user_id", "topics_filter"."last_post_user_id", "topics_filter"."reply_count", "topics_filter"."featured_user1_id",
"topics_filter"."featured_user2_id", "topics_filter"."featured_user3_id", "topics_filter"."deleted_at", "topics_filter"."highest_post_number", "topics_filter"."like_count",
"topics_filter"."incoming_link_count", "topics_filter"."category_id", "topics_filter"."visible", "topics_filter"."moderator_posts_count", "topics_filter"."closed",
"topics_filter"."archived", "topics_filter"."bumped_at", "topics_filter"."has_summary", "topics_filter"."archetype", "topics_filter"."featured_user4_id", "topics_filter"."notify_moderators_count",
"topics_filter"."spam_count", "topics_filter"."pinned_at", "topics_filter"."score", "topics_filter"."percent_rank", "topics_filter"."subtype", "topics_filter"."slug",
"topics_filter"."deleted_by_id", "topics_filter"."participant_count", "topics_filter"."word_count", "topics_filter"."excerpt", "topics_filter"."pinned_globally",
"topics_filter"."pinned_until", "topics_filter"."fancy_title", "topics_filter"."highest_staff_post_number", "topics_filter"."featured_link", "topics_filter"."reviewable_score",
"topics_filter"."image_upload_id", "topics_filter"."slow_mode_seconds"
FROM (select * from "topics"
      where "topics"."deleted_at" IS NULL
      and (topics.id IN ( SELECT topic_id FROM topic_allowed_users WHERE user_id = 1234
                          UNION ALL
                          SELECT topic_id FROM topic_allowed_groups  WHERE group_id IN ( SELECT group_id FROM group_users WHERE user_id = 1234 )
                         ))
      AND "topics"."archetype" = 'private_message'
      AND "topics"."visible" = TRUE
      )   as topics_filter
LEFT OUTER JOIN (select topic_id from topic_users where user_id = 1234) AS tu ON (topics_filter.id = tu.topic_id )
LEFT JOIN group_archived_messages gm ON gm.topic_id = topics_filter.id
LEFT JOIN ( select user_id, topic_id from user_archived_messages where user_id = 1234) um
ON um.topic_id = topics_filter.id
WHERE (um.user_id IS NULL AND gm.topic_id IS NULL) ORDER BY topics_filter.bumped_at DESC LIMIT 30;

参考までに、topics テーブルは 1000 万行以上、topic_users テーブルは 5000 万行以上あります。

これらの問題に対処するために、クエリを再構成することは可能でしょうか?

追記:
念のため補足しますが、実行時間が 2 分、あるいは 5 分以上の長いクエリを調査すると、これらしか表示されません。最新のアップデート以降、Postgres の CPU 使用率が常に 99% になっています。これらのクエリを終了すると、CPU 使用率が正常なレベルに戻るのが確認できます。

「いいね!」 3

@tgxworld 直接タグ付けして申し訳ありませんが、著者であるあなたに何かご提案やフィードバックがあればと思い、ご連絡いたしました。

「いいね!」 1

私の記憶では、@sam はそれを常にリスクが高く危険な機能と表現していました。ここで大きな回帰が発生しても驚きはしません。

このバグトピックは、以下の投稿後に発見されました:Slow loading on private-message-topic-tracking-state.json - #9 by tgxworld

v2.8.0beta6 とタグ付けされたコミットの後に、このパフォーマンス問題のいくつかに対処していると思われるコミットがあるようです。その特定のコミット参照をターゲットとしてビルドを再構築し、問題が緩和されるかどうかを確認しようとしています。

「いいね!」 2

現在の RDS インスタンスタイプとデータベースの総容量はいくらですか?

「いいね!」 1

db.m5.2xlarge

ディスク使用量は約 250GB です。

「いいね!」 1