Files
silo-server/internal/playback/subtitle_fonts_test.go
CoffeeKnyteandGitHub a2ef26bece perf: root-cause fixes for endpoints still slow after #292 (NextUp, series badges, resume tail, subtitle fonts) (#350)
* docs(plans): root-cause analysis for endpoints still slow after PR #292

Five endpoint groups stayed slow after the home/Continue Watching/Latest
latency work shipped: Resume (110s p95), NextUp (17s p95), Latest (17s),
/Items, and the home sections routes. The caps and caches from PR #292 are
live in the deployed binary; they bounded how many rows the loops touch but
not what each underlying query costs. Documents the four confirmed root
causes (4.3M stale completed-with-position progress rows + missing resume
index, unbounded next-up anchor scan, per-episode series rollup fanout, two
index-starved history/scanner paths) with live EXPLAIN ANALYZE measurements
and the fix plan implemented by the follow-up commits.

AI-use disclosure: analysis and doc produced with AI (Claude) assistance.

* perf(catalog): bound the global next-up anchor scan to recent completions

The completed_episodes CTE in buildListNextUpQuery derived per-series
anchors from the profile's ENTIRE completed history — DISTINCT ON over 233k
rows joined to episodes for the worst bulk-import profile, then a per-series
LATERAL that scans every episode of a fully-watched series before yielding
nothing. 648 slow executions in a 19h window, 44.7s worst; this drove
/Shows/NextUp (17.1s p95) and the next-up injection on the native home
sections aggregate.

Global queries now derive anchors from the profile's nextUpAnchorMaxRows
(500) most recent completed rows — an ordered index walk on
idx_uwp_profile_completed, with the hidden-items exclusion and date cutoff
applied inside the bounded scan so hidden/old rows never consume the anchor
budget. A next-up rail surfaces ~24 series; the 500 most recent completions
cover every series that can realistically rank on it. Series-scoped calls
(the show-detail tile) keep the unbounded shape: they must anchor on the
series' last completed episode no matter how long ago it was watched, and
are naturally bounded by one series.

Measured on the live worst-case profile with the exact generated SQL:
44.7s worst / ~2.6s avg before; 10ms after (together with the one-time
stale-resume-point data repair applied directly to the deployment DB — see
docs/superpowers/plans/2026-07-06-slow-endpoint-root-causes.md).

AI-use disclosure: implemented with AI (Claude) assistance.

* perf(jellycompat,userstore): aggregate series watch-state rollup in SQL

The series Played/UnplayedItemCount badge on list rails (per-library Latest,
library browse, search results) and series detail pages was computed by
materializing EVERY episode of every series on the page
(episodeRepo.ListBySeriesIDs) and then batching per-episode progress+history
lookups in 500-id chunks. A 50-series page of an episode-heavy library
(Sports) expanded to 32,467 episode rows and ~65 sequential queries —
measured 17-18s per /Items/Latest request, and PR #292's cached Latest fast
path pays it on every response for series libraries. The same fanout made
/Items?searchTerm=... slow whenever the result set was mostly series
(Meilisearch itself answers in milliseconds).

New optional store capability userstore.SeriesEpisodeRollupStore, implemented
by PostgresUserStore as one GROUP BY e.series_id aggregate with semantics
identical to the chunked path (episode availability via episode_libraries,
hidden-items visibility on progress rows, completed-history fold, in-progress
= not watched with position > 0 — verified value-for-value against the old
semantics on a real 1,586-episode series). enrichSeriesListUserData and
enrichDetailUserData use it when present; SQLite-backed stores and rollup
query failures keep the existing chunked path as fallback.
catalog.SeasonUserDataFromCounts pins the counts-to-DTO mapping to
EpisodeRollupUserData.

Measured on the live worst-case profile against the real 50-series Sports
Latest page: ~17s of chunked round-trips before, 119ms in one query after.

Part of docs/superpowers/plans/2026-07-06-slow-endpoint-root-causes.md.

AI-use disclosure: implemented with AI (Claude) assistance.

* perf(catalog): bound superseded-episode completed walk to recent history

The Resume / Continue Watching superseded-episode filter loaded a
profile's *entire* completed history into memory on every request that
contained an in-progress episode: CompletedProgressSnapshots paged
user_watch_progress WHERE completed=TRUE with no upper bound. The
2026-07-06 slow-query comparison showed this surviving as a 60-116s
Resume tail even after the in-progress index landed live, because the
4.3M zeroed Plex-import rows are still completed=TRUE and were re-walked
every load.

A completed episode can only supersede an in-progress one it was
finished more recently than (the query gates on
done_progress.updated_at > ip_progress.updated_at), so only completed
rows newer than the oldest in-progress entry can matter. Compute that
cutoff in SupersededEpisodeProgressIDs and pass it to
CompletedProgressSnapshots, which — since the completed listing is
ordered updated_at DESC — stops paging as soon as it crosses the cutoff.
Import-heavy profiles whose back-catalogue predates their current
in-progress items now stop on the first page instead of paging hundreds
of thousands of irrelevant rows. Correctness is unchanged: no relevant
superseding row is excluded.

