Chargement lent de private-message-topic-tracking-state.json

Depuis la version 2.8.0.beta5, le chargement de la boîte de réception des messages privés de groupe prend plus de 4 secondes, la majeure partie du temps (2 à 3 secondes) étant consacrée à la requête SQL volumineuse de private-message-topic-tracking-state.json.

Nous avons environ 800 000 sujets, 3,8 millions d’utilisateurs et probablement un grand graphe de MP non lus vers les utilisateurs, mais je ne vois pas vraiment grand-chose de notable dans l’analyse de la requête (je suis probablement juste mauvais pour la lire).

Cela fonctionnait bien avant la beta5 ; maintenant, les boîtes de réception des MP sont très difficiles et ennuyeuses à suivre.

1 « J'aime »

Hmm, chez nous sur Meta, cela tourne en moyenne autour de 200 ms.

Cela dit, c’est assez suspect que l’accès aux messages dans votre profil déclenche maintenant trois requêtes distinctes, et que celle dont vous parlez renvoie un JSON de 92 Ko contenant 900 objets pour moi :scream:

2 « J'aime »

Cela semble également invalider l’état de miniprofiler en cours de route, si bien que je ne peux même pas récupérer la requête SQL pour l’EXPLIQUER correctement.

2 « J'aime »

Oui, cette transition de route ne se comporte pas normalement.

Au fait, j’ai extrait un plan ici : ieWq | explain.depesz.com

3 « J'aime »

Cette correction devrait le ramener à environ 13 ms.

Notez que plus vous avez de messages non lus, plus la requête sera coûteuse.

@sam Une autre chose que je dois corriger est que la fermeture des messages non lus ne met pas à jour les optimisations first_unread_at que nous avons pour les sujets normaux et les messages privés.

4 « J'aime »

1,73 seconde après avoir sélectionné ce changement et redémarré Unicorn, mais le temps de non-lu pour moi et mes groupes est probablement bien en retard (je n’ai que 59 nouveaux et 4 non lus visibles pour cette boîte de réception – cette route est-elle par utilisateur ? même pour « tous les messages », j’ai 61 nouveaux et 7 non lus).

1 « J'aime »

Le moment où un message est marqué comme non lu est-il corrélé aux non-lus dans vos boîtes de réception ?

1 « J'aime »
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)

Curieusement, la plage n’est même pas si élevée, donc une autre condition est lente (bien que, mystérieusement, elle se soit accélérée jusqu’à 700 ms maintenant après avoir ignoré quelques messages non lus, ce qui est supportable. Je ne suis pas sûr de quelle était ma plage first_unread_pm_at auparavant, peut-être quelques semaines ?).

Existe-t-il un moyen pour moi de récupérer la requête depuis miniprofiler après qu’elle se soit actualisée, en supprimant toutes les anciennes requêtes sur la page des messages, afin que je puisse exécuter un EXPLAIN ?

C’est en effet assez étrange, mais je n’arrive pas à reproduire ce problème dans l’environnement de développement. Je consacrerai du temps à l’examiner la semaine prochaine.

1 « J'aime »

Corrigé dans

1 « J'aime »

Merci ! Je vais essayer de penser à vérifier à nouveau lors de la prochaine fenêtre de reconstruction/redémarrage.

1 « J'aime »

J’ai obtenu un plan de requête / un résultat EXPLAIN ANALYZE (remontant à 1,3 s :confused:) : CvUX | explain.depesz.com

Après un reindex index concurrently index_topics_on_timestamps_private;, cela est devenu un peu plus rapide (768 ms). Il se pourrait donc qu’il s’agisse simplement d’un artefact dû à un grand nombre d’anciens MP (le bot de narration, avant le nettoyage, polluaient énormément la table des MP !)… bien que cela reste lent sur le même index.

Pouvez-vous exécuter Topic.where(archetype: Archetype.private_message).count pour moi dans une console Rails ?

Au fait, la requête est désormais effectuée de manière asynchrone, elle ne bloquera donc pas le chargement de la page des messages ou d’un message privé.

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

Ça aurait pu être bien pire, nous avons récemment éliminé tous les sujets résiduels des bots narratifs. :sweat_smile: Toujours plus que ce à quoi je m’attendais !

Ah, je me demandais pourquoi cette requête n’apparaissait dans le miniprofiler qu’après un certain temps. C’est une bonne chose !

Nous avons récemment mis à jour à nouveau pour intégrer cette fonctionnalité FEATURE: New and Unread messages for user personal messages. by tgxworld · Pull Request #13603 · discourse/discourse · GitHub (c’est-à-dire que nous sommes actuellement sur la version 2.8.0beta6).

Il semble que l’opération « obtenir tous les MP pour un utilisateur », qui aboutit finalement à l’endroit indiqué ici FEATURE: New and Unread messages for user personal messages. by tgxworld · Pull Request #13603 · discourse/discourse · GitHub, génère une requête de ce type :

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;

Cette requête fait planter notre serveur RDS. Un membre de notre équipe a suggéré de filtrer les données en utilisant les index disponibles avant de procéder aux jointures. Cette requête s’exécute en moins de 100 ms :

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;

Pour référence : topics > 10 millions de lignes, topic_users > 50 millions de lignes.

Est-il possible de restructurer la requête pour résoudre ces problèmes d’une manière ou d’une autre ?

Édition :

Pour préciser, lorsque nous examinons nos requêtes les plus longues (> 2 minutes, voire 5 minutes), ce sont les seules qui apparaissent. Avec le dernier changement, le CPU de notre Postgres est constamment à 99 %. Lorsque je termine ces requêtes, nous constatons que l’utilisation du CPU revient à la normale.

3 « J'aime »

@tgxworld désolé de te taguer directement, mais comme tu en es l’auteur, je me demandais si tu avais des suggestions ou des retours.

1 « J'aime »

À ce que je me souvienne, @sam l’a toujours décrit comme une fonctionnalité risquée et dangereuse. De grosses régressions ici ne me surprendraient pas.

Nous avons trouvé ce sujet de bug après avoir publié ceci : Slow loading on private-message-topic-tracking-state.json - #9 by tgxworld

Il semble qu’il y ait peut-être un commit après celui tagué v2.8.0beta6 qui semble résoudre une partie de ce problème de performance. Nous allons essayer de reconstruire en ciblant cette référence de commit spécifique pour voir si cela atténue quoi que ce soit.

2 « J'aime »

Quelle est votre instance RDS actuelle et quelle est la taille totale de la base de données ?

1 « J'aime »

db.m5.2xlarge

~ 250 Go en termes d’utilisation du disque.

1 « J'aime »