FoundKeyGang/FoundKey
FoundKeyGang
/
FoundKey
7
19
Fork 22
Code Issues 37 Pull Requests 4 Releases Activity

POST /api/notes/children runs into timeouts #256

New Issue
Closed
opened 2022-11-29 10:28:23 +00:00 by puniko · 4 comments
puniko commented 2022-11-29 10:28:23 +00:00
Contributor
Copy Link

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 (6efc3b7989/packages/backend/src/server/api/endpoints/notes/children.ts (L55))

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
Copy Link

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
Copy Link

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 ```
Johann150 commented 2023-01-12 18:48:03 +00:00
Owner
Copy Link

Is this still happening after the linked PR was merged?

Is this still happening after the linked PR was merged?
puniko commented 2023-01-13 07:05:02 +00:00
Author
Contributor
Copy Link

Not on my side. replies now load without running into a timeout

Not on my side. replies now load without running into a timeout
Sign in to join this conversation.
No Branch/Tag Specified
Branches Tags
main
refactor-deliver-actor
markdown
move-autoblock
feature/requests
context
indicator-circle-v2
v13.0.0-preview6
v13.0.0-preview5.1
v13.0.0-preview5
v13.0.0-preview4
v13.0.0-preview3
v13.0.0-preview2
v13.0.0-preview1
Labels
Clear labels   
feature

task that proposes new feature(s)

  
fix

task to fix behavioral problems in the FoundKey codebase

  
upkeep

task that should make FoundKey smaller and more maintainable

No Label
feature
fix
upkeep
Milestone
Clear milestone
No items
No Milestone
Assignees
Clear assignees
No Assignees
2 Participants
Notifications
Due Date
The due date is invalid or out of range. Please use the format 'yyyy-mm-dd'.

No due date set.

Dependencies

No dependencies set.

Reference: FoundKeyGang/FoundKey#256
No description provided.
Delete Branch "%!s(<nil>)"

Deleting a branch is permanent. Although the deleted branch may continue to exist for a short time before it actually gets removed, it CANNOT be undone in most cases. Continue?