Langsames Laden von private-message-topic-tracking-state.json

Seit Version 2.8.0.beta5 dauert das Laden eines Gruppen-PM-Postfachs über 4 Sekunden, wobei der Großteil der Zeit (2–3 Sekunden) auf die riesige SQL-Abfrage in private-message-topic-tracking-state.json entfällt.

Wir haben etwa 800.000 Themen, rund 3,8 Millionen Nutzer und wahrscheinlich einen großen Graphen ungelesener PMs pro Nutzer. Allerdings sehe ich bei der Analyse der Abfrage selbst nichts Auffälliges (ich bin vielleicht einfach nur schlecht darin, sie zu lesen).

Vor beta5 funktionierte dies problemlos; jetzt ist die Nachverfolgung von PM-Postfächern sehr mühsam und nervig.

1 „Gefällt mir“

Hmmm, bei uns auf Meta liegt der Durchschnitt hier bei 200 ms.

Allerdings ist es ziemlich verdächtig, dass der Aufruf von Nachrichten in deinem Profil jetzt drei separate Abrufe auslöst und dass der von dir erwähnte eine 92 kB große JSON-Datei mit 900 Objekten zurückgibt :scream:

2 „Gefällt mir“

Es scheint tatsächlich auch den Status von Miniprofiler mitten im Prozess ungültig zu machen, sodass ich die SQL-Abfrage nicht einmal erfassen kann, um sie ordnungsgemäß zu EXPLAIN.

2 „Gefällt mir“

Ja, dieser Routenübergang verhält sich nicht normal.

Übrigens habe ich hier einen Plan extrahiert: ieWq | explain.depesz.com

3 „Gefällt mir“

Diese Korrektur sollte den Wert auf etwa 13 ms senken.

Beachte bitte, dass die Abfrage umso aufwendiger wird, je mehr ungelesene Beiträge du hast.

@sam Eine weitere Sache, die ich beheben muss, ist, dass das Abhaken von Ungelesen die first_unread_at-Optimierungen, die wir für normale Themen und PN-Themen haben, nicht aktualisiert.

4 „Gefällt mir“

1,73 Sekunden nach dem Cherry-Pick dieser Änderung und dem Neustart von Unicorn, aber die Zeit für ungelesene Nachrichten für mich selbst und meine Gruppen liegt wahrscheinlich deutlich zurück (ich sehe nur 59 neue und 4 ungelesene für dieses Postfach – ist diese Route pro Benutzer? Obwohl selbst bei „alle Nachrichten" ich 61 neue und 7 ungelesene habe).

1 „Gefällt mir“

Hängt die Zeit, seit der letzten Lesebestätigung, mit den ungelesenen Nachrichten in deinen Postfächern zusammen?

1 „Gefällt mir“
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)

Seltsamerweise ist der Bereich nicht einmal so groß, sodass eine andere Bedingung langsam ist (obwohl sie sich nach dem Abhaken einiger ungelesener Nachrichten mysteriös auf 700 ms beschleunigt hat, was erträglich ist. Ich bin mir nicht sicher, wie groß mein first_unread_pm_at-Bereich vorher war, vielleicht einige Wochen?).

Gibt es eine Möglichkeit, die Abfrage aus dem MiniProfiler zu erhalten, nachdem er sich aktualisiert und alle alten Anfragen auf der Nachrichten-Seite entfernt hat, damit ich ein EXPLAIN ausführen kann?

Das ist zwar wirklich seltsam, aber ich kann das in der Entwicklungsumgebung nicht reproduzieren. Ich werde nächste Woche etwas Zeit investieren, um dem auf den Grund zu gehen.

1 „Gefällt mir“

Ich habe es in folgendem Pull Request behoben:

1 „Gefällt mir“

Danke! Ich werde versuchen, beim nächsten Neustart- oder Neuaufbau-Fenster wieder zu prüfen.

1 „Gefällt mir“

