Sidekiq lent + Postmaster utilisant plus de 95 % du CPU (32 cœurs) après la mise à niveau de la version PostgreSQL

Soutien Installation
1

J’ai effectué une mise à niveau aujourd’hui et il semble que la version de PostgreSQL ait été mise à jour dans le processus. Depuis, ce problème (ou un similaire) est revenu (l’ancien sujet est maintenant fermé) :

J’ai essayé ce qui avait résolu ce problème auparavant :

cd /var/discourse/
./launcher enter app
sudo -u postgres psql
\c discourse
VACUUM FULL VERBOSE;

ainsi que :

REINDEX DATABASE discourse;

Aucun succès :upside_down_face:

Le processus Postmaster utilise 95 % à 100 % des 32 cœurs CPU. Sidekiq progresse à environ 1 tâche par seconde.

J’ai également essayé de vider Redis et de reconstruire à nouveau. J’ai testé entre 12, 8 et 4 Sidekiqs et workers Unicorn.

Tout fonctionnait vraiment de manière solide et fluide avant la mise à niveau de PostgreSQL avec 12 workers et Sidekiqs Unicorn. J’exécute actuellement la version 2.5.0.beta5 et je pense que j’étais sous la version 2.5.0.beta2 avant la mise à jour.

:firstworldproblem:

2

Vous devez vérifier quelles sont les requêtes exactes que PostgreSQL exécute afin que nous puissions vous faire des suggestions.

Activer pg_stat_statements est très utile pour cela.

3