* perf(catalog): hard-cap superseded-episode completed walk at 5 pages

The updated_at cutoff added in the previous commit bounds the completed
walk on the relevance axis, but a very old in-progress entry sitting
behind a large volume of newer completions could still page deep. Add a
5-page (2,500-row) hard backstop on top of the cutoff: normal profiles
still stop on page one via the cutoff, and only the adversarial tail hits
the cap. When it engages the tail of the completed set goes unscanned, so
a superseded episode could momentarily survive on Continue Watching — we
log a warning when that happens (with profile_id + rows scanned) rather
than mis-filter silently, and it self-corrects once the stale in-progress
entry ages out of the scanned window.

* perf(playback): extract subtitle fonts in a single ffmpeg pass

Embedded ASS/SSA font extraction spawned one ffmpeg process per font
attachment, each re-opening the (usually CephFS-backed) media file. Anime
releases carry 15-47 fonts, so the per-spawn file-open cost dominated and
pushed GET /api/v1/stream/{sid}/subtitles/{track}/fonts to a 17-60 s plateau
(p95 ~33 s in the live logs).

Collapse the N spawns into one ffmpeg invocation that dumps every attachment
to a temp dir (-dump_attachment:idx path ... -i file -map 0:t? -c copy), then
read the files back. The file is opened once instead of N times, taking p95
from ~30 s to ~1-2 s with no change to output.

Safety is preserved. The 32-attachment / 32 MiB caps still apply: attachment
size is stat'd before read so an over-limit font never enters memory, and a
watchdog polls the dump dir and kills ffmpeg if its on-disk output crosses the
cap -- restoring the hard bound the old pipe-per-attachment reader enforced by
killing at maxBytes+1, so a container with oversized "font" attachments can't
fill the disk.

Part of the slow-endpoint follow-up; see
slow-query-analysis/subtitle-fonts-extraction-findings.md.

* fix(review): report enforced font-byte cap; correct doc subtitle scope

Address PR #350 review:
- dumpFontAttachments reported the maxSubtitleFontBytes package constant in
  both over-limit errors instead of the maxBytes argument the caller passed,
  so the message misstated the enforced bound whenever a different cap was in
  effect (as the tests use). Interpolate maxBytes in both messages.
- The root-cause plan claimed subtitle extraction was 'out of scope' while the
  branch actually optimizes /subtitles/{track}/fonts. Scope the out-of-scope
  note to subtitle *track* conversion and record the fonts single-pass work as
  deliverable 5.
2026-07-09 09:02:45 -04:00

201 lines
5.8 KiB
Go

