일부 사용자 프로필을 열 때 502 오류 발생

volas · 5월 24, 2024, 9:01오후

서버가 일부 랜덤 사용자의 summary.json 처리에 문제가 있어 502 코드를 반환하고 있습니다. 아마도 마지막 업데이트 이후에 시작되었을 것 같지만 확실하지 않습니다.

저는 Discourse 스택에 익숙하지 않아 로그를 찾는 데 어려움을 겪고 있습니다. 사용자 이름과 IP를 숨기기 위해 편집했으며, 시간은 다를 수 있지만 대부분 동일한 프로필 페이지 요청이 여러 번 반복되는 것입니다.

앱의 /var/log/nginx/error.log:

[error] 560#560: *416 upstream prematurely closed connection while reading response header from upstream, client: *.*.*.*, server: _, request: "GET /u/user/summary.json HTTP/2.0", upstream: "http://127.0.0.1:3000/u/user/summary.json", host: "forum.taucetistation.org", referrer: "https://forum.taucetistation.org/u/user"

/shared/log/rails/production_errors.log는 비어 있으며, /shared/log/rails/production.log에는 다음 내용만 포함되어 있습니다.

Started GET "/u/user/summary.json" for *.*.*.* at 2024-05-24 20:26:56 +0000
Processing by UsersController#summary as JSON
  Parameters: {"username"=>"user"}

비슷한 요청들에 대해 "Completed 200 OK"가 없습니다.

Unicorn에는 관련 로그가 없는 것 같습니다(시작 시 Redis와의 연결 오류만 있고, 결국 성공한 것으로 보이며 관련이 없어 보입니다).

하지만 /var/log/postgres/current에서 긴 실행 시간을 가진 의심스러운 요청이 하나 있습니다:

2024-05-24 20:49:12.727 UTC [2919] discourse@discourse LOG:  duration: 95288.368 ms  execute <unnamed>: SELECT replies.user_id, COUNT(*) FROM "posts" INNER JOIN "topics" "topics_posts" ON "topics_posts"."deleted_at" IS NULL AND "topics_posts"."id" = "posts"."topic_id" JOIN posts replies ON posts.topic_id = replies.topic_id AND posts.reply_to_post_number = replies.post_number JOIN topics ON replies.topic_id = topics.id AND topics.archetype <> 'private_message' AND replies.post_type IN (1) WHERE "posts"."deleted_at" IS NULL AND (posts.post_type IN (1,4)) AND "topics"."deleted_at" IS NULL AND (topics.archetype <> 'private_message') AND "topics"."visible" = TRUE AND (topics.category_id IS NULL OR topics.category_id IN (SELECT id FROM categories WHERE NOT read_restricted OR id IN (4,8,20,46,55,60,62,67))) AND "posts"."user_id" = 5318 AND (replies.user_id <> posts.user_id) GROUP BY "replies"."user_id" ORDER BY COUNT(*) DESC LIMIT 6
2024-05-24 20:49:12.728 UTC [2919] discourse@discourse LOG:  could not send data to client: Broken pipe
2024-05-24 20:49:12.729 UTC [2919] discourse@discourse FATAL:  connection to client lost

volas · 5월 24, 2024, 9:17오후

모든 활성 사용자 프로필에서 발생하는 문제인 것 같습니다. 캐시 때문에 빠르게 처리되기도 하지만, 때로는 시간이 오래 걸리기도 합니다.

가끔은 시간이 초과되어 502 오류가 발생하기도 합니다.

저희는 포럼용으로 DO의 이 드롭렛만 사용하고 있습니다.

크지는 않지만, 과거에는 저희에게 충분했습니다.

Arkshine · 5월 24, 2024, 9:29오후

summary.json이 로드되는 데 20초에서 30초가 걸리는 것을 볼 수 있습니다.

또한 콘솔에 이러한 오류가 나타납니다:

그리고 때로는 실제로 502 오류가 발생합니다:

안전 모드를 확인해 보니 플러그인/테마 컴포넌트와 관련이 없어 보입니다.

