Errore 502 all'apertura di alcuni profili utente

[volas (Alexander V)]

Il server ha problemi con summary.json di alcuni utenti casuali e restituisce il codice 502. Probabilmente è iniziato dopo l’ultimo aggiornamento, ma non ne sono sicuro.

Non ho familiarità con lo stack di discourse e ho difficoltà a trovare i log. Modificato per nascondere nome utente e IP, l’ora può variare ma si tratta per lo più della stessa richiesta di pagina del profilo ripetuta più volte.

Dal file dell’applicazione /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 è vuoto, e /shared/log/rails/production.log contiene solo

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

senza “Completed 200 OK” per richieste simili.

Sembra che non ci siano log correlati in unicorn (solo errori di connessione con redis all’avvio, ma sembra che alla fine abbia successo e non sia correlato).

Ma c’è una richiesta sospetta con una lunga durata da /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 (Alexander V)]

Sembra un problema per ogni profilo utente attivo. A volte richiede molto tempo, a volte è veloce grazie a una cache.

E a volte va fuori tempo e genera un errore 502.

Usiamo questo droppled da DO solo per il forum.

Non molto, ma in passato è stato sufficiente per noi.

[Arkshine]

Posso vedere summary.json che impiega tra i 20 e i 30 secondi per caricarsi.

Inoltre, questi errori nella console:

E a volte 502, infatti:

Guardando la modalità sicura, non sembra che sia correlata a plugin/componenti del tema.

Vedo che sei dietro Cloudflare. Puoi provare a disabilitare qualsiasi ottimizzazione?

[volas (Alexander V)]

@Arkshine

Puoi provare a disabilitare qualsiasi ottimizzazione?

Proxy CF disabilitato.

Ma non sembra un problema di frontend, e più una richiesta DB pesante sul backend.

[volas (Alexander V)]

la nostra lista di plugin

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]

@volas

Non molto, ma in passato era sufficiente per noi.

Non sono un esperto, ma Discourse tende a richiedere più RAM al giorno d’oggi, a seconda della configurazione (almeno 2 GB). Hai configurato uno swap?

Vedi informazioni pertinenti nel percorso /logs?

Per quanto riguarda i plugin, a prima vista non vedo plugin difettosi.

Spero che qualcuno possa fornire maggiori informazioni qui.

[volas (Alexander V)]

Sì, 4 GB di swap. E in /logs solo alcuni avvisi come notifiche di deprecazione o qualcosa su 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

Per quanto ho capito, si tratta di una richiesta per “Most Replied To” (Più risposte date), ed è stata modificata di recente in PERF: Improve performance of `most_replied_to_users` by janzenisaac · Pull Request #26373 · discourse/discourse · GitHub, quindi forse questa patch ci sta influenzando.

Ho eseguito EXPLAIN ANALYZE se può aiutare:

 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]

Potrebbe essere utile avere
vmstat 5
in esecuzione sul server (in una connessione ssh) mentre fai questo, per vedere cosa potrebbe succedere con il paging. (top può essere usato ma è molto meno utile qui)

[pfaffman (Jay Pfaffman)]

Quanta RAM hai? Quanto è grande il tuo database? È probabile che tu abbia solo bisogno di più RAM.

[volas (Alexander V)]

Sembra che postgresql faccia delle ottimizzazioni/cache, quindi a volte non ci vuole molto tempo, quindi devo cercare nuovi utenti per testare le richieste.

@Ed_S

vmstat 5

  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

@pfaffman

Quanta RAM hai? Quanto è grande il tuo database? È probabile che ti serva solo più RAM.

   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 di RAM + 4 GB di swap, stiamo usando questo droplet (CPU legacy) da DigitalOcean

[volas (Alexander V)]

