Files
silo-server/internal/userstore/progress_helpers.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

228 lines
7.2 KiB
Go

package userstore
import (
"context"
"strings"
"time"
)
type HistoryVisibilityStore interface {
VisibleHistoryTimestamps(ctx context.Context, profileID string, mediaItemIDs []string, at time.Time) (map[string]string, error)
}
type VisibleHistoryAdder interface {
AddVisibleHistory(ctx context.Context, entry WatchHistoryEntry) (WatchHistoryEntry, error)
}
func AddVisibleHistory(ctx context.Context, store UserStore, entry WatchHistoryEntry) (WatchHistoryEntry, error) {
if adder, ok := store.(VisibleHistoryAdder); ok {
return adder.AddVisibleHistory(ctx, entry)
}
entryTimes, err := VisibleHistoryTimestamps(ctx, store, entry.ProfileID, []string{entry.MediaItemID}, parseHistoryTimestamp(entry.WatchedAt))
if err != nil {
return entry, err
}
if entryTime := entryTimes[entry.MediaItemID]; entryTime != "" {
entry.WatchedAt = entryTime
}
if err := store.AddHistory(ctx, entry); err != nil {
return entry, err
}
return entry, nil
}
func VisibleHistoryTimestamps(ctx context.Context, store UserStore, profileID string, mediaItemIDs []string, at time.Time) (map[string]string, error) {
mediaItemIDs = compactHistoryMediaItemIDs(mediaItemIDs)
result := make(map[string]string, len(mediaItemIDs))
if len(mediaItemIDs) == 0 {
return result, nil
}
if visibilityStore, ok := store.(HistoryVisibilityStore); ok {
return visibilityStore.VisibleHistoryTimestamps(ctx, profileID, mediaItemIDs, at)
}
timestamp := at.UTC().Format(time.RFC3339)
if at.IsZero() {
timestamp = time.Now().UTC().Format(time.RFC3339)
}
for _, mediaItemID := range mediaItemIDs {
result[mediaItemID] = timestamp
}
return result, nil
}
func parseHistoryTimestamp(value string) time.Time {
if value == "" {
return time.Time{}
}
parsed, err := time.Parse(time.RFC3339, value)
if err != nil {
return time.Time{}
}
return parsed
}
// SeriesWatchCounts is the aggregate episode watch state for one series, as
// computed by SeriesEpisodeRollupStore.
type SeriesWatchCounts struct {
TotalEpisodes int
WatchedCount int
InProgressCount int
}
// SeriesEpisodeRollupStore is an optional store capability: compute the
// per-series episode watch-state rollup (total / watched / in-progress
// episode counts) in SQL instead of materializing every episode of every
// series and batching per-episode progress lookups through
// ListProgressWithCompletedHistory. Implemented by the Postgres store, where
// episodes and progress live in the same database; SQLite-backed stores fall
// back to the chunked in-memory path. Semantics must match
// ListProgressWithCompletedHistory + catalog.EpisodeRollupUserData: an episode
// is watched when its visible progress row is completed or a visible completed
// history row exists, and in-progress when it is not watched and its visible
// progress row has position_seconds > 0.
type SeriesEpisodeRollupStore interface {
SeriesEpisodeWatchCounts(ctx context.Context, profileID string, seriesIDs []string) (map[string]SeriesWatchCounts, error)
}
// CompletedHistoryItemMap returns the latest completed-history item row for a
// scoped item query. Lookup failures degrade to an empty map so user-data
// enrichment can keep returning progress rows.
func CompletedHistoryItemMap(ctx context.Context, store ProgressCompletionStore, query CompletedHistoryItemQuery) map[string]CompletedHistoryItem {
result := map[string]CompletedHistoryItem{}
if store == nil || query.ProfileID == "" {
return result
}
query.MediaItemIDs = compactHistoryMediaItemIDs(query.MediaItemIDs)
if len(query.MediaItemIDs) == 0 {
return result
}
items, err := store.ListCompletedHistoryItems(ctx, query)
if err != nil {
return result
}
for _, item := range items {
if item.MediaItemID != "" {
result[item.MediaItemID] = item
}
}
return result
}
// GetProgressWithCompletedHistory returns normal progress overlaid with
// completed history for callers that present a single item's played state.
func GetProgressWithCompletedHistory(ctx context.Context, store UserStore, profileID, mediaItemID string) (*WatchProgress, error) {
mediaItemID = strings.TrimSpace(mediaItemID)
if store == nil || profileID == "" || mediaItemID == "" {
return nil, nil
}
progress, err := store.GetProgress(ctx, profileID, mediaItemID)
if err != nil {
return nil, err
}
if progress != nil && progress.Completed {
return progress, nil
}
completed := CompletedHistoryItemMap(ctx, store, CompletedHistoryItemQuery{
ProfileID: profileID,
MediaItemIDs: []string{mediaItemID},
})[mediaItemID]
if completed.MediaItemID == "" {
return progress, nil
}
if progress == nil {
return &WatchProgress{
ProfileID: profileID,
MediaItemID: mediaItemID,
Completed: true,
UpdatedAt: completed.WatchedAt,
}, nil
}
progress.Completed = true
if timestampAfter(completed.WatchedAt, progress.UpdatedAt) {
progress.UpdatedAt = completed.WatchedAt
}
return progress, nil
}
// ListProgressWithCompletedHistory returns progress for mediaItemIDs with
// completed history folded into the map. History is only queried for IDs that
// are not already completed by a progress row.
func ListProgressWithCompletedHistory(ctx context.Context, store ProgressCompletionStore, profileID string, mediaItemIDs []string) (map[string]WatchProgress, error) {
mediaItemIDs = compactHistoryMediaItemIDs(mediaItemIDs)
if store == nil || profileID == "" || len(mediaItemIDs) == 0 {
return map[string]WatchProgress{}, nil
}
progressMap, err := store.ListProgressByMediaItems(ctx, profileID, mediaItemIDs)
if err != nil {
return nil, err
}
if progressMap == nil {
progressMap = map[string]WatchProgress{}
}
candidates := make([]string, 0, len(mediaItemIDs))
for _, mediaItemID := range mediaItemIDs {
if progress, ok := progressMap[mediaItemID]; ok && progress.Completed {
continue
}
candidates = append(candidates, mediaItemID)
}
if len(candidates) == 0 {
return progressMap, nil
}
completed := CompletedHistoryItemMap(ctx, store, CompletedHistoryItemQuery{
ProfileID: profileID,
MediaItemIDs: candidates,
})
for mediaItemID, completedItem := range completed {
if progress, ok := progressMap[mediaItemID]; ok {
progress.Completed = true
if timestampAfter(completedItem.WatchedAt, progress.UpdatedAt) {
progress.UpdatedAt = completedItem.WatchedAt
}
progressMap[mediaItemID] = progress
continue
}
progressMap[mediaItemID] = WatchProgress{
ProfileID: profileID,
MediaItemID: mediaItemID,
Completed: true,
UpdatedAt: completedItem.WatchedAt,
}
}
return progressMap, nil
}
func compactHistoryMediaItemIDs(mediaItemIDs []string) []string {
result := make([]string, 0, len(mediaItemIDs))
seen := make(map[string]struct{}, len(mediaItemIDs))
for _, mediaItemID := range mediaItemIDs {
mediaItemID = strings.TrimSpace(mediaItemID)
if mediaItemID == "" {
continue
}
if _, ok := seen[mediaItemID]; ok {
continue
}
seen[mediaItemID] = struct{}{}
result = append(result, mediaItemID)
}
return result
}
func timestampAfter(left, right string) bool {
if left == "" {
return false
}
if right == "" {
return true
}
leftTime, leftErr := time.Parse(time.RFC3339, left)
rightTime, rightErr := time.Parse(time.RFC3339, right)
if leftErr == nil && rightErr == nil {
return leftTime.After(rightTime)
}
return left > right
}