Медленная загрузка private-message-topic-tracking-state.json

Начиная с версии 2.8.0.beta5, загрузка общей папки входящих сообщений занимает более 4 секунд, при этом основная часть времени (2–3 секунды) тратится на выполнение огромного SQL-запроса в файле private-message-topic-tracking-state.json.

У нас около 800 тысяч тем, 3,8 миллиона пользователей и, вероятно, большой граф непрочитанных личных сообщений, но я не вижу ничего примечательного в анализе запроса (возможно, я просто плохо умею его читать).

До версии beta5 всё работало нормально, а теперь отслеживать папки личных сообщений стало очень сложно и раздражающе.

1 лайк

Хм, у нас на Meta в среднем это занимает 200 мс.

Тем не менее, довольно подозрительно, что переход в сообщения в вашем профиле теперь вызывает три отдельных запроса, и тот, о котором вы говорите, возвращает JSON объёмом 92 КБ с 900 объектами :scream:

2 лайка

Кажется, это также сбрасывает состояние miniprofiler’а на полпути, поэтому я даже не могу получить SQL-запрос, чтобы корректно выполнить его EXPLAIN.

2 лайка

Да, переход маршрута ведёт себя ненормально.

Кстати, я составил план здесь: ieWq | explain.depesz.com

3 лайка

Это исправление должно снизить время до примерно 13 мс.

Обратите внимание: чем больше непрочитанных сообщений у вас есть, тем дороже будет выполняться запрос.

@sam Ещё одно, что мне нужно исправить: отметка непрочитанного как прочитанного не обновляет оптимизацию first_unread_at, которую мы используем для обычных тем и личных сообщений.

4 лайка

1,73 секунды после выбора этого изменения и перезапуска unicorn, но время непрочитанных сообщений для меня и моих групп, вероятно, значительно отстает (я вижу только 59 новых и 4 непрочитанных сообщения для этого почтового ящика — этот маршрут относится к каждому пользователю? хотя даже для «всех сообщений» у меня 61 новое и 7 непрочитанных).

1 лайк

Соответствует ли время последнего прочтения непрочитанным сообщениям в ваших почтовых ящиках?

1 лайк
discourse=# select first_unread_pm_at from group_users where user_id = 2334 order by first_unread_pm_at asc;
     first_unread_pm_at
----------------------------
 2021-09-03 06:54:13.493514
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
 2021-09-03 07:05:33.138986
(17 строк)
discourse=# select first_unread_pm_at from user_stats where user_id = 2334;
     first_unread_pm_at
----------------------------
 2021-09-03 07:05:00.565522
(1 строка)

Любопытно, что диапазон даже не такой большой, значит, какое-то другое условие работает медленно (хотя, загадочным образом, после отметки нескольких непрочитанных как прочитанные время выполнения сократилось до 700 мс, что вполне приемлемо. Не уверен, каким был мой диапазон first_unread_pm_at раньше — может быть, несколько недель?).

Есть ли способ получить запрос из miniprofiler после того, как он обновится и удалит все старые запросы на странице сообщений, чтобы я мог выполнить EXPLAIN?

Это действительно странно, но мне не удаётся воспроизвести это в среде разработки. На следующей неделе я уделю этому время и разберусь.

1 лайк

Исправлено в

1 лайк

Спасибо! Постараюсь не забыть проверить это снова во время следующего окна пересборки/перезапуска.

1 лайк

Получил план запроса/результат EXPLAIN ANALYZE (вплоть до 1,3 с :confused:): CvUX | explain.depesz.com

После выполнения reindex index concurrently index_topics_on_timestamps_private; скорость немного улучшилась (768 мс), так что это может быть просто артефактом большого количества предыдущих ЛС (бот-рассказчик до очистки сильно засорял таблицу ЛС!)… хотя на том же индексе запрос всё ещё работает медленно

Не могли бы вы выполнить Topic.where(archetype: Archetype.private_message).count в консоли Rails для меня?

Кстати, запрос теперь выполняется асинхронно, поэтому он не будет блокировать загрузку страницы сообщений или приватного сообщения.

[1] pry(main)> Topic.where(archetype: Archetype.private_message).count
=> 543855

Могло быть и хуже — мы недавно удалили все оставшиеся темы бота-нарратива. :sweat_smile: Всё равно больше, чем я ожидал!

А, вот почему этот запрос в miniprofiler появлялся только через некоторое время. Отлично!

Мы недавно обновились, чтобы получить эту функцию FEATURE: New and Unread messages for user personal messages. by tgxworld · Pull Request #13603 · discourse/discourse · GitHub (то есть сейчас на версии 2.8.0beta6).

Похоже, что запрос «получить все личные сообщения для пользователя», который в конечном итоге приводит к ссылке FEATURE: New and Unread messages for user personal messages. by tgxworld · Pull Request #13603 · discourse/discourse · GitHub, генерирует следующий запрос —

