Postgresql 버전 업그레이드 후 Sidekiq + Postmaster가 32코어 CPU의 95% 이상 사용

제품 지원 자체 호스팅
1

오늘 업그레이드를 진행했는데, 그 과정에서 PostgreSQL 버전도 업데이트된 것 같습니다. 이 작업을 한 이후로 이 문제(또는 유사한 문제)가 다시 발생하고 있습니다 (기존 토픽은 이제 닫혀 있음):

이전에 이 문제를 해결했던 방법을 시도해 보았습니다:

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

그리고:

REINDEX DATABASE discourse;

아무 소용이 없었습니다 :upside_down_face:

Postmaster가 32개의 CPU 코어 중 95%~100%를 사용 중입니다. Sidekiq는 초당 약 1개의 작업만 처리하고 있습니다.

Redis를 플러시하고 다시 재구축하는 것도 시도해 보았습니다. Unicorn Sidekiq와 Unicorn 워커를 12개, 8개, 4개로 나눠서 테스트해 보았습니다.

PostgreSQL 업그레이드 전에는 12개의 Unicorn 워커와 Sidekiq를 사용하면서 정말 안정적이고 부드럽게 작동했습니다. 현재는 2.5.0.beta5를 실행 중이며, 업데이트 전에는 2.5.0.beta2를 실행 중이었을 것으로 생각합니다.

:firstworldproblem:

2

제안 드리기 위해 PostgreSQL이 실제로 실행 중인 정확한 쿼리를 확인해야 합니다.

이를 위해 pg_stat_statements를 활성화하는 것이 매우 유용합니다.

3

@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
4

간단히 말씀드리자면, 저도 같은 문제를 겪고 있습니다. PostgreSQL에 대한 전문 지식이 없어서 죄송합니다. 만약 제가 어딘가를 확인해야 한다면, 좀 더 상세한 안내가 필요합니다.

5

vacuum verbose analyze를 시도해 보시겠어요? @eboehnisch 님에게도 해당됩니다. 아래처럼 매우 간단한 쿼리가 평균 2초가 걸리는 것은 정말 이상합니다:

PostgreSQL 12 업데이트 주제에서 언급했듯이, 업데이트 후 통계 정보를 생성하는 것이 좋습니다.

6

VACUUM VERBOSE ANALYZE;를 실행해 보았습니다. 결과에서 무엇을 확인해야 하나요?

7

좋아요, 감사합니다! 이제 포스트마스터가 CPU를 과도하게 사용하면서 문제를 일으키던 상황이 해결된 것 같습니다. 이는 큰 개선입니다.

불행히도 Sidekiq는 여전히 느리지만, VACUUM VERBOSE ANALYZE;를 실행했을 때보다 나아졌습니다.

8

특별한 것은 없습니다. 큰 오류 메시지가 나오는 경우가 아니라면요.

성능은 이제 회복되어야 합니다.

좋았어요!

이제 경주에서 이겨서 결국 큐를 처리할 수 있을 것입니다.

9

이로 인해 상황이 확실히 개선되었지만, 잠시 후 다시 세 개의 postmaster 프로세스가 각각 1분 이상 CPU를 100% 사용했습니다.

10

조금 기다리는 게 나을 것 같아. 느린 기간 동안 쌓인 큐를 처리해야 할 테니까. /sidekiq에서 통계를 확인해 봐.

11

:smiley: 속도 진짜 많이 빨라졌네요, 고쳐진 것 같아요. 도움 주셔서 정말 감사합니다 @Falco! 잠시 더 실행해 보고 나중에 여기에 업데이트를 올릴게요~

12

아래 명령어를 실행해 보세요:

VACUUM FULL VERBOSE;

그리고 (데이터베이스 이름이 기본값인 'discourse’라고 가정하면):

REINDEX DATABASE discourse;

이것은 일반적인 reindex보다 더 나은 결과를 줄 수 있지만, 저는 아직 테스트해 보지 않았습니다: PostgreSQL 12 update

13

위에서 나열된 두 작업 모두 라이브 사이트에서 매우 심각할 수 있는 락(lock)을 생성합니다. post-update-optional-tasks에 나열된 작업들을 권장합니다. CPU를 많이 사용하지만, 일반적인 데이터베이스 작업을 차단하지는 않기 때문입니다.

14

두 가지를 모두 실행하세요. 후자가 오류를 보고합니다:

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를 사용하는 피크가 발생합니다. 그래서 더 이상의 문제가 있는 것 같습니다.

15

PostgreSQL 10으로 되돌리는 것이 가능한가요?

16

네, 업그레이드 전에 만든 백업이 있다면 가능합니다. 다만, 백업 이후에 생성된 모든 데이터는 손실됩니다.

새로운 설치에는 이제 Postgres12가 표준으로 사용되므로, 이러한 문제의 근본 원인을 파악하는 것이 훨씬 낫습니다.

17

아니요, 그것은 불가능합니다… 우리는 PG12로 영구적으로 마이그레이션하고 있습니다.

18

참고:

19

네, 후속 보고로, 현재까지 모든 것이 정상적으로 보입니다. postmaster의 상태가 크게 안정되었고, sidekiq도 다시 매우 빠르게 동작하고 있습니다.

제 환경(기본 DB 이름이 'discourse’인 경우)에서 효과적이었던 내용을 요약하면 다음과 같습니다:

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

그 다음 postgres 콘솔에서 아래 명령어들을 각각 실행했습니다. DB 크기에 따라 완료까지 시간이 다소 소요되며, 처음 두 명령어는 CPU 사용량이 특히 높았습니다:

VACUUM FULL VERBOSE;

REINDEX DATABASE discourse;

VACUUM VERBOSE ANALYZE;

참고: @Falco의 추천에 따라 VACUUM VERBOSE ANALYZE;를 실행했을 때 비로소 차이를 체감했습니다. 따라서 처음 두 명령어는 필수적이지 않았을 수 있습니다. 다만, 이전 버전의 Postgresql에서 과거에 이 문제를 해결할 때 처음 두 명령어가 핵심적인 역할을 한 것으로 보입니다.

REINDEX DATABASE discourse; 실행 중 'ERROR: deadlock detected’와 같은 오류가 발생하면, 작동할 때까지 다시 실행해 보세요. 지난번(이전 Postgresql 버전)에도 이런 일이 있었습니다.

위 재인덱싱 대신 동시 재인덱싱(concurrent reindex)을 실행하라는 권장 사항이 있습니다: PostgreSQL 12 update

다만, 위에서 언급했듯이 @eboehnisch가 동시 재인덱싱에서 오류를 겪은 적이 있으니 참고하시기 바랍니다. 상단 참조.

20

다양한 이관 과정에서 이 상황이 충분히 자주 발생하여, @Falco 님이 마이그레이션 스크립트에 이 명령을 추가해야 한다고 생각합니다.

성능이 꽤나 저하되지만, 그만한 가치가 있으며 지원 요청을 줄이는 데 도움이 될 것입니다.

참고로… 여기서 VERBOSE는 처리되는 동안 출력을 표시한다는 의미일 뿐입니다. 빠진 핵심은 VACUUM ANALYZE이며, 재인덱싱은 주로 공간을 회수하는 데 목적이 있습니다.