Error 502 al abrir algunos perfiles de usuario

Error
1

El servidor tiene problemas con summary.json de algunos usuarios aleatorios y devuelve el código 502. Probablemente comenzó después de la última actualización, pero no estoy seguro.

No estoy familiarizado con la pila de Discourse y tengo dificultades para buscar registros. Editado para ocultar el nombre de usuario y la IP, el tiempo puede variar, pero en su mayoría es la misma solicitud de página de perfil repetida varias veces.

Desde la aplicación /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 está vacío, y /shared/log/rails/production.log solo contiene

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

sin “Completed 200 OK” para solicitudes similares.

Parece que no hay registros relacionados en unicorn (solo errores de conexión con redis al inicio, pero parece exitoso al final y no está relacionado).

Pero hay una solicitud sospechosa con un tiempo de duración largo de /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 me gusta
2

Parece un problema para cada perfil de usuario activo. A veces lleva mucho tiempo, a veces es rápido debido a alguna caché.

Y a veces simplemente se agota el tiempo y lanza un error 502.

Estamos usando este droppled de DO solo para el foro.
Снимок экрана от 2024-05-25 00-12-28

No mucho, pero fue suficiente para nosotros en el pasado.

3

Puedo ver summary.json que tarda entre 20 y 30 segundos en cargarse.

También, estos errores en la consola:

image
image1342×190 14.1 KB

Y a veces 502, de hecho:

image
image799×111 5.06 KB

Mirando el modo seguro, no parece que esté relacionado con plugins/componentes de tema.

Veo que estás detrás de Cloudflare. ¿Puedes intentar deshabilitar alguna optimización?

1 me gusta
4

Proxy de CF deshabilitado.

Pero no parece un problema de frontend, sino más bien una solicitud pesada de la base de datos en el backend.

1 me gusta
5

nuestra lista de plugins

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

No soy un experto, pero Discourse tiende a requerir más RAM hoy en día, dependiendo de tu configuración (al menos 2 GB). ¿Tienes configurado un swap?

¿Ves alguna información relevante en la ruta /logs?

En cuanto a los plugins, a primera vista no veo ningún plugin defectuoso. :thinking:

Espero que alguien pueda ofrecer mejores ideas aquí.

7

Sí, 4 GB de swap. Y en /logs solo algunas advertencias como avisos de deprecación o algo sobre 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

Según entiendo, es una consulta para “Los más respondidos”, y fue modificada recientemente en PERF: Improve performance of `most_replied_to_users` by janzenisaac · Pull Request #26373 · discourse/discourse · GitHub, así que tal vez este parche nos está afectando.

Hice EXPLAIN ANALYZE por si puede ayudar:

 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

Podría ser útil tener
vmstat 5
ejecutándose en el servidor (en una conexión ssh) mientras haces esto, para ver qué podría estar pasando con la paginación. (se puede usar top pero es mucho menos útil aquí)

3 Me gusta
9

¿Cuánta RAM tienes? ¿Qué tamaño tiene tu base de datos? Es probable que solo necesites más RAM.

2 Me gusta
10

Parece que PostgreSQL realiza algunas optimizaciones/caché, por lo que a veces no lleva mucho tiempo, así que necesito buscar nuevos usuarios para probar las solicitudes.

  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 de RAM + 4 GB de swap, estamos usando esta droplet (CPU heredada) de DigitalOcean

11

Quiero intentar probarlo con los cambios revertidos de PERF: Improve performance of `most_replied_to_users` (#26373) · discourse/discourse@db10dd5 · GitHub, pero a pesar de editar app/models/user_summary.rb mientras estaba en el contenedor de discourse, todavía veo que la página de perfil realiza esta solicitud con tres JOIN.

¿Necesito limpiar la caché en algún lugar? ¿O hay una mejor manera de hacerlo?

ACTUALIZACIÓN: Reiniciar el contenedor ayudó, ¡y parece que ahora funciona mejor después de la reversión! Las páginas de perfil cargan más rápido y no hay errores 502.

3 Me gusta
12

Confirmo; ahora es increíblemente rápido y no veo ningún error.

2 Me gusta
13

Gracias por la salida de vmstat. Para mí, eso dice que la memoria no está sobrecomprometida - linux no está intercambiando - pero la base de datos no ha podido asignar suficiente RAM - está haciendo mucha E/S de disco.

Así que creo que este sería un caso de que se necesita más RAM, y agregar intercambio no ayudaría mucho.

¿Así que tú también has revertido el cambio y has descubierto que el rendimiento ha vuelto a la normalidad?

1 me gusta
14

Yo no, Alexander, en su publicación anterior. Quería confirmarlo, ya que estuve probando antes en su foro. Y sí, el problema de rendimiento ha desaparecido al revertir ese commit.

2 Me gusta
15

Quizás también sea un problema de CPU. Pero excepto cuando discourse estaba ejecutando algunas tareas de mantenimiento, casi nunca tuvimos problemas de rendimiento antes. Solo ahora con la página de perfil, así que estaba pensando en la última actualización.

Pero debo decir que antes de intentar revertir, también modifiqué app.yml:

  1. Por alguna razón teníamos db_shared_buffers: \"128MB\", cuatro veces menos de lo recomendado, probablemente algo heredado de la época en que configuré el foro por primera vez. He comentado esto, para que discourse pueda configurarlo él mismo basándose en la RAM del host.
  2. También he descomentado db_work_mem: \"40MB\"

Pero hice una reconstrucción adecuada y probé esto primero, y no nos ayudó. Solo después de revertir mejoró.

Acabo de probar de nuevo sin revertir por si acaso, y puedo ver 502 en los perfiles de nuevo.

Si es necesario, puedo hacer más pruebas con/sin parche.

1 me gusta
16

¡Buenas pruebas exhaustivas!

Quizás, pero viendo el tiempo dedicado a la espera, creo que se trata principalmente de E/S. Una vez que se solucione el cuello de botella de E/S, vmstat podrá mostrar si la CPU está al máximo.

2 Me gusta
17

No lo hará. Puedes ejecutar discourse-setup y lo hará (puedes presionar control-c después del primer mensaje) o introducir el número correcto tú mismo.

A menudo es útil aumentar esto, pero solo si tienes suficiente RAM.

Parece que tu problema original podría ser un problema con la consulta en la fuente, pero definitivamente quieres configurar db_work_mem. Comentarlo no es una solución (hasta donde yo sé).

2 Me gusta
18

La conclusión aquí, creo, es que la solicitud de extracción aceptada, destinada a hacer las cosas más rápidas, en realidad las ha hecho más lentas, o incluso las ha roto, en sitios con RAM mínima.

¿Podemos revertir esa solicitud de extracción hasta que esto se entienda?

¿Podemos cambiar la categoría de este tema a error?

1 me gusta
19

Gracias por notarlo, me equivoqué por el comentario. Siento que establecer esto en 512 MB manualmente ayudó un poco, pero el rendimiento en las páginas de perfil todavía no es lo suficientemente bueno y a veces tarda medio minuto en cargarse.

1 me gusta