Opening a search result takes ~1 minute (4.10.0.20 and .21). Root cause: Coalesce() in the "recently searched"

[motey 3]

Howdy,
Since 4.10.0.x, clicking a search result takes about a minute before the detail
page appears. Searching itself is instant. I traced it to a single query and I
think I have the exact cause, with measurements. Still present on 4.10.0.21.

I saw that 4.10.0.21 lists "improve search performance" in its changelog. I
updated and re-measured: the request below was still running when I cut it off
at 180 seconds. So whatever that improvement covered, it does not cover this.

ENVIRONMENT

  Emby Server 4.10.0.20, then 4.10.0.21 (native .deb)
  Debian 13, 8 cores, 32 GB RAM, no swapping, library.db on SSD
  library.db 295 MB
  Reproduced in Emby Web (Firefox) and in Emby for Android

Library contents, which turn out to matter:

  MediaItems total ........... 168,514
  of which Person ............ 132,785   (79% of the table)
  ItemPeople2 rows ........... 310,687
  Movies ....................... 4,109
  Series ......................... 677
  Episodes .................... 17,356
  UserDatas rows .............. 21,552
  of those with a search date ..... 23

WHAT IS ACTUALLY SLOW

Not the search. SearchTerm=batman returns in 20 ms. The slow request is the
"recently searched" list that the client loads on the search screen:

  GET /emby/Users/{uid}/Items
      ?SortBy=DateLastSearched,SortName
      &SortOrder=Descending
      &Limit=20
      &Recursive=true
      &ImageTypeLimit=1
      &EnableTotalRecordCount=false
      &WasSearched=true

I let it run to completion instead of letting the client time out:

  200, 458.6 seconds

Emby logged it itself:

  Debug SqliteItemRepository: ItemsService.GetItems.GetItemList
  query time (slow 6x): 458608ms

WHY THAT TURNS INTO A ONE MINUTE DETAIL PAGE

Opening an item fires POST /SearchedItems and this refresh at the same time.
The refresh holds a DB connection for minutes, so the POST queues behind it.
From my log:

  Time: 30006ms  GET  .../Items?SortBy=DateLastSearched...WasSearched=true
  Time: 27512ms  GET  .../Items?SortBy=DateLastSearched...WasSearched=true
  Time: 25879ms  POST .../SearchedItems

The client gives up around 30 seconds and retries, but the server keeps burning
a full core for another 7 minutes per abandoned request, so repeated attempts
stack up and it gets worse the more you poke it.

THE QUERY

Captured with debug logging enabled on 4.10.0.20. Abbreviated where it repeats,
happy to post the full text.

 

select A.type, A.Id, ... ,
    (select ShareLevel from UserItemShares
       join AncestorIds2 on AncestorIds2.AncestorId = UserItemShares.ItemId
      where UserItemShares.UserId = 3
        and UserItemShares.ShareLevel not null
        and AncestorIds2.ItemId = A.Id
      order by Distance limit 1) as ShareLevel
  from mediaitems A
  left join UserDatas
    on A.UserDataKeyId = UserDatas.UserDataKeyId and UserDatas.UserId = 3
  where A.Type in (1,2,5,6,8,9,10,11,12,13,14,15,16,18,19,20,21,22,23,24,25,26,27,28,29,34)
    AND Coalesce(UserDatas.DateLastSearchedInt, 0) > 0
    AND (Coalesce(ShareLevel, 0) > 0 OR A.Type in (...) OR A.IsPublic = 1)
    AND A.ExtraType is null
    AND (   EXISTS (SELECT 1 FROM AncestorIds2
                     WHERE AncestorIds2.itemid = A.Id
                       AND AncestorIds2.AncestorId in (8 library ids))
         OR exists (select 1 from ListItems join ancestorids2 ...)
         OR EXISTS (SELECT 1 FROM itemPeople2 JOIN AncestorIds2 ...)
         OR Exists (select 1 From ItemLinks2 join ancestorids2 ...)
         OR Exists (select 1 from ItemLinks2 ItemLinks2TwoLevel
                     where exists (select 1 From ItemLinks2 join ancestorids2 ...)
                       and ItemLinks2TwoLevel.LinkedId = A.Id)
         OR A.Type in (27,28))
  Group by A.PresentationUniqueKey
  ORDER BY MAX(UserDatas.DateLastSearchedInt) DESC,
           A.SortName collate NATURALSORT DESC
  LIMIT 20

