Erro 502 ao abrir alguns perfis de usuário

volas · Maio 24, 2024, 9:01pm

O servidor está com problemas com o summary.json de alguns usuários aleatórios e retorna o código 502. Provavelmente começou após a última atualização, mas não tenho certeza.

Não estou familiarizado com a stack do Discourse e tenho dificuldade em encontrar os logs. Editei para ocultar o nome de usuário e o IP, o tempo pode variar, mas na maioria das vezes é a mesma solicitação de página de perfil repetida várias vezes.

Do aplicativo /var/log/nginx/error.log:

[error] 560#560: *416 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: _, request: "GET /u/user/summary.json HTTP/2.0", upstream: "http://127.0.0.1:3000/u/user/summary.json", host: "forum.taucetistation.org", referrer: "https://forum.taucetistation.org/u/user"

/shared/log/rails/production_errors.log está vazio, e /shared/log/rails/production.log contém apenas

Started GET "/u/user/summary.json" for *.*.*.* at 2024-05-24 20:26:56 +0000
Processing by UsersController#summary as JSON
  Parameters: {"username"=>"user"}

sem “Completed 200 OK” para solicitações semelhantes.

Parece não haver logs relacionados no unicorn (apenas erros de conexão com o redis na inicialização, mas parece bem-sucedido no final e não relacionado).

Mas há uma solicitação suspeita com um longo tempo de duração de /var/log/postgres/current:

2024-05-24 20:49:12.727 UTC [2919] discourse@discourse LOG: duration: 95288.368 ms execute <unnamed>: SELECT replies.user_id, COUNT(*) FROM "posts" INNER JOIN "topics" "topics_posts" ON "topics_posts"."deleted_at" IS NULL AND "topics_posts"."id" = "posts"."topic_id" JOIN posts replies ON posts.topic_id = replies.topic_id AND posts.reply_to_post_number = replies.post_number JOIN topics ON replies.topic_id = topics.id AND topics.archetype <> 'private_message' AND replies.post_type IN (1) WHERE "posts"."deleted_at" IS NULL AND (posts.post_type IN (1,4)) AND "topics"."deleted_at" IS NULL AND (topics.archetype <> 'private_message') AND "topics"."visible" = TRUE AND (topics.category_id IS NULL OR topics.category_id IN (SELECT id FROM categories WHERE NOT read_restricted OR id IN (4,8,20,46,55,60,62,67))) AND "posts"."user_id" = 5318 AND (replies.user_id <> posts.user_id) GROUP BY "replies"."user_id" ORDER BY COUNT(*) DESC LIMIT 6
2024-05-24 20:49:12.728 UTC [2919] discourse@discourse LOG: could not send data to client: Broken pipe
2024-05-24 20:49:12.729 UTC [2919] discourse@discourse FATAL: connection to client lost

volas · Maio 24, 2024, 9:17pm

Parece um problema para todos os perfis de usuário ativos. Às vezes, leva muito tempo, às vezes é rápido por causa de algum cache.

E às vezes simplesmente expira o tempo e lança um erro 502.

Estamos usando este droplet da DO apenas para o fórum.

Não é muito, mas foi o suficiente para nós no passado.

Arkshine · Maio 24, 2024, 9:29pm

Consigo ver summary.json que leva entre 20 e 30 segundos para carregar.

Também, estes erros no console:

E às vezes 502, de fato:

Olhando o modo de segurança, não parece que está relacionado a plugins/componentes de tema.

Vejo que você está usando o Cloudflare. Você pode tentar desativar otimizações?

volas · Maio 24, 2024, 9:35pm

Proxy CF desabilitado.

Mas não parece um problema de frontend, e sim uma requisição pesada de banco de dados no backend.

volas · Maio 24, 2024, 9:38pm

nossa lista de plugins

hooks:
  after_code:
    - exec:
        cd: $home/plugins
        cmd:
          - git clone https://github.com/discourse/docker_manager.git
          - git clone https://github.com/discourse/discourse-patreon.git
          - git clone https://github.com/discourse/discourse-solved.git
          - git clone https://github.com/discourse/discourse-staff-notes.git
          - git clone https://github.com/discourse/discourse-spoiler-alert.git
          - git clone https://github.com/discourse/discourse-bbcode.git
          - git clone https://github.com/discourse/discourse-signatures.git
          - git clone https://github.com/discourse/discourse-github
          - git clone https://github.com/discourse/discourse-whos-online.git
          - git clone https://github.com/discourse/discourse-chat-integration.git
          - git clone https://github.com/discourse/discourse-assign
          - git clone https://github.com/discourse/discourse-question-answer.git

