Sidekiq lento + Postmaster usando 95%+ de CPU (32 núcleos) após atualização da versão do PostgreSQL

Suporte Instalação
1

Então, fiz uma atualização hoje e parece que a versão do PostgreSQL foi atualizada no processo. Desde então, esse problema (ou um similar) voltou (o tópico antigo está fechado agora):

Tentei o que resolveu esse problema antes:

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

e também:

REINDEX DATABASE discourse;

Sem sorte :upside_down_face:

O Postmaster está usando de 95% a 100% dos 32 núcleos de CPU. O Sidekiq está processando cerca de 1 job por segundo.

Também tentei limpar o Redis e reconstruir novamente. Testei entre 12, 8 e 4 workers Sidekiq do Unicorn e workers do Unicorn.

Estava funcionando de forma muito sólida e suave antes da atualização do PostgreSQL com 12 workers do Unicorn e Sidekiq. Atualmente estou rodando a versão 2.5.0.beta5 e acredito que estava na 2.5.0.beta2 antes da atualização.

:firstworldproblem:

2

Você precisa verificar quais são as consultas exatas que o PostgreSQL está executando para que possamos fazer sugestões.

Habilitar o pg_stat_statements é realmente útil para isso.

3

Obrigado @Falco - aqui estão algumas estatísticas. Avise-me se precisar ver mais consultas, pois elas são cortadas no final.

                                                                                                                                                     query                                                                                                                                                     | total_time | calls |   min   |  mean   |    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

Só uma observação rápida: tenho o mesmo problema — e, receio, não tenho experiência com PostgreSQL. Se for preciso procurar algo, preciso de instruções um pouco mais detalhadas. Desculpe.

5

Você poderia tentar um vacuum verbose analyze? Isso também se aplica a você, @eboehnisch. A seguinte consulta muito simples, que leva em média 2s, é realmente estranha:

Como mencionado no tópico Atualização do PostgreSQL 12, gerar estatísticas é uma boa ideia após a atualização.

6

Tentei VACUUM VERBOSE ANALYZE;. O que devo procurar nos resultados?

7

Ótimo, obrigado! Acredito que isso resolveu o problema dos postmasters consumindo toda a CPU. Então, é uma grande melhoria.

O Sidekiq ainda está lento, infelizmente, mas melhor do que antes de executar o VACUUM VERBOSE ANALYZE;

8

Nada de especial, a menos que seja uma mensagem de erro grave.

O desempenho deve se recuperar agora.

YAY!

Agora, ele deve ser capaz de vencer a corrida e processar a fila eventualmente.

9

Isso definitivamente melhorou a situação, mas depois de um tempo, novamente três processos postmaster passaram a usar 100% da CPU por mais de um minuto cada.

10

Eu diria para esperar um pouco, porque você provavelmente tem uma fila para processar do período de baixa. Verifique /sidekiq para estatísticas.

11

:smiley: A velocidade realmente acelerou agora, parece que foi corrigido. Muito obrigado pela ajuda @Falco! Vou deixá-lo rodando por um tempo e postarei uma atualização aqui mais tarde~

12

Talvez tente executar:

VACUUM FULL VERBOSE;

e (assumindo que o nome do seu banco de dados seja ‘discourse’, que é o padrão):

REINDEX DATABASE discourse;

Isso pode ser melhor do que o reindex normal, mas eu não testei: PostgreSQL 12 update

13

Ambas as operações listadas acima geram bloqueios que podem ser realmente difíceis em um site ao vivo. Recomendo as listadas em post-update-optional-tasks, pois, além de consumir muitos recursos da CPU, elas não bloqueiam as operações normais do banco de dados.

14

Execute ambos. O segundo relata um erro, no entanto:

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

Acho que é hora de me aprofundar no PostgreSQL e encontrar e excluir o registro.

O vacuum funcionou, mais ou menos, mas ainda tenho picos a cada poucos minutos, com um a três processos postmaster consumindo CPU por um ou dois minutos cada. Então, acho que há mais a ser feito.

15

É possível reverter para o PostgreSQL 10?

16

Claro, se você tiver um backup feito antes da atualização. No entanto, você perderá tudo o que foi criado desde esse backup.

É quase certamente melhor resolver esses problemas, pois o Postgres 12 agora é o padrão para qualquer nova instalação.

17

Não, isso não é possível… estamos migrando permanentemente para PG12.

18

veja:

19

Ok, então, para dar continuidade: tudo parece estar bem, o postmaster se acalmou drasticamente e o Sidekiq está rodando muito rápido novamente.

Para resumir o que funcionou no meu cenário (com o nome de banco de dados padrão ‘discourse’):

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

Em seguida, do console do PostgreSQL, cada um dos comandos abaixo foi executado. Cada um leva um pouco de tempo para completar, dependendo do tamanho do banco de dados; os dois primeiros também causaram alto uso de CPU:

VACUUM FULL VERBOSE;

REINDEX DATABASE discourse;

VACUUM VERBOSE ANALYZE;

Nota: Não notei diferença até que o comando VACUUM VERBOSE ANALYZE; fosse executado, conforme recomendado por @Falco. Portanto, os dois primeiros podem não ter sido necessários. No entanto, os dois primeiros pareciam ser fundamentais para resolver esse problema no passado na versão anterior do PostgreSQL.

Se você receber um erro como ‘ERROR: deadlock detected’ durante o comando REINDEX DATABASE discourse; — basta tentar executá-lo novamente até que funcione. Isso aconteceu comigo da última vez (na versão anterior do PostgreSQL).

Existem algumas recomendações para executar um reindexamento concorrente em vez do reindexamento acima: PostgreSQL 12 update

No entanto, observe que @eboehnisch acima recebeu um erro ao executar o reindexamento concorrente, veja acima.

20

Já vimos isso acontecer várias vezes em diversas migrações, então acho que deveríamos incluí-lo no script de migração, @Falco…

Sei que isso deixa as coisas um pouco mais lentas, mas vale a pena e reduzirá a necessidade de suporte.

Observação: a palavra VERBOSE ali apenas significa que ele exibe informações enquanto executa… o principal que faltava era o VACUUM ANALYZE. O reindexamento está principalmente relacionado à recuperação de espaço.