POST /api/notes/children runs into timeouts

puniko commented

2022-11-29 10:28:23 +00:00

Contributor

Not sure if this is just on my instance, but most of the time, the /api/notes/children endpoint returns a 500 indicating a timeout in query execution.

this has the effect, that it can't show replies to threads

EDIT: played around a bit (for a couple of minutes) to send different limits and depths params. as soon as i set limit > 1, it timeouts.

EDIT 2: did a bit more digging. seems like either the join on avatar or on the banner (or both) are causing the issue (

.leftJoinAndSelect('user.avatar', 'avatar')

)

EDIT 3: its definitly both. without those 2 joins, the query returns data instantly

Not sure if this is just on my instance, but most of the time, the /api/notes/children endpoint returns a 500 indicating a timeout in query execution. this has the effect, that it can't show replies to threads EDIT: played around a bit (for a couple of minutes) to send different limits and depths params. as soon as i set limit > 1, it timeouts. EDIT 2: did a bit more digging. seems like either the join on avatar or on the banner (or both) are causing the issue (https://akkoma.dev/FoundKeyGang/FoundKey/src/commit/6efc3b7989bdd6ed0710fd2927b6a5e05077f359/packages/backend/src/server/api/endpoints/notes/children.ts#L55) EDIT 3: its definitly both. without those 2 joins, the query returns data instantly

puniko commented

2022-11-29 11:01:29 +00:00

Author

Contributor

considering that this seems to be an issue with drive files, i suspect #143 is maybe related to this

considering that this seems to be an issue with drive files, i suspect https://akkoma.dev/FoundKeyGang/FoundKey/issues/143 is maybe related to this

puniko commented

2022-11-29 12:51:24 +00:00

Author

Contributor

EXPLAIN on the query shows me 2 parts with an awefull high cost

->  Hash Join  (cost=591010.12..1640990.66 rows=5586168 width=2937) (actual time=53684.512..53723.567 rows=1 loops=1)

and

->  Hash  (cost=532339.23..532339.23 rows=198366 width=2295) (actual time=53630.359..53630.362 rows=197874 loops=1)

i checked the indexes and it seems that every field, where this query is joining has an index. so doesn't look to me, that its an indexing issue (might be wrong with this tho)

Full Query:

