* 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.
248 lines
7.9 KiB
Go
248 lines
7.9 KiB
Go
package catalog
|
|
|
|
import (
|
|
"context"
|
|
"strconv"
|
|
"strings"
|
|
"testing"
|
|
"time"
|
|
|
|
"github.com/Silo-Server/silo-server/internal/userstore"
|
|
)
|
|
|
|
func TestFilterSupersededProgressDropsOlderPartialsAfterLaterCompletedEpisode(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
entries := []userstore.WatchProgress{
|
|
{MediaItemID: "boys-s1e1"},
|
|
{MediaItemID: "boys-s5e3"},
|
|
{MediaItemID: "movie-1"},
|
|
}
|
|
superseded := map[string]struct{}{
|
|
"boys-s1e1": {},
|
|
"boys-s5e3": {},
|
|
}
|
|
|
|
filtered := FilterSupersededProgress(entries, superseded)
|
|
|
|
if len(filtered) != 1 || filtered[0].MediaItemID != "movie-1" {
|
|
t.Fatalf("filtered entries = %+v, want only movie-1", filtered)
|
|
}
|
|
}
|
|
|
|
func TestCompletedProgressSnapshotsPagesThroughConfiguredStore(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
entries := make([]userstore.WatchProgress, supersededProgressPageSize+1)
|
|
for i := range entries {
|
|
entries[i] = userstore.WatchProgress{
|
|
MediaItemID: "done-" + time.Unix(int64(i), 0).Format("150405"),
|
|
UpdatedAt: time.Date(2025, 1, 1, 0, 0, i, 0, time.UTC).Format(time.RFC3339),
|
|
}
|
|
}
|
|
store := &stubProgressLister{entries: entries}
|
|
|
|
snapshots, err := CompletedProgressSnapshots(context.Background(), store, "p1", time.Time{})
|
|
if err != nil {
|
|
t.Fatalf("CompletedProgressSnapshots: %v", err)
|
|
}
|
|
if len(snapshots) != len(entries) {
|
|
t.Fatalf("completed snapshots count = %d, want %d", len(snapshots), len(entries))
|
|
}
|
|
if len(store.calls) != 2 {
|
|
t.Fatalf("ListProgress calls = %+v, want 2 paged calls", store.calls)
|
|
}
|
|
if store.calls[0] != (progressListCall{profileID: "p1", status: "completed", limit: supersededProgressPageSize, offset: 0}) {
|
|
t.Fatalf("first ListProgress call = %+v", store.calls[0])
|
|
}
|
|
if store.calls[1] != (progressListCall{profileID: "p1", status: "completed", limit: supersededProgressPageSize, offset: supersededProgressPageSize}) {
|
|
t.Fatalf("second ListProgress call = %+v", store.calls[1])
|
|
}
|
|
}
|
|
|
|
func TestCompletedProgressSnapshotsStopsAtCutoff(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
// Newest-first, spanning two full pages: the store hands rows back in
|
|
// updated_at DESC order the same way the completed listing query does.
|
|
entries := make([]userstore.WatchProgress, 2*supersededProgressPageSize)
|
|
base := time.Date(2025, 1, 1, 0, 0, 0, 0, time.UTC)
|
|
for i := range entries {
|
|
entries[i] = userstore.WatchProgress{
|
|
MediaItemID: "done-" + strconv.Itoa(i),
|
|
UpdatedAt: base.Add(time.Duration(-i) * time.Minute).Format(time.RFC3339),
|
|
}
|
|
}
|
|
store := &stubProgressLister{entries: entries}
|
|
|
|
// Cut off inside the first page: only rows strictly newer than the cutoff
|
|
// are returned, and paging stops without ever reading the second page.
|
|
cutoff := base.Add(-10 * time.Minute)
|
|
snapshots, err := CompletedProgressSnapshots(context.Background(), store, "p1", cutoff)
|
|
if err != nil {
|
|
t.Fatalf("CompletedProgressSnapshots: %v", err)
|
|
}
|
|
if len(snapshots) != 10 {
|
|
t.Fatalf("completed snapshots count = %d, want 10 (rows newer than cutoff)", len(snapshots))
|
|
}
|
|
if len(store.calls) != 1 {
|
|
t.Fatalf("ListProgress calls = %+v, want a single page before the cutoff halts paging", store.calls)
|
|
}
|
|
}
|
|
|
|
func TestCompletedProgressSnapshotsHaltsAtPageCap(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
// More completed history than the page cap allows, all newer than the
|
|
// (zero) cutoff so nothing halts the walk except the cap itself.
|
|
entries := make([]userstore.WatchProgress, (supersededProgressMaxPages+1)*supersededProgressPageSize)
|
|
base := time.Date(2025, 1, 1, 0, 0, 0, 0, time.UTC)
|
|
for i := range entries {
|
|
entries[i] = userstore.WatchProgress{
|
|
MediaItemID: "done-" + strconv.Itoa(i),
|
|
UpdatedAt: base.Add(time.Duration(-i) * time.Second).Format(time.RFC3339),
|
|
}
|
|
}
|
|
store := &stubProgressLister{entries: entries}
|
|
|
|
snapshots, err := CompletedProgressSnapshots(context.Background(), store, "p1", time.Time{})
|
|
if err != nil {
|
|
t.Fatalf("CompletedProgressSnapshots: %v", err)
|
|
}
|
|
if len(store.calls) != supersededProgressMaxPages {
|
|
t.Fatalf("ListProgress calls = %d, want %d (page cap)", len(store.calls), supersededProgressMaxPages)
|
|
}
|
|
if len(snapshots) != supersededProgressMaxPages*supersededProgressPageSize {
|
|
t.Fatalf("completed snapshots count = %d, want %d (capped pages)", len(snapshots), supersededProgressMaxPages*supersededProgressPageSize)
|
|
}
|
|
}
|
|
|
|
func TestBuildSupersededEpisodeProgressQueryUsesStoreSnapshotsWithFreshnessGate(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
query := buildSupersededEpisodeProgressQuery()
|
|
expectedFragments := []string{
|
|
"unnest($1::text[], $2::timestamptz[])",
|
|
"unnest($3::text[], $4::timestamptz[])",
|
|
"FROM in_progress ip_progress",
|
|
"done_progress.updated_at > ip_progress.updated_at",
|
|
}
|
|
for _, fragment := range expectedFragments {
|
|
if !strings.Contains(query, fragment) {
|
|
t.Fatalf("expected superseded progress query to contain %q, got:\n%s", fragment, query)
|
|
}
|
|
}
|
|
unexpectedFragments := []string{
|
|
"user_watch_progress",
|
|
"user_history_hidden_items",
|
|
}
|
|
for _, fragment := range unexpectedFragments {
|
|
if strings.Contains(query, fragment) {
|
|
t.Fatalf("superseded progress query contains %q, got:\n%s", fragment, query)
|
|
}
|
|
}
|
|
}
|
|
|
|
func TestSupersededEpisodeProgressIDsWithoutPoolReturnsEmptySet(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
filter := NewContinueWatchingProgressFilter(nil)
|
|
entries := []userstore.WatchProgress{{
|
|
MediaItemID: "ep-1",
|
|
UpdatedAt: time.Date(2025, 1, 1, 0, 0, 0, 0, time.UTC).Format(time.RFC3339),
|
|
}}
|
|
store := &stubProgressLister{}
|
|
|
|
superseded, err := filter.SupersededEpisodeProgressIDs(context.Background(), store, "p1", entries)
|
|
if err != nil {
|
|
t.Fatalf("SupersededEpisodeProgressIDs: %v", err)
|
|
}
|
|
if len(superseded) != 0 {
|
|
t.Fatalf("superseded = %v, want empty set", superseded)
|
|
}
|
|
if len(store.calls) != 0 {
|
|
t.Fatalf("ListProgress calls = %+v, want none without a pool", store.calls)
|
|
}
|
|
}
|
|
|
|
func TestHomeDismissalIndexFilterProgressDropsOnlyMatchingTimestamps(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
dismissedAt := "2025-01-01T00:00:00Z"
|
|
resumedAt := "2025-01-02T00:00:00Z"
|
|
idx := NewHomeDismissalIndex([]userstore.HomeItemDismissal{
|
|
{MediaItemID: "still-dismissed", ProgressUpdatedAt: &dismissedAt},
|
|
{MediaItemID: "resumed-since", ProgressUpdatedAt: &dismissedAt},
|
|
{MediaItemID: "no-timestamp"},
|
|
})
|
|
|
|
entries := []userstore.WatchProgress{
|
|
{MediaItemID: "still-dismissed", UpdatedAt: dismissedAt},
|
|
{MediaItemID: "resumed-since", UpdatedAt: resumedAt},
|
|
{MediaItemID: "no-timestamp", UpdatedAt: dismissedAt},
|
|
{MediaItemID: "never-dismissed", UpdatedAt: dismissedAt},
|
|
}
|
|
|
|
filtered := idx.FilterProgress(entries)
|
|
|
|
got := make([]string, 0, len(filtered))
|
|
for _, entry := range filtered {
|
|
got = append(got, entry.MediaItemID)
|
|
}
|
|
want := []string{"resumed-since", "no-timestamp", "never-dismissed"}
|
|
if len(got) != len(want) {
|
|
t.Fatalf("filtered = %v, want %v", got, want)
|
|
}
|
|
for i := range want {
|
|
if got[i] != want[i] {
|
|
t.Fatalf("filtered = %v, want %v", got, want)
|
|
}
|
|
}
|
|
}
|
|
|
|
func TestProgressSnapshotsSkipsBlankIDsAndBadTimestamps(t *testing.T) {
|
|
t.Parallel()
|
|
|
|
valid := time.Date(2025, 1, 1, 0, 0, 0, 0, time.UTC)
|
|
entries := []userstore.WatchProgress{
|
|
{MediaItemID: "ok", UpdatedAt: valid.Format(time.RFC3339)},
|
|
{MediaItemID: " ", UpdatedAt: valid.Format(time.RFC3339)},
|
|
{MediaItemID: "bad-time", UpdatedAt: "not-a-time"},
|
|
}
|
|
|
|
snapshots := ProgressSnapshots(entries)
|
|
|
|
if len(snapshots) != 1 || snapshots[0].ContentID != "ok" || !snapshots[0].UpdatedAt.Equal(valid) {
|
|
t.Fatalf("snapshots = %+v, want single valid snapshot for %q", snapshots, "ok")
|
|
}
|
|
}
|
|
|
|
type progressListCall struct {
|
|
profileID string
|
|
status string
|
|
limit int
|
|
offset int
|
|
}
|
|
|
|
type stubProgressLister struct {
|
|
entries []userstore.WatchProgress
|
|
calls []progressListCall
|
|
}
|
|
|
|
func (s *stubProgressLister) ListProgress(_ context.Context, profileID, status string, limit, offset int) ([]userstore.WatchProgress, error) {
|
|
s.calls = append(s.calls, progressListCall{
|
|
profileID: profileID,
|
|
status: status,
|
|
limit: limit,
|
|
offset: offset,
|
|
})
|
|
if offset >= len(s.entries) {
|
|
return nil, nil
|
|
}
|
|
end := offset + limit
|
|
if end > len(s.entries) {
|
|
end = len(s.entries)
|
|
}
|
|
return s.entries[offset:end], nil
|
|
}
|