Postgresqlバージョンアップ後のSlow Sidekiq + PostmasterでCPU（32コア）使用率が95%超に

markersocial · 2020 年 5 月 27 日午後 4:08

今日はアップグレードを行い、その過程で PostgreSQL のバージョンも更新されたようです。それ以降、この問題（または類似のもの）が再発しました（以前のトピックは現在クローズされています）：

以前この問題を解決した方法を試してみました：

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

また、以下のコマンドも試しました：

REINDEX DATABASE discourse;

しかし、効果はありませんでした

Postmaster が 32 コアの CPU の 95%〜100% を使用しており、Sidekiq は約 1 ジョブ/秒の速度でしか処理できていません。

Redis をフラッシュして再構築することも試みました。12、8、4 の Unicorn Sidekiq と Unicorn ワーカーの間でテストを行いました。

PostgreSQL アップグレード前は、12 の Unicorn ワーカーと Sidekiq で非常に安定してスムーズに動作していました。現在は 2.5.0.beta5 を実行しており、アップデート前は 2.5.0.beta2 を実行していたと思います。

Falco · 2020 年 5 月 27 日午後 4:10

PostgreSQL が実際に実行しているクエリを特定していただく必要があります。そうすれば、具体的な提案が可能になります。

そのために、pg_stat_statements を有効にすることをお勧めします。

markersocial · 2020 年 5 月 27 日午後 4:48

@Falco ありがとうございます。いくつかの統計データをお送りします。クエリが末尾で切れてしまう場合は、さらに詳細なデータが必要かお知らせください。

                                                                                                                                                     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

eboehnisch · 2020 年 5 月 27 日午後 4:49

ただの簡単な note ですが、私も同じ問題に直面しています。PostgreSQL の専門知識は残念ながらありません。もしどこかを探す必要があるなら、もう少し詳しい手順が必要です。申し訳ありません。

Falco · 2020 年 5 月 27 日午後 5:21

VACUUM VERBOSE ANALYZEを試してみられますか？@eboehnisch の方も同様です。以下の非常に単純なクエリが平均 2 秒もかかるのは本当に奇妙です：

PostgreSQL 12 アップデートトピックでも述べられている通り、アップデート後に統計情報を生成するのは良い考えです。

eboehnisch · 2020 年 5 月 27 日午後 5:44

VACUUM VERBOSE ANALYZE;を実行しました。結果で何を確認すればよいでしょうか？

markersocial · 2020 年 5 月 27 日午後 5:45

素晴らしい、ありがとう！これで、ポストマスターが暴走して CPU を全て使い果たすという問題は解決したと思います。これは大きな改善ですね。

残念ながら Sidekiq はまだ遅いですが、VACUUM VERBOSE ANALYZE; を実行する前よりはマシです。

Falco · 2020 年 5 月 27 日午後 5:46

大きなエラーメッセージが出ていない限り、特に気にする必要はありません。

パフォーマンスは現在回復しているはずです。

やったー！

これで、競合に勝ってキューを処理できるようになるはずです。

eboehnisch · 2020 年 5 月 27 日午後 5:49

この改善は確かに状況を改善しましたが、しばらくすると再び3つの postmaster プロセスがそれぞれ1分以上にわたり100%のCPUを使用するようになりました。

Falco · 2020 年 5 月 27 日午後 5:50

少し待ったほうがいいと思います。低速期からの処理待ちが溜まっている可能性があります。統計は /sidekiq を確認してください。

markersocial · 2020 年 5 月 27 日午後 5:52

速度が本当に上がりましたね、もう直ったみたいです。@Falco さん、本当にありがとうございました！しばらくそのまま動かして、後でここに更新情報を書きますね~

markersocial · 2020 年 5 月 27 日午後 5:54

以下のコマンドを実行してみてください。

VACUUM FULL VERBOSE;

（データベース名がデフォルトの ‘discourse’ であると仮定します）

REINDEX DATABASE discourse;

これは通常の再インデックスより良いかもしれませんが、私はテストしていません：PostgreSQL 12 update