package playback
import (
"context"
"os"
"path/filepath"
"runtime"
"strings"
"testing"
)
// fakeFFmpegDumping returns a shell script that mimics ffmpeg's
// -dump_attachment behaviour: it writes payload to every path that follows a
// -dump_attachment:* flag. This exercises the single-invocation extractor
// without a real ffmpeg. The shebang must stay on the first line.
func fakeFFmpegDumping(payload string) string {
return "#!/bin/sh\nPAYLOAD='" + payload + `'
prev=""
for a in "$@"; do
case "$prev" in
-dump_attachment:*) printf '%s' "$PAYLOAD" > "$a" ;;
esac
prev="$a"
done
`
}
// TestDumpFontAttachmentsArgvOrder pins the ffmpeg argument contract: every
// -dump_attachment flag must precede -i (they are per-input options for the
// following input), and the -map 0:t? / -c copy stream-copy flags must be
// present (without them ffmpeg decodes the whole video). A fake ffmpeg records
// its argv so a malformed invocation can't pass silently.
func TestDumpFontAttachmentsArgvOrder(t *testing.T) {
if runtime.GOOS == "windows" {
t.Skip("shell script test helper is unix-only")
}
dir := t.TempDir()
argvFile := filepath.Join(dir, "argv")
ffmpegPath := filepath.Join(dir, "ffmpeg")
writeExecutable(t, ffmpegPath, "#!/bin/sh\nprintf '%s\\n' \"$@\" > '"+argvFile+`'
prev=""
for a in "$@"; do
case "$prev" in
-dump_attachment:*) printf 'x' > "$a" ;;
esac
prev="$a"
done
`)
if _, err := dumpFontAttachments(context.Background(), "input.mkv", ffmpegPath,
[]attachmentProbeStream{{Index: 2}, {Index: 5}}, maxSubtitleFontBytes); err != nil {
t.Fatalf("dumpFontAttachments returned error: %v", err)
}
raw, err := os.ReadFile(argvFile)
if err != nil {
t.Fatalf("read argv: %v", err)
}
argv := strings.Split(strings.TrimRight(string(raw), "\n"), "\n")
inputIdx, mapIdx := -1, -1
lastDumpIdx := -1
for i, a := range argv {
switch {
case a == "-i":
inputIdx = i
case a == "-map":
mapIdx = i
case strings.HasPrefix(a, "-dump_attachment:"):
lastDumpIdx = i
}
}
if inputIdx < 0 {
t.Fatalf("argv missing -i: %v", argv)
}
if lastDumpIdx < 0 || lastDumpIdx > inputIdx {
t.Fatalf("dump_attachment flags must precede -i; argv=%v", argv)
}
if mapIdx < 0 || argv[mapIdx+1] != "0:t?" {
t.Fatalf("argv missing -map 0:t?: %v", argv)
}
if !containsSeq(argv, "-c", "copy") {
t.Fatalf("argv missing -c copy: %v", argv)
}
}
func containsSeq(argv []string, a, b string) bool {
for i := 0; i+1 < len(argv); i++ {
if argv[i] == a && argv[i+1] == b {
return true
}
}
return false
}
func TestExtractAttachedSubtitleFontsSingleInvocation(t *testing.T) {
if runtime.GOOS == "windows" {
t.Skip("shell script test helper is unix-only")
}
dir := t.TempDir()
ffmpegPath := filepath.Join(dir, "ffmpeg")
writeExecutable(t, filepath.Join(dir, "ffprobe"), `#!/bin/sh
cat <<'JSON'
{"streams":[{"index":2,"codec_name":"ttf","codec_type":"attachment","tags":{"filename":"MyFont.ttf","mimetype":"font/ttf"}},{"index":3,"codec_name":"otf","codec_type":"attachment","tags":{"filename":"Other.otf","mimetype":"font/otf"}}]}
JSON
`)
writeExecutable(t, ffmpegPath, fakeFFmpegDumping("fontdata"))
fonts, err := ExtractAttachedSubtitleFonts(context.Background(), "input.mkv", ffmpegPath)
if err != nil {
t.Fatalf("ExtractAttachedSubtitleFonts returned error: %v", err)
}
if len(fonts) != 2 {
t.Fatalf("font count = %d, want 2", len(fonts))
}
if fonts[0].Name != "MyFont.ttf" || fonts[1].Name != "Other.otf" {
t.Fatalf("font names = %q/%q, want MyFont.ttf/Other.otf", fonts[0].Name, fonts[1].Name)
}
if string(fonts[0].Data) != "fontdata" {
t.Fatalf("font data = %q, want fontdata", string(fonts[0].Data))
}
}
// A dump file ffmpeg never wrote (an attachment it could not stream-copy) must
// be skipped rather than fail the whole bundle.
func TestDumpFontAttachmentsSkipsMissingDumps(t *testing.T) {
if runtime.GOOS == "windows" {
t.Skip("shell script test helper is unix-only")
}
dir := t.TempDir()
ffmpegPath := filepath.Join(dir, "ffmpeg")
// Only writes the first dump target; the second path is left absent.
writeExecutable(t, ffmpegPath, `#!/bin/sh
prev=""
first=1
for a in "$@"; do
case "$prev" in
-dump_attachment:*)
if [ "$first" = "1" ]; then printf 'fontdata' > "$a"; first=0; fi ;;
esac
prev="$a"
done
`)
fonts, err := dumpFontAttachments(context.Background(), "input.mkv", ffmpegPath,
[]attachmentProbeStream{{Index: 2}, {Index: 3}}, maxSubtitleFontBytes)
if err != nil {
t.Fatalf("dumpFontAttachments returned error: %v", err)
}
if len(fonts) != 1 {
t.Fatalf("font count = %d, want 1 (missing dump skipped)", len(fonts))
}
}
func TestDumpFontAttachmentsRejectsOverLimitData(t *testing.T) {
if runtime.GOOS == "windows" {
t.Skip("shell script test helper is unix-only")
}
dir := t.TempDir()
ffmpegPath := filepath.Join(dir, "ffmpeg")
writeExecutable(t, ffmpegPath, fakeFFmpegDumping("12345"))
_, err := dumpFontAttachments(
context.Background(),
"input.mkv",
ffmpegPath,
[]attachmentProbeStream{{Index: 2}},
4,
)
if err == nil {
t.Fatal("expected size limit error, got nil")
}
if !strings.Contains(err.Error(), "attached font data exceeds") {
t.Fatalf("error = %q, want attached font data limit", err.Error())
}
}
func TestFFprobePathFromFFmpegRewritesOnlyBasename(t *testing.T) {
got := ffprobePathFromFFmpeg(filepath.Join("tmp", "ffmpeg-tools", "ffmpeg"))
want := filepath.Join("tmp", "ffmpeg-tools", "ffprobe")
if got != want {
t.Fatalf("ffprobePathFromFFmpeg basename path = %q, want %q", got, want)
}
got = ffprobePathFromFFmpeg(filepath.Join("tmp", "ffmpeg-tools", "custom"))
if got != "ffprobe" {
t.Fatalf("ffprobePathFromFFmpeg custom basename = %q, want ffprobe", got)
}
}
func writeExecutable(t *testing.T, path string, content string) {
t.Helper()
if err := os.WriteFile(path, []byte(content), 0o755); err != nil {
t.Fatalf("write %s: %v", path, err)
}
}