Ошибка 502 при открытии некоторых профилей пользователей

Внести вклад Ошибка
1

Сервер испытывает проблемы с файлом 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
1 лайк
2

Похоже, это проблема для каждого активного профиля пользователя. Иногда это просто занимает много времени, иногда быстро благодаря кэшу.

А иногда просто истекает время и возвращается ошибка 502.

Мы используем этот Droplet от DO только для форума.
Снимок экрана от 2024-05-25 00-12-28

Немного, но нам этого хватало в прошлом.

3

Я вижу файл summary.json, загрузка которого занимает от 20 до 30 секунд.

Также в консоли есть следующие ошибки:

image
image1342×190 14.1 KB

А иногда и 502 ошибка, действительно:

image
image799×111 5.06 KB

Судя по безопасному режиму, проблема не связана с плагинами или компонентами темы.

Я вижу, что вы используете Cloudflare. Можете ли вы попробовать отключить какие-либо оптимизации?

1 лайк
4

Отключил прокси CF.

Но похоже, что проблема не во фронтенде, а в тяжёлом запросе к базе данных на бэкенде.

1 лайк
5

список наших плагинов

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

Я не эксперт, но сейчас Discourse, в зависимости от вашей конфигурации, обычно требует больше оперативной памяти (как минимум 2 ГБ). У вас настроен файл подкачки?

Есть ли какая-либо важная информация в маршруте /logs?

Что касается плагинов, на первый взгляд я не вижу проблемных плагинов. :thinking:

Надеюсь, кто-нибудь сможет дать здесь более подробные разъяснения.

7

Да, 4 ГБ подкачки. И в /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)
8

Полезно будет запустить
vmstat 5
на сервере (в сеансе SSH), пока вы это делаете, чтобы увидеть, что происходит с подкачкой. (Можно использовать top, но в данном случае он гораздо менее полезен)

3 лайка
9

Сколько у вас оперативной памяти? Каков размер вашей базы данных? Скорее всего, вам просто нужно больше оперативной памяти.

2 лайка
10

Похоже, 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 |

2 ГБ ОЗУ + 4 ГБ swap, мы используем этот (устаревший CPU) дроплет от DigitalOcean

11

Я хочу протестировать это с откатом изменений из PERF: Improve performance of `most_replied_to_users` (#26373) · discourse/discourse@db10dd5 · GitHub, но, несмотря на то, что я редактировал app/models/user_summary.rb внутри контейнера Discourse, страница профиля по-прежнему выполняет этот запрос с тремя JOIN’ами.

Мне нужно очистить кэш где-то? Или есть лучший способ сделать это.

ОБНОВЛЕНИЕ: Перезапуск контейнера помог, и, похоже, после отката всё работает лучше! Страницы профилей загружаются быстрее, и ошибок 502 больше нет.

3 лайка
12

Подтверждаю: теперь это невероятно быстро, и я не вижу никаких ошибок.

2 лайка
13

Спасибо за вывод vmstat. Для меня это означает, что память не перераспределена — Linux не использует подкачку, — но базе данных не удалось выделить достаточно оперативной памяти, поэтому она выполняет много операций ввода-вывода на диск.

Поэтому я считаю, что в данном случае требуется больше оперативной памяти, и добавление раздела подкачки мало поможет.

Значит, вы тоже отменили изменение и обнаружили, что производительность вернулась к норме?

1 лайк
14

Это не я, Александр, в своём сообщении выше. Я хотел это подтвердить, так как ранее тестировал на вашем форуме. И да, проблема с производительностью исчезла после отката того коммита.

2 лайка
15

Возможно, проблема также в процессоре. Однако, за исключением случаев, когда Discourse выполнял задачи обслуживания, у нас практически никогда не было проблем с производительностью. Сейчас проблема возникает только на странице профиля, поэтому я подумал о последнем обновлении.

Но стоит сказать, что перед попыткой отката я также внес изменения в файл app.yml:

  1. По какой-то причине у нас было установлено значение db_shared_buffers: "128MB", что в четыре раза меньше рекомендуемого, вероятно, это наследие от времени, когда я впервые настраивал форум. Я закомментировал эту строку, чтобы Discourse мог настроить параметр самостоятельно на основе объема оперативной памяти хоста.
  2. Также я раскомментировал строку db_work_mem: "40MB".

Однако я выполнил корректную пересборку и сначала протестировал эти изменения, но это не помогло. Ситуация улучшилась только после отката.

Только что снова протестировал без отката, на всякий случай, и снова вижу ошибку 502 на страницах профилей.

При необходимости я могу провести дополнительные тесты с патчем и без него.

1 лайк
16

Отличное тщательное тестирование!

Возможно, но, судя по времени, затраченному на ожидание, я думаю, что дело в основном в операциях ввода-вывода (I/O). Как только узкое место в I/O будет устранено, утилита vmstat покажет, загружен ли процессор на 100%.

2 лайка
17

Это не сработает. Вы можете запустить discourse-setup, и он сделает это (вы можете прервать процесс нажатием Ctrl+C после первого сообщения) или ввести правильное число самостоятельно.

Часто полезно увеличить это значение, но только если у вас достаточно оперативной памяти.

Похоже, что ваша первоначальная проблема может быть связана с запросом в источнике, но вам определённо стоит установить db_work_mem. Комментирование этого параметра не является решением (насколько мне известно).

2 лайка
18

Я считаю, что вывод здесь таков: принятый pull request, который должен был ускорить работу, на самом деле замедлил её или даже сломал функциональность на сайтах с минимальным объёмом оперативной памяти.

Можно ли откатить этот pull request, пока ситуация не будет прояснена?

Можно ли изменить категорию этой темы на «баг»?

1 лайк
19

Спасибо, что обратили на это внимание, меня ввёл в заблуждение тот комментарий. Похоже, ручная установка значения в 512 МБ немного помогла, но производительность на страницах профилей всё ещё недостаточна: иногда загрузка занимает полминуты.

1 лайк