502-Fehler beim Öffnen einiger Benutzerprofile

Fehler
1

Der Server hat Probleme mit summary.json von einigen zufälligen Benutzern und gibt den Code 502 zurück. Wahrscheinlich begann es nach dem letzten Update, aber ich bin mir nicht sicher.

Ich bin mit dem Discourse-Stack nicht vertraut und habe Schwierigkeiten, die Protokolle zu finden. Ich habe die Benutzernamen und IPs ausgeblendet. Die Zeit kann variieren, aber meistens handelt es sich um wiederholte Anfragen an dieselbe Profilseite.

Aus der App /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 ist leer, und /shared/log/rails/production.log enthält nur

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

ohne “Completed 200 OK” für ähnliche Anfragen.

Es scheint keine verwandten Protokolle in Unicorn zu geben (nur Verbindungsfehler mit Redis beim Start, aber es scheint am Ende erfolgreich zu sein und ist nicht relevant).

Es gibt jedoch eine verdächtige Anfrage mit langer Dauerzeit aus /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
1 „Gefällt mir“
2

Scheint ein Problem für jedes aktive Benutzerprofil zu sein. Manchmal dauert es einfach lange, manchmal geht es wegen eines Caches schnell.

Und manchmal ist es einfach zu spät und wirft einen 502-Fehler.

Wir nutzen diesen Dropped von DO nur für das Forum.
Снимок экрана от 2024-05-25 00-12-28

Nicht viel, aber es reichte uns in der Vergangenheit.

3

Ich kann sehen, dass summary.json zwischen 20 und 30 Sekunden zum Laden braucht.

Außerdem diese Fehler in der Konsole:

image
image1342×190 14.1 KB

Und manchmal 502, tatsächlich:

image
image799×111 5.06 KB

Wenn ich mir den abgesicherten Modus ansehe, sieht es nicht so aus, als ob dies mit Plugins/Theme-Komponenten zusammenhängt.

Ich sehe, dass Sie hinter Cloudflare sind. Können Sie versuchen, alle Optimierungen zu deaktivieren?

1 „Gefällt mir“
4

CF-Proxy deaktiviert.

Aber es sieht nicht nach einem Frontend-Problem aus, sondern eher nach einer schweren DB-Anfrage im Backend.

1 „Gefällt mir“
5

unsere Plugin-Liste

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
6

Ich bin kein Experte, aber Discourse benötigt heutzutage tendenziell mehr RAM, abhängig von Ihrer Konfiguration (mindestens 2 GB). Haben Sie einen Swap konfiguriert?

Sehen Sie relevante Informationen unter der Route /logs?

Plugin-bezogen sehe ich auf den ersten Blick keine fehlerhaften Plugins. :thinking:

Hoffentlich kann jemand hier bessere Einblicke geben.

7

Ja, 4 GB Swap. Und in /logs nur einige Warnungen wie Deprecation Notices oder etwas über 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

Soweit ich das verstehe, ist das eine Anfrage für „Am häufigsten beantwortet“ und wurde kürzlich in PERF: Improve performance of `most_replied_to_users` by janzenisaac · Pull Request #26373 · discourse/discourse · GitHub geändert, also wirkt sich dieser Patch vielleicht auf uns aus.

Ich habe EXPLAIN ANALYZE ausgeführt, falls das hilft:

 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)
8

Es könnte nützlich sein,
vmstat 5
auf dem Server (in einer SSH-Verbindung) laufen zu lassen, während Sie dies tun, um zu sehen, was mit dem Paging passieren könnte. (top kann verwendet werden, ist hier aber viel weniger nützlich)

3 „Gefällt mir“
9

Wie viel RAM hast du? Wie groß ist deine Datenbank? Wahrscheinlich brauchst du einfach mehr RAM.

2 „Gefällt mir“
10

Es scheint, dass PostgreSQL einige Optimierungen/Caches durchführt, sodass es manchmal nicht zu viel Zeit in Anspruch nimmt. Daher muss ich nach neuen Benutzern suchen, um Anfragen zu testen.

  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 |

2 GB RAM + 4 GB Swap, wir verwenden diesen (Legacy CPU) Droplet von DigitalOcean

11

