private-message-topic-tracking-state.json 로딩이 느립니다

2.8.0.beta5 이후 그룹 개인 메시지(PM) 수신함을 불러오는 데 4초 이상 걸리며, 이 중 대부분(2~3초)이 private-message-topic-tracking-state.json의 방대한 SQL 쿼리에 소요되고 있습니다.

현재 약 80만 개의 토픽, 약 380만 명의 사용자를 보유하고 있으며, 읽지 않은 PM과 사용자 간의 그래프도 상당히 크리라 생각됩니다. 하지만 쿼리 분석 결과에서 특별히 눈에 띄는 문제는 잘 보이지 않습니다(아마도 분석 결과를 제대로 읽지 못하고 있는 것 같습니다).

beta5 이전에는 문제가 없었지만, 지금은 PM 수신함을 관리하는 것이 매우 어렵고 귀찮습니다.

1개의 좋아요

음, 여기서는 Meta에서 평균 200ms 정도 걸립니다.

그럼에도 불구하고, 이제 프로필에서 메시지로 이동하면 3개의 서로 다른 fetch 요청이 발생하고, 언급하신 그 요청이 제 경우 900개 객체를 포함한 92kB의 JSON을 반환하는 것은 꽤 의심스럽습니다 :scream:

2개의 좋아요

실제로 miniprofiler의 상태가 중간에 무효화되는 것 같아서 SQL 쿼리를 제대로 EXPLAIN할 수도 없습니다.

2개의 좋아요

네, 해당 라우트 전환이 정상적으로 작동하지 않는 것 같습니다.

참고로 여기에서 실행 계획을 추출했습니다: ieWq | explain.depesz.com

3개의 좋아요

이 수정으로 13ms 정도로 줄어들 것입니다.

읽지 않은 항목이 많을수록 쿼리 비용이 더 커진다는 점에 유의하세요.

@sam 수정해야 할 또 다른 사항은 읽지 않은 항목을 무시할 때 일반 주제와 PM 주제에 대해 가지고 있는 first_unread_at 최적화가 업데이트되지 않는다는 것입니다.

4개의 좋아요

1.73초 후에 이 변경사항을 체리픽하고 유니콘을 재시작했지만, 나와 내 그룹의 읽지 않음 시각은 아마 꽤 뒤처져 있을 것입니다. 이 받은 편지함에서는 새 메시지 59개와 읽지 않은 메시지 4개만 표시되고 있거든요. 이 라우트는 사용자별로 처리되는 건가요? 그런데 '모든 메시지’에서도 새 메시지 61개와 읽지 않은 메시지 7개만 표시되고 있습니다.

1개의 좋아요

읽지 않은 시간(unread-at)이 받은 편지함의 읽지 않은 항목 수와 일치하나요?

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 rows)
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 row)

흥미롭게도 범위가 그렇게 크지 않은데도 다른 조건이 느린 것 같습니다(다만, 신기하게도 읽지 않은 메시지를 몇 개 처리한 후 지금은 700ms로 빨라졌는데, 이는 감내할 수 있는 수준입니다. 이전 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; 실행 후 약간 빨라졌습니다 (768ms). 따라서 이전 DM이 많이 쌓여 있는 것이 원인일 수 있습니다 (정리 작업 전의 내러티브 봇이 DM 테이블을 많이 오염시켰었거든요!)… 하지만 같은 인덱스에서 여전히 느립니다.

Rails 콘솔에서 Topic.where(archetype: Archetype.private_message).count를 실행해 주실 수 있나요?

참고로, 현재 이 쿼리는 비동기 방식으로 실행되므로 메시지 페이지나 개인 메시지의 로딩을 차단하지 않습니다.

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

훨씬 나쁠 수도 있었을 텐데, 최근 남은 내러티브 봇 토픽을 모두 정리했으니 다행입니다. :sweat_smile: 그래도 예상보다 많네요!

아, 왜 그 쿼리가 이제 미니프로파일러에 한참 후에야 표시되는지 궁금했었는데. 좋습니다!

최근에 해당 기능을 반영하기 위해 다시 업데이트를 했습니다 (현재 2.8.0beta6 버전).

사용자의 모든 개인 메시지(PM)를 가져오는 로직이 결국 FEATURE: New and Unread messages for user personal messages. - 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 서버를 멈추게 합니다. 팀의 한 멤버가 조인(join)을 수행하기 전에 우리가 가지고 있는 인덱스를 사용하여 데이터를 필터링하라고 제안했습니다. 이렇게 하면 쿼리 실행 시간이 100ms 미만으로 줄어듭니다.

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 테이블은 1,000만 행 이상, topic_users 테이블은 5,000만 행 이상의 데이터를 가지고 있습니다.

이러한 문제를 해결하기 위해 쿼리를 재구성하는 것이 가능한가요?

수정:

명확히 하기 위해, 2분 또는 심지어 5분 이상 실행되는 쿼리를 조사해 보면, 이 쿼리들이 유일하게 나타납니다. 최신 변경 사항 이후로, 우리의 Postgres CPU 사용률이 지속적으로 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

디스크 사용량 기준 약 250GB입니다.

1개의 좋아요