Falco · 2020 年 5 月 27 日午後 5:58

上記の両方の操作は、ライブサイトにおいて非常に扱いにくいロックを生成します。post-update-optional-tasks に記載されている操作をお勧めします。これらは大量の CPU を使用しますが、通常のデータベース操作をブロックしないためです。

eboehnisch · 2020 年 5 月 27 日午後 7:33

両方実行してください。ただし、後者は以下のエラーを報告します：

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

PostgreSQL に深入りして、該当レコードを探し削除する時が来たようです。

vacuum はある程度効果がありましたが、それでも数分おきに 1〜3 個の postmaster プロセスがそれぞれ 1〜2 分間 CPU を消費するピークが発生しています。つまり、まだ他にも問題があるようです。

eboehnisch · 2020 年 5 月 27 日午後 10:16

PostgreSQL 10 にロールバックすることは可能ですか？

Stephen · 2020 年 5 月 27 日午後 10:51

もちろん、アップグレード前のバックアップがあれば可能です。ただし、バックアップ以降に作成されたデータはすべて失われます。

これらの問題の根本原因を特定する方がはるかに良いでしょう。Postgres12 は、新しいインストールの標準となっています。

codinghorror · 2020 年 5 月 28 日午前 12:21

いいえ、それは不可能です……私たちは恒久的に PG12 に移行します。

sam · 2020 年 5 月 28 日午前 12:58

参照:

markersocial · 2020 年 5 月 28 日午前 5:56

さて、フォローアップですが、すべて順調で、postmaster の負荷が劇的に落ち着き、sidekiq も再び非常に高速に動作しています。

私の環境（デフォルトの DB 名は ‘discourse’）で機能した手順をまとめます。

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

次に、postgres コンソールから以下のコマンドをそれぞれ実行してください。DB のサイズに応じて完了までに少し時間がかかります。特に最初の 2 つでは CPU 使用率が高くなります。

VACUUM FULL VERBOSE;

REINDEX DATABASE discourse;

VACUUM VERBOSE ANALYZE;

注：@Falco さんの推奨通り「VACUUM VERBOSE ANALYZE;」を実行するまで変化に気づきませんでした。そのため、最初の 2 つのコマンドは不要だったかもしれません。ただし、最初の 2 つは、以前の Postgresql バージョンにおいてこの問題を解決する鍵となったようです（過去の記事を参照）。

「REINDEX DATABASE discourse;」の実行中に「ERROR: deadlock detected」というエラーが表示された場合は、成功するまで再度実行してみてください。これは前回（以前の Postgresql バージョン）に私自身も経験しました。

上記の reindex の代わりに、同時実行可能な reindex を実行するという推奨事項もあります：PostgreSQL 12 update

ただし、上記の @eboehnisch さんは同時実行 reindex でエラーが発生したようです（こちらを参照）。

sam · 2020 年 5 月 28 日午前 5:59

Falco さん、さまざまな移行でこの現象を何度も目にしてきたため、移行スクリプトにこれを追加すべきだと感じています。

確かに処理速度は多少低下しますが、その価値はあり、サポートの負担を軽減できます。

なお、ここで言う VERBOSE は、実行中に情報を出力することを意味します。VACUUM ANALYZE が欠けていたことが大きな問題でした。再インデックスの主な目的は、領域の回収です。

トピック		返信	表示
Very slow Sidekiq issue with large queue due to massive numbers of unread user notifications Self-hosting	69	7547	2020 年 5 月 11 日
Long-Running Sidekiq Jobs Feature	21	1694	2020 年 12 月 24 日
PostgreSQL runaway IO Self-hosting	37	3091	2021 年 3 月 17 日
PostgreSQL 13 update Announcements	3	11121	2025 年 5 月 12 日
Primary Postgres database process (postmaster) eating all CPU Self-hosting server-resources	13	4146	2020 年 5 月 28 日

Postgresqlバージョンアップ後のSlow Sidekiq + PostmasterでCPU（32コア）使用率が95%超に

関連トピック