Carga lenta en private-message-topic-tracking-state.json

Desde la versión 2.8.0.beta5, cargar la bandeja de entrada de mensajes privados grupales tarda más de 4 segundos, y la mayor parte de ese tiempo (2-3 segundos) se consume en la consulta SQL masiva de private-message-topic-tracking-state.json.

Tenemos aproximadamente 800k temas, 3.8M de usuarios y probablemente un grafo extenso de mensajes privados no leídos por usuario, pero tampoco estoy viendo nada destacable en el análisis de la consulta (probablemente sea porque no sé interpretarlo bien).

Esto funcionaba bien antes de la beta5; ahora, mantener la bandeja de entrada de mensajes privados es muy difícil y molesto.

1 me gusta

Hmm, aquí en Meta nos da un promedio de 200 ms.

Dicho esto, es bastante sospechoso que al ir a los mensajes en tu perfil ahora se realicen tres solicitudes distintas, y que la que mencionas me esté devolviendo un JSON de 92 kB con 900 objetos :scream:

2 Me gusta

Parece que también invalida el estado de miniprofiler a mitad de camino, por lo que ni siquiera puedo obtener la consulta SQL para explicarla correctamente.

2 Me gusta

Sí, esa transición de ruta no está actuando con normalidad.

Por cierto, he extraído un plan aquí: ieWq | explain.depesz.com

3 Me gusta

Esta corrección debería reducirlo a unos 13 ms.

Ten en cuenta que cuantos más mensajes sin leer tengas, más costosa será la consulta.

@sam Otra cosa que necesito corregir es que marcar como leído no actualiza las optimizaciones de first_unread_at que tenemos para temas normales y de mensajes privados.

4 Me gusta

1.73 segundos después de aplicar selectivamente este cambio y reiniciar Unicorn, pero el tiempo de no leído para mí y mis grupos probablemente esté bastante atrasado (solo tengo 59 nuevos y 4 no leídos visibles para esta bandeja de entrada: ¿es esta ruta por usuario? aunque incluso para «todos los mensajes» tengo 61 nuevos y 7 no leídos).

1 me gusta

¿Se correlaciona el tiempo de no leído con los no leídos en tus bandejas de entrada?

1 me gusta
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 filas)
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 fila)

Curiosamente, el rango ni siquiera es tan alto, por lo que alguna otra condición está siendo lenta (aunque, misteriosamente, ahora sí se aceleró a 700 ms después de descartar algunos mensajes no leídos, lo cual es soportable; no estoy seguro de cuál era mi rango de first_unread_pm_at antes, ¿quizás unas pocas semanas?).

¿Existe alguna forma de que pueda obtener la consulta de miniprofiler después de que se actualice a sí mismo, eliminando todas las solicitudes antiguas en la página de mensajes, para que pueda ejecutar un EXPLAIN?

Esto es realmente bastante extraño, pero no puedo reproducirlo en el entorno de desarrollo. Pasaré un tiempo investigando esto la próxima semana.

1 me gusta

Arreglado en

1 me gusta

¡Gracias! Intentaré recordar revisar nuevamente en la próxima ventana de reconstrucción/reinicio.

1 me gusta

Tengo un plan de consulta/resultados de EXPLAIN ANALYZE (hasta 1.3 s :confused:): CvUX | explain.depesz.com

Después de ejecutar reindex index concurrently index_topics_on_timestamps_private; se volvió un poco más rápido (768 ms), así que esto podría ser simplemente un artefacto de la gran cantidad de mensajes directos anteriores (el bot de narrativa, antes de la limpieza, estaba contaminando mucho la tabla de mensajes directos)… aunque sigue siendo lento en ese mismo índice.

¿Podrías ejecutar Topic.where(archetype: Archetype.private_message).count en una consola de Rails para mí?

Por cierto, ahora la consulta se realiza de forma asíncrona, por lo que no bloqueará la carga de la página de mensajes ni de un mensaje privado.

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

Podría haber sido mucho peor; recientemente eliminamos todos los temas sobrantes del bot de narrativa. :sweat_smile: ¡Aún así hay más de lo que esperaba!

Ah, me preguntaba por qué esa consulta solo aparecía en el miniprofiler después de un tiempo. ¡Eso es bueno!

Actualizamos recientemente la versión para incorporar esta funcionalidad FEATURE: New and Unread messages for user personal messages. by tgxworld · Pull Request #13603 · discourse/discourse · GitHub (es decir, actualmente estamos en la 2.8.0beta6).

Parece que la operación de obtener todos los mensajes privados para un usuario, que finalmente deriva en algún punto de FEATURE: New and Unread messages for user personal messages. by tgxworld · Pull Request #13603 · discourse/discourse · GitHub, genera una consulta como esta:

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;

Básicamente, esto hace que nuestro servidor RDS se cuelgue. Creo que un miembro de nuestro equipo sugirió que filtráramos los datos utilizando los índices que tengamos antes de realizar los joins. Esta consulta se ejecuta en < 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;

Como referencia, topics > 10M de filas, topic_users > 50M de filas.

¿Es posible reestructurar la consulta para abordar estos problemas de alguna manera?

Edición:

Solo para aclarar, cuando inspeccionamos nuestras consultas de mayor duración (> 2 min o incluso 5 min), estas son las únicas que aparecen. Con el último cambio, la CPU de nuestro Postgres se mantiene constantemente al 99%. Cuando termino estas consultas, observamos que el uso de la CPU vuelve a la normalidad.

3 Me gusta

@tgxworld, siento etiquetarte directamente, pero como fuiste el autor, me preguntaba si tenías alguna sugerencia o comentario.

1 me gusta

Por lo que recuerdo, @sam siempre lo describió como una característica arriesgada y peligrosa. No me sorprenderían grandes regresiones aquí.

Encontramos este tema de error después de publicar esto: Slow loading on private-message-topic-tracking-state.json - #9 by tgxworld

Parece que podría haber un commit posterior al etiquetado como v2.8.0beta6 que parece abordar parte de este problema de rendimiento. Vamos a intentar reconstruir apuntando a esa referencia de commit específica y ver si alivia algo.

2 Me gusta

¿Cuál es el tipo de instancia RDS actual y el tamaño total de la base de datos?

1 me gusta

db.m5.2xlarge

~ 250 GB en términos de uso de disco.

1 me gusta