diff options
| author | Claude <noreply@anthropic.com> | 2026-10-07 09:14:11 +0000 |
|---|---|---|
| committer | Claude <noreply@anthropic.com> | 2026-10-07 09:14:11 +0000 |
| commit | 9ba30c95c6bc9a6405ab21f616e933b09fa0358f (patch) | |
| tree | 76c40975e4dd962fbcea631883ef627b23df8d8a | |
| parent | 7847e13c3fab23edfda096396e4dbe01df3471c3 (diff) | |
Examine each batch once instead of every poll
The first full pass over all 42 feeds finished, then the server kept
re-deriving the same answers: Radiolab reported "53:29 of 59:39" four
times in one day. pollOne called detect unconditionally and the mirror
skips files it already has, so nothing had changed between passes. At
~6.5 minutes a show that is 4.5 hours a cycle against a two-hour poll
interval -- the machine never finished a cycle and never idled, burning
13h42m of CPU in 11h of wall clock, roughly 60% of it on the intro search
whose results are deliberately not published.
Show.DetectedBatch records the episode ids a completed pass examined.
The batch is the unit rather than the episode because every offset and
every break comes from comparing an episode against the others fetched
alongside it, so one arrival or one pruning legitimately changes all of
them. Order-independent, since feeds are not reliably sorted. Recorded
only on completion, so a cancelled or failed pass is retried.
Episode.DetectedAtUnix could not serve as the gate: it is only set for
episodes appearing in result.Offsets, so an episode nothing was found in
never got a timestamp and the gate would never close.
Also records what the first full corpus showed, including a disproven
hypothesis worth not retrying -- filtering breaks by partner count or run
length looks obviously right and makes agreement with the declared length
gap substantially worse -- and a correction: Sleepy History's 117 minutes
of "advertising" was a show-level sum sitting almost entirely inside the
two episodes its own guard already refused.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_018AwnALZL6bD4VBtATDVv3B
| -rw-r--r-- | CLAUDE.md | 13 | ||||
| -rw-r--r-- | docs/detection-findings.md | 83 | ||||
| -rw-r--r-- | server/cmd/listend/main.go | 18 | ||||
| -rw-r--r-- | server/internal/store/store.go | 31 | ||||
| -rw-r--r-- | server/internal/store/store_test.go | 82 |
5 files changed, 223 insertions, 4 deletions
@@ -296,6 +296,19 @@ by default and correct; it is simply waiting for a publisher who marks breaks. 71% and 105%. First time in this project that detection has been checked against external ground truth and agreed. + **Detection runs once per batch, not once per poll.** `Show.DetectedBatch` holds the set of + episode ids the last completed pass examined; `pollOne` skips detection when the batch is + unchanged. Without it the server re-derived identical results every cycle -- 4.5 hours of work + against a two-hour poll interval, so it never idled. The batch is the unit because every + result depends on which other episodes it was compared against, so one arrival or one pruning + must re-run all of them. `Episode.DetectedAtUnix` cannot serve as this gate: it is only set + for episodes that appear in `result.Offsets`. + + **Do not filter breaks by partner count or run length.** It looks obviously right -- 40% of + breaks have one partner and a 5s median -- and it is wrong: measured against the declared + length gap it drops agreement from 67% to 43%. Detection already under-reports. Table in + `docs/detection-findings.md`. + Breaks are published as ranges into `episode_midrolls`, which `MidrollSkip` and `PlayheadPolicy` already read -- no playback changes, no migration. Two guards publish nothing rather than something wrong: an episode whose matches cover over 35% of it, and any single diff --git a/docs/detection-findings.md b/docs/detection-findings.md index 35c4525..c821062 100644 --- a/docs/detection-findings.md +++ b/docs/detection-findings.md @@ -668,3 +668,86 @@ Found by reading the journal after a restart, not by a test: State is also saved after every feed now, so a restart costs one feed's progress rather than a whole cycle's. + +## Detection re-ran forever, and what the first full corpus then showed + +The first complete pass over Peter's 42 feeds finished on 2026-10-06: 322 episodes mirrored, +286 publishing ad breaks. It then kept going over the same unchanged files, producing results +identical to the digit -- Radiolab reported "53:29 of 59:39" four separate times in one day. + +`pollOne` called `detect` unconditionally, and the mirror skips files it already has, so nothing +had changed between passes. One cycle is ~6.5 minutes a show, 4.5 hours for 42 shows, against a +two-hour poll interval: the machine never finished a cycle and never idled -- 13h42m of CPU in +11h of wall clock. Roughly 60% of that was the intro/outro search whose results are deliberately +not published. + +`Episode.DetectedAtUnix` existed but could not be used as the gate: it is only set for episodes +that appear in `result.Offsets`, so an episode nothing was found in never got a timestamp and +the gate would never close. The unit is the batch anyway -- every offset and every break is +found by comparing an episode against the others fetched alongside it, so one arrival or one +pruning legitimately changes all of them. `Show.DetectedBatch` records the set of episode ids +the last completed pass examined, order-independent because feeds are not reliably sorted. +Recorded only after a pass completes, so a cancelled or failed one is retried. + +Deployed 2026-10-07 with the field backfilled for the 42 shows already examined, which saved an +immediate 4.5-hour redundant cycle. Verified in production: 31 feeds polled in five minutes with +exactly one detection running -- The Ezra Klein Show, which had genuinely gained an episode. + +### Filtering by partner count or run length is wrong, and the length gap proves it + +The obvious cleanup is to drop weakly-supported breaks. 635 of 1574 published breaks (40%) have +`partners == 1`, with a median length of 5.0s against 19.0s for `partners >= 4` -- they look +exactly like correlation noise, and 270 of them sit at `MinRunSamples`, the 4-second floor. + +Measured against the declared-versus-served length gap -- the one figure the detector does not +produce -- every such filter makes agreement **worse**: + +| filter | median found/inserted | within 75-125% | skipping on shows with no gap | +|---|---|---|---| +| none (current) | 67% | 31% | 164 min | +| `partners >= 2` | 43% | 17% | 141 min | +| `partners >= 3` | 39% | 13% | 127 min | +| length >= 8s | 58% | 24% | 141 min | +| both | 41% | 13% | 130 min | + +Detection already **under**-reports -- a 67% median means a third of the advertising is missed -- +so removing breaks moves away from the truth, and it barely dents the unverifiable skipping it +was meant to clean up. The single-partner short runs are mostly real advertising. Hypothesis +disproven; the thresholds stay as they are. + +### What is worth fixing is fragmentation + +45% of the gaps between consecutive breaks are under ten seconds, and **152 of 262** multi-break +episodes contain at least one such gap -- which plays as a skip, one to nine seconds of audible +advertisement, then another skip. `merge` only folds breaks that overlap or touch. + +Merging across a tolerance both cleans that up and moves agreement the right way, because the +bridged gap was advertising too: + +| merge tolerance | median found/inserted | within 75-125% | total breaks | +|---|---|---|---| +| 0s (current) | 69% | 32% | 1240 | +| 2s | 70% | 33% | 973 | +| 5s | 70% | 34% | 885 | +| 10s | 73% | 34% | 820 | +| 15s | 73% | 35% | 786 | + +### Sleepy History was not eating the programme + +Reported on 2026-10-06 as finding 117:42 of "advertising" in a show whose feed declares no +inserted ads at all. That reading was wrong: it was a show-level sum, and almost all of it sat +inside the two episodes the 35% guard **already refused** -- a 3h08m Rosa Parks compilation that +literally contains other episodes (53:41 matched) and Antarctica (22:30). + +The six episodes that do publish skip 0:34 to 4:33 each, under 10% of their runtime, and the +largest block in each is a genuine closing segment shared by every episode in the batch -- +`48:20-51:36 partners=22`, `46:19-49:19 partners=26`. That is the show's own outro, which is what +intro/outro detection was supposed to find in the first place. The rest is 4-second floor noise. + +Across the whole corpus only 4 of 279 published episodes skip more than 20% of their runtime, and +all but one are corroborated by the length gap to within a minute. The exception is The Trip +(3:54 of 14:51, no declared gap), which is the one show worth watching. + +Sleepy History also serves files consistently **shorter** than declared -- 50:59 declared against +49:23 served, about 1:36 short on every episode -- so `Accounting` reports a zero gap for it. A +feed can be wrong in that direction too, and when it is there is no external check available. diff --git a/server/cmd/listend/main.go b/server/cmd/listend/main.go index 04c933f..3e5c65a 100644 --- a/server/cmd/listend/main.go +++ b/server/cmd/listend/main.go @@ -278,6 +278,7 @@ func (w *worker) pollOne(ctx context.Context, feedURL string) { // over weeks and lost it whenever retention reclaimed the file it was holding. func (w *worker) detect(ctx context.Context, show *store.Show, candidates []*store.Episode) { var episodes []skips.Episode + var ids []string byID := map[string]*store.Episode{} for _, e := range candidates { if !e.Mirrored() { @@ -288,11 +289,15 @@ func (w *worker) detect(ctx context.Context, show *store.Show, candidates []*sto Path: filepath.Join(w.mirror.AudioDir, e.Path), DeclaredDurationMs: e.DeclaredDurationMs, }) + ids = append(ids, e.ID) byID[e.ID] = e } if len(episodes) < skips.DefaultConfirmThreshold || ctx.Err() != nil { return } + if !show.NeedsDetection(ids) { + return + } started := time.Now() result, err := skips.Detect(ctx, w.decoder, episodes, skips.DefaultConfig()) @@ -323,7 +328,9 @@ func (w *worker) detect(ctx context.Context, show *store.Show, candidates []*sto result.OutroConfirmedOn, len(episodes), checkNote(result.OutroCheck), time.Since(started).Round(time.Second)) - w.detectAds(ctx, show, episodes, byID) + if w.detectAds(ctx, show, episodes, byID) { + show.RecordDetected(ids) + } } // detectAds finds the advertising a batch of episodes shares, which is what simultaneous @@ -334,20 +341,22 @@ func (w *worker) detect(ctx context.Context, show *store.Show, candidates []*sto // is how it came to confirm an advertisement as an intro. This uses that dependence rather than // being defeated by it -- and reports what it found against the declared-versus-served length // gap, a figure it did not produce and which can therefore contradict it. +// Reports whether the scan completed, so an interrupted or failed pass is examined again rather +// than written off as done. func (w *worker) detectAds( ctx context.Context, show *store.Show, episodes []skips.Episode, byID map[string]*store.Episode, -) { +) bool { if ctx.Err() != nil { - return + return false } started := time.Now() ads, err := skips.DetectAds(ctx, w.decoder, episodes, skips.DefaultAdConfig()) if err != nil { log.Printf("%s: ad scan failed: %v", show.Title, err) - return + return false } var withBreaks, refused int @@ -381,6 +390,7 @@ func (w *worker) detectAds( log.Printf("%s: ads on %d/%d episode(s)%s, accounted %s of %s inserted, took %s", show.Title, withBreaks, len(episodes), refusedNote(refused), clock(foundTotal), clock(insertedTotal), time.Since(started).Round(time.Second)) + return true } func refusedNote(refused int) string { diff --git a/server/internal/store/store.go b/server/internal/store/store.go index a67e637..51e4ed7 100644 --- a/server/internal/store/store.go +++ b/server/internal/store/store.go @@ -75,6 +75,10 @@ type Show struct { // says so instead of silently having nothing. LastPolledUnix int64 `json:"lastPolledUnix,omitempty"` LastError string `json:"lastError,omitempty"` + + // DetectedBatch is the set of episodes the last detection pass examined. Stored as the + // plain ids rather than a hash so the state file says what was actually done. + DetectedBatch string `json:"detectedBatch,omitempty"` } // Partition splits a show's episodes into the newest keep and everything else, newest first. @@ -316,3 +320,30 @@ func matchIn(show *Show, guid, enclosureURL, title string) *Episode { } return nil } + +// NeedsDetection reports whether this batch of episodes still has to be examined. +// +// The batch is the unit, not the episode: every offset and every ad break is found by comparing +// an episode against the others fetched alongside it, so one arrival or one pruning legitimately +// changes all of them. An unchanged batch, though, produces results identical to the digit -- +// and re-deriving them cost four minutes a show against a two-hour poll interval, which for +// forty-two shows meant the machine never finished a cycle and never idled. +func (s *Show) NeedsDetection(episodeIDs []string) bool { + return s.DetectedBatch != batchKey(episodeIDs) +} + +// RecordDetected notes that this exact batch has been examined. +// +// Called only after a pass completes, so a cancelled or failed one is retried rather than +// written off. +func (s *Show) RecordDetected(episodeIDs []string) { + s.DetectedBatch = batchKey(episodeIDs) +} + +// batchKey identifies a set of episodes irrespective of order, which matters because feeds are +// not reliably sorted: the same eight episodes arriving shuffled must not read as a change. +func batchKey(episodeIDs []string) string { + ordered := append([]string(nil), episodeIDs...) + sort.Strings(ordered) + return strings.Join(ordered, " ") +} diff --git a/server/internal/store/store_test.go b/server/internal/store/store_test.go index cd5cf6f..0540fbf 100644 --- a/server/internal/store/store_test.go +++ b/server/internal/store/store_test.go @@ -237,3 +237,85 @@ func TestSaveIsAtomic(t *testing.T) { } } } + +// Detection is the expensive thing this server does -- four minutes a show -- and it used to +// re-run on every poll over episodes that had not changed, producing results identical to the +// digit. Forty-two shows at ~6.5 minutes each is 4.5 hours of work against a two-hour poll +// interval, so the machine never finished a cycle and never idled. +// +// The batch is what has to match, not the individual episode: every answer depends on which +// other episodes it was compared against, so one new episode legitimately changes all of them. + +func TestAShowNotYetExaminedNeedsDetection(t *testing.T) { + s := New() + show := s.Merge("https://f", "A Show", []feed.Episode{ep("g1", "One", "https://cdn/1.mp3", 100)}) + + if !show.NeedsDetection([]string{"a", "b"}) { + t.Fatal("a show that has never been examined should need detection") + } +} + +func TestTheSameBatchIsNotExaminedTwice(t *testing.T) { + s := New() + show := s.Merge("https://f", "A Show", nil) + + show.RecordDetected([]string{"a", "b", "c"}) + + if show.NeedsDetection([]string{"a", "b", "c"}) { + t.Fatal("re-examining an unchanged batch; this is the rerun that pegged the server") + } +} + +func TestANewEpisodeInTheBatchNeedsDetectionAgain(t *testing.T) { + s := New() + show := s.Merge("https://f", "A Show", nil) + show.RecordDetected([]string{"a", "b", "c"}) + + if !show.NeedsDetection([]string{"a", "b", "c", "d"}) { + t.Fatal("a new episode changes what every other episode is compared against") + } +} + +func TestAPrunedEpisodeNeedsDetectionAgain(t *testing.T) { + s := New() + show := s.Merge("https://f", "A Show", nil) + show.RecordDetected([]string{"a", "b", "c"}) + + if !show.NeedsDetection([]string{"b", "c"}) { + t.Fatal("losing an episode changes the comparison too") + } +} + +// Feeds are not reliably ordered, and Partition sorts by publish date, so the same eight +// episodes can arrive in a different order. Treating that as a change would never close +// the gate. +func TestTheOrderOfTheBatchDoesNotMatter(t *testing.T) { + s := New() + show := s.Merge("https://f", "A Show", nil) + show.RecordDetected([]string{"a", "b", "c"}) + + if show.NeedsDetection([]string{"c", "a", "b"}) { + t.Fatal("the same batch in a different order is the same batch") + } +} + +// Otherwise every restart redoes every show -- which at 4.5 hours a cycle is most of a day. +func TestWhatHasBeenExaminedSurvivesARestart(t *testing.T) { + dir := t.TempDir() + path := filepath.Join(dir, "state.json") + + s := New() + s.Merge("https://f", "A Show", nil) + s.Show("https://f").RecordDetected([]string{"a", "b"}) + if err := s.Save(path); err != nil { + t.Fatalf("save: %v", err) + } + + loaded, err := Load(path) + if err != nil { + t.Fatalf("load: %v", err) + } + if loaded.Show("https://f").NeedsDetection([]string{"a", "b"}) { + t.Fatal("a restart would redo every show") + } +} |