Arkshine · Maio 24, 2024, 10:10pm

Não sou um especialista, mas o Discourse tende a exigir mais RAM atualmente, dependendo da sua configuração (pelo menos 2 GB). Você tem alguma swap configurada?

Você vê alguma informação relevante na rota /logs?

Em relação aos plugins, não vejo plugins com falha à primeira vista.

Espero que alguém consiga fornecer melhores insights aqui.

volas · Maio 25, 2024, 2:16am

Sim, 4gb de swap. E em /logs apenas alguns avisos como notices de depreciação ou algo sobre geolite.

2024-05-24 20:49:12.727 UTC [2919] discourse@discourse LOG:  duration: 95288.368 ms  execute <unnamed>: SELECT replies.user_id, COUNT(*) FROM "posts" INNER JOIN "topics" "topics_posts" ON "topics_posts"."deleted_at" IS NULL AND "topics_posts"."id" = "posts"."topic_id" JOIN posts replies ON posts.topic_id = replies.topic_id AND posts.reply_to_post_number = replies.post_number JOIN topics ON replies.topic_id = topics.id AND topics.archetype <> 'private_message' AND replies.post_type IN (1) WHERE "posts"."deleted_at" IS NULL AND (posts.post_type IN (1,4)) AND "topics"."deleted_at" IS NULL AND (topics.archetype <> 'private_message') AND "topics"."visible" = TRUE AND (topics.category_id IS NULL OR topics.category_id IN (SELECT id FROM categories WHERE NOT read_restricted OR id IN (4,8,20,46,55,60,62,67))) AND "posts"."user_id" = 5318 AND (replies.user_id <> posts.user_id) GROUP BY "replies"."user_id" ORDER BY COUNT(*) DESC LIMIT 6

Pelo que entendi, é uma consulta para “Mais Respondidos”, e foi alterada recentemente em PERF: Improve performance of `most_replied_to_users` by janzenisaac · Pull Request #26373 · discourse/discourse · GitHub, então talvez esse patch nos afete.

Eu fiz o EXPLAIN ANALYZE caso ajude:

 Limit  (cost=2552.39..2552.39 rows=1 width=12) (actual time=94412.810..94412.824 rows=6 loops=1)
   ->  Sort  (cost=2552.39..2552.39 rows=1 width=12) (actual time=94412.804..94412.808 rows=6 loops=1)
         Sort Key: (count(*)) DESC
         Sort Method: top-N heapsort  Memory: 25kB
         ->  GroupAggregate  (cost=2552.36..2552.38 rows=1 width=12) (actual time=94412.361..94412.743 rows=160 loops=1)
               Group Key: replies.user_id
               ->  Sort  (cost=2552.36..2552.36 rows=1 width=4) (actual time=94412.323..94412.405 rows=729 loops=1)
                     Sort Key: replies.user_id
                     Sort Method: quicksort  Memory: 59kB
                     ->  Nested Loop  (cost=12.24..2552.35 rows=1 width=4) (actual time=0.279..94409.497 rows=729 loops=1)
                           Join Filter: (topics_posts.id = topics.id)
                           ->  Nested Loop  (cost=1.13..2507.59 rows=4 width=16) (actual time=0.164..94354.548 rows=746 loops=1)
                                 Join Filter: ((replies.user_id <> posts.user_id) AND (posts.reply_to_post_number = replies.post_number))
                                 Rows Removed by Join Filter: 15395502
                                 ->  Nested Loop  (cost=0.71..1419.07 rows=131 width=16) (actual time=0.113..240.052 rows=1399 loops=1)
                                       ->  Index Scan using idx_posts_user_id_deleted_at on posts  (cost=0.42..561.22 rows=135 width=12) (actual time=0.077..59.712 rows=1408 loops=1)
                                             Index Cond: (user_id = 5318)
                                             Filter: (post_type = ANY ('{1,4}'::integer[]))
                                       ->  Index Only Scan using index_topics_on_id_and_deleted_at on topics topics_posts  (cost=0.29..6.35 rows=1 width=4) (actual time=0.123..0.123 rows=1 loops=1408)
                                             Index Cond: ((id = posts.topic_id) AND (deleted_at IS NULL))
                                             Heap Fetches: 1394
                                 ->  Index Scan using index_posts_on_topic_id_and_reply_to_post_number on posts replies  (cost=0.42..7.77 rows=36 width=12) (actual time=0.098..65.083 rows=11005 loops=1399)
                                       Index Cond: (topic_id = topics_posts.id)
                                       Filter: (post_type = 1)
                                       Rows Removed by Filter: 4
                           ->  Index Scan using topics_pkey on topics  (cost=11.11..11.18 rows=1 width=4) (actual time=0.065..0.065 rows=1 loops=746)
                                 Index Cond: (id = replies.topic_id)
                                 Filter: ((deleted_at IS NULL) AND visible AND ((archetype)::text <> 'private_message'::text) AND ((archetype)::text <> 'private_message'::text) AND ((category_id IS NULL) OR (hashed SubPlan 1)))
                                 Rows Removed by Filter: 0
                                 SubPlan 1
                                   ->  Seq Scan on categories  (cost=0.00..10.74 rows=31 width=4) (actual time=0.012..0.066 rows=37 loops=1)
                                         Filter: ((NOT read_restricted) OR (id = ANY ('{4,8,20,46,55,60,62,67}'::integer[])))
 Planning Time: 3.895 ms
 Execution Time: 94416.415 ms
