* 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.
263 lines
9.8 KiB
Go
263 lines
9.8 KiB
Go
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 60–116s
|
||
// 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
|
||
}
|