Sidekiq lento + Postmaster che utilizza oltre il 95% di CPU (32 core) dopo l'aggiornamento della versione di PostgreSQL

Supporto Installazione
1

Quindi oggi ho eseguito un aggiornamento e sembra che la versione di PostgreSQL sia stata aggiornata nel processo. Da allora, questo problema (o uno simile) è ricomparso (il vecchio argomento è ora chiuso):

Ho provato ciò che aveva risolto il problema in precedenza:

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

e anche:

REINDEX DATABASE discourse;

Nessun risultato :upside_down_face:

Postmaster sta utilizzando il 95%-100% dei 32 core della CPU. Sidekiq elabora circa 1 job al secondo.

Ho anche provato a svuotare Redis e a ricostruire di nuovo. Ho fatto dei test con 12, 8 e 4 unicorn sidekiq e unicorn worker.

Prima dell’aggiornamento di PostgreSQL, tutto funzionava in modo solido e fluido con 12 unicorn worker e sidekiq. Attualmente sto eseguendo la versione 2.5.0.beta5 e credo di aver utilizzato la 2.5.0.beta2 prima dell’aggiornamento.

:firstworldproblem:

2

È necessario verificare quali siano le query esatte che PostgreSQL sta eseguendo, così da poter fornire suggerimenti.

Attivare pg_stat_statements è molto utile a questo scopo.

3

Grazie @Falco - ecco alcune statistiche, fammi sapere se hai bisogno di vedere più query, dato che vengono troncate alla fine.

                                                                                                                                                     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

Solo una breve nota: ho lo stesso problema e, temo, nessuna esperienza con PostgreSQL. Se devo cercare da qualche parte, ho bisogno di istruzioni un po’ più dettagliate. Scusa.

5

Puoi provare con VACUUM VERBOSE ANALYZE? Vale anche per te @eboehnisch. Questa query molto semplice qui sotto, che impiega in media 2 secondi, è davvero strana:

Come detto nel topic Aggiornamento PostgreSQL 12, dopo l’aggiornamento è una buona idea generare le statistiche.

6

Ho provato VACUUM VERBOSE ANALYZE;. Cosa dovrei cercare nei risultati?

7

Ottimo, grazie! Quindi penso che questo abbia risolto il problema dei postmaster che impazzivano usando tutta la CPU. È un grande miglioramento.

Sidekiq è ancora lento, purtroppo, ma meglio di prima dell’esecuzione di VACUUM VERBOSE ANALYZE;

8

Niente di speciale, a meno che non si tratti di un messaggio di errore importante.

Le prestazioni dovrebbero riprendersi ora.

YAY!

Ora dovrebbe essere in grado di vincere la corsa e elaborare la coda alla fine.

9

Ciò ha senz’altro migliorato la situazione, ma dopo un po’ di tempo di nuovo tre processi postmaster hanno utilizzato il 100% della CPU per oltre un minuto ciascuno.

10

Direi di aspettare un po’, perché probabilmente hai una coda da smaltire dopo il periodo di calma. Controlla /sidekiq per le statistiche.

11

:smiley: La velocità è davvero aumentata, sembra che sia stato risolto. Grazie mille per l’aiuto, @Falco! Lo lascerò in esecuzione per un po’ e pubblicherò un aggiornamento qui più tardi~

12

Forse puoi provare a eseguire:

VACUUM FULL VERBOSE;

e (assumendo che il nome del tuo database sia ‘discourse’, che è quello predefinito):

REINDEX DATABASE discourse;

Questo potrebbe essere meglio rispetto al reindicizzamento normale, ma non l’ho testato: PostgreSQL 12 update

13

Le due operazioni elencate sopra generano lock che possono essere davvero problematici in un sito attivo. Consiglio quelle elencate in post-update-optional-tasks, poiché oltre a utilizzare molte risorse CPU, non bloccano le normali operazioni del database.

14

Esegui entrambi. Quest’ultimo riporta un errore, tuttavia:

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

Credo sia il momento di approfondire PostgreSQL per trovare ed eliminare il record.

Il vacuum ha funzionato, più o meno, ma ricevo ancora picchi ogni pochi minuti con uno o tre processi postmaster che consumano CPU per uno o due minuti ciascuno. Quindi immagino ci sia dell’altro.

15

È possibile tornare a PostgreSQL 10?

16

Certo, se hai un backup precedente all’aggiornamento. Tieni presente che perderai tutto ciò che è stato creato da allora.

È quasi certamente meglio risolvere alla radice questi problemi: Postgres12 è ora lo standard per qualsiasi nuova installazione.

17

No, non è possibile… stiamo passando definitivamente a PG12.

18

vedi:

19

Ok, per fare un aggiornamento: tutto sembra ancora a posto, postmaster si è calmato drasticamente e sidekiq sta tornando a muoversi molto velocemente.

Per riassumere cosa ha funzionato nel mio scenario (con il nome predefinito del database ‘discourse’):

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

Poi, dalla console di postgres, sono stati eseguiti ciascuno dei seguenti comandi. Ciascuno richiede un po’ di tempo per completarsi, a seconda delle dimensioni del DB; i primi due comportano anche un elevato utilizzo della CPU:

VACUUM FULL VERBOSE;

REINDEX DATABASE discourse;

VACUUM VERBOSE ANALYZE;

Nota: Non ho notato alcuna differenza fino a quando non è stato eseguito VACUUM VERBOSE ANALYZE; come raccomandato da @Falco, quindi i primi due potrebbero non essere stati necessari. Tuttavia, i primi due sembravano fondamentali per risolvere questo problema in passato nella versione precedente di PostgreSQL.

Se ricevi un errore come ‘ERROR: deadlock detected’ durante REINDEX DATABASE discourse; riprova semplicemente a eseguirlo finché non funziona. Questo mi è capitato l’ultima volta (con la versione precedente di PostgreSQL).

Ci sono alcune raccomandazioni per eseguire un reindex concorrente invece del reindex sopra: PostgreSQL 12 update

Tuttavia, nota che @eboehnisch sopra ha ricevuto un errore dal reindex concorrente, vedi sopra.

20

Abbiamo visto questo accadere abbastanza spesso in varie migrazioni, quindi penso che dovremmo aggiungerlo allo script di migrazione @Falco…

So che rallenta le cose un po’, ma ne vale la pena: ridurrà il supporto.

Nota… la parola VERBOSE significa semplicemente che produce output mentre esegue… la cosa importante mancante era VACUUM ANALYZE. Il reindicizzamento serve principalmente a recuperare spazio.