EXPLAIN ANALYZE 
SELECT 
  "note"."id" AS "note_id", 
  "note"."createdAt" AS "note_createdAt", 
  "note"."replyId" AS "note_replyId", 
  "note"."renoteId" AS "note_renoteId", 
  "note"."threadId" AS "note_threadId", 
  "note"."text" AS "note_text", 
  "note"."name" AS "note_name", 
  "note"."cw" AS "note_cw", 
  "note"."userId" AS "note_userId", 
  "note"."localOnly" AS "note_localOnly", 
  "note"."renoteCount" AS "note_renoteCount", 
  "note"."repliesCount" AS "note_repliesCount", 
  "note"."reactions" AS "note_reactions", 
  "note"."visibility" AS "note_visibility", 
  "note"."uri" AS "note_uri", 
  "note"."url" AS "note_url", 
  "note"."fileIds" AS "note_fileIds", 
  "note"."attachedFileTypes" AS "note_attachedFileTypes", 
  "note"."visibleUserIds" AS "note_visibleUserIds", 
  "note"."mentions" AS "note_mentions", 
  "note"."emojis" AS "note_emojis", 
  "note"."tags" AS "note_tags", 
  "note"."hasPoll" AS "note_hasPoll", 
  "note"."channelId" AS "note_channelId", 
  "note"."userHost" AS "note_userHost", 
  "note"."replyUserId" AS "note_replyUserId", 
  "note"."replyUserHost" AS "note_replyUserHost", 
  "note"."renoteUserId" AS "note_renoteUserId", 
  "note"."renoteUserHost" AS "note_renoteUserHost", 
  "user"."id" AS "user_id", 
  "user"."createdAt" AS "user_createdAt", 
  "user"."updatedAt" AS "user_updatedAt", 
  "user"."lastFetchedAt" AS "user_lastFetchedAt", 
  "user"."lastActiveDate" AS "user_lastActiveDate", 
  "user"."hideOnlineStatus" AS "user_hideOnlineStatus", 
  "user"."username" AS "user_username", 
  "user"."name" AS "user_name", 
  "user"."followersCount" AS "user_followersCount", 
  "user"."followingCount" AS "user_followingCount", 
  "user"."notesCount" AS "user_notesCount", 
  "user"."avatarId" AS "user_avatarId", 
  "user"."bannerId" AS "user_bannerId", 
  "user"."tags" AS "user_tags", 
  "user"."isSuspended" AS "user_isSuspended", 
  "user"."isSilenced" AS "user_isSilenced", 
  "user"."isLocked" AS "user_isLocked", 
  "user"."isBot" AS "user_isBot", 
  "user"."isCat" AS "user_isCat", 
  "user"."isAdmin" AS "user_isAdmin", 
  "user"."isModerator" AS "user_isModerator", 
  "user"."isExplorable" AS "user_isExplorable", 
  "user"."isDeleted" AS "user_isDeleted", 
  "user"."emojis" AS "user_emojis", 
  "user"."host" AS "user_host", 
  "user"."inbox" AS "user_inbox", 
  "user"."sharedInbox" AS "user_sharedInbox", 
  "user"."featured" AS "user_featured", 
  "user"."uri" AS "user_uri", 
  "user"."followersUri" AS "user_followersUri", 
  "user"."showTimelineReplies" AS "user_showTimelineReplies", 
  "user"."token" AS "user_token", 
  "user"."federateBlocks" AS "user_federateBlocks", 
  "avatar"."id" AS "avatar_id", 
  "avatar"."createdAt" AS "avatar_createdAt", 
  "avatar"."userId" AS "avatar_userId", 
  "avatar"."userHost" AS "avatar_userHost", 
  "avatar"."md5" AS "avatar_md5", 
  "avatar"."name" AS "avatar_name", 
  "avatar"."type" AS "avatar_type", 
  "avatar"."size" AS "avatar_size", 
  "avatar"."comment" AS "avatar_comment", 
  "avatar"."blurhash" AS "avatar_blurhash", 
  "avatar"."properties" AS "avatar_properties", 
  "avatar"."storedInternal" AS "avatar_storedInternal", 
  "avatar"."url" AS "avatar_url", 
  "avatar"."thumbnailUrl" AS "avatar_thumbnailUrl", 
  "avatar"."webpublicUrl" AS "avatar_webpublicUrl", 
  "avatar"."webpublicType" AS "avatar_webpublicType", 
  "avatar"."accessKey" AS "avatar_accessKey", 
  "avatar"."thumbnailAccessKey" AS "avatar_thumbnailAccessKey", 
  "avatar"."webpublicAccessKey" AS "avatar_webpublicAccessKey", 
  "avatar"."uri" AS "avatar_uri", 
  "avatar"."src" AS "avatar_src", 
  "avatar"."folderId" AS "avatar_folderId", 
  "avatar"."isSensitive" AS "avatar_isSensitive", 
  "avatar"."isLink" AS "avatar_isLink", 
  "banner"."id" AS "banner_id", 
  "banner"."createdAt" AS "banner_createdAt", 
  "banner"."userId" AS "banner_userId", 
  "banner"."userHost" AS "banner_userHost", 
  "banner"."md5" AS "banner_md5", 
  "banner"."name" AS "banner_name", 
  "banner"."type" AS "banner_type", 
  "banner"."size" AS "banner_size", 
  "banner"."comment" AS "banner_comment", 
  "banner"."blurhash" AS "banner_blurhash", 
  "banner"."properties" AS "banner_properties", 
  "banner"."storedInternal" AS "banner_storedInternal", 
  "banner"."url" AS "banner_url", 
  "banner"."thumbnailUrl" AS "banner_thumbnailUrl", 
  "banner"."webpublicUrl" AS "banner_webpublicUrl", 
  "banner"."webpublicType" AS "banner_webpublicType", 
  "banner"."accessKey" AS "banner_accessKey", 
  "banner"."thumbnailAccessKey" AS "banner_thumbnailAccessKey", 
  "banner"."webpublicAccessKey" AS "banner_webpublicAccessKey", 
  "banner"."uri" AS "banner_uri", 
  "banner"."src" AS "banner_src", 
  "banner"."folderId" AS "banner_folderId", 
  "banner"."isSensitive" AS "banner_isSensitive", 
  "banner"."isLink" AS "banner_isLink" 