Cloudflare를 사용 중이신 것 같습니다. 최적화 기능을 비활성화해 보시겠습니까?

volas · 5월 24, 2024, 9:35오후

CF 프록시를 비활성화했습니다.

하지만 프론트엔드 문제보다는 백엔드에서 무거운 DB 요청이 발생하는 것 같습니다.

volas · 5월 24, 2024, 9:38오후

우리 플러그인 목록

hooks:
  after_code:
    - exec:
        cd: $home/plugins
        cmd:
          - git clone https://github.com/discourse/docker_manager.git
          - git clone https://github.com/discourse/discourse-patreon.git
          - git clone https://github.com/discourse/discourse-solved.git
          - git clone https://github.com/discourse/discourse-staff-notes.git
          - git clone https://github.com/discourse/discourse-spoiler-alert.git
          - git clone https://github.com/discourse/discourse-bbcode.git
          - git clone https://github.com/discourse/discourse-signatures.git
          - git clone https://github.com/discourse/discourse-github
          - git clone https://github.com/discourse/discourse-whos-online.git
          - git clone https://github.com/discourse/discourse-chat-integration.git
          - git clone https://github.com/discourse/discourse-assign
          - git clone https://github.com/discourse/discourse-question-answer.git

Arkshine · 5월 24, 2024, 10:10오후

전문가는 아니지만, Discourse는 현재 설정에 따라 더 많은 RAM을 요구하는 경향이 있습니다(최소 2GB). 스왑이 구성되어 있나요?

/logs 경로에서 관련 정보를 볼 수 있나요?

플러그인 관련해서는, 한눈에 보기에는 문제가 있는 플러그인이 보이지 않습니다.

다행히 누군가가 여기서 더 나은 통찰력을 제공해 주기를 바랍니다.

volas · 5월 25, 2024, 2:16오전

네, 스왑이 4GB입니다. 그리고 /logs에는 비추천(deprecation) 알림이나 geolite에 관한 경고 정도가 있네요.

2024-05-24 20:49:12.727 UTC [2919] discourse@discourse LOG:  duration: 95288.368 ms  execute <unnamed>: SELECT replies.user_id, COUNT(*) FROM "posts" INNER JOIN "topics" "topics_posts" ON "topics_posts"."deleted_at" IS NULL AND "topics_posts"."id" = "posts"."topic_id" JOIN posts replies ON posts.topic_id = replies.topic_id AND posts.reply_to_post_number = replies.post_number JOIN topics ON replies.topic_id = topics.id AND topics.archetype <> 'private_message' AND replies.post_type IN (1) WHERE "posts"."deleted_at" IS NULL AND (posts.post_type IN (1,4)) AND "topics"."deleted_at" IS NULL AND (topics.archetype <> 'private_message') AND "topics"."visible" = TRUE AND (topics.category_id IS NULL OR topics.category_id IN (SELECT id FROM categories WHERE NOT read_restricted OR id IN (4,8,20,46,55,60,62,67))) AND "posts"."user_id" = 5318 AND (replies.user_id <> posts.user_id) GROUP BY "replies"."user_id" ORDER BY COUNT(*) DESC LIMIT 6

제 이해로는 “가장 많이 답글 달린”(Most Replied To) 항목에 대한 요청이고, PERF: Improve performance of `most_replied_to_users` by janzenisaac · Pull Request #26373 · discourse/discourse · GitHub 에서 최근 변경되었기 때문에 이 패치가 우리에게 영향을 미치고 있는 것 같습니다.

