Carregamento lento em private-message-topic-tracking-state.json

Contribuir Bug
1

Desde a versão 2.8.0.beta5, o carregamento da caixa de entrada de mensagens privadas em grupo leva mais de 4 segundos, sendo que a maior parte desse tempo (2 a 3 segundos) é gasta na enorme consulta SQL do arquivo private-message-topic-tracking-state.json.

Temos cerca de 800 mil tópicos, 3,8 milhões de usuários e provavelmente um grande grafo de mensagens privadas não lidas vinculadas aos usuários, mas não estou vendo nada de relevante na análise da consulta (provavelmente sou apenas ruim em interpretá-la).

Isso funcionava bem antes da beta5; agora, as caixas de entrada de mensagens privadas tornaram-se muito difíceis e irritantes de acompanhar.

1 curtida
2

Hmm, aqui no Meta para nós isso está em média a 200 ms.

Dito isso, é bastante suspeito que acessar as mensagens no seu perfil agora gere 3 requisições distintas e que a que você mencionou esteja retornando um JSON de 92 kB com 900 objetos para mim :scream:

2 curtidas
5

Parece que isso também invalida o estado do miniprofiler no meio do caminho, então nem consigo pegar a consulta SQL para EXPLAIN-la corretamente.

2 curtidas
6

Sim, essa transição de rota não está agindo normalmente.

A propósito, extraí um plano aqui: ieWq | explain.depesz.com

3 curtidas
9

Essa correção deve reduzir para cerca de 13ms.

Observe que quanto mais mensagens não lidas você tiver, mais custosa será a consulta.

@sam Outra coisa que preciso corrigir é que ao marcar como lido, não atualizamos as otimizações de first_unread_at que temos para tópicos normais e de mensagens privadas.

4 curtidas
10

1,73 segundos após aplicar seletivamente essa alteração e reiniciar o unicorn, mas o tempo de não lido para mim e meus grupos provavelmente está bem atrás (tenho apenas 59 novos e 4 não lidos visíveis para esta caixa de entrada — essa rota é por usuário? embora, mesmo para ‘todas as mensagens’, eu tenha 61 novos e 7 não lidos)

1 curtida
11

O tempo de não lido correlaciona-se com as mensagens não lidas nas suas caixas de entrada?

1 curtida
12 
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 linhas)

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 linha)

Curiosamente, o intervalo nem mesmo é tão alto, então alguma outra condição está sendo lenta (embora, misteriosamente, ela tenha acelerado para 700ms agora após descartar algumas mensagens não lidas, o que é suportável; não tenho certeza de qual era meu intervalo de first_unread_pm_at antes, talvez algumas semanas?).

Existe alguma maneira de eu obter a consulta do miniprofiler após ele se atualizar, removendo todas as solicitações antigas na página de mensagens, para que eu possa executar um EXPLAIN?

13

Isso é realmente bastante estranho, mas não consigo reproduzir isso no ambiente de desenvolvimento. Vou dedicar algum tempo a investigar isso na próxima semana.

1 curtida
14

Corrigido em

1 curtida
15

Obrigado! Vou tentar lembrar de verificar novamente na próxima janela de reconstrução/reinício.

1 curtida
16

Tenho um plano de consulta / resultado de EXPLAIN ANALYZE (volte a 1,3s :confused:): CvUX | explain.depesz.com

Após um reindex index concurrently index_topics_on_timestamps_private;, ficou um pouco mais rápido (768ms), então isso pode ser apenas um artefato de muitas DMs anteriores (o bot de narrativa, antes da limpeza, estava poluindo muito a tabela de DMs!)… embora ainda seja lento nesse mesmo índice.

17

Você consegue executar Topic.where(archetype: Archetype.private_message).count para mim no console do Rails?

A propósito, a consulta agora é feita de forma assíncrona, então não irá bloquear o carregamento da página de mensagens ou de uma mensagem privada.

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

Poderia ser muito pior, nós eliminamos todos os tópicos restantes do bot de narrativa recentemente. :sweat_smile Ainda é mais do que eu esperava!

Ah, eu me perguntava por que essa consulta só aparecia no miniprofiler depois de um tempo. Isso é ótimo!

19

Atualizamos recentemente novamente para incorporar esse recurso FEATURE: New and Unread messages for user personal messages. by tgxworld · Pull Request #13603 · discourse/discourse · GitHub (ou seja, atualmente na versão 2.8.0beta6)

Parece que a obtenção de todas as mensagens privadas do usuário, que eventualmente leva a algum lugar FEATURE: New and Unread messages for user personal messages. by tgxworld · Pull Request #13603 · discourse/discourse · GitHub, resulta em uma 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;

Basicamente, isso trava nosso servidor RDS. Acredito que um membro da nossa equipe sugeriu que filtrássemos os dados com os índices que temos antes de fazer os joins. Essa consulta executa em < 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;

Para referência, topics > 10M de linhas, topic_users > 50M de linhas.

É possível reestruturar a consulta para resolver esses problemas de alguma forma?

Edição:

Só para esclarecer, quando inspecionamos nossas consultas de execução mais longa > 2 minutos ou até 5 minutos. Essas são as únicas consultas que aparecem. Com a mudança mais recente, nossa CPU do Postgres está constantemente em 99%. Quando encerro essas consultas, vemos que o uso da CPU volta ao normal.

3 curtidas
20

@tgxworld desculpe te marcar diretamente, mas como você foi o autor, gostaria de saber se você tem alguma sugestão ou feedback.

1 curtida
21

Se bem me lembro, @sam sempre descreveu isso como um recurso arriscado e perigoso. Grandes regressões aqui não me surpreenderiam.

22

Encontramos este tópico de bug após postar isso: Slow loading on private-message-topic-tracking-state.json - #9 by tgxworld

Parece que pode haver um commit após o marcado como v2.8.0beta6 que parece resolver parte desse problema de desempenho. Vamos tentar reconstruir apontando para essa referência específica de commit e ver se isso alivia algo.

2 curtidas
23

Qual é o tipo atual da sua instância RDS e o tamanho total do banco de dados?

1 curtida
24

db.m5.2xlarge

~ 250 GB em termos de uso de disco.

1 curtida