Erreur 502 lors de l'ouverture de certains profils utilisateur

Bug
1

Le serveur rencontre des problèmes avec summary.json de certains utilisateurs aléatoires et renvoie un code 502. Cela a probablement commencé après la dernière mise à jour, mais je ne suis pas sûr.

Je ne suis pas familier avec la pile Discourse et j’ai du mal à trouver les logs. J’ai édité pour masquer le nom d’utilisateur et l’IP, l’heure peut varier mais il s’agit principalement de la même requête de page de profil répétée plusieurs fois.

Depuis l’application /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 vide, et /shared/log/rails/production.log ne contient que

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

sans “Completed 200 OK” pour des requêtes similaires.

Il ne semble y avoir aucun log lié dans unicorn (juste des erreurs de connexion avec redis au démarrage, mais cela semble réussir à la fin et n’est pas lié).

Mais il y a une requête suspecte avec une longue durée depuis /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
1 « J'aime »
2

Il semble que ce soit un problème pour chaque profil utilisateur actif. Parfois, cela prend beaucoup de temps, parfois c’est rapide grâce à un cache.

Et parfois, c’est juste hors délai et renvoie une erreur 502.

Nous utilisons ce serveur déployé depuis DO juste pour le forum.
Снимок экрана от 2024-05-25 00-12-28

Pas grand-chose, mais c’était suffisant pour nous par le passé.

3

Je peux voir summary.json qui prend entre 20 et 30 secondes à charger.

Aussi, ces erreurs dans la console :

image
image1342×190 14.1 KB

Et parfois 502, en effet :

image
image799×111 5.06 KB

En regardant le mode sans échec, il ne semble pas que cela soit lié aux plugins/composants de thème.

Je vois que vous êtes derrière Cloudflare. Pouvez-vous essayer de désactiver les optimisations ?

1 « J'aime »
4

Proxy CF désactivé.

Mais cela ne ressemble pas à un problème de frontend, mais plutôt à une requête DB lourde côté backend.

1 « J'aime »
5

notre liste 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
6

Je ne suis pas un expert, mais Discourse a tendance à nécessiter plus de RAM de nos jours, selon votre configuration (au moins 2 Go). Avez-vous configuré un espace d’échange (swap) ?

Voyez-vous des informations pertinentes dans la section /logs ?

En ce qui concerne les plugins, je ne vois pas vraiment de plugins défectueux à première vue. :thinking:

J’espère que quelqu’un pourra apporter de meilleurs éclaircissements ici.

7

Oui, 4 Go de swap. Et dans /logs, seulement quelques avertissements comme des notices de dépréciation ou quelque chose concernant 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

D’après ce que je comprends, il s’agit d’une requête pour “Most Replied To” (le plus souvent répondu), et elle a été récemment modifiée dans PERF: Improve performance of `most_replied_to_users` by janzenisaac · Pull Request #26373 · discourse/discourse · GitHub, donc peut-être que ce correctif nous affecte.

J’ai exécuté EXPLAIN ANALYZE si cela peut aider :

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

Il pourrait être utile d’avoir
vmstat 5
en cours d’exécution sur le serveur (dans une connexion ssh) pendant que vous faites cela, pour voir ce qui pourrait se passer avec la pagination. (top peut être utilisé mais est beaucoup moins utile ici)

3 « J'aime »
9

Combien de RAM possédez-vous ? Quelle est la taille de votre base de données ? Il est probable que vous ayez simplement besoin de plus de RAM.

2 « J'aime »
10

Il semble que PostgreSQL effectue des optimisations/un cache, donc cela ne prend pas trop de temps, j’ai donc besoin de trouver de nouveaux utilisateurs pour tester les requêtes.

  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

  Nom    |  Propriétaire | Encodage | Fournisseur de locale |  Collation   |    Ctype     | Locale ICU | Règles ICU |   Privilèges d'accès    |  Taille   | Tablespace | Description 
-----------+----------+----------+-----------------+-------------+-------------+------------+-----------+------------------------+---------+------------+-------------
 discourse | postgres | UTF8     | libc            | ru_RU.UTF-8 | ru_RU.UTF-8 |            |           | =Tc/postgres          +| 9493 Mo | pg_default |