ROOT CAUSE

This line:

 AND Coalesce(UserDatas.DateLastSearchedInt, 0) > 0

Wrapping the column in a function makes SQLite unable to use the index that
exists for exactly this purpose:

  CREATE INDEX idx_UserDatas_DateLastSearched
    ON UserDatas (DateLastSearchedInt DESC)
    WHERE DateLastSearchedInt IS NOT NULL

In my database exactly 23 rows have a non-null DateLastSearchedInt. Instead of
touching 23 rows, the query scans all 168,514 rows of MediaItems, running the
correlated ShareLevel subquery and the five branch EXISTS chain on every one.
Group by A.PresentationUniqueKey then forces the whole result set to be
materialised before LIMIT 20 can apply.

I tested this on a copy of library.db, changing only that one expression to

  AND UserDatas.DateLastSearchedInt > 0

and leaving everything else identical:

  original ................. 763 seconds
  without the Coalesce() ..... 0.003 seconds

Run in the sqlite3 CLI with the Emby internal NATURALSORT collation replaced by
a plain sort, since that collation is not available outside the server.

WHY THIS MAY NOT SHOW UP IN TESTING

I think the deciding factor is cast and crew depth, not library size. My video
count is unremarkable: 4,109 movies, 677 series, 17,356 episodes. But
MediaItems also holds 132,785 Person rows.

Person rows are the worst case for that EXISTS OR chain. I checked: zero of my
132,785 Person rows have an AncestorIds2 row pointing at any of the 8 library
folders named in the query. Normal library items match the very first EXISTS
branch and short circuit immediately, which is cheap. Person rows cannot, so
every one of them falls through to later branches before anything can match.

That shows up cleanly when timing the same request per item type:

  Movie ......................... 6 ms
  Series ........................ 3 ms
  Episode ...................... 14 ms
  Audio ......................... 2 ms
  Book .......................... 1 ms
  MusicArtist .................. 65 ms
  BoxSet ...................... 174 ms
  Person ...................... 117 s
  no filter, what the client sends ... 458 s

That is roughly 0.9 ms per Person row, scaling linearly. A test library with a
few hundred fully scraped titles has maybe 3,000 to 10,000 people, so the same
query lands somewhere between 3 and 9 seconds, which is easy to write off as a
cold cache or a first load. At 132,785 people it becomes minutes.

To be clear about what I am claiming: the bug is the unusable index. The people
count is only what turns it from invisible into a hang.

THINGS THAT ARE NOT THE CAUSE

I checked these so nobody has to ask:

  I have zero orphaned Person rows, so a People cleanup does not help.
  ExcludeItemTypes=Person has no effect, the server still emits type 23 in the
  SQL Type IN list.
  Clearing search history does not help, the scan happens regardless of how
  many rows match.
  Not disk bound. One thread sits at 99.9% CPU for the whole duration.

SUGGESTED FIX

Drop the Coalesce() and compare the column directly, so
idx_UserDatas_DateLastSearched becomes usable. Coalesce(x, 0) > 0 and x > 0 are
equivalent here, since NULL fails both. That change alone took it from 763
seconds to 3 milliseconds for me.

CLIENT SIDE CONTEXT

dashboard-ui/search/searchfields.js gates this request on the server version:

  function supportsRecentlySearched(instance){
    return apiClient.isMinServerVersion("4.10.0.5")
  }

If the gate is false the function returns an empty result without issuing a
request, so this only fires against 4.10.0.5 and newer. TV layouts skip it as
well, and it only fires when the search box is empty. When it does fire,
IncludeItemTypes is unconditionally null, which is what pulls all 132,785
Person rows into the query. Emby for Android sends the same unfiltered request,
so this is not specific to the web client.

For reference, the same request against the same database returns in 27 ms with
IncludeItemTypes=Movie,Series,Episode,Audio,Book.

WORKAROUND FOR ANYONE ELSE HITTING THIS

Until it is fixed, injecting

  IncludeItemTypes=Movie,Series,Episode,Audio,Book,BoxSet

into any request carrying WasSearched=true, either through a reverse proxy or
by patching that line in searchfields.js, takes the request from 458 seconds to
about 200 milliseconds.

Happy to run further tests or post the full unredacted query and logs.