Caricamento lento su private-message-topic-tracking-state.json

Dalla versione 2.8.0.beta5, il caricamento della casella di posta delle chat di gruppo richiede oltre 4 secondi, con la maggior parte del tempo (2-3 secondi) assorbito dalla query SQL molto pesante di private-message-topic-tracking-state.json.

Abbiamo circa 800.000 topic, 3,8 milioni di utenti e probabilmente un ampio grafo di PM non letti per utente, ma non riesco a notare nulla di rilevante nell’analisi della query (probabilmente sono solo poco abile nel leggerla).

Prima della beta5 non c’erano problemi; ora le caselle di posta delle chat private sono molto difficili e fastidiose da tenere sotto controllo.

1 Mi Piace

Hmm, qui su Meta per noi la media è di 200 ms.

Detto questo, è piuttosto sospetto che l’accesso ai messaggi nel tuo profilo ora generi 3 richieste distinte e che quella che menzioni restituisca un JSON da 92 kB con 900 oggetti per me :scream:

2 Mi Piace

Sembra anche che invalidi lo stato di miniprofiler a metà percorso, quindi non riesco nemmeno a catturare la query SQL per spiegarla correttamente con EXPLAIN.

2 Mi Piace

Sì, quella transizione di percorso non si comporta normalmente.

A proposito, ho estratto un piano qui: ieWq | explain.depesz.com

3 Mi Piace

Questa correzione dovrebbe portarlo a circa 13 ms.

Tieni presente che più messaggi non letti hai, più costosa sarà la query.

@sam Un’altra cosa che devo correggere è che la chiusura dei messaggi non letti non aggiorna le ottimizzazioni first_unread_at che abbiamo per i topic normali e quelli privati.

4 Mi Piace

1,73 secondi dopo aver selezionato questa modifica e riavviato Unicorn, ma il tempo di ‘non letto’ per me e per i miei gruppi è probabilmente molto indietro (vedo solo 59 nuovi e 4 non letti per questa casella di posta: questa rotta è per utente? anche per ‘tutti i messaggi’ ne ho 61 nuovi e 7 non letti)

1 Mi Piace

L’orario dell’ultima lettura non letta è correlato ai messaggi non letti nelle tue caselle di posta?

1 Mi Piace
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 righe)
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 riga)

Curiosamente, l’intervallo non è nemmeno così ampio, quindi qualche altra condizione sta rallentando l’esecuzione (anche se, misteriosamente, si è effettivamente accelerata fino a 700 ms ora dopo aver ignorato alcuni messaggi non letti, il che è sopportabile; non sono sicuro di qual fosse il mio intervallo di first_unread_pm_at in precedenza, forse qualche settimana?).

Esiste un modo per ottenere la query da miniprofiler dopo che si è aggiornata, rimuovendo tutte le vecchie richieste nella pagina dei messaggi, in modo da poter eseguire un EXPLAIN?

È davvero strano, ma non riesco a riprodurlo nell’ambiente di sviluppo. Ci dedicherò un po’ di tempo la prossima settimana.

1 Mi Piace

Ho risolto il problema in

1 Mi Piace

Grazie! Cercherò di ricordarmi di controllare di nuovo alla prossima finestra di ricostruzione/riavvio.

1 Mi Piace

Ho ottenuto un piano di query/risultato di EXPLAIN ANALYZE (fino a 1,3s :confused:): CvUX | explain.depesz.com

Dopo un reindex index concurrently index_topics_on_timestamps_private; è diventato leggermente più veloce (768ms), quindi potrebbe essere solo un artefatto di molti DM precedenti (il bot narrativo, prima della pulizia, stava inquinando molto la tabella dei DM!)… anche se è ancora lento sullo stesso indice

Puoi eseguire Topic.where(archetype: Archetype.private_message).count per me in una console di Rails?

A proposito, la query viene ora eseguita in modo asincrono, quindi non bloccherà il caricamento della pagina dei messaggi o di un messaggio privato.

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

Potrebbe andare molto peggio, abbiamo recentemente eliminato tutti i topic residui dei bot narrativi. :sweat_smile: Comunque più di quanto mi aspettassi!

Ah, mi chiedevo perché quella query apparisse nel miniprofiler solo dopo un po’ di tempo. È un’ottima cosa!

Di recente abbiamo aggiornato nuovamente per includere questa funzionalità FEATURE: New and Unread messages for user personal messages. by tgxworld · Pull Request #13603 · discourse/discourse · GitHub (ossia siamo attualmente alla versione 2.8.0beta6)

Sembra che la funzione per ottenere tutti i messaggi privati di un utente, che alla fine porta da qualche parte FEATURE: New and Unread messages for user personal messages. by tgxworld · Pull Request #13603 · discourse/discourse · GitHub, generi una query come questa →

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;

Essenzialmente blocca il nostro server RDS. Penso che un membro del nostro team abbia suggerito di filtrare i dati utilizzando gli indici disponibili prima di eseguire le join. Questa query viene eseguita in < 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;

A titolo di riferimento, topics > 10 milioni di righe, topic_users > 50 milioni di righe.

È possibile ristrutturare la query per risolvere in qualche modo questi problemi?

Modifica:

Per chiarire, quando esaminiamo le query con tempi di esecuzione più lunghi (> 2 minuti o addirittura 5 minuti), queste sono le uniche che compaiono. Con l’ultima modifica, la CPU di Postgres è costantemente al 99%. Quando termino queste query, vediamo che l’utilizzo della CPU torna alla normalità.

3 Mi Piace

@tgxworld scusa per il tag diretto, ma dato che sei l’autore, mi chiedevo se avessi qualche suggerimento o feedback.

1 Mi Piace

Per quanto ricordo, @sam lo ha sempre descritto come una funzionalità rischiosa e pericolosa. Non mi sorprenderebbero gravi regressioni in questo ambito.

Abbiamo trovato questo argomento relativo al bug dopo aver pubblicato questo: Slow loading on private-message-topic-tracking-state.json - #9 by tgxworld

Sembra che possa esserci un commit successivo a quello contrassegnato come v2.8.0beta6 che sembra risolvere parte di questo problema di prestazioni. Proviamo a ricompilare puntando a quel riferimento specifico del commit per vedere se risolve qualcosa.

2 Mi Piace

Qual è la tua istanza RDS attuale e qual è la dimensione totale del database?

1 Mi Piace

db.m5.2xlarge

Circa 250 GB in termini di utilizzo del disco.

1 Mi Piace