2 Go de RAM + 4 Go de swap, nous utilisons ce droplet (CPU hérité) de DigitalOcean

11

Je veux essayer de tester avec les modifications annulées de PERF: Improve performance of `most_replied_to_users` (#26373) · discourse/discourse@db10dd5 · GitHub, mais malgré la modification de app/models/user_summary.rb dans le conteneur discourse, je vois toujours que la page de profil effectue cette requête avec trois JOIN.

Dois-je vider le cache quelque part ? Ou y a-t-il une meilleure façon de le faire.

MISE À JOUR : Le redémarrage du conteneur a aidé, et il semble que cela fonctionne mieux maintenant après l’annulation ! Les pages de profil se chargent plus rapidement et sans erreurs 502.

3 « J'aime »
12

Je confirme ; c’est incroyablement rapide maintenant, et je ne vois aucune erreur.

2 « J'aime »
13

Merci pour la sortie vmstat. Pour moi, cela indique que la mémoire n’est pas en surallocation - Linux ne swappe pas - mais que la base de données n’a pas pu allouer suffisamment de RAM - elle effectue beaucoup d’E/S disque.

Je pense donc qu’il faudrait plus de RAM, et l’ajout de swap n’aiderait pas beaucoup.

Donc, vous aussi, vous avez annulé le changement et constaté que les performances sont revenues à la normale ?

1 « J'aime »
14

Pas moi, Alexander, dans son message ci-dessus. Je voulais le confirmer, car j’ai testé plus tôt sur son forum. Et oui, le problème de performance a disparu en annulant ce commit.

2 « J'aime »
15

Peut-être aussi un problème de CPU. Mais à part lorsque Discourse exécutait des tâches de maintenance, nous n’avons presque jamais eu de problèmes de performance auparavant. Seulement maintenant avec la page de profil, donc je pensais à la dernière mise à jour.

Mais je dois dire qu’avant d’essayer de revenir en arrière, j’ai aussi modifié app.yml :

  1. Pour une raison quelconque, nous avions db_shared_buffers: \"128MB\", quatre fois moins que recommandé, probablement un vestige de l’époque où j’installais le forum pour la première fois. J’ai commenté cela, donc Discourse peut le configurer lui-même en fonction de la RAM de l’hôte.
  2. J’ai également décommenté db_work_mem: \"40MB\"

Mais j’ai fait une reconstruction appropriée et testé cela d’abord, et cela ne nous a pas aidés. Ce n’est qu’après être revenu en arrière que cela s’est amélioré.

Je viens de tester à nouveau sans revenir en arrière juste au cas où, et je vois à nouveau 502 sur les profils.

Si nécessaire, je peux faire plus de tests avec/sans patch.

1 « J'aime »
16

Bon test approfondi !

Peut-être, mais à en juger par le temps passé en attente, je pense que c’est surtout lié aux E/S. Une fois le goulot d’étranglement des E/S résolu, vmstat pourra montrer si le processeur est saturé.

2 « J'aime »
17

Il ne le fera pas. Vous pouvez exécuter discourse-setup et il le fera (vous pouvez faire Ctrl+C après le premier message) ou entrer le bon nombre vous-même.

Il est souvent utile d’augmenter cela, mais seulement si vous avez suffisamment de RAM.

Il semble que votre problème initial pourrait être un problème avec la requête dans la source, mais vous voulez absolument définir db_work_mem. Le mettre en commentaire n’est pas une solution (d’après ce que je sais).

2 « J'aime »
18

La conclusion ici, je pense, est que la pull request acceptée, qui visait à accélérer les choses, a en fait ralenti les choses, voire les a cassées, sur les sites avec une RAM minimale ?

Pouvons-nous faire annuler cette pull request jusqu’à ce que cela soit compris ?

Pouvons-nous changer la catégorie de ce sujet en bug ?

1 « J'aime »
19

Merci d’avoir remarqué cela, j’ai été induit en erreur par le commentaire alors. J’ai l’impression que régler cela manuellement à 512 Mo a un peu aidé, mais les performances sur les pages de profil ne sont toujours pas assez bonnes et prennent parfois une demi-minute à se charger.

1 « J'aime »