The read path costs about four times upstream's CPU per request #83
Loading…
Reference in a new issue
No description provided.
Delete branch "%!s()"
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?
The read path costs about four times upstream's CPU per request, and that is the
whole of the throughput difference.
Measured on one host against a database copied from a running Jellyfin — 55,523
items, 43,466
UserDatarows, 116,813 stream rows, 14 users. Both servers rannatively from a release build, each pinned to its own four CPUs, each given its
own copy of the library, both answering the same eleven listing requests — the
ones both servers answer identically, so this is not a comparison of different
work. Five repetitions, medians below.
Throughput plateaus at a quarter of upstream's.
Both saturate at four concurrent requests and both stay flat to 128, so neither
is falling over — they are simply CPU-bound at different levels.
The level is the CPU each spends per request. At saturation four cores are
fully busy on each side, so the ceiling is arithmetic:
Both predictions land on the measured plateau. There is no queueing effect, no
lock, no pool limit to look for: the throughput gap is the per-request CPU
gap, and nothing else contributes to it.
It is not that we send less. Bytes per response are within 1% at every point
— 42.4 KB against 42.4 KB. Both servers are serializing the same pages.
Latency follows. At concurrency 1, with nothing queued: p50 40ms upstream
against 120ms ours, p90 81ms against 504ms. Under a fixed offered rate the gap
becomes the difference between working and not — at 25 requests a second, a rate
upstream serves at 50ms p50, ours delivers 13.4 rps and a p50 of 11.9
seconds, because it cannot take the rate at all and the queue grows for the
length of the run.
What we do spend it on is the open question. One measurement narrows it:
at concurrency 1 the process uses about 1.8 cores per request, so there is
already parallelism inside a single request, and it is not enough to hide the
cost. Candidates, in the order they are cheap to eliminate:
Peopleexpansion — we return 22 cast rows per item on a fifty-item pagewhere upstream returns none at all (see the sibling issue on fields a listing
sends that upstream does not). Twenty-two joins per item, fifty items.
/Personsdoes, which on the same library never returns at all. Ifthe by-name path is doing work proportional to the table rather than the page,
the same shape may be under these listings.
do the same amount of.
Where we win, for completeness. Cold start to first answer is 617ms against
upstream's 3,546ms, and resident memory at idle is 10.8 MB against 165 MB. Under
load ours peaks higher — 1,160 MB against 905 MB — which is worth its own look.
To reproduce. Point both servers at their own copy of a library of this size
on the same host, pin each to a disjoint set of cores so neither starves the
other, warm both, then hold a fixed number of requests in flight against a
listing both answer identically and read
cpu.statfor each:The per-request CPU figures above are
usage_usecdeltas from each scopedivided by that server's own completed responses. They include a warmup and a
correctness pass, so the absolute numbers are a little high on both sides; the
figures derived from the saturation plateau (74.8ms and 298ms) do not, and the
two agree.
Three fixes land most of this. Processor time per request is now 3.5× lower across the seventeen reads a listing client makes, and the largest single cause was not any of the three candidates named above.
Measured on a copy of the same anchor (55,523 items, 43,466
UserDatarows), one request at a time, asutime+stimedeltas of the server process divided by the requests that produced them — not the harness's gated comparison, so these are our own before-and-after and not a ratio against upstream. All 29 responses captured across listings, by-name routes, search, filters and counts are byte-identical before and after./Items/Counts/Artists/Artists/AlbumArtists/Studios/MusicGenres/Genres/UserItems/Resume/Items(Movie,Episode, IsPlayed)/Items(DateCreated)/Items(Movie, page 1)/Items/Latest/Items/Filters2/Search/Hints/UserViews/Items(Episode, deep page)/Years/PersonsThe database was never mapped, so a page was read once per connection
This is the one that touches every route, and it is not in the list of candidates above. Without
mmap_sizeevery read copies pages out of the file into a per-connection cache whose default 2 MiB holds almost none of a real library's indexes — so the same pages are read again for the next query, and again for the next pooled connection. Four configurations, same measurement:cache_size64 MiBmmap_size1 GiBRaising the cache instead buys less and costs heap per connection. Mapped, the heap is smaller than it was — pages are read in place rather than copied — and what is counted resident beyond that is file-backed and reclaimable. Neither the file nor a lock is touched, so an upstream server against the same database is unaffected. The cost is that an I/O error inside the mapping arrives as
SIGBUSrather than as an error.This is worth weighing against the RSS note above: under load ours peaks higher — 1,160 MB against 905 MB. That peak is heap, and this makes it smaller.
A by-name page was described one entry at a time
/Artistsspent 397 statements on fifty names — fifty image reads each binding a single id, fifty user-data reads, and aPermissionsread twice per entry. This is the per-item readassemble::manyalready existed to replace, and the by-name routes were simply not using it. The page is now resolved once and described whole./Items/Countsran the narrowed query eleven timesOnce per kind, and each run re-derived the user's libraries: 33
TopParentIdscans and 11 counts for twelve numbers. Upstream sums one grouped query; so do we now — 90 statements to 9.The value narrowing collected every id before it filtered
named_inandvalues_innarrowed withItemValuesMap.ItemId IN (SELECT id ...), which fixes the order of work: every item the query selects is materialised first and the mapping probed once per id. On a listing that narrows to nothing that is the whole library — 279 ms of a 334 ms/Artists. Written as a join, SQLite flattens it and picks its own order, driving from the value type when the query is broad and from the items when it is narrow. Both directions matter: an earlier attempt that forced the value-driven order made/Items/Filters2(narrowed toMovie) worse, 117 ms to 304 ms.What is still open
/Years— 332 ms, barely moved. It reads every row in the library to keep one integer column, then spends two queries per year resolving the item standing for it (144 statements). It needs the same treatment as the others; the wrinkle is that upstream orders these by the items rather than by the year, so the existing distinct-year projection is not a drop-in.user_librariescosts three index scans per request, on every route. Deciding which libraries a user may see reads every descendant of each of their views — 16,230 ancestor rows for one library — to return a single id. It cannot be made cheaper without an index that is not in upstream's schema, so it wants caching or one call per request instead of one per view.Re-measured with the three fixes in, same host, same anchor, five repetitions, medians. The finding in this issue no longer holds: the read path now costs less processor time per request than upstream, not four times more.
Run
20260805T083531Z— oursbc2a104, no uncommitted changes; upstreamv12.0-rc3-49-g7215950bd4, artifact9a0e3959c847.Processor per request
Counted per server over the agreement pass, the warmup and every measurement — 34,884 responses ours against 24,090 upstream, each divided by its own count. The absolute figures are not comparable with the ones above them: that window includes warmup, and the timed set is 13 requests rather than 11.
Throughput
The plateau moved from ~13.4 rps to ~72.5 rps while upstream's stayed at ~39.5. Bytes per response are within 1% at every point, so this is not faster because it sent less.
The arithmetic that explained the old ceiling still explains the new one: 4 cores ÷ 55 ms ≈ 72 rps.
Latency, and the case this issue called out
At concurrency 1, p50 25.0 ms against upstream's 49.9 ms — where it was 120 ms against 40 ms.
The issue's sharpest example was that at 25 requests a second, a rate upstream served at 50 ms p50, we delivered 13.4 rps and a p50 of 11.9 seconds. Under a fixed offered rate now:
At 50/s we take the offered rate with a 37 ms median and upstream is the one that cannot — its p50 is 42× ours there.
Memory, which was the other open question
Under load ours peaks higher — 1,160 MB against 905 MB — which is worth its own look. That reversed too:
Mapping the database moved reads off the heap, so the peak fell even though 369 MB of file-backed pages are now counted resident. Idle rose 14 MB, still under a sixth of upstream's.
Cold start unchanged at 621 ms against 3,652 ms.
What this does not say
The gate is unchanged: 13 of 21 requests timed, 8 still dropped for disagreeing. They are the same eight, and they are #79, #80 and #81 —
Fields=Peoplepopulated where upstream leaves it empty,/Items/Countstwo out,/GenrescarryingUserData, theIsPlayed+DatePlayedordering. Several are heavy requests, so the timed set is not the whole read path, and fixing those correctness issues will change what is measured here. A ratio under 1 on thirteen requests is not a claim about the fourteenth.Two reads are also known to be untouched by this work and remain slow in absolute terms —
/Yearsstill reads every row in the library, and deciding which libraries a user may see still costs three index scans per request on every route. Neither is in the timed set often enough to move these numbers, and both are worth doing.The exact gate, from run
20260805T083531Z, so the timed set and what is missing from it are written down rather than re-derived. 21 requests replayed, 13 timed, 8 dropped.The 13 that are timed
These are what every number in this issue describes.
movies-page-1/Items?Recursive=true&IncludeItemTypes=Movie&SortBy=SortName&SortOrder=Ascending&Limit=50episodes-page-1/Items?…&IncludeItemTypes=Episode&SortBy=SortName&SortOrder=Ascending&Limit=50episodes-deep-page&StartIndex=10000series-with-user-data/Items?…&IncludeItemTypes=Series&SortBy=SortName&Limit=50&Fields=Overview,ItemCountsunplayed-movies/Items?…&IncludeItemTypes=Movie&Filters=IsUnplayed&SortBy=SortName&Limit=50latest/Items/Latestresume/UserItems/Resume?Limit=12&MediaTypes=Video&Fields=PrimaryImageAspectRatiopersons-page-1/Persons?Limit=50&SortBy=SortNamepersons-deep-page/Persons?Limit=50&SortBy=SortName&StartIndex=20000studios/Studios?Limit=50&SortBy=SortNameartists/Artists?Limit=50&SortBy=SortNamesearch-hints/Search/Hints?SearchTerm=a&Limit=20filters/Items/Filters2?IncludeItemTypes=MovieThe 8 that disagree, and what owns each
Every difference in the run classified by field — not sampled — so a request whose only blocker is fixed enters the timed set.
countsItemCounteverything-by-date-addedTotalRecordCountviewsgenresUserDataepisodes-deep-page-fieldsPeople, 9×MediaStreams[].Scoremovies-page-1-fieldsPeople, 13×Score, 33×UserData.Keyplayed-descendingIddiffering on 50/50audio-by-album-artistIddiffering on 50/50Six of the eight are blocked by a single issue each. #79 and #81 are worth two and three requests respectively, and #79 is two rows.
Why this matters for the numbers above
The timed set is not a random 13 of 21. It excludes:
Fields=…People…requests, which are the heaviest reads in the scenario and the ones where we do work upstream does not (#81). Fixing that moves them into the set and makes them cheaper, so the ratio should improve twice over./Items/Counts, now 22.5 ms of processor against 541 ms before, entirely unmeasured against upstream over a two-row count gap.audio-by-album-artist, the only audio listing in the scenario — so the music path contributes nothing to any figure here.A ratio of 0.58 on thirteen requests is not a claim about the twenty-one. Closing #78 through #81 and #84 is what makes it one.
Re-measured with the gate cleared. The finding this issue reports is gone, and so is the reason the earlier correction in this thread was flattering.
Run
20260811T211300Z— oursba8f44e, no uncommitted changes; upstreamv12.0-rc3-49-g7215950bd4, artifact9a0e3959c847. Five repetitions, medians, each server pinned to its own four CPUs, one copy of the library each, 56,337 items.The gate
60 requests replayed, 50 timed, 10 dropped. The comment above listed 21 replayed and 13 timed; the request set is now the id-free one from #82, and every request that was dropped for #78, #79, #80, #81 or #84 is in the timed set.
The ten still dropped are #86. None of them belongs to a closed issue.
Processor time per request
Counted per server over the agreement pass, the warmup and every measurement — 43,233 responses ours against 15,122 upstream, each divided by its own count.
Upstream's figure nearly tripled, and that is the part worth reading carefully. It is not a regression on upstream's side: the earlier runs measured an upstream that could not resolve a single person, genre, studio or artist, because the run gave both servers a metadata directory outside their data directories (see the comment above, and
f064438). An upstream answeringPeople: []is not doing the work being compared. On top of that the timed set now includes the heaviest requests in the scenario — the ones that ask for a cast — which the old gate dropped.So neither the 3.98 nor the 0.58 was measured against an upstream doing the work. The three ratios above are over three different timed sets and are not comparable with each other; only the last one is over a set both servers answer identically with the fixture arranged correctly.
Throughput
Both still saturate at four concurrent requests and both hold flat to 128.
It is not that we send less — we send more. 58.2 KB per response against upstream's 55.4 KB. That 5% is itself worth a look, and it is the opposite of the failure mode the measurement exists to catch.
Latency
At concurrency 1, nothing queued: p50 21.6 ms against upstream's 37.3 ms.
Under a fixed offered rate, the example this issue made its sharpest point with has inverted:
At 25 a second — the rate this issue reported upstream serving at a 50 ms median — upstream now delivers 14.5 rps and a median of five seconds, because it cannot take the rate over this request set and the queue grows for the length of the run. Ours takes it at 25 ms.
Memory and cold start
The peak reversed with the earlier mapping change and has stayed reversed.
What this does not say
Closing: the read path does not cost four times upstream's CPU per request, and the measurement that said so has been corrected at its root rather than argued with.