(34 rows)

Ed_S · Maio 25, 2024, 6:39am

Pode ser útil ter
vmstat 5
rodando no servidor (em uma conexão ssh) enquanto você faz isso, para ver o que pode estar acontecendo com a paginação. (top pode ser usado, mas é muito menos útil aqui)

pfaffman · Maio 25, 2024, 7:47am

Quanta RAM você tem? Qual o tamanho do seu banco de dados? É provável que você só precise de mais RAM.

volas · Maio 25, 2024, 3:24pm

Parece que o postgresql faz algumas otimizações/cache, então às vezes não leva muito tempo, então preciso procurar novos usuários para testar as requisições.

  procs -----------memory---------- ---swap-- -----io---- -system-- -------cpu------
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st gu
 0  0 287852  75220  17660 587788    6    8  4685   244  496    9  6  3 88  3  0  0
 0  0 287852  74048  17668 587836    0    0     0    18  209  465  1  2 96  0  0  0
 0  1 287852  82496  13452 582360    2   13 39937    38 4186 7339  8 16 14 62  0  0
 0  1 288620  77924   1020 601604    2  138 64178   166 5352 8263  9 22  0 68  0  0
 1  0 290156  80472    968 599840    1  313 37518    42 3612 5160 22 37  0 41  0  0
 1  0 289900  67588   3720 609896    4   29 13800    75 2062 2635 43 49  0  8  0  0
 1  0 291180  76816   2368 606924    0  245 30042    27 3414 5477 34 39  0 27  0  0
 2  0 292716  67184   1696 622528    4  318 44820    18 4152 6198 23 30  0 47  0  0
 1  0 293228  75100   3008 614144    0  132 10030     4 1803 1986 39 49  0 11  0  0
 1  0 293484  76020   2860 613444    1   34  3331    10 1197  767 44 54  0  2  0  0
 1  0 294508  66296   2868 623376    2  218  4994    24 1389 1206 40 54  0  6  0  0
 1  0 295020  75432   2892 614384    0  120  1304    58 1161  728 43 55  0  2  0  0
 1  0 295020  73084   2904 615984    0    0   314    11 1060  448 43 57  0  0  0  0
 1  0 295020  68864   3148 619388    6   33  8209    63  663 1190 10 13 74  3  0  0

      Name      |  Owner   | Encoding | Locale Provider |   Collate   |    Ctype    | ICU Locale | ICU Rules |   Access privileges    |  Size   | Tablespace | Description
----------------+----------+----------+-----------------+-------------+-------------+------------+-----------+------------------------+---------+------------+-------------
 discourse      | postgres | UTF8     | libc            | ru_RU.UTF-8 | ru_RU.UTF-8 |            |           | =Tc/postgres          +| 9493 MB | pg_default |

2gb de ram + 4gb de swap, estamos usando este droplet (CPU legado) da DigitalOcean

volas · Maio 25, 2024, 4:29pm