Merci @Falco - voici quelques statistiques ; faites-moi savoir si vous avez besoin de voir davantage de requêtes, car elles sont tronquées à la fin.

                                                                                                                                                     requête                                                                                                                                                     | temps_total | appels |   min   |  moyen  |    max    | pct_cpu
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------+-------+---------+---------+-----------+---------
SELECT "posts"."id", "posts"."user_id", "posts"."topic_id", "posts"."post_number", "posts"."raw", "posts"."cooked", "posts"."created_at", "posts"."updated_at", "posts"."reply_to_post_number", "posts"."reply_count", "posts"."quote_count", "posts"."deleted_at", "posts"."off_topic_count", "posts"."like | 4018799.92 |  2031 | 1458.34 | 1978.73 |   2690.51 |   38.90
SELECT COUNT(*) FROM "posts" WHERE ("posts"."deleted_at" IS NULL) AND (posts.post_type IN ($1,$2,$3)) AND (post_number > COALESCE(( SELECT last_read_post_number FROM topic_users tu WHERE tu.user_id = $4 AND tu.topic_id = $5 ),$6)) AND (reply_to_user_id = $7 OR exists( SELECT $8 from topic_users tu W | 3959915.35 |  2021 | 1467.53 | 1959.38 |   2753.25 |   38.33
SELECT COUNT(*) FROM "posts" INNER JOIN "topics" ON "topics"."id" = "posts"."topic_id" AND ("topics"."deleted_at" IS NULL) WHERE ("posts"."deleted_at" IS NULL) AND (topics.category_id = $1) AND (topics.visible = $2) AND (posts.deleted_at IS NULL) AND (posts.user_deleted = $3) AND (topics.id <> $4) A |  349840.54 |   148 |   55.14 | 2363.79 | 111182.89 |    3.39
SELECT "posts"."id" FROM "posts" WHERE ("posts"."deleted_at" IS NULL) AND "posts"."topic_id" = $1 AND (posts.user_id = $2 OR post_type IN ($3,$4,$5)) AND "posts"."post_number" = $6 LIMIT $7                                                                                                                |  237109.72 |   123 | 1488.37 | 1927.72 |   2387.02 |    2.30
SELECT "posts"."id", "posts"."user_id", "posts"."topic_id", "posts"."post_number", "posts"."raw", "posts"."cooked", "posts"."created_at", "posts"."updated_at", "posts"."reply_to_post_number", "posts"."reply_count", "posts"."quote_count", "posts"."deleted_at", "posts"."off_topic_count", "posts"."like |  223843.91 |   560 |  269.46 |  399.72 |    522.30 |    2.17
SELECT "posts"."id", "posts"."user_id", "posts"."topic_id", "posts"."post_number", "posts"."raw", "posts"."cooked", "posts"."created_at", "posts"."updated_at", "posts"."reply_to_post_number", "posts"."reply_count", "posts"."quote_count", "posts"."deleted_at", "posts"."off_topic_count", "posts"."like |  222330.42 |   113 | 1516.53 | 1967.53 |   2620.96 |    2.15
SELECT l.post_id, l.url, l.clicks, COALESCE(t.title, l.title) AS title, l.internal, l.reflection, l.domain FROM topic_links l LEFT JOIN topics t ON t.id = l.link_topic_id LEFT JOIN categories AS c ON c.id = t.category_id WHERE (t.deleted_at IS NULL) AND (COALESCE(t.archetype, $1) <> $2) AND (l.post_ |   77597.13 |   134 |  479.18 |  579.08 |    662.30 |    0.75
SELECT "posts"."id", EXTRACT($1 FROM CURRENT_TIMESTAMP - created_at)::INT AS jours_écoulés FROM "posts" WHERE ("posts"."deleted_at" IS NULL) AND "posts"."topic_id" = $2 AND (posts.user_id = $3 OR post_type IN ($4,$5,$6)) ORDER BY "posts"."sort_order" ASC                                                    |   57100.18 |   131 |  285.36 |  435.88 |    545.55 |    0.55
SELECT MAX("posts"."post_number") FROM "posts" WHERE ("posts"."deleted_at" IS NULL) AND "posts"."topic_id" = $1 AND (posts.user_id = $2 OR post_type IN ($3,$4,$5))                                                                                                                                          |   56887.08 |   131 |  285.22 |  434.25 |    534.65 |    0.55
SELECT COALESCE(SUM(rs.score), $1) AS score_spam_total, COUNT(DISTINCT rs.user_id) AS nombre_utilisateurs_spam FROM reviewables AS r INNER JOIN reviewable_scores AS rs ON rs.reviewable_id = r.id WHERE r.target_created_by_id = $2 AND rs.reviewable_score_type = $3 AND rs.status IN ($4, $5)                      |   16211.73 |   119 |   86.25 |  136.23 |    163.52 |    0.16
SELECT COUNT(*) FROM "topics" WHERE ("topics"."deleted_at" IS NULL) AND "topics"."category_id" = $1 AND "topics"."visible" = $2 AND (topics.id <> $3) AND (topics.created_at > $4)                                                                                                                           |   14922.91 |   152 |   61.68 |   98.18 |    154.13 |    0.14
SELECT COUNT(*) FROM "users" INNER JOIN "topic_allowed_users" ON "users"."id" = "topic_allowed_users"."user_id" WHERE "topic_allowed_users"."topic_id" = $1                                                                                                                                                  |   14358.68 |   186 |    9.17 |   77.20 |    109.96 |    0.14
SELECT ftl.url, COALESCE(ft.title, ftl.title) AS title, ftl.link_topic_id, ftl.reflection, ftl.internal, ftl.domain, MIN(ftl.user_id) AS user_id, SUM(clicks) AS clicks FROM topic_links AS ftl LEFT JOIN topics AS ft ON ftl.link_topic_id = ft.id LEFT JOIN categories AS c ON c.id = ft.category_id WHERE |   14029.70 |   186 |   12.82 |   75.43 |     94.01 |    0.14
SELECT COUNT(*) FROM ( SELECT $1 FROM notifications n LEFT JOIN topics t ON t.id = n.topic_id WHERE t.deleted_at IS NULL AND n.high_priority = $2 AND n.user_id = $3 AND n.id > $4 AND NOT read LIMIT $5 ) AS X                                                                                              |    3364.46 |  3790 |    0.02 |    0.89 |      3.21 |    0.03
SELECT * FROM ( SELECT n.id, n.read FROM notifications n LEFT JOIN topics t ON n.topic_id = t.id WHERE t.deleted_at IS NULL AND n.high_priority AND n.user_id = $1 AND NOT read ORDER BY n.id DESC LIMIT $2 ) AS x UNION ALL SELECT * FROM ( SELECT n.id, n.read FROM notifications n LEFT JOIN topics t ON  |     968.26 |  3654 |    0.06 |    0.26 |      1.04 |    0.01
SELECT tags.name AS nom_tag, SUM(stats.topic_count) AS somme_topic_count FROM category_tag_stats stats JOIN tags ON stats.tag_id = tags.id AND stats.topic_count > $1 WHERE stats.category_id IN ($2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14,$15,$16,$17,$18,$19,$20,$21,$22,$23,$24,$25,$26,$27,$28,$29,$30 |     953.21 |   173 |    3.57 |    5.51 |      7.52 |    0.01
SELECT a.attname FROM ( SELECT indrelid, indkey, generate_subscripts(indkey, $1) idx FROM pg_index WHERE indrelid = $2::regclass AND indisprimary ) i JOIN pg_attribute a ON a.attrelid = i.indrelid AND a.attnum = i.indkey[i.idx] ORDER BY i.idx                                                           |     657.76 |   163 |    0.01 |    4.04 |      8.66 |    0.01
SELECT $1 AS one FROM "push_subscriptions" WHERE "push_subscriptions"."user_id" = $2 LIMIT $3                                                                                                                                                                                                                |     381.25 |  2029 |    0.10 |    0.19 |      0.41 |    0.00
INSERT INTO "notifications" ("notification_type", "user_id", "data", "created_at", "updated_at", "topic_id", "post_number") VALUES ($1, $2, $3, $4, $5, $6, $7) RETURNING "id"                                                                                                                               |     339.56 |  2028 |    0.08 |    0.17 |      0.94 |    0.00
SELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT $2                                                                                                                                                                                                                                               |     313.51 |  7521 |    0.02 |    0.04 |      0.16 |    0.00
4

Juste un petit mot pour dire que je rencontre le même problème — et, je crains, sans aucune expertise en PostgreSQL. Si je dois chercher quelque part, j’aurais besoin d’instructions un peu plus détaillées. Désolé.

5

Peux-tu essayer un VACUUM VERBOSE ANALYZE ? Cela s’applique également à toi, @eboehnisch. Cette requête très simple suivante, qui prend en moyenne 2 secondes, est vraiment étrange :

Comme mentionné dans le sujet Mise à jour PostgreSQL 12, générer des statistiques est une bonne idée après la mise à jour.

6

J’ai essayé VACUUM VERBOSE ANALYZE;. Que dois-je rechercher dans les résultats ?

7

Super, merci ! Je pense donc que cela a résolu le problème des postmasters qui consommaient tout le processeur. C’est donc une grande amélioration.

Sidekiq reste lent malheureusement, mais c’est mieux qu’avant d’avoir exécuté VACUUM VERBOSE ANALYZE ;

8

Rien de spécial, sauf s’il s’agit d’un message d’erreur important.

Les performances devraient se rétablir maintenant.

OUAIP !

Il devrait maintenant pouvoir gagner la course et traiter la file d’attente à terme.

9

Cela a certes amélioré la situation, mais après un certain temps, trois processus postmaster ont de nouveau utilisé 100 % du CPU pendant plus d’une minute chacun.

10

Je dirais d’attendre un peu, car vous avez probablement une file d’attente à traiter suite à la période creuse. Vérifiez /sidekiq pour les statistiques.

11

:smiley: La vitesse a vraiment augmenté maintenant, ça a l’air d’être corrigé. Merci beaucoup pour l’aide @Falco ! Je vais le laisser tourner un moment et je posterai une mise à jour ici plus tard~

12

Essayez peut-être d’exécuter :

VACUUM FULL VERBOSE;

et (en supposant que le nom de votre base de données est ‘discourse’, ce qui est la valeur par défaut) :

REINDEX DATABASE discourse;

Cela pourrait être mieux qu’une réindexation normale, mais je ne l’ai pas testé : PostgreSQL 12 update

13

Les deux opérations listées ci-dessus génèrent des verrous qui peuvent être très problématiques sur un site en production. Je recommande celles listées à post-update-optional-tasks, car, en plus d’utiliser beaucoup de CPU, elles ne bloquent pas les opérations normales de la base de données.

14

Exécutez les deux. Le second signale une erreur, cependant :

discourse=# REINDEX SCHEMA CONCURRENTLY public;
ERROR:  could not create unique index "index_users_on_username_lower_ccnew"
DETAIL:  Key (username_lower)=(marks) is duplicated.

Je pense qu’il est temps de se pencher sur PostgreSQL pour trouver et supprimer l’enregistrement.

Le vacuum a fait l’affaire, plus ou moins, mais je constate toujours des pics toutes les quelques minutes, avec un à trois processus postmaster consommant du CPU pendant une ou deux minutes chacun. Je suppose donc qu’il y a plus.

15

Est-il possible de revenir à PostgreSQL 10 ?

16

Bien sûr, si vous avez une sauvegarde antérieure à la mise à niveau. Cependant, vous perdrez tout ce qui a été créé depuis cette sauvegarde.

Il est presque certainement préférable de résoudre ces problèmes, car Postgres12 est désormais la norme pour toute nouvelle installation.

17

Non, ce n’est pas possible… nous passons définitivement à PG12.

18

voir :

19

Ok, pour faire suite, tout semble toujours bon, postmaster s’est considérablement calmé et sidekiq tourne à nouveau très vite.

Pour résumer ce qui a fonctionné dans mon cas (avec le nom de base de données par défaut ‘discourse’) :

cd /var/discourse/
./launcher enter app
sudo -u postgres psql
\c discourse

Ensuite, depuis la console postgres, chacune des commandes ci-dessous a été exécutée. Chacune prend un peu de temps pour s’achever, selon la taille de la base de données, avec une utilisation intensive du processeur pour les deux premières :

VACUUM FULL VERBOSE;

REINDEX DATABASE discourse;

VACUUM VERBOSE ANALYZE;

Note : Je n’ai remarqué de différence qu’après l’exécution de VACUUM VERBOSE ANALYZE; comme recommandé par @Falco, donc les deux premières commandes n’étaient peut-être pas nécessaires. Cependant, les deux premières semblaient être essentielles pour résoudre ce problème par le passé sur l’ancienne version de Postgresql.

Si vous rencontrez une erreur du type ‘ERROR: deadlock detected’ lors de l’exécution de REINDEX DATABASE discourse; - essayez simplement de l’exécuter à nouveau jusqu’à ce que cela fonctionne. Cela m’est arrivé la dernière fois (avec l’ancienne version de Postgresql).

Il existe des recommandations pour exécuter un reindex concurrentiel plutôt que le reindex ci-dessus : PostgreSQL 12 update

Cependant, notez que @eboehnisch ci-dessus a rencontré une erreur avec le reindex concurrentiel, voir ci-dessus.

20

Nous avons vu cela se produire à plusieurs reprises lors de diverses migrations, et je pense que nous devrions l’ajouter au script de migration @Falco…

Je sais que cela ralentit considérablement les choses, mais cela en vaut la peine et réduira le nombre de demandes d’assistance.

Note : le mot VERBOSE signifie simplement qu’il affiche des informations pendant l’exécution… la chose importante manquante était le VACUUM ANALYZE. La réindexation sert principalement à libérer de l’espace.