Voglio provare a testarlo con le modifiche annullate da PERF: Improve performance of `most_replied_to_users` (#26373) · discourse/discourse@db10dd5 · GitHub, ma nonostante abbia modificato app/models/user_summary.rb mentre ero nel container di discourse, vedo ancora che la pagina del profilo effettua questa richiesta con tre JOIN.

Devo pulire la cache da qualche parte? O c’è un modo migliore per farlo.

AGGIORNAMENTO: Il riavvio del container ha aiutato, e sembra che ora funzioni meglio dopo l’annullamento! Le pagine del profilo si caricano più velocemente e non ci sono errori 502.

[Arkshine]

Confermo; ora è incredibilmente veloce e non vedo errori.

[Ed_S]

@volas

Sembra che postgresql…

Grazie per l’output di vmstat. Per me, questo indica che la memoria non è sovra-allocata - linux non sta facendo swapping - ma il database non è stato in grado di allocare abbastanza RAM - sta facendo molto I/O su disco.

Quindi penso che questo sarebbe un caso di necessità di più RAM, e l’aggiunta di swap non aiuterebbe molto.

@Arkshine

confermo

Quindi anche tu hai annullato la modifica e hai riscontrato che le prestazioni sono tornate alla normalità?

[Arkshine]

@Ed_S

Anche tu hai annullato la modifica e hai riscontrato che le prestazioni sono tornate alla normalità?

@volas

AGGIORNAMENTO: Il riavvio del container ha aiutato, e sembra che ora funzioni meglio dopo l’annullamento! Le pagine del profilo si caricano più velocemente e non ci sono errori 502.

Non io, Alexander, nel suo post sopra. Volevo confermarlo, dato che stavo testando in precedenza sul suo forum. E sì, il problema delle prestazioni è scomparso dopo aver annullato quel commit.

[volas (Alexander V)]

@Ed_S

Grazie per l’output di vmstat. Per me, questo indica che la memoria non è sovra-allocata - linux non sta facendo swapping - ma il database non è riuscito ad allocare abbastanza RAM - sta facendo molto I/O su disco.

Forse anche un problema di CPU. Ma tranne quando discourse stava eseguendo alcuni lavori di manutenzione, non abbiamo quasi mai avuto problemi di prestazioni prima. Solo ora con la pagina del profilo, quindi stavo pensando all’ultimo aggiornamento.

Ma dovrei dire che prima di provare a ripristinare ho anche modificato app.yml:

1. Per qualche motivo avevamo db_shared_buffers: \"128MB\", quattro volte meno del raccomandato, probabilmente un residuo del tempo in cui stavo configurando il forum per la prima volta. Ho commentato questa riga, così discourse può impostarla da solo in base alla RAM dell’host.
2. Ho anche decommentato db_work_mem: \"40MB\"

Ma ho fatto una ricostruzione completa e testato prima questo, e non ci ha aiutato. Solo dopo il ripristino è migliorato.

Proprio ora ho testato di nuovo senza ripristino per sicurezza, e vedo di nuovo 502 sui profili.

Se necessario posso fare altri test con/senza patch.

[Ed_S]

@volas

Solo dopo il ripristino è migliorato.

Testato di nuovo adesso senza ripristino

Buon test approfondito!

@volas

Forse anche un problema di CPU

Forse, ma guardando il tempo trascorso in Attesa, penso che si tratti principalmente di I/O. Una volta risolto il collo di bottiglia I/O, vmstat potrà mostrare se la CPU è al massimo.

[pfaffman (Jay Pfaffman)]

@volas

Ho commentato questa riga, così discourse può impostarla da solo in base alla RAM dell’host

Non lo farà. Puoi eseguire discourse-setup e lo farà lui (puoi premere control-c dopo il primo messaggio) o inserire tu stesso il numero corretto.

@volas

Inoltre ho decommentato db_work_mem: "40MB"

Spesso è utile aumentarlo, ma solo se hai abbastanza RAM.

Sembra che il tuo problema originale possa essere un problema con la query nella sorgente, ma vuoi assolutamente impostare db_work_mem. Commentarlo non è una soluzione (per quanto ne so)

[Ed_S]

La conclusione qui, credo, è che la pull request accettata, intesa a velocizzare le cose, abbia in realtà rallentato le cose, o addirittura rotto, sui siti con RAM minima?

Possiamo annullare quella pull request finché questo non sarà compreso?

Possiamo cambiare la categoria di questo argomento in bug?

[volas (Alexander V)]

@pfaffman

Non lo farà. Puoi eseguire discourse-setup e lo farà (puoi premere control-c dopo il primo messaggio) o inserire tu stesso il numero corretto.

Grazie per averlo notato, sono stato tratto in inganno dal commento allora. Sembra che impostare manualmente questo valore a 512 MB abbia aiutato un po’, ma le prestazioni sulle pagine del profilo non sono ancora abbastanza buone e a volte impiegano mezzo minuto per caricarsi.