SELECT "topics"."id", "topics"."title", "topics"."last_posted_at", "topics"."created_at", "topics"."updated_at", "topics"."views", "topics"."posts_count", "topics"."user_id", "topics"."last_post_user_id", "topics"."reply_count", "topics"."featured_user1_id", "topics"."featured_user2_id", "topics"."featured_user3_id", "topics"."deleted_at", "topics"."highest_post_number", "topics"."like_count", "topics"."incoming_link_count", "topics"."category_id", "topics"."visible", "topics"."moderator_posts_count", "topics"."closed", "topics"."archived", "topics"."bumped_at", "topics"."has_summary", "topics"."archetype", "topics"."featured_user4_id", "topics"."notify_moderators_count", "topics"."spam_count", "topics"."pinned_at", "topics"."score", "topics"."percent_rank", "topics"."subtype", "topics"."slug", "topics"."deleted_by_id", "topics"."participant_count", "topics"."word_count", "topics"."excerpt", "topics"."pinned_globally", "topics"."pinned_until", "topics"."fancy_title", "topics"."highest_staff_post_number", "topics"."featured_link", "topics"."reviewable_score", "topics"."image_upload_id", "topics"."slow_mode_seconds" FROM "topics" LEFT OUTER JOIN topic_users AS tu ON (topics.id = tu.topic_id AND tu.user_id = 1234) LEFT JOIN group_archived_messages gm ON gm.topic_id = topics.id
LEFT JOIN user_archived_messages um
ON um.user_id = 1234
AND um.topic_id = topics.id WHERE "topics"."deleted_at" IS NULL AND (topics.id IN (
SELECT topic_id
FROM topic_allowed_users
WHERE user_id = 1234
 UNION ALL
SELECT topic_id FROM topic_allowed_groups
 WHERE group_id IN (
SELECT group_id FROM group_users WHERE user_id = 1234
  )
)) AND "topics"."archetype" = 'private_message' AND "topics"."visible" = TRUE AND (um.user_id IS NULL AND gm.topic_id IS NULL) ORDER BY topics.bumped_at DESC LIMIT 30;

Это буквально вешает наш сервер RDS. Я думаю, что кто-то из нашей команды предложил фильтровать данные с помощью имеющихся у нас индексов перед выполнением соединений. Этот запрос выполняется за < 100 мс.

SELECT "topics_filter"."id", "topics_filter"."title", "topics_filter"."last_posted_at", "topics_filter"."created_at", "topics_filter"."updated_at",
"topics_filter"."views", "topics_filter"."posts_count", "topics_filter"."user_id", "topics_filter"."last_post_user_id", "topics_filter"."reply_count", "topics_filter"."featured_user1_id",
"topics_filter"."featured_user2_id", "topics_filter"."featured_user3_id", "topics_filter"."deleted_at", "topics_filter"."highest_post_number", "topics_filter"."like_count",
"topics_filter"."incoming_link_count", "topics_filter"."category_id", "topics_filter"."visible", "topics_filter"."moderator_posts_count", "topics_filter"."closed",
"topics_filter"."archived", "topics_filter"."bumped_at", "topics_filter"."has_summary", "topics_filter"."archetype", "topics_filter"."featured_user4_id", "topics_filter"."notify_moderators_count",
"topics_filter"."spam_count", "topics_filter"."pinned_at", "topics_filter"."score", "topics_filter"."percent_rank", "topics_filter"."subtype", "topics_filter"."slug",
"topics_filter"."deleted_by_id", "topics_filter"."participant_count", "topics_filter"."word_count", "topics_filter"."excerpt", "topics_filter"."pinned_globally",
"topics_filter"."pinned_until", "topics_filter"."fancy_title", "topics_filter"."highest_staff_post_number", "topics_filter"."featured_link", "topics_filter"."reviewable_score",
"topics_filter"."image_upload_id", "topics_filter"."slow_mode_seconds"
FROM (select * from "topics"
      where "topics"."deleted_at" IS NULL
      and (topics.id IN ( SELECT topic_id FROM topic_allowed_users WHERE user_id = 1234
                          UNION ALL
                          SELECT topic_id FROM topic_allowed_groups  WHERE group_id IN ( SELECT group_id FROM group_users WHERE user_id = 1234 )
                         ))
      AND "topics"."archetype" = 'private_message'
      AND "topics"."visible" = TRUE
      )   as topics_filter
LEFT OUTER JOIN (select topic_id from topic_users where user_id = 1234) AS tu ON (topics_filter.id = tu.topic_id )
LEFT JOIN group_archived_messages gm ON gm.topic_id = topics_filter.id
LEFT JOIN ( select user_id, topic_id from user_archived_messages where user_id = 1234) um
ON um.topic_id = topics_filter.id
WHERE (um.user_id IS NULL AND gm.topic_id IS NULL) ORDER BY topics_filter.bumped_at DESC LIMIT 30;

Для справки: в таблице topics более 10 млн строк, в таблице topic_users — более 50 млн строк.

Возможно ли как-то перестроить этот запрос, чтобы решить эти проблемы?

Редактирование:

Только для уточнения: когда мы проверяем наши более длительные запросы (> 2 минут или даже 5 минут), появляются только эти запросы. С последним изменением загрузка CPU нашего Postgres постоянно составляет 99%. Когда я завершаю эти запросы, мы видим, что использование CPU возвращается к норме.

3 лайка

@tgxworld Извините, что отмечу вас напрямую, но так как вы автор, хотел бы узнать, есть ли у вас какие-либо предложения или отзывы.

1 лайк

Насколько я помню, @sam всегда описывал это как рискованную и опасную функцию. Большие регрессии здесь меня не удивят.

Мы нашли эту тему с багом после публикации: Slow loading on private-message-topic-tracking-state.json - #9 by tgxworld

Похоже, что после коммита, помеченного как v2.8.0beta6, есть ещё один коммит, который, судя по всему, решает часть этой проблемы с производительностью. Мы попробуем пересобрать, указав ссылку на этот конкретный коммит, и посмотрим, поможет ли это что-то исправить.

2 лайка

Какой у вас сейчас тип экземпляра RDS и общий размер базы данных?

1 лайк

db.m5.2xlarge

~ 250 ГБ с точки зрения использования диска.

1 лайк