도움이 될지 모르겠지만 EXPLAIN ANALYZE를 실행해 보았습니다:

 Limit  (cost=2552.39..2552.39 rows=1 width=12) (actual time=94412.810..94412.824 rows=6 loops=1)
   ->  Sort  (cost=2552.39..2552.39 rows=1 width=12) (actual time=94412.804..94412.808 rows=6 loops=1)
         Sort Key: (count(*)) DESC
         Sort Method: top-N heapsort  Memory: 25kB
         ->  GroupAggregate  (cost=2552.36..2552.38 rows=1 width=12) (actual time=94412.361..94412.743 rows=160 loops=1)
               Group Key: replies.user_id
               ->  Sort  (cost=2552.36..2552.36 rows=1 width=4) (actual time=94412.323..94412.405 rows=729 loops=1)
                     Sort Key: replies.user_id
                     Sort Method: quicksort  Memory: 59kB
                     ->  Nested Loop  (cost=12.24..2552.35 rows=1 width=4) (actual time=0.279..94409.497 rows=729 loops=1)
                           Join Filter: (topics_posts.id = topics.id)
                           ->  Nested Loop  (cost=1.13..2507.59 rows=4 width=16) (actual time=0.164..94354.548 rows=746 loops=1)
                                 Join Filter: ((replies.user_id <> posts.user_id) AND (posts.reply_to_post_number = replies.post_number))
                                 Rows Removed by Join Filter: 15395502
                                 ->  Nested Loop  (cost=0.71..1419.07 rows=131 width=16) (actual time=0.113..240.052 rows=1399 loops=1)
                                       ->  Index Scan using idx_posts_user_id_deleted_at on posts  (cost=0.42..561.22 rows=135 width=12) (actual time=0.077..59.712 rows=1408 loops=1)
                                             Index Cond: (user_id = 5318)
                                             Filter: (post_type = ANY ('{1,4}'::integer[]))
                                       ->  Index Only Scan using index_topics_on_id_and_deleted_at on topics topics_posts  (cost=0.29..6.35 rows=1 width=4) (actual time=0.123..0.123 rows=1 loops=1408)
                                             Index Cond: ((id = posts.topic_id) AND (deleted_at IS NULL))
                                             Heap Fetches: 1394
                                 ->  Index Scan using index_posts_on_topic_id_and_reply_to_post_number on posts replies  (cost=0.42..7.77 rows=36 width=12) (actual time=0.098..65.083 rows=11005 loops=1399)
                                       Index Cond: (topic_id = topics_posts.id)
                                       Filter: (post_type = 1)
                                       Rows Removed by Filter: 4
                           ->  Index Scan using topics_pkey on topics  (cost=11.11..11.18 rows=1 width=4) (actual time=0.065..0.065 rows=1 loops=746)
                                 Index Cond: (id = replies.topic_id)
                                 Filter: ((deleted_at IS NULL) AND visible AND ((archetype)::text <> 'private_message'::text) AND ((archetype)::text <> 'private_message'::text) AND ((category_id IS NULL) OR (hashed SubPlan 1)))
                                 Rows Removed by Filter: 0
                                 SubPlan 1
                                   ->  Seq Scan on categories  (cost=0.00..10.74 rows=31 width=4) (actual time=0.012..0.066 rows=37 loops=1)
                                         Filter: ((NOT read_restricted) OR (id = ANY ('{4,8,20,46,55,60,62,67}'::integer[])))
 Planning Time: 3.895 ms
 Execution Time: 94416.415 ms
(34 rows)

Ed_S · 5월 25, 2024, 6:39오전

이 작업을 수행하는 동안 서버에서 vmstat 5를 실행해 두면(ssh 연결을 통해) 페이지ング와 관련하여 어떤 일이 일어나고 있는지 확인할 수 있어 유용할 수 있습니다. (top도 사용할 수 있지만, 여기서는 훨씬 유용하지 않습니다)

pfaffman · 5월 25, 2024, 7:47오전

RAM 용량은 얼마나 되나요? 데이터베이스 크기는 얼마나 되나요? 아마도 RAM 용량을 늘리는 것만으로도 해결될 가능성이 큽니다.

volas · 5월 25, 2024, 3:24오후

postgresql이 어떤 최적화/캐싱을 수행하는 것 같아서, 때로는 시간이 많이 걸리지 않는 경우가 있습니다. 그래서 요청을 테스트할 새로운 사용자를 찾아야 합니다.

