search

advplyr / audiobookshelf

Self-hosted audiobook and podcast server
https://audiobookshelf.org
GNU General Public License v3.0
6.23k stars 436 forks source link

[Bug]: 'Recent Series' on home taking 25s to load #3237

Open alxgarci opened 1 month ago

alxgarci commented 1 month ago

What happened?

Everytime i open or switch between libraries, the home page takes too long to load. I've read another topics addressing similar issues but not this one. I had a 100k book library (epub, mobi, pdf,...) which i split in 20k libraries. Changing between libraries also triggers this. Problem occurs accessing the server through last Android app release, Chrome and Chrome for Android. If i change libraries while inside 'Library' tab, it takes 4 seconds, which is okay. Tested on docker versions 'edge' and 'v2.12.0'

What did you expect to happen?

To load faster, every other home item loads in less than 2 seconds. Or to optionally disable 'recent series' item.

Steps to reproduce the issue

  1. Go to audiobookshelf main page (entering just http://LOCAL_IP_ADDRESS:13378) or change between libraries (20k books each in my case) from Android or a web browser (Chrome).
  2. Wait until the page is loaded (logs show 25 seconds for the 'Recent Series' to load, but the actual page takes even longer).

Audiobookshelf version

v2.12.0

How are you running audiobookshelf?

Docker

What OS is your Audiobookshelf server hosted from?

Linux

If the issue is being seen in the UI, what browsers are you seeing the problem on?

Chrome

Logs

Config /config /metadata
[2024-08-05 13:13:34.551] INFO: === Starting Server ===
[2024-08-05 13:13:34.553] INFO: [Server] Init v2.12.0
[2024-08-05 13:13:34.553] INFO: [Server] Node.js Version: v20.16.0
[2024-08-05 13:13:34.553] INFO: [Server] Platform: linux
[2024-08-05 13:13:34.554] INFO: [Server] Arch: x64
[2024-08-05 13:13:34.730] INFO: [BinaryManager] ffmpeg not found or version too old
[2024-08-05 13:13:34.775] INFO: [BinaryManager] ffprobe not found or version too old
[2024-08-05 13:13:34.776] INFO: [BinaryManager] unicode not found or version too old
[2024-08-05 13:13:34.777] INFO: [BinaryManager] Installing binaries: ffmpeg, ffprobe, unicode
[2024-08-05 13:13:40.732] INFO: [BinaryManager] Binaries installed to /
[2024-08-05 13:13:40.784] INFO: [BinaryManager] Found valid binary ffmpeg at /ffmpeg
[2024-08-05 13:13:40.784] INFO: [BinaryManager] Updating process.env.FFMPEG_PATH
[2024-08-05 13:13:40.830] INFO: [BinaryManager] Found valid binary ffprobe at /ffprobe
[2024-08-05 13:13:40.830] INFO: [BinaryManager] Updating process.env.FFPROBE_PATH
[2024-08-05 13:13:40.830] INFO: [BinaryManager] Found valid binary unicode at /unicode.so
[2024-08-05 13:13:40.830] INFO: [BinaryManager] Updating process.env.SQLEAN_UNICODE_PATH
[2024-08-05 13:13:40.831] INFO: [Database] Initializing db at "/config/absdatabase.sqlite"
[2024-08-05 13:13:40.866] INFO: [Database] Loading extension /unicode.so
[2024-08-05 13:13:40.867] INFO: [Database] Successfully loaded extension /unicode.so
[2024-08-05 13:13:40.867] INFO: [Database] Db connection was successful
[2024-08-05 13:13:40.968] INFO: [Database] Db initialized with models: user, library, libraryFolder, book, podcast, podcastEpisode, libraryItem, mediaProgress, series, bookSeries, author, bookAuthor, collection, collectionBook, playlist, playlistMediaItem, device, playbackSession, feed, feedEpisode, setting, customMetadataProvider, mediaItemShare
[2024-08-05 13:13:40.973] DEBUG: Set Log Level to DEBUG (Logger.js:103)
[2024-08-05 13:13:42.011] INFO: [Database] Server upgrade detected from 2.11.0 to 2.12.0
[2024-08-05 13:13:42.021] DEBUG: Daily Log file found 2024-08-04.txt (LogManager.js:94)
[2024-08-05 13:13:42.021] DEBUG: Daily Log file found 2024-08-05.txt (LogManager.js:94)
[2024-08-05 13:13:42.022] INFO: [LogManager] Init current daily log filename: 2024-08-05.txt
[2024-08-05 13:13:42.022] DEBUG: [LogManager] Daily log file already exists - set in Logger (LogManager.js:71)
[2024-08-05 13:13:42.025] DEBUG: [DailyLog] 2024-08-05: Loaded 790 Logs (DailyLog.js:132)
[2024-08-05 13:13:42.030] INFO: [BackupManager] 0 Backups Found
[2024-08-05 13:13:42.031] INFO: [BackupManager] Auto Backups are disabled
[2024-08-05 13:13:42.045] INFO: [Watcher] Initializing watcher for "Books Vol. I".
[2024-08-05 13:13:42.046] DEBUG: [Watcher] Init watcher for library folder path "/HDD/books/books_part1" (Watcher.js:57)
[2024-08-05 13:13:42.047] INFO: [Watcher] Initializing watcher for "Books Vol. II".
[2024-08-05 13:13:42.047] DEBUG: [Watcher] Init watcher for library folder path "/HDD/books/books_part2" (Watcher.js:57)
[2024-08-05 13:13:42.047] INFO: [Watcher] Initializing watcher for "Books Vol. III".
[2024-08-05 13:13:42.047] DEBUG: [Watcher] Init watcher for library folder path "/HDD/books/books_part3" (Watcher.js:57)
[2024-08-05 13:13:42.048] INFO: [Watcher] Initializing watcher for "Books Vol. IV".
[2024-08-05 13:13:42.048] DEBUG: [Watcher] Init watcher for library folder path "/HDD/books/books_part4" (Watcher.js:57)
[2024-08-05 13:13:42.048] INFO: [Watcher] Initializing watcher for "Books Vol. V".
[2024-08-05 13:13:42.048] DEBUG: [Watcher] Init watcher for library folder path "/HDD/books/books_part5" (Watcher.js:57)
[2024-08-05 13:13:42.056] INFO: Listening on port :80
[2024-08-05 13:13:44.065] INFO: [Watcher] "Books Vol. III" Ready
[2024-08-05 13:13:44.069] INFO: [Watcher] "Books Vol. I" Ready
[2024-08-05 13:13:44.072] INFO: [Watcher] "Books Vol. II" Ready
[2024-08-05 13:13:44.075] INFO: [Watcher] "Books Vol. IV" Ready
[2024-08-05 13:13:44.078] INFO: [Watcher] "Books Vol. V" Ready
[2024-08-05 13:13:45.968] INFO: [SocketAuthority] Socket Connected 3xNJ_EIwAUAHtsPXAAAB
[2024-08-05 13:13:45.985] DEBUG: [SocketAuthority] User Online root (SocketAuthority.js:204)
[2024-08-05 13:13:48.507] DEBUG: [SocketAuthority] User Offline root (SocketAuthority.js:131)
[2024-08-05 13:13:48.508] INFO: [SocketAuthority] Socket 3xNJ_EIwAUAHtsPXAAAB disconnected from client "root" after 2540ms (Reason: transport close)
[2024-08-05 13:13:49.153] DEBUG: [ApiCacheManager] count: 0 size: 0 (ApiCacheManager.js:39)
[2024-08-05 13:13:50.109] DEBUG: Loaded filterdata in 0.95s (libraryFilters.js:537)
[2024-08-05 13:13:50.113] DEBUG: [ApiCacheManager] Cache miss: {"user":"root","url":"/libraries/a04edc94-0e05-4fb3-97cf-7bb6c492f8a7?include=filterdata"} (ApiCacheManager.js:50)
[2024-08-05 13:13:50.290] INFO: [SocketAuthority] Socket Connected qh3aYPkoCAjkjm06AAAD
[2024-08-05 13:13:50.304] DEBUG: [ApiCacheManager] count: 1 size: 480707 (ApiCacheManager.js:39)
[2024-08-05 13:13:50.312] DEBUG: [SocketAuthority] User Online root (SocketAuthority.js:204)
[2024-08-05 13:13:50.320] DEBUG: [ApiCacheManager] count: 1 size: 480707 (ApiCacheManager.js:39)
[2024-08-05 13:13:50.347] DEBUG: [ApiCacheManager] Cache miss: {"user":"root","url":"/libraries"} (ApiCacheManager.js:50)
[2024-08-05 13:13:50.484] DEBUG: Loaded 0 of 0 items for "Continue Listening/Reading" in 0.15s (LibraryItem.js:626)
[2024-08-05 13:13:50.509] DEBUG: Loaded 0 of 0 items for "Continue Series" in 0.02s (LibraryItem.js:643)
[2024-08-05 13:13:50.684] DEBUG: Loaded 10 of 20000 items for "Recently Added" in 0.17s (LibraryItem.js:673)
[2024-08-05 13:14:16.071] DEBUG: Loaded 5 of 1346 series for "Recent Series" in 25.39s (LibraryItem.js:689)
[2024-08-05 13:14:16.500] DEBUG: Loaded 10 of 10391 items for "Discover" in 0.43s (LibraryItem.js:704)
[2024-08-05 13:14:16.637] DEBUG: Loaded 0 of 0 items for "Listen/Read Again" in 0.14s (LibraryItem.js:735)
[2024-08-05 13:14:40.627] DEBUG: Loaded 10 of 4437 authors for "Newest Authors" in 23.99s (LibraryItem.js:751)
[2024-08-05 13:14:40.628] DEBUG: Loaded 4 personalized shelves in 50.30s (LibraryItem.js:754)
[2024-08-05 13:14:40.628] DEBUG: [ApiCacheManager] Cache miss: {"user":"root","url":"/libraries/a04edc94-0e05-4fb3-97cf-7bb6c492f8a7/personalized?include=rssfeed,numEpisodesIncomplete,share"} (ApiCacheManager.js:50)
[2024-08-05 13:14:40.629] DEBUG: [ApiCacheManager] Caching with 1800000 ms TTL (ApiCacheManager.js:53)
[2024-08-05 13:14:40.813] DEBUG: [FfmpegHelpers] Resize Image Cmd: ffmpeg -i /metadata/items/21f49f0f-9e6f-440e-a7dc-913c9080daf4/cover.jpg -y -vf scale=400:-1 /metadata/cache/covers/21f49f0f-9e6f-440e-a7dc-913c9080daf4_400.webp (ffmpegHelpers.js:85)
[2024-08-05 13:14:40.817] DEBUG: [FfmpegHelpers] Resize Image Cmd: ffmpeg -i /metadata/items/5786a0f5-3bb7-423e-bbc5-14e21007288d/cover.jpg -y -vf scale=400:-1 /metadata/cache/covers/5786a0f5-3bb7-423e-bbc5-14e21007288d_400.webp (ffmpegHelpers.js:85)
[2024-08-05 13:14:40.829] DEBUG: [FfmpegHelpers] Resize Image Cmd: ffmpeg -i /metadata/items/57593f57-3c4c-4b64-97c6-2b65071df4f4/cover.jpg -y -vf scale=400:-1 /metadata/cache/covers/57593f57-3c4c-4b64-97c6-2b65071df4f4_400.webp (ffmpegHelpers.js:85)
[2024-08-05 13:14:40.834] DEBUG: [FfmpegHelpers] Resize Image Cmd: ffmpeg -i /metadata/items/85ad9833-5a9b-41a5-bbfb-7f6ef449ed4f/cover.jpg -y -vf scale=400:-1 /metadata/cache/covers/85ad9833-5a9b-41a5-bbfb-7f6ef449ed4f_400.webp (ffmpegHelpers.js:85)
[2024-08-05 13:14:40.865] DEBUG: [FfmpegHelpers] Resize Image Cmd: ffmpeg -i /metadata/items/ef4de438-5ab8-4acd-9251-bfb795b72451/cover.jpg -y -vf scale=400:-1 /metadata/cache/covers/ef4de438-5ab8-4acd-9251-bfb795b72451_400.webp (ffmpegHelpers.js:85)
[2024-08-05 13:14:40.878] DEBUG: [FfmpegHelpers] Resize Image Cmd: ffmpeg -i /metadata/items/b168b111-971b-4ce5-b740-cf35391eb0fa/cover.jpg -y -vf scale=400:-1 /metadata/cache/covers/b168b111-971b-4ce5-b740-cf35391eb0fa_400.webp (ffmpegHelpers.js:85)
[2024-08-05 13:14:40.879] DEBUG: [FfmpegHelpers] Image resized Successfully (ffmpegHelpers.js:92)
[2024-08-05 13:14:40.894] DEBUG: [FfmpegHelpers] Image resized Successfully (ffmpegHelpers.js:92)
[2024-08-05 13:14:40.914] DEBUG: [FfmpegHelpers] Resize Image Cmd: ffmpeg -i /metadata/items/6c01db0d-2415-4aa9-9eae-18c90b24b0a8/cover.jpg -y -vf scale=400:-1 /metadata/cache/covers/6c01db0d-2415-4aa9-9eae-18c90b24b0a8_400.webp (ffmpegHelpers.js:85)
[2024-08-05 13:14:40.917] DEBUG: [FfmpegHelpers] Image resized Successfully (ffmpegHelpers.js:92)
[2024-08-05 13:14:40.933] DEBUG: [FfmpegHelpers] Resize Image Cmd: ffmpeg -i /metadata/items/ac4c4eac-3017-4298-9df5-7674ac35ac0e/cover.jpg -y -vf scale=400:-1 /metadata/cache/covers/ac4c4eac-3017-4298-9df5-7674ac35ac0e_400.webp (ffmpegHelpers.js:85)
[2024-08-05 13:14:40.941] DEBUG: [FfmpegHelpers] Image resized Successfully (ffmpegHelpers.js:92)
[2024-08-05 13:14:40.945] DEBUG: [FfmpegHelpers] Image resized Successfully (ffmpegHelpers.js:92)
[2024-08-05 13:14:40.949] DEBUG: [FfmpegHelpers] Image resized Successfully (ffmpegHelpers.js:92)
[2024-08-05 13:14:40.987] DEBUG: [FfmpegHelpers] Image resized Successfully (ffmpegHelpers.js:92)
[2024-08-05 13:14:40.995] DEBUG: [FfmpegHelpers] Image resized Successfully (ffmpegHelpers.js:92)

Additional Notes

Tried splitting the 100k book library in 20k smaller libraries, thinking 100k books were too many. Also tried android app and searching previous performance issues already solved.

nichwall commented 1 month ago

I'm not very familiar with SQL or database queries, but from initial research, it looks like the slowdown for "Recent Series" and "Newest Authors" are both related to needing to verify the author and series have books after removing any permissions (from access control from limiting by tag or whether the item is explicit). Your logs show you as the root user which has access to all library items, so bookWhere will be empty and just be checking that authors have books.

The authors query is simpler than the series query, so putting that here for reference. https://github.com/advplyr/audiobookshelf/blob/930bacd45d232b44a967c0744c9cfb82dcc592f4/server/utils/queries/libraryFilters.js#L324C1-L358C5

Maybe we can try adding the separate: true to the include part of the query because the bookAuthor has belongsToMany associations? I'd also be curious if the query gets faster as more authors and series are no longer "new" after 60 days or if this is specifically related to the book count. https://sequelize.org/docs/v7/querying/select-in-depth/#separate-eager-loading-queries

(customized shelves related to https://github.com/advplyr/audiobookshelf/issues/1241)

nichwall commented 1 month ago

Well, I just tried that change locally, and turns out the HasMany association does not exist for this query, so separate: true does not work. I played with changing the attributes that are used to see if removing the checks for tags or explicit would speed the query up at all and I didn't notice a change in loading time on a test library with 962 new authors and just under 6000 books.

alxgarci commented 1 month ago

For others having the same issue: Since it's hard for me to understand all the code and queries, i opted to comment every line inside those methods and return an empty array, which disables the section in the 'Home' tab.

This cleanly disables both queries and makes everything load in under 2 seconds. For me this is a temporary fix, just enter in container's bash shell and install nano/vim.