Ich habe einen Query-Plan/EXPLAIN ANALYZE-Ergebnis erhalten (bis zu 1,3 s :confused:): CvUX | explain.depesz.com

Nach einem reindex index concurrently index_topics_on_timestamps_private; wurde es etwas schneller (768 ms). Das könnte also nur ein Artefakt der vielen früheren DMs sein (der Narrative-Bot hat die DM-Tabelle vor der Bereinigung stark verschmutzt!) … dennoch ist es auf demselben Index immer noch langsam.

Kannst du bitte Topic.where(archetype: Archetype.private_message).count in einer Rails-Konsole für mich ausführen?

Übrigens wird die Abfrage jetzt asynchron ausgeführt, sodass das Laden der Nachrichtenseite oder einer privaten Nachricht nicht blockiert wird.

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

Es hätte schlimmer kommen können – wir haben kürzlich alle übrig gebliebenen Themen des Narrative-Bots bereinigt. :sweat_smile: Trotzdem mehr als ich erwartet habe!

Ah, jetzt verstehe ich, warum die Abfrage im MiniProfiler erst nach einer Weile angezeigt wurde. Das ist gut!

Wir haben kürzlich erneut aktualisiert, um dieses Feature zu übernehmen: FEATURE: New and Unread messages for user personal messages. by tgxworld · Pull Request #13603 · discourse/discourse · GitHub (aktuell also auf Version 2.8.0beta6).

Es scheint, als führe die Abfrage „Alle PMs für einen Benutzer abrufen", die letztlich zu diesem Punkt führt: FEATURE: New and Unread messages for user personal messages. by tgxworld · Pull Request #13603 · discourse/discourse · GitHub, zu einer Abfrage wie dieser:

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;

Diese Abfrage führt im Wesentlichen dazu, dass unser RDS-Server einfriert. Ein Mitglied unseres Teams hat vorgeschlagen, dass wir die Daten mit Hilfe der vorhandenen Indizes filtern, bevor wir die Joins durchführen. Diese Abfrage läuft in unter 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;

Zur Information: Die Tabelle topics enthält über 10 Millionen Zeilen, topic_users über 50 Millionen.

Ist es möglich, die Abfrage so umzustrukturieren, dass diese Probleme behoben werden?

Edit:

Nur zur Klarstellung: Wenn wir unsere längeren Abfragen (> 2 Minuten oder sogar 5 Minuten) untersuchen, tauchen ausschließlich diese Abfragen auf. Mit der neuesten Änderung liegt die CPU-Auslastung unseres Postgres-Server ständig bei 99 %. Wenn ich diese Abfragen abbringe, sehen wir, dass die CPU-Auslastung wieder auf Normalniveau zurückkehrt.

3 „Gefällt mir“

@tgxworld tut mir leid, dich direkt zu erwähnen, aber da du der Autor bist, wollte ich fragen, ob du Vorschläge oder Feedback hast.

1 „Gefällt mir“

Wie ich mich erinnere, hat @sam dies immer als riskantes und gefährliches Feature beschrieben. Große Regressionen hier würden mich nicht überraschen.

Wir haben dieses Bug-Thema nach unserem Beitrag gefunden: Slow loading on private-message-topic-tracking-state.json - #9 by tgxworld

Es scheint, dass es möglicherweise ein Commit nach dem mit v2.8.0beta6 getaggten gibt, das einige dieser Leistungsprobleme adressiert. Wir werden versuchen, einen Neuaufbau mit Bezug auf diesen spezifischen Commit-Referenz durchzuführen und prüfen, ob dies etwas verbessert.

2 „Gefällt mir“

Welche RDS-Instanzklasse verwenden Sie aktuell und wie groß ist die gesamte Datenbank?

1 „Gefällt mir“

db.m5.2xlarge

Ca. 250 GB bezogen auf die Festplattennutzung.

1 „Gefällt mir“