Sidekiq lento y Postmaster usando más del 95% de CPU (32 núcleos) después de la actualización de la versión de Postgresql

Soporte Instalación
1

Así que hoy realicé una actualización y parece que la versión de PostgreSQL se actualizó en el proceso. Desde entonces, este problema (o uno similar) ha vuelto a aparecer (el tema anterior ya está cerrado):

Intenté lo que solucionó este problema antes:

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

y también:

REINDEX DATABASE discourse;

Sin suerte :upside_down_face:

Postmaster está utilizando el 95%-100% de los 32 núcleos de CPU. Sidekiq avanza a aproximadamente 1 trabajo por segundo.

También intenté limpiar Redis y volver a construir. He probado entre 12, 8 y 4 unicorn sidekiqs y unicorn workers.

Antes de la actualización de PostgreSQL funcionaba muy sólido y fluido con 12 unicorn workers y sidekiqs. Actualmente estoy ejecutando la versión 2.5.0.beta5 y creo que antes de la actualización estaba ejecutando la 2.5.0.beta2.

:firstworldproblem:

2

Necesitas verificar exactamente qué consultas está ejecutando PostgreSQL para que podamos ofrecerte sugerencias.

Activar pg_stat_statements es muy útil para ello.

3

Gracias @Falco: aquí tienes algunas estadísticas. Avísame si necesitas ver más consultas, ya que se cortan al final.

                                                                                                                                                     query                                                                                                                                                     | total_time | llamadas |   min   |  media   |    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 days_ago 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 total_spam_score, COUNT(DISTINCT rs.user_id) AS spam_user_count 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 tag_name, SUM(stats.topic_count) AS sum_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

Solo una nota rápida: tengo el mismo problema y, temo, no tengo experiencia en PostgreSQL. Si debo buscar algo, necesito instrucciones un poco más detalladas. Lo siento.

5

¿Podrías probar con un vacuum verbose analyze? Esto también aplica para ti, @eboehnisch. Es realmente extraño que la siguiente consulta muy simple promedie 2 segundos:

Como se mencionó en el tema Actualización de PostgreSQL 12, generar estadísticas es una buena idea después de la actualización.

6

¿Has probado VACUUM VERBOSE ANALYZE;? ¿Qué debo buscar en los resultados?

7

¡Genial, gracias! Creo que esto ha resuelto el problema de que los postmasters se volvieran locos usando toda la CPU. Así que es una gran mejora.

Sidekiq sigue siendo lento, lamentablemente, pero es mejor que antes de ejecutar VACUUM VERBOSE ANALYZE;

8

Nada especial, a menos que sea un mensaje de error importante.

El rendimiento debería recuperarse ahora.

¡YAY!

Ahora debería poder ganar la carrera y procesar la cola eventualmente.

9

Esto definitivamente mejoró la situación, pero después de un tiempo, nuevamente tres procesos postmaster utilizan el 100% de la CPU durante más de un minuto cada uno.

10

Diría que esperes un poco, porque probablemente tengas una cola de trabajos pendientes acumulados durante el periodo de baja actividad. Revisa /sidekiq para ver las estadísticas.

11

:smiley: ¡La velocidad ha mejorado mucho ahora, parece que está arreglado! Muchas gracias por la ayuda, @Falco. Lo dejaré funcionando un rato y publicaré una actualización aquí más tarde~

12

Quizás intentes ejecutar:

VACUUM FULL VERBOSE;

y (asumiendo que el nombre de tu base de datos es ‘discourse’, que es el predeterminado):

REINDEX DATABASE discourse;

Esto podría ser mejor que un reindexado normal, pero no lo he probado: PostgreSQL 12 update

13

Ambas operaciones listadas arriba generan bloqueos que pueden ser realmente difíciles en un sitio en vivo. Recomiendo las listadas en post-update-optional-tasks porque, aparte de consumir mucha CPU, no bloquean las operaciones normales de la base de datos.

14

Ejecuta ambos. Sin embargo, el segundo reporta un error:

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

Supongo que es hora de adentrarme en PostgreSQL para encontrar y eliminar el registro.

El vaciado funcionó, más o menos, pero aún tengo picos cada pocos minutos con uno a tres procesos postmaster consumiendo CPU durante uno o dos minutos cada uno. Así que supongo que hay más.

15

¿Es posible volver a PostgreSQL 10?

16

Claro, si tienes una copia de seguridad anterior a la actualización. Sin embargo, perderás todo lo creado desde que se realizó esa copia.

Casi con total seguridad es mejor resolver estos problemas, ya que Postgres12 es ahora el estándar para cualquier instalación nueva.

17

No, eso no es posible… nos estamos mudando permanentemente a PG12.

18

ver:

19

Ok, para dar seguimiento, todo sigue bien: Postmaster se ha calmado drásticamente y Sidekiq está funcionando muy rápido de nuevo.

Para resumir lo que funcionó en mi caso (con el nombre de base de datos predeterminado ‘discourse’):

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

Luego, desde la consola de PostgreSQL, se ejecutó cada uno de los siguientes comandos. Cada uno tarda un poco en completarse, dependiendo del tamaño de la base de datos; los dos primeros también generan un uso intenso de la CPU:

VACUUM FULL VERBOSE;

REINDEX DATABASE discourse;

VACUUM VERBOSE ANALYZE;

Nota: No noté ninguna diferencia hasta que se ejecutó VACUUM VERBOSE ANALYZE; según la recomendación de @Falco, por lo que los dos primeros podrían no haber sido necesarios. Sin embargo, los dos primeros parecían ser clave para solucionar este problema en el pasado en la versión anterior de PostgreSQL.

Si obtienes un error como ‘ERROR: deadlock detected’ durante REINDEX DATABASE discourse; simplemente vuelve a ejecutarlo hasta que funcione. Esto me sucedió la última vez (en la versión anterior de PostgreSQL).

Hay algunas recomendaciones para ejecutar un reindexado concurrente en lugar del reindexado anterior: PostgreSQL 12 update

Sin embargo, ten en cuenta que @eboehnisch obtuvo un error con el reindexado concurrente, ver arriba.

20

Hemos visto esto ocurrir lo suficiente en varias migraciones como para sentir que deberíamos agregarlo al script de migración @Falco…

Sé que ralentiza las cosas bastante, pero vale la pena; reducirá el soporte.

Nota… la palabra VERBOSE allí simplemente significa que muestra información mientras se ejecuta… lo más importante que faltaba era el VACUUM ANALYZE; la reindexación se trata principalmente de recuperar espacio.