一部のユーザープロフィールを開く際に502エラー

volas · 2024 年 5 月 24 日午後 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 から、実行時間が長い疑わしいリクエストが 1 件あります。

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 · 2024 年 5 月 24 日午後 9:17

アクティブな全ユーザープロファイルで問題が発生しているようです。時間がかかる場合もあれば、キャッシュのおかげで速い場合もあります。

そして時には、タイムアウトして502エラーが発生することもあります。

フォーラム専用にDOからドロップされたものを使用しています。

大したものではありませんが、過去には十分でした。

Arkshine · 2024 年 5 月 24 日午後 9:29

summary.json の読み込みに 20 ～ 30 秒かかります。

また、コンソールにこれらのエラーが表示されます。

そして、時折 502 が発生します。

セーフモードを見ると、プラグイン/テーマコンポーネントに関連しているようには見えません。

Cloudflare を利用しているようですが、最適化を無効にしてみてください。

volas · 2024 年 5 月 24 日午後 9:35

CFプロキシを無効にしました。

しかし、これはフロントエンドの問題ではなく、バックエンドでの重いDBリクエストのように見えます。

volas · 2024 年 5 月 24 日午後 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 · 2024 年 5 月 24 日午後 10:10

専門家ではありませんが、Discourseは現在、セットアップによってはより多くのRAMを必要とします（少なくとも2GB）。スワップは設定されていますか？

/logsルートに何か関連情報が表示されますか？

プラグインに関しては、一見したところ、問題のあるプラグインは見当たりません。

誰かがここでより良い洞察を提供できることを願っています。

volas · 2024 年 5 月 25 日午前 2:16

はい、スワップは4GBです。/logs には、非推奨通知や 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

これは「最も返信された」リクエストであり、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 · 2024 年 5 月 25 日午前 6:39

これを実行している間に、ページングで何が起こっているかを確認するために、サーバー（ssh接続で）で vmstat 5 を実行しておくと便利かもしれません。（topも使用できますが、ここではあまり役に立ちません）

pfaffman · 2024 年 5 月 25 日午前 7:47

RAMはどれくらいありますか？データベースのサイズはどれくらいですか？おそらくRAMを増やす必要があるでしょう。

volas · 2024 年 5 月 25 日午後 3:24

postgresql は最適化/キャッシュを行っているようで、時間がかからない場合があるため、リクエストをテストする新しいユーザーを探す必要があります。

  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 |

RAM 2GB + スワップ 4GB で、DigitalOcean のレガシー CPU ドロップレットを使用しています。

volas · 2024 年 5 月 25 日午後 4:29

PERF: Improve performance of `most_replied_to_users` (#26373) · discourse/discourse@db10dd5 · GitHub の変更を元に戻してテストしたいのですが、discourse コンテナ内で app/models/user_summary.rb を編集しても、プロフィールページで3つのJOINを持つリクエストが表示されます。

どこかでキャッシュをクリアする必要がありますか？それとも、もっと良い方法がありますか？

更新: コンテナの再起動で解決しました。元に戻した後、動作が改善されたようです！プロフィールページの読み込みが速くなり、502エラーも発生しなくなりました。

Arkshine · 2024 年 5 月 25 日午後 4:59

確認しました。これは非常に高速になり、エラーも見られません。

Ed_S · 2024 年 5 月 26 日午後 6:05

vmstatの出力ありがとうございます。これは、メモリがオーバーコミットされておらず、Linuxがスワップしていないことを示していますが、データベースは十分なRAMを割り当てることができず、多くのディスクI/Oを実行しています。

したがって、これはより多くのRAMが必要なケースであり、スワップを追加してもあまり助けにならないと思います。

つまり、あなたも変更を元に戻し、パフォーマンスが正常に戻ったということですか？

Arkshine · 2024 年 5 月 26 日午後 6:41

私ではありません、アレクサンダーです。彼は上記の投稿でそう述べています。以前彼のフォーラムでテストしていたので、確認したかったのです。はい、そのコミットを元に戻すことでパフォーマンスの問題は解消されました。

volas · 2024 年 5 月 26 日午後 7:16

CPU の問題の可能性もあります。しかし、Discourse がメンテナンスジョブを実行しているときを除いて、以前はパフォーマンスに関する問題はほとんどありませんでした。プロファイルページで問題が発生したのは最近のことなので、最後のアップデートについて考えていました。

しかし、revert を試す前に app.yml を調整したことも言っておくべきです。

何らかの理由で、推奨値の 4 分の 1 である db_shared_buffers: \"128MB\" が設定されていました。これは、私が初めてフォーラムを設定したときの古い設定の名残である可能性が高いです。これをコメントアウトしたので、Discourse はホスト RAM に基づいて自分で設定できます。
また、db_work_mem: \"40MB\" のコメントアウトを解除しました。

しかし、適切に再構築して最初にテストしましたが、役に立ちませんでした。revert して初めて改善しました。

念のため、revert せずに再度テストしたところ、プロファイルで再び 502 が発生していることがわかります。

必要であれば、パッチあり/なしでさらにテストを行うことができます。

Ed_S · 2024 年 5 月 26 日午後 7:23

徹底的なテスト、ありがとうございます！

その可能性もありますが、「Wait」で費やされた時間を見ると、主にI/Oの問題だと思います。I/Oのボトルネックが解消されれば、vmstatでCPUが最大になっているかどうかを確認できます。

pfaffman · 2024 年 5 月 26 日午後 11:12

できません。discourse-setup を実行すれば、それがすべて行います（最初のメッセージの後で Ctrl+C を押すことができます）。または、自分で正しい数値を入力してください。

これはしばしば増やすと役立ちますが、十分なRAMがある場合に限ります。

元の問題はソースのクエリの問題のようですが、db_work_mem を設定することは間違いなく必要です。コメントアウトすることは（私が知る限り）解決策ではありません。

Ed_S · 2024 年 5 月 27 日午前 5:16

結論として、高速化を目的として受け入れられたプルリクエストが、実際にはRAMが少ないサイトで、パフォーマンスを低下させたり、破損させたりしているのではないかと考えられます。

この問題が理解されるまで、そのプルリクエストを元に戻すことはできますか？

このトピックのカテゴリをバグに変更することはできますか？

volas · 2024 年 5 月 27 日午前 6:09

これに気づいてくれてありがとう。コメントに惑わされていました。これを手動で 512MB に設定したところ、少し改善されたように感じますが、プロファイルページのパフォーマンスはまだ十分ではなく、読み込みに半分の時間がかかることがあります。

トピック		返信	表示
Discourse installation has been getting slower and slower and slower Installation server-resources	37	1615	2023 年 5 月 15 日
Users reporting lots of 502 errors when attempting to post due to "max consecutive replies" check Bug	37	2846	2019 年 1 月 18 日
Slow Profile Loads with 100GB+ database Feature	43	2916	2021 年 1 月 1 日
Long loading times for user summary page with slow database Installation unsupported-install	19	1784	2023 年 7 月 13 日
Bursts of 502 Service Unavailable, pointers to debug Installation	16	1597	2024 年 6 月 8 日

一部のユーザープロフィールを開く際に502エラー

関連トピック