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

[alxgarci]

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]

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 #1241)

[nichwall]

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]

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.

• So changing the getNewestAuthors: https://github.com/advplyr/audiobookshelf/blob/930bacd45d232b44a967c0744c9cfb82dcc592f4/server/utils/queries/libraryFilters.js#L324C1-L358C5 commenting from line 325 to line 357, just leaving inside the method return { authors: [], count: 0 }.

• And changing getSeriesMostRecentlyAdded:
  https://github.com/advplyr/audiobookshelf/blob/930bacd45d232b44a967c0744c9cfb82dcc592f4/server/utils/queries/libraryFilters.js#L200C9-L200C35 commenting from line 201 to 313, just leaving inside the method return { series: [], count: 0 }.

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.

[github-actions]

Fixed in v2.16.0.

[advplyr]

If you update to v2.16.0 I'm curious how much the performance improves

[alxgarci]

Sry just gave up on having 100k+ books and started a new library with just 2k, so can't monitor the performance for now. But thanks for the fix! Will try in the future.

[oddstr13]

If you update to v2.16.0 I'm curious how much the performance improves

I can't say I see a noticeable improvement, but the time is still beyond the "stare at it while it loads" threshold, so there could

I just updated to v2.16.2, but the following log is from v2.16.0.
Seeing as there are no mentions of this kind of optimizations in the .1 and .2 changelogs I don't expect any difference.

audiobookshelf  | [2024-11-01 17:26:22.438] DEBUG: [ApiCacheManager] Cache miss: {"user":"Oddstr13","url":"/libraries/d05b23dd-012a-4067-919e-2fa88d7e4730/series?sort=lastBookUpdated&desc=1&filter=all&limit=24&page=0&minified=1&include=rssfeed,numEpisodesIncomplete,share"}
audiobookshelf  | [2024-11-01 17:26:23.138] DEBUG: Loaded 3 of 3 items for "Continue Listening/Reading" in 37.35s
audiobookshelf  | [2024-11-01 17:26:24.138] DEBUG: Loaded 5 of 5 items for "Continue Series" in 1.00s
audiobookshelf  | [2024-11-01 17:26:25.666] DEBUG: Loaded 10 of 28 items for "Recently Added" in 1.52s
audiobookshelf  | [2024-11-01 17:26:25.962] DEBUG: Loaded 5 of 7 series for "Recent Series" in 0.29s
audiobookshelf  | [2024-11-01 17:26:27.867] DEBUG: Loaded 10 of 22 items for "Discover" in 1.90s
audiobookshelf  | [2024-11-01 17:26:28.402] DEBUG: Loaded 10 of 43 items for "Listen/Read Again" in 0.53s
audiobookshelf  | [2024-11-01 17:26:28.559] DEBUG: Loaded 8 of 8 authors for "Newest Authors" in 0.15s
audiobookshelf  | [2024-11-01 17:26:28.560] DEBUG: Loaded 7 personalized shelves in 42.77s

Once those queries are cached, loading the android app takes about 3s, but the cache lasts for 30m, and I rarely load the app more often than that while listening to audiobooks.

If desirable, I could go look for older logs to compare, but I don't remember when I enabled debug logging, so there may not be too much data to find.

[nichwall]

Would you be willing to share your database? I'm curious why the "Continue Listening/Reading" query is 30 seconds long. That seems excessive, especially for only having 170 items in the library.

[oddstr13]

@nichwall I'd rather not dump the whole database, but I can run some queries for you, if you give me some pointers?

[nichwall]

I'd rather not dump the whole database, but I can run some queries for you, if you give me some pointers?

If you set the environment variable QUERY_LOGGING to be benchmark, that will tell us exactly what queries are being run and how long each of them are taking. If you can then share the full log with all of the queries related to loading the home page (and maybe navigating around the web client to check if any other queries are being really slow) that will help narrow down where things need to be improved. We have been testing several API endpoints to improve performance recently and have some more things identified, but would be helpful if there is a specific operation with your database which is much slower.

Edit to add: it may be helpful to open a new issue with the log file to help keep things distinct between different endpoints

[oddstr13]

I've enabled query logging.
Not seeing the slowness right now, but it tends to only happen the first time loading the app (after a longer pause).
The app connects and starts loading the library, and I'll have to wait for it to finish, even tho the book I want to listen to is downloaded locally.

I'll create a new issue with the verbose logs if and when I next encounter it.

[nichwall]

Sounds like a plan. Are you seeing something like "Ran query in X Ms" in the logs? You will need to switch the log level to Debug in the server settings as well (not an environment variable)

[oddstr13]

Yep, the appropriate logs are active.

I wouldn't expect relatively simple queries such as this one to take quite this long, but I suppose my NAS is more over-worked than I thought, especially with backups and other IO heavy tasks running right now.

That wouldn't explain 30s+ response times from a query tho, I think.

audiobookshelf  | [2024-11-01 21:49:42.923] DEBUG: Ran the following query in 2227ms:
audiobookshelf  |  Executed (default): UPDATE `devices` SET `id`=$1,`deviceId`=$2,`clientName`=$3,`clientVersion`=$4,`ipAddress`=$5,`deviceName`=$6,`deviceVersion`=$7,`userId`=$8,`extraData`=$9,`updatedAt`=$10 WHERE `id` = $11