procs -----------memory---------- ---swap-- -----io---- -system-- -------cpu-------
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st gu
 0  0 287852  75220  17660 587788    6    8  4685   244  496    9  6  3 88  3  0  0
 0  0 287852  74048  17668 587836    0    0     0    18  209  465  1  2 96  0  0  0
 0  1 287852  82496  13452 582360    2   13 39937    38 4186 7339  8 16 14 62  0  0
 0  1 288620  77924   1020 601604    2  138 64178   166 5352 8263  9 22  0 68  0  0
 1  0 290156  80472    968 599840    1  313 37518    42 3612 5160 22 37  0 41  0  0
 1  0 289900  67588   3720 609896    4   29 13800    75 2062 2635 43 49  0  8  0  0
 1  0 291180  76816   2368 606924    0  245 30042    27 3414 5477 34 39  0 27  0  0
 2  0 292716  67184   1696 622528    4  318 44820    18 4152 6198 23 30  0 47  0  0
 1  0 293228  75100   3008 614144    0  132 10030     4 1803 1986 39 49  0 11  0  0
 1  0 293484  76020   2860 613444    1   34  3331    10 1197  767 44 54  0  2  0  0
 1  0 294508  66296   2868 623376    2  218  4994    24 1389 1206 40 54  0  6  0  0
 1  0 295020  75432   2892 614384    0  120  1304    58 1161  728 43 55  0  2  0  0
 1  0 295020  73084   2904 615984    0    0   314    11 1060  448 43 57  0  0  0  0
 1  0 295020  68864   3148 619388    6   33  8209    63  663 1190 10 13 74  3  0  0

   Name    |  Owner   | Encoding | Locale Provider |   Collate   |    Ctype    | ICU Locale | ICU Rules |   Access privileges    |  Size   | Tablespace | Description 
-----------+----------+----------+-----------------+-------------+-------------+------------+-----------+------------------------+---------+------------+-------------
 discourse | postgres | UTF8     | libc            | ru_RU.UTF-8 | ru_RU.UTF-8 |            |           | =Tc/postgres          +| 9493 MB | pg_default |

2GB RAM + 4GB 스왑, 우리는 DigitalOcean의 이 (레거시 CPU) 드롭렛을 사용하고 있습니다

volas · 5월 25, 2024, 4:29오후