FROM 
  "note" "note" 
  INNER JOIN "user" "user" ON "user"."id" = "note"."userId" 
  LEFT JOIN "drive_file" "avatar" ON "avatar"."id" = "user"."avatarId" 
  LEFT JOIN "drive_file" "banner" ON "banner"."id" = "user"."bannerId" 
WHERE 
  "note"."id" IN (
    SELECT 
      id 
    FROM 
      note_replies($noteId, $depth, $limit)
  ) 
  AND (
    "note"."visibility" = 'public' 
    OR "note"."visibility" = 'home'
  ) 
ORDER BY 
  "note"."id" DESC;

note: replace $noteId, $depth (FE sends 6 by default) and $limit (FE sends 30 by default)

Full Query Plan:

                                                                                       QUERY PLAN                                                                                        
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Sort  (cost=14713970.76..14727936.18 rows=5586168 width=2937) (actual time=53723.573..53723.588 rows=1 loops=1)
   Sort Key: note.id DESC
   Sort Method: quicksort  Memory: 27kB
   ->  Hash Join  (cost=591010.12..1640990.66 rows=5586168 width=2937) (actual time=53684.512..53723.567 rows=1 loops=1)
         Hash Cond: ((note."userId")::text = ("user".id)::text)
         ->  Nested Loop  (cost=13.31..524.04 rows=5586168 width=642) (actual time=1.340..1.360 rows=1 loops=1)
               ->  HashAggregate  (cost=12.75..14.75 rows=200 width=32) (actual time=1.300..1.312 rows=1 loops=1)
                     Group Key: (note_replies.id)::text
                     ->  Function Scan on note_replies  (cost=0.25..10.25 rows=1000 width=32) (actual time=1.294..1.296 rows=1 loops=1)
               ->  Index Scan using "PK_96d0c172a4fba276b1bbed43058" on note  (cost=0.56..2.78 rows=1 width=642) (actual time=0.037..0.038 rows=1 loops=1)
                     Index Cond: ((id)::text = (note_replies.id)::text)
                     Filter: ((visibility = 'public'::note_visibility_enum) OR (visibility = 'home'::note_visibility_enum))
         ->  Hash  (cost=532339.23..532339.23 rows=198366 width=2295) (actual time=53630.359..53630.362 rows=197874 loops=1)
               Buckets: 4096  Batches: 128  Memory Usage: 2297kB
               ->  Nested Loop Left Join  (cost=0.86..532339.23 rows=198366 width=2295) (actual time=0.064..27558.572 rows=197874 loops=1)
                     ->  Nested Loop Left Join  (cost=0.43..272668.95 rows=198366 width=1345) (actual time=0.058..24216.821 rows=197874 loops=1)
                           ->  Seq Scan on "user"  (cost=0.00..12998.66 rows=198366 width=395) (actual time=0.013..287.009 rows=197874 loops=1)
                           ->  Index Scan using "PK_43ddaaaf18c9e68029b7cbb032e" on drive_file avatar  (cost=0.43..1.31 rows=1 width=950) (actual time=0.119..0.119 rows=1 loops=197874)
                                 Index Cond: ((id)::text = ("user"."avatarId")::text)
                     ->  Index Scan using "PK_43ddaaaf18c9e68029b7cbb032e" on drive_file banner  (cost=0.43..1.31 rows=1 width=950) (actual time=0.015..0.015 rows=1 loops=197874)
                           Index Cond: ((id)::text = ("user"."bannerId")::text)
 Planning Time: 2.435 ms
 Execution Time: 53723.845 ms