Ich möchte versuchen, es mit rückgängig gemachten Änderungen von PERF: Improve performance of `most_replied_to_users` (#26373) · discourse/discourse@db10dd5 · GitHub zu testen, aber obwohl ich app/models/user_summary.rb innerhalb des Discourse-Containers bearbeitet habe, sehe ich immer noch, dass die Profilseite diese Anfrage mit drei JOIN’s durchführt.

Muss ich den Cache irgendwo leeren? Oder gibt es einen besseren Weg, dies zu tun.

AKTUALISIERUNG: Ein Neustart des Containers hat geholfen, und es scheint, dass es jetzt nach dem Rückgängigmachen besser funktioniert! Profilseiten laden schneller und es gibt keine 502-Fehler mehr.

3 „Gefällt mir“
12

Ich bestätige; das ist jetzt rasend schnell, und ich sehe keine Fehler.

2 „Gefällt mir“
13

Danke für die vmstat-Ausgabe. Für mich bedeutet das, dass der Arbeitsspeicher nicht überbucht ist – Linux tauscht nicht aus –, aber die Datenbank konnte nicht genügend RAM zuweisen – sie führt viele Festplatten-I/O durch.

Ich denke also, dass hier mehr RAM benötigt wird und das Hinzufügen von Swap nicht viel helfen würde.

Sie haben also die Änderung ebenfalls rückgängig gemacht und festgestellt, dass sich die Leistung wieder normalisiert hat?

1 „Gefällt mir“
14

Nicht ich, Alexander, in seinem obigen Beitrag. Ich wollte das bestätigen, da ich früher auf seinem Forum getestet habe. Und ja, das Leistungsproblem ist nach dem Rückgängigmachen dieses Commits verschwunden.

2 „Gefällt mir“
15

Vielleicht auch ein CPU-Problem. Aber außer wenn Discourse einige Wartungsjobs durchführte, hatten wir fast nie Leistungsprobleme. Nur jetzt mit der Profilseite, deshalb dachte ich an das letzte Update.

Aber ich muss sagen, dass ich vor dem Versuch des Reverts auch app.yml angepasst habe:

  1. Aus irgendeinem Grund hatten wir db_shared_buffers: \"128MB\", viermal weniger als empfohlen, wahrscheinlich ein Überbleibsel aus der Zeit, als ich das Forum zum ersten Mal eingerichtet habe. Ich habe dies auskommentiert, damit Discourse es selbst basierend auf dem Host-RAM einrichten kann.
  2. Außerdem habe ich db_work_mem: \"40MB\" auskommentiert.

Aber ich habe einen ordnungsgemäßen Rebuild durchgeführt und dies zuerst getestet, und es hat uns nicht geholfen. Erst nach dem Revert wurde es besser.

Gerade noch einmal ohne Revert getestet, nur für den Fall, und ich sehe wieder 502 auf Profilen.

Wenn nötig, kann ich weitere Tests mit/ohne Patch durchführen.

1 „Gefällt mir“
16

Gute, gründliche Tests!

Vielleicht, aber wenn man sich die Zeit ansieht, die im Wartezustand verbracht wird, denke ich, dass es hauptsächlich um I/O geht. Sobald der I/O-Engpass behoben ist, kann vmstat zeigen, ob die CPU ausgelastet ist.

2 „Gefällt mir“
17

Das wird es nicht. Sie können discourse-setup ausführen und es wird dies tun (Sie können Strg+C nach der ersten Nachricht drücken) oder die richtige Zahl selbst eingeben.

Es ist oft hilfreich, dies zu erhöhen, aber nur, wenn Sie genügend RAM haben.

Es scheint, dass Ihr ursprüngliches Problem ein Problem mit der Abfrage in der Quelle sein könnte, aber Sie möchten definitiv db_work_mem festlegen. Das Auskommentieren ist (soweit ich weiß) keine Lösung.

2 „Gefällt mir“
18

Die Schlussfolgerung hier ist meiner Meinung nach, dass der akzeptierte Pull-Request, der darauf abzielte, Dinge schneller zu machen, in der Tat Dinge langsamer gemacht oder sogar kaputt gemacht hat, auf Websites mit minimalem RAM?

Können wir diesen Pull-Request rückgängig machen, bis dies verstanden ist?

Können wir die Kategorie dieses Themas auf Fehler ändern?

1 „Gefällt mir“
19

Danke, dass Sie das bemerkt haben, ich wurde durch den Kommentar getäuscht. Es fühlt sich an, als hätte das manuelle Einstellen auf 512 MB ein wenig geholfen, aber die Leistung auf Profilseiten ist immer noch nicht gut genug und dauert manchmal eine halbe Minute zum Laden.

1 „Gefällt mir“