PERF: Improve performance of `most_replied_to_users` (#26373) · discourse/discourse@db10dd5 · GitHub 의 변경 사항을 되돌린 상태로 테스트해 보고 싶습니다. 하지만 discourse 컨테이너 안에서 app/models/user_summary.rb 파일을 수정했음에도 불구하고, 프로필 페이지가 여전히 세 개의 JOIN을 포함하는 요청을 보내고 있습니다.

어딘가에 캐시를 정리해야 하나요? 아니면 더 나은 방법이 있을까요?

UPD: 컨테이너를 재시작하니 해결되었고, 되돌린 후로 훨씬 더 잘 작동하는 것 같습니다! 프로필 페이지가 더 빨리 로드되고 502 에러도 발생하지 않습니다.

Arkshine · 5월 25, 2024, 4:59오후

확인합니다. 지금은 매우 빠르고, 오류도 보이지 않습니다.

Ed_S · 5월 26, 2024, 6:05오후

vmstat 출력을 제공해 주셔서 감사합니다. 제게 그것은 메모리가 과대 할당되지 않았으며, Linux가 스왑을 하지 않고 있지만, 데이터베이스가 충분한 RAM을 할당하지 못했다는 것을 의미합니다. 많은 디스크 I/O가 발생하고 있습니다.

따라서 더 많은 RAM이 필요한 경우라고 생각하며, 스왑을 추가해도 큰 도움이 되지 않을 것입니다.

그러면 당신도 변경 사항을 되돌렸고, 성능이 정상으로 돌아온 것을 확인했나요?

Arkshine · 5월 26, 2024, 6:41오후

저는 아닙니다. 위 게시물에서 Alexander가 그렇게 말했습니다. 저는 그의 포럼에서 먼저 테스트를 했었기 때문에 이를 확인하고 싶었습니다. 그리고 네, 해당 커밋을 되돌리면서 성능 문제가 사라졌습니다.

volas · 5월 26, 2024, 7:16오후

CPU 문제일 수도 있습니다. 하지만 Discourse가 유지 관리 작업을 실행하는 경우가 아니면, 이전에 성능 관련 문제를 거의 겪지 않았습니다. 최근에는 프로필 페이지에서만 문제가 발생해서 마지막 업데이트를 의심하고 있었습니다.

다만, 롤백을 시도하기 전에 app.yml 파일도 조정했습니다:

db_shared_buffers: "128MB"가 설정되어 있었는데, 이는 권장 값보다 4배 적은 것이었습니다. 아마도 처음 포럼을 설정했을 때의 잔재인 것 같습니다. 이 항목을 주석 처리하여 Discourse가 호스트 RAM에 기반하여 스스로 설정하도록 했습니다.
db_work_mem: "40MB"도 주석을 해제했습니다.

하지만 먼저 적절한 리빌드와 테스트를 수행해 보았으나 도움이 되지 않았습니다. 롤백을 한 후에야 상황이 나아졌습니다.

혹시 모르니 방금 롤백 없이 다시 테스트해 보았는데, 프로필에서 다시 502 에러가 나타나는 것을 확인할 수 있었습니다.

필요하다면 패치를 적용한/안 한 상태로 더 많은 테스트를 수행할 수 있습니다.

Ed_S · 5월 26, 2024, 7:23오후

철저한 테스트를 해주셔서 감사합니다!

가능성은 있지만, Wait 상태에 걸린 시간을 보면 주로 I/O 문제인 것 같습니다. I/O 병목 현상이 해결되면 vmstat를 통해 CPU가 최대치에 도달했는지 확인할 수 있습니다.

pfaffman · 5월 26, 2024, 11:12오후

그렇지 않습니다. discourse-setup을 실행하면 해당 설정이 수행됩니다(첫 번째 메시지 이후에는 Ctrl+C를 눌러 중단할 수 있습니다) 또는 직접 올바른 수치를 입력할 수 있습니다.

이 값을 높이는 것이 종종 도움이 되지만, RAM이 충분할 때만 가능합니다.

원래 문제는 소스의 쿼리 문제일 수 있어 보이지만, db_work_mem 설정은 반드시 해야 합니다. 주석 처리하는 것은 해결책이 아닙니다(제가 알기로는).

Ed_S · 5월 27, 2024, 5:16오전

여기서 제가 내린 결론은, 더 빠르게 만들려고 제안된 해당 풀 리퀘스트가 실제로는 RAM이 적은 사이트에서 성능을 더 떨어뜨리거나 심지어 문제를 일으켰다는 것입니다.

이것이 명확히 파악될 때까지 해당 풀 리퀘스트를 되돌릴 수 있을까요?

이 토픽의 카테고리를 버그로 변경할 수 있을까요?

volas · 5월 27, 2024, 6:09오전

이 부분을 알아봐 주셔서 감사합니다. 그 코멘트에 속아 있었네요. 수동으로 512MB로 설정한 것이 조금은 도움이 된 것 같지만, 프로필 페이지의 성능은 여전히 충분하지 않고 때로는 로딩에 30초가 걸리기도 합니다.

글		댓글	조회수
Discourse installation has been getting slower and slower and slower Self-hosting server-resources	36	2172	4월 15, 2023
Users reporting lots of 502 errors when attempting to post due to "max consecutive replies" check Bug	36	3360	1월 18, 2019
Slow Profile Loads with 100GB+ database Feature	42	3573	12월 29, 2020
Long loading times for user summary page with slow database Self-hosting unsupported-install	17	2136	10월 29, 2019
Bursts of 502 Service Unavailable, pointers to debug Self-hosting	15	1814	2월 18, 2018

일부 사용자 프로필을 열 때 502 오류 발생

Related topics