EXPLAIN on the query shows me 2 parts with an awefull high cost ``` -> Hash Join (cost=591010.12..1640990.66 rows=5586168 width=2937) (actual time=53684.512..53723.567 rows=1 loops=1) ``` and ``` -> Hash (cost=532339.23..532339.23 rows=198366 width=2295) (actual time=53630.359..53630.362 rows=197874 loops=1) ``` i checked the indexes and it seems that every field, where this query is joining has an index. so doesn't look to me, that its an indexing issue (might be wrong with this tho) Full Query: ``` EXPLAIN ANALYZE SELECT "note"."id" AS "note_id", "note"."createdAt" AS "note_createdAt", "note"."replyId" AS "note_replyId", "note"."renoteId" AS "note_renoteId", "note"."threadId" AS "note_threadId", "note"."text" AS "note_text", "note"."name" AS "note_name", "note"."cw" AS "note_cw", "note"."userId" AS "note_userId", "note"."localOnly" AS "note_localOnly", "note"."renoteCount" AS "note_renoteCount", "note"."repliesCount" AS "note_repliesCount", "note"."reactions" AS "note_reactions", "note"."visibility" AS "note_visibility", "note"."uri" AS "note_uri", "note"."url" AS "note_url", "note"."fileIds" AS "note_fileIds", "note"."attachedFileTypes" AS "note_attachedFileTypes", "note"."visibleUserIds" AS "note_visibleUserIds", "note"."mentions" AS "note_mentions", "note"."emojis" AS "note_emojis", "note"."tags" AS "note_tags", "note"."hasPoll" AS "note_hasPoll", "note"."channelId" AS "note_channelId", "note"."userHost" AS "note_userHost", "note"."replyUserId" AS "note_replyUserId", "note"."replyUserHost" AS "note_replyUserHost", "note"."renoteUserId" AS "note_renoteUserId", "note"."renoteUserHost" AS "note_renoteUserHost", "user"."id" AS "user_id", "user"."createdAt" AS "user_createdAt", "user"."updatedAt" AS "user_updatedAt", "user"."lastFetchedAt" AS "user_lastFetchedAt", "user"."lastActiveDate" AS "user_lastActiveDate", "user"."hideOnlineStatus" AS "user_hideOnlineStatus", "user"."username" AS "user_username", "user"."name" AS "user_name", "user"."followersCount" AS "user_followersCount", "user"."followingCount" AS "user_followingCount", "user"."notesCount" AS "user_notesCount", "user"."avatarId" AS "user_avatarId", "user"."bannerId" AS "user_bannerId", "user"."tags" AS "user_tags", "user"."isSuspended" AS "user_isSuspended", "user"."isSilenced" AS "user_isSilenced", "user"."isLocked" AS "user_isLocked", "user"."isBot" AS "user_isBot", "user"."isCat" AS "user_isCat", "user"."isAdmin" AS "user_isAdmin", "user"."isModerator" AS "user_isModerator", "user"."isExplorable" AS "user_isExplorable", "user"."isDeleted" AS "user_isDeleted", "user"."emojis" AS "user_emojis", "user"."host" AS "user_host", "user"."inbox" AS "user_inbox", "user"."sharedInbox" AS "user_sharedInbox", "user"."featured" AS "user_featured", "user"."uri" AS "user_uri", "user"."followersUri" AS "user_followersUri", "user"."showTimelineReplies" AS "user_showTimelineReplies", "user"."token" AS "user_token", "user"."federateBlocks" AS "user_federateBlocks", "avatar"."id" AS "avatar_id", "avatar"."createdAt" AS "avatar_createdAt", "avatar"."userId" AS "avatar_userId", "avatar"."userHost" AS "avatar_userHost", "avatar"."md5" AS "avatar_md5", "avatar"."name" AS "avatar_name", "avatar"."type" AS "avatar_type", "avatar"."size" AS "avatar_size", "avatar"."comment" AS "avatar_comment", "avatar"."blurhash" AS "avatar_blurhash", "avatar"."properties" AS "avatar_properties", "avatar"."storedInternal" AS "avatar_storedInternal", "avatar"."url" AS "avatar_url", "avatar"."thumbnailUrl" AS "avatar_thumbnailUrl", "avatar"."webpublicUrl" AS "avatar_webpublicUrl", "avatar"."webpublicType" AS "avatar_webpublicType", "avatar"."accessKey" AS "avatar_accessKey", "avatar"."thumbnailAccessKey" AS "avatar_thumbnailAccessKey", "avatar"."webpublicAccessKey" AS "avatar_webpublicAccessKey", "avatar"."uri" AS "avatar_uri", "avatar"."src" AS "avatar_src", "avatar"."folderId" AS "avatar_folderId", "avatar"."isSensitive" AS "avatar_isSensitive", "avatar"."isLink" AS "avatar_isLink", "banner"."id" AS "banner_id", "banner"."createdAt" AS "banner_createdAt", "banner"."userId" AS "banner_userId", "banner"."userHost" AS "banner_userHost", "banner"."md5" AS "banner_md5", "banner"."name" AS "banner_name", "banner"."type" AS "banner_type", "banner"."size" AS "banner_size", "banner"."comment" AS "banner_comment", "banner"."blurhash" AS "banner_blurhash", "banner"."properties" AS "banner_properties", "banner"."storedInternal" AS "banner_storedInternal", "banner"."url" AS "banner_url", "banner"."thumbnailUrl" AS "banner_thumbnailUrl", "banner"."webpublicUrl" AS "banner_webpublicUrl", "banner"."webpublicType" AS "banner_webpublicType", "banner"."accessKey" AS "banner_accessKey", "banner"."thumbnailAccessKey" AS "banner_thumbnailAccessKey", "banner"."webpublicAccessKey" AS "banner_webpublicAccessKey", "banner"."uri" AS "banner_uri", "banner"."src" AS "banner_src", "banner"."folderId" AS "banner_folderId", "banner"."isSensitive" AS "banner_isSensitive", "banner"."isLink" AS "banner_isLink" FROM "note" "note" INNER JOIN "user" "user" ON "user"."id" = "note"."userId" LEFT JOIN "drive_file" "avatar" ON "avatar"."id" = "user"."avatarId" LEFT JOIN "drive_file" "banner" ON "banner"."id" = "user"."bannerId" WHERE "note"."id" IN ( SELECT id FROM note_replies($noteId, $depth, $limit) ) AND ( "note"."visibility" = 'public' OR "note"."visibility" = 'home' ) ORDER BY "note"."id" DESC; ``` note: replace $noteId, $depth (FE sends 6 by default) and $limit (FE sends 30 by default) Full Query Plan: ``` QUERY PLAN ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- Sort (cost=14713970.76..14727936.18 rows=5586168 width=2937) (actual time=53723.573..53723.588 rows=1 loops=1) Sort Key: note.id DESC Sort Method: quicksort Memory: 27kB -> Hash Join (cost=591010.12..1640990.66 rows=5586168 width=2937) (actual time=53684.512..53723.567 rows=1 loops=1) Hash Cond: ((note."userId")::text = ("user".id)::text) -> Nested Loop (cost=13.31..524.04 rows=5586168 width=642) (actual time=1.340..1.360 rows=1 loops=1) -> HashAggregate (cost=12.75..14.75 rows=200 width=32) (actual time=1.300..1.312 rows=1 loops=1) Group Key: (note_replies.id)::text -> Function Scan on note_replies (cost=0.25..10.25 rows=1000 width=32) (actual time=1.294..1.296 rows=1 loops=1) -> Index Scan using "PK_96d0c172a4fba276b1bbed43058" on note (cost=0.56..2.78 rows=1 width=642) (actual time=0.037..0.038 rows=1 loops=1) Index Cond: ((id)::text = (note_replies.id)::text) Filter: ((visibility = 'public'::note_visibility_enum) OR (visibility = 'home'::note_visibility_enum)) -> Hash (cost=532339.23..532339.23 rows=198366 width=2295) (actual time=53630.359..53630.362 rows=197874 loops=1) Buckets: 4096 Batches: 128 Memory Usage: 2297kB -> Nested Loop Left Join (cost=0.86..532339.23 rows=198366 width=2295) (actual time=0.064..27558.572 rows=197874 loops=1) -> Nested Loop Left Join (cost=0.43..272668.95 rows=198366 width=1345) (actual time=0.058..24216.821 rows=197874 loops=1) -> Seq Scan on "user" (cost=0.00..12998.66 rows=198366 width=395) (actual time=0.013..287.009 rows=197874 loops=1) -> Index Scan using "PK_43ddaaaf18c9e68029b7cbb032e" on drive_file avatar (cost=0.43..1.31 rows=1 width=950) (actual time=0.119..0.119 rows=1 loops=197874) Index Cond: ((id)::text = ("user"."avatarId")::text) -> Index Scan using "PK_43ddaaaf18c9e68029b7cbb032e" on drive_file banner (cost=0.43..1.31 rows=1 width=950) (actual time=0.015..0.015 rows=1 loops=197874) Index Cond: ((id)::text = ("user"."bannerId")::text) Planning Time: 2.435 ms Execution Time: 53723.845 ms ```