Quero tentar testar com as alterações revertidas de PERF: Improve performance of `most_replied_to_users` (#26373) · discourse/discourse@db10dd5 · GitHub, mas, apesar de eu ter editado app/models/user_summary.rb enquanto estava no container do discourse, ainda vejo que a página de perfil faz essa solicitação com três JOINs.

Preciso limpar o cache em algum lugar? Ou existe uma maneira melhor de fazer isso.

ATUALIZAÇÃO: Reiniciar o container ajudou, e parece que está funcionando melhor agora após a reversão! As páginas de perfil carregam mais rápido e sem erros 502.

Arkshine · Maio 25, 2024, 4:59pm

Confirmo; está incrivelmente rápido agora e não vejo nenhum erro.

Ed_S · Maio 26, 2024, 6:05pm

Obrigado pela saída do vmstat. Para mim, isso diz que a memória não está supercomprometida - o Linux não está trocando - mas o banco de dados não conseguiu alocar RAM suficiente - ele está fazendo muita E/S de disco.

Então, acho que este seria um caso de mais RAM necessária, e adicionar swap não ajudaria muito.

Então você também reverteu a alteração e descobriu que o desempenho voltou ao normal?

Arkshine · Maio 26, 2024, 6:41pm

Não eu, Alexander, em sua postagem acima. Eu queria confirmar, já que estava testando antes no fórum dele. E sim, o problema de desempenho desapareceu com a reversão desse commit.

volas · Maio 26, 2024, 7:16pm

Talvez também seja um problema de CPU. Mas, exceto quando o Discourse estava executando alguns trabalhos de manutenção, quase nunca tivemos problemas de desempenho antes. Apenas agora com a página de perfil, então eu estava pensando na última atualização.

Mas devo dizer que antes de tentar reverter, também ajustei o app.yml:

Por algum motivo, tínhamos db_shared_buffers: \"128MB\", quatro vezes menos do que o recomendado, provavelmente algum legado da época em que configurei o fórum pela primeira vez. Comentei isso, para que o Discourse possa configurá-lo sozinho com base na RAM do host.
Também descomentei db_work_mem: \"40MB\"

Mas fiz uma reconstrução adequada e testei isso primeiro, e não nos ajudou. Somente após a reversão ficou melhor.

Acabei de testar novamente sem reverter, por via das dúvidas, e posso ver 502 nos perfis novamente.

Se necessário, posso fazer mais testes com/sem o patch.

Ed_S · Maio 26, 2024, 7:23pm

Bom teste minucioso!

Talvez, mas olhando o tempo gasto em Wait, acho que é principalmente sobre I/O. Assim que o gargalo de I/O for resolvido, o vmstat pode mostrar se a CPU está no máximo.

pfaffman · Maio 26, 2024, 11:12pm

Não vai. Você pode executar o discourse-setup e ele fará isso (você pode pressionar Control+C após a primeira mensagem) ou inserir o número correto você mesmo.

Geralmente é útil aumentar isso, mas apenas se você tiver RAM suficiente.

Parece que seu problema original pode ser um problema com a consulta na origem, mas você definitivamente quer definir db_work_mem. Comentá-lo não é uma solução (pelo que sei).

Ed_S · Maio 27, 2024, 5:16am

A conclusão aqui, eu acho, é que o pull request aceito, que tinha como objetivo tornar as coisas mais rápidas, na verdade as tornou mais lentas, ou até mesmo as quebrou, em sites com RAM mínima?

Podemos reverter esse pull request até que isso seja compreendido?

Podemos mudar a categoria deste tópico para bug?

volas · Maio 27, 2024, 6:09am

Obrigado por notar isso, fui enganado pelo comentário então. Parece que definir isso para 512MB manualmente ajudou um pouco, mas o desempenho nas páginas de perfil ainda não é bom o suficiente e às vezes leva meio minuto para carregar.

Tópico		Respostas	Visualizações
Discourse installation has been getting slower and slower and slower Installation server-resources	37	1620	15 de Maio de 2023
Users reporting lots of 502 errors when attempting to post due to "max consecutive replies" check Bug	37	2850	18 de Janeiro de 2019
Slow Profile Loads with 100GB+ database Feature	43	2918	1 de Janeiro de 2021
Long loading times for user summary page with slow database Installation unsupported-install	19	1789	13 de Julho de 2023
Bursts of 502 Service Unavailable, pointers to debug Installation	16	1597	8 de Junho de 2024

Erro 502 ao abrir alguns perfis de usuário

Tópicos relacionados