Files
silo-server/internal/catalog/continue_watching_progress.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

263 lines
9.8 KiB
Go
Raw Permalink Blame History

This file contains ambiguous Unicode characters
This file contains Unicode characters that might be confused with other characters. If you think that this is intentional, you can safely ignore this warning. Use the Escape button to reveal them.
package catalog
import (
"context"
"fmt"
"log/slog"
"strings"
"time"
"github.com/jackc/pgx/v5/pgxpool"
"github.com/Silo-Server/silo-server/internal/userstore"
)
// ProgressLister pages watch-progress rows for one profile.
// userstore.UserStore satisfies it.
type ProgressLister interface {
ListProgress(ctx context.Context, profileID, status string, limit, offset int) ([]userstore.WatchProgress, error)
}
// ProgressSnapshot pairs a media item with the time its progress row last changed.
type ProgressSnapshot struct {
ContentID string
UpdatedAt time.Time
}
// ContinueWatchingProgressFilter identifies in-progress entries that Continue
// Watching surfaces should hide: episodes superseded by a later-completed
// episode in the same series. The first-party sections fetcher and the
// jellycompat Resume endpoint share it so both surfaces agree on what "still
// watching" means.
type ContinueWatchingProgressFilter struct {
pool *pgxpool.Pool
}
// NewContinueWatchingProgressFilter creates a filter. A nil pool disables the
// superseded-episode check, leaving entries unfiltered.
func NewContinueWatchingProgressFilter(pool *pgxpool.Pool) *ContinueWatchingProgressFilter {
return &ContinueWatchingProgressFilter{pool: pool}
}
const supersededProgressPageSize = 500
// supersededProgressMaxPages hard-caps how many completed-history pages the
// superseded-episode walk reads in one request. The updated_at cutoff normally
// halts paging far sooner (an import-heavy profile's completed rows predate its
// active in-progress items, so the scan stops on the first page); this bound
// only engages in the adversarial case of a very old in-progress entry sitting
// behind a large volume of newer completions. Hitting it means the tail of the
// completed set went unscanned, so a genuinely-superseded episode could
// momentarily survive on the Continue Watching row — we log when that happens
// rather than silently mis-filter, and it self-corrects once the stale
// in-progress entry ages out of the scanned window.
const supersededProgressMaxPages = 5
// SupersededEpisodeProgressIDs returns the content IDs of in-progress entries
// whose series has a later episode completed more recently than the entry's
// own progress. Those entries are stale — the viewer already moved past them.
// Non-episode entries never match.
func (f *ContinueWatchingProgressFilter) SupersededEpisodeProgressIDs(ctx context.Context, store ProgressLister, profileID string, entries []userstore.WatchProgress) (map[string]struct{}, error) {
if f == nil || f.pool == nil {
return map[string]struct{}{}, nil
}
inProgress := ProgressSnapshots(entries)
if len(inProgress) == 0 {
return map[string]struct{}{}, nil
}
// 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 the only completed
// rows that can matter are those updated after the oldest in-progress entry;
// anything older can supersede nothing. Bounding the completed walk at that
// timestamp keeps import-heavy profiles — whose entire back-catalogue is
// completed=TRUE with old timestamps — from re-paging hundreds of thousands
// of irrelevant rows on every Resume/Continue Watching load (the 60116s
// tail in the 2026-07-06 slow-query comparison).
oldestInProgress := inProgress[0].UpdatedAt
for _, snapshot := range inProgress[1:] {
if snapshot.UpdatedAt.Before(oldestInProgress) {
oldestInProgress = snapshot.UpdatedAt
}
}
completed, err := CompletedProgressSnapshots(ctx, store, profileID, oldestInProgress)
if err != nil {
return nil, err
}
if len(completed) == 0 {
return map[string]struct{}{}, nil
}
inProgressIDs, inProgressUpdatedAts := splitProgressSnapshots(inProgress)
completedIDs, completedUpdatedAts := splitProgressSnapshots(completed)
query := buildSupersededEpisodeProgressQuery()
rows, err := f.pool.Query(ctx, query, inProgressIDs, inProgressUpdatedAts, completedIDs, completedUpdatedAts)
if err != nil {
return nil, fmt.Errorf("querying superseded episode progress: %w", err)
}
defer rows.Close()
superseded := make(map[string]struct{})
for rows.Next() {
var mediaItemID string
if err := rows.Scan(&mediaItemID); err != nil {
return nil, fmt.Errorf("scanning superseded episode progress: %w", err)
}
superseded[mediaItemID] = struct{}{}
}
if err := rows.Err(); err != nil {
return nil, fmt.Errorf("iterating superseded episode progress: %w", err)
}
return superseded, nil
}
// CompletedProgressSnapshots pages through the profile's completed progress
// rows and returns deduplicated snapshots updated after notBefore. The
// completed listing is ordered updated_at DESC (newest first), so once a row at
// or before notBefore is reached every later page is older still and paging
// stops — callers only care about completed episodes finished more recently
// than an in-progress entry, so older rows are irrelevant. Pass a zero
// notBefore to walk the whole history.
func CompletedProgressSnapshots(ctx context.Context, store ProgressLister, profileID string, notBefore time.Time) ([]ProgressSnapshot, error) {
seen := make(map[string]struct{})
snapshots := make([]ProgressSnapshot, 0)
for page := 0; page < supersededProgressMaxPages; page++ {
offset := page * supersededProgressPageSize
entries, err := store.ListProgress(ctx, profileID, "completed", supersededProgressPageSize, offset)
if err != nil {
return nil, fmt.Errorf("listing completed progress for superseded episodes: %w", err)
}
reachedCutoff := false
for _, snapshot := range ProgressSnapshots(entries) {
if !snapshot.UpdatedAt.After(notBefore) {
reachedCutoff = true
break
}
contentID := snapshot.ContentID
if _, ok := seen[contentID]; ok {
continue
}
seen[contentID] = struct{}{}
snapshots = append(snapshots, snapshot)
}
if reachedCutoff || len(entries) < supersededProgressPageSize {
return snapshots, nil
}
}
// Fell out of the loop with a full final page: the page cap halted the walk
// before the cutoff, so completed rows past the scanned window were skipped.
// Log it so a real profile that trips this backstop is visible rather than
// silently under-filtered.
slog.Warn("continue-watching: superseded-episode walk hit page cap; completed-history tail left unscanned",
"profile_id", profileID,
"pages_scanned", supersededProgressMaxPages,
"rows_scanned", len(snapshots))
return snapshots, nil
}
// ProgressSnapshots converts progress rows to snapshots, dropping rows with a
// blank media item ID or an unparseable timestamp.
func ProgressSnapshots(entries []userstore.WatchProgress) []ProgressSnapshot {
snapshots := make([]ProgressSnapshot, 0, len(entries))
for _, entry := range entries {
contentID := strings.TrimSpace(entry.MediaItemID)
if contentID == "" {
continue
}
updatedAt, err := time.Parse(time.RFC3339, entry.UpdatedAt)
if err != nil || updatedAt.IsZero() {
continue
}
snapshots = append(snapshots, ProgressSnapshot{
ContentID: contentID,
UpdatedAt: updatedAt.UTC(),
})
}
return snapshots
}
func splitProgressSnapshots(snapshots []ProgressSnapshot) ([]string, []time.Time) {
contentIDs := make([]string, len(snapshots))
updatedAts := make([]time.Time, len(snapshots))
for i, snapshot := range snapshots {
contentIDs[i] = snapshot.ContentID
updatedAts[i] = snapshot.UpdatedAt
}
return contentIDs, updatedAts
}
// The snapshots arrive as unnest arrays instead of joins against
// user_watch_progress because per-user progress may live in a SQLite store
// rather than this Postgres database.
func buildSupersededEpisodeProgressQuery() string {
return `
WITH in_progress(content_id, updated_at) AS (
SELECT * FROM unnest($1::text[], $2::timestamptz[])
),
completed(content_id, updated_at) AS (
SELECT * FROM unnest($3::text[], $4::timestamptz[])
)
SELECT DISTINCT ip.content_id
FROM in_progress ip_progress
JOIN episodes ip ON ip.content_id = ip_progress.content_id
JOIN episodes done
ON done.series_id = ip.series_id
AND (done.season_number, done.episode_number) > (ip.season_number, ip.episode_number)
JOIN completed done_progress
ON done_progress.content_id = done.content_id
WHERE done_progress.updated_at > ip_progress.updated_at`
}
// FilterSupersededProgress drops entries whose media item ID is in the
// superseded set.
func FilterSupersededProgress(entries []userstore.WatchProgress, superseded map[string]struct{}) []userstore.WatchProgress {
if len(entries) == 0 || len(superseded) == 0 {
return entries
}
filtered := make([]userstore.WatchProgress, 0, len(entries))
for _, entry := range entries {
if _, ok := superseded[entry.MediaItemID]; ok {
continue
}
filtered = append(filtered, entry)
}
return filtered
}
// HomeDismissalIndex maps media item ID to its dismissal row for one home surface.
type HomeDismissalIndex map[string]userstore.HomeItemDismissal
// NewHomeDismissalIndex builds an index from dismissal rows.
func NewHomeDismissalIndex(dismissals []userstore.HomeItemDismissal) HomeDismissalIndex {
index := make(HomeDismissalIndex, len(dismissals))
for _, dismissal := range dismissals {
index[dismissal.MediaItemID] = dismissal
}
return index
}
// FilterProgress drops entries still covered by a dismissal. A dismissal only
// holds while the entry's progress timestamp matches the one captured when the
// user dismissed it; resuming playback re-surfaces the item.
func (idx HomeDismissalIndex) FilterProgress(entries []userstore.WatchProgress) []userstore.WatchProgress {
if len(entries) == 0 || len(idx) == 0 {
return entries
}
filtered := make([]userstore.WatchProgress, 0, len(entries))
for _, entry := range entries {
dismissal, ok := idx[entry.MediaItemID]
if !ok || dismissal.ProgressUpdatedAt == nil || *dismissal.ProgressUpdatedAt != entry.UpdatedAt {
filtered = append(filtered, entry)
}
}
return filtered
}