From 79d5433e18193e302578c4f47eb65e0de12e9686 Mon Sep 17 00:00:00 2001 From: Fredrik Ahlgren Date: Sat, 3 Oct 2026 15:12:14 +0200 Subject: [PATCH 1/2] fix(mpc): skip Core DP shadows that cannot finish in time On the home box (Raspberry Pi 4, Energyplan primary, 26 Sep to 3 Oct), the Core DP shadow ran out of its 10 s limit on 213 of 228 replans with a car plugged in. Each try cost about 10 s of CPU and compared nothing. Battery-only shadows finished all 826 times, in 2 s at most. After a shadow runs out of time, Core now skips shadows with at least as much DP work per slot (battery SoC and power levels, times EV SoC levels and charger steps) for an hour, then tries one again. The horizon shrinks through the day, so a later try may fit. Each skip is recorded in dp_shadow with status "skipped", the reason and the time of the next try, and logged, so the plan view and /api/mpc/diagnose tell a skip from a missing comparison. Smaller shadows still run. A cancelled shadow does not count as slow. The active plan, dispatch, validation and the Energyplan request do not change. Replayed over the same records, the rule leaves 20 timeouts instead of 213 and keeps 3 of the 5 EV comparisons that finished, plus every battery-only one. Signed-off-by: Fredrik Ahlgren Co-Authored-By: Claude Opus 5.5 --- .changeset/dp-shadow-skip-slow.md | 5 + go/internal/mpc/core_dp_shadow.go | 56 +++++++- go/internal/mpc/core_dp_shadow_test.go | 169 ++++++++++++++++++++++++- go/internal/mpc/service.go | 2 + optimizer/native/README.md | 4 + 5 files changed, 233 insertions(+), 3 deletions(-) create mode 100644 .changeset/dp-shadow-skip-slow.md diff --git a/.changeset/dp-shadow-skip-slow.md b/.changeset/dp-shadow-skip-slow.md new file mode 100644 index 000000000..d6ae63a99 --- /dev/null +++ b/.changeset/dp-shadow-skip-slow.md @@ -0,0 +1,5 @@ +--- +"ftw": patch +--- + +On a slow box such as a Raspberry Pi 4, the Core DP shadow no longer spends 10 s of CPU on almost every replan with a car plugged in, only to run out of time. After a shadow runs out of time, Core skips shadows of that size or larger for an hour and records each skip in the plan diagnostics, with the reason and the time of the next try. Battery-only shadows still run. The active plan and dispatch do not change. diff --git a/go/internal/mpc/core_dp_shadow.go b/go/internal/mpc/core_dp_shadow.go index c79c316d7..9f3d34da3 100644 --- a/go/internal/mpc/core_dp_shadow.go +++ b/go/internal/mpc/core_dp_shadow.go @@ -7,6 +7,16 @@ import ( "time" ) +// A shadow that runs past its deadline compares nothing; on a Raspberry Pi 4 +// that is most shadows with a car plugged in. After a timeout, Core skips +// shadows at least that large for an hour, then tries one again: the horizon +// shrinks through the day, so a later one may fit. +const ( + coreDPShadowTimeout = 10 * time.Second + coreDPShadowRetry = time.Hour + coreDPShadowBasis = "same downside input, Core DP shadow" +) + type coreDPShadowRequest struct { champion Plan slots []Slot @@ -15,23 +25,57 @@ type coreDPShadowRequest struct { replanAtMs int64 } +// coreDPShadowSkip remembers the last shadow that ran out of time: its DP work +// per slot, and when Core may try a shadow that large again. +type coreDPShadowSkip struct { + work int64 + until time.Time +} + +// coreDPSlotWork counts the choices Core DP weighs in each slot: battery SoC +// levels times battery power levels, times EV SoC levels and charger steps +// when a car is plugged in. Solve time grows with it and with the slot count. +func coreDPSlotWork(p Params) int64 { + work := int64(max(p.SoCLevels, 3)) * int64(max(p.ActionLevels, 3)) + if lp := p.Loadpoint; lp.active() { + work *= int64(lp.Levels) * int64(len(lp.normalizedSteps())) + } + return work +} + // startCoreDPShadow runs at most one bounded comparison, after publication. // Results belong to a decision ID and can never replace the active actions. +// A skipped shadow is recorded with its reason, so it never looks missing. func (s *Service) startCoreDPShadow(champion Plan, slots []Slot, p Params, reason string, replanAtMs int64) { if coreDPModelError(p) != nil { return } + work := coreDPSlotWork(p) s.mu.Lock() if s.stopping || s.last == nil || s.last.DecisionID != champion.DecisionID { s.mu.Unlock() return } + if skip := s.shadowSkip; work >= skip.work && s.planningNow().Before(skip.until) { + s.mu.Unlock() + block := &ShadowPlan{ForecastBasis: coreDPShadowBasis, Solver: coreSolverInfo(p, 0)} + block.Solver.Status = "skipped" + block.Solver.FallbackReason = "skipped: a shadow no larger than this one ran out of time; next try after " + + skip.until.UTC().Format(time.RFC3339) + slog.Info("mpc: Core DP shadow skipped", "decision_id", champion.DecisionID, "reason", block.Solver.FallbackReason) + s.recordCoreDPShadow(champion, slots, p, reason, replanAtMs, block) + return + } if s.shadowBusy { s.pendingCoreShadow = &coreDPShadowRequest{champion, slots, p, reason, replanAtMs} s.mu.Unlock() return } - ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second) + timeout := s.shadowTimeout + if timeout == 0 { + timeout = coreDPShadowTimeout + } + ctx, cancel := context.WithTimeout(context.Background(), timeout) s.shadowBusy, s.shadowCancel = true, cancel s.shadowWG.Add(1) s.mu.Unlock() @@ -49,10 +93,18 @@ func (s *Service) startCoreDPShadow(champion Plan, slots []Slot, p Params, reaso if errors.Is(err, context.Canceled) { return } + if errors.Is(err, context.DeadlineExceeded) { + until := s.planningNow().Add(coreDPShadowRetry) + s.mu.Lock() + s.shadowSkip = coreDPShadowSkip{work: work, until: until} + s.mu.Unlock() + slog.Warn("mpc: Core DP shadow ran out of time; skipping shadows this large", + "decision_id", champion.DecisionID, "dp_work_per_slot", work, "next_try", until) + } if err == nil { err = ValidatePlan(slots, p, &shadow) } - block := &ShadowPlan{ForecastBasis: "same downside input, Core DP shadow", Solver: coreSolverInfo(p, msSince(start))} + block := &ShadowPlan{ForecastBasis: coreDPShadowBasis, Solver: coreSolverInfo(p, msSince(start))} if err != nil { block.Solver.Status = "rejected" block.Solver.FallbackReason = err.Error() diff --git a/go/internal/mpc/core_dp_shadow_test.go b/go/internal/mpc/core_dp_shadow_test.go index 6356d65b0..e3dd7967a 100644 --- a/go/internal/mpc/core_dp_shadow_test.go +++ b/go/internal/mpc/core_dp_shadow_test.go @@ -1,10 +1,13 @@ package mpc import ( - "github.com/srcfl/ftw/go/internal/state" + "context" "path/filepath" + "strings" "testing" "time" + + "github.com/srcfl/ftw/go/internal/state" ) func shadowTestService(t *testing.T) *Service { @@ -50,3 +53,167 @@ func waitFor(t *testing.T, what string, cond func() bool) { } t.Fatalf("timed out waiting for %s", what) } + +// shadowSkipFixture returns a service with a published plan, a clock the test +// moves, and that plan's inputs with and without a plugged-in car. The car's +// SoC levels and charger steps make each slot far more work for Core DP. The +// clock only moves between shadows, after shadowWG.Wait. +func shadowSkipFixture(t *testing.T) (svc *Service, now *time.Time, slots []Slot, battery, ev Params) { + t.Helper() + svc = shadowTestService(t) + if svc.Replan(context.Background()) == nil { + t.Fatal("no base plan") + } + clock := time.Date(2026, 10, 3, 12, 0, 0, 0, time.UTC) + svc.now = func() time.Time { return clock } + slots, battery = svc.lastSlots, svc.lastParams + ev = battery + ev.Loadpoint = &LoadpointSpec{ID: "car", CapacityWh: 60000, Levels: 11, InitialSoC: .4, SoCMax: 1, + PluggedIn: true, MaxChargeW: 11000, ChargeEfficiency: .9, AllowedStepsW: []float64{0, 4140, 11000}} + ev.Loadpoints = []*LoadpointSpec{ev.Loadpoint} + return svc, &clock, slots, battery, ev +} + +// publishAndShadow makes a Core DP plan for these inputs the current plan, +// starts its shadow and waits for any background comparison to finish. +func publishAndShadow(t *testing.T, svc *Service, id string, slots []Slot, p Params) *ShadowPlan { + t.Helper() + champion := Optimize(slots, p) + champion.DecisionID = id + svc.mu.Lock() + svc.last, svc.executionPlan, svc.lastSlots, svc.lastParams = &champion, &champion, slots, p + svc.mu.Unlock() + svc.startCoreDPShadow(champion, slots, p, "test", champion.GeneratedAtMs) + svc.shadowWG.Wait() + return svc.Latest().DPShadow +} + +// On a Raspberry Pi 4 a shadow with a car in it needs far more than its +// deadline. After one runs out of time, the next replan of that size records +// a skip and its reason instead of spending another 10 s of CPU. +func TestCoreDPShadowSkipsAfterTimeout(t *testing.T) { + svc, _, slots, _, ev := shadowSkipFixture(t) + var persisted []*ShadowPlan + svc.SaveDiag = func(d *Diagnostic, _ string) error { + persisted = append(persisted, d.DPShadow) + return nil + } + svc.shadowTimeout = -1 // already expired: the comparison runs out of time at once + if got := publishAndShadow(t, svc, "slow", slots, ev); got == nil || got.Solver.Status != "rejected" { + t.Fatalf("shadow past its deadline = %+v, want rejected", got) + } + + svc.shadowTimeout = 0 // the real 10 s: a comparison that ran would finish + got := publishAndShadow(t, svc, "next", slots, ev) + if got == nil || got.Solver == nil || got.Solver.Status != "skipped" || got.ComparedSlots != 0 { + t.Fatalf("same-size shadow after a timeout = %+v, want a recorded skip", got) + } + if why := got.Solver.FallbackReason; !strings.Contains(why, "ran out of time") || !strings.Contains(why, "2026-10-03T13:00:00Z") { + t.Fatalf("skip reason %q must say why and when Core tries again", why) + } + if d := svc.Diagnose(); d == nil || d.DecisionID != "next" || d.DPShadow == nil || d.DPShadow.Solver.Status != "skipped" { + t.Fatalf("diagnostic does not show the skip: %+v", d) + } + if n := len(persisted); n == 0 || persisted[n-1] == nil || persisted[n-1].Solver.Status != "skipped" { + t.Fatal("persisted diagnostic does not show the skip") + } +} + +// A skip covers shadows at least as large as the one that ran out of time. +// A battery-only shadow is far smaller than one with a car and still runs. +func TestCoreDPShadowSkipKeepsSmallerShadows(t *testing.T) { + svc, _, slots, battery, ev := shadowSkipFixture(t) + svc.shadowTimeout = -1 + publishAndShadow(t, svc, "slow", slots, ev) + svc.shadowTimeout = 0 + got := publishAndShadow(t, svc, "battery", slots, battery) + if got == nil || got.Solver.Status != "optimal" || got.ComparedSlots != len(slots) { + t.Fatalf("battery-only shadow while EV shadows are skipped = %+v, want a comparison", got) + } +} + +// The skip lasts an hour, then a shadow of that size runs again. The horizon +// shrinks through the day, so a later try may fit the deadline. +func TestCoreDPShadowRetriesAfterAnHour(t *testing.T) { + svc, now, slots, _, ev := shadowSkipFixture(t) + svc.shadowTimeout = -1 + publishAndShadow(t, svc, "slow", slots, ev) + svc.shadowTimeout = 0 + *now = now.Add(59 * time.Minute) + if got := publishAndShadow(t, svc, "early", slots, ev); got == nil || got.Solver.Status != "skipped" { + t.Fatalf("shadow 59 min after a timeout = %+v, want skipped", got) + } + *now = now.Add(time.Minute) + got := publishAndShadow(t, svc, "retry", slots, ev) + if got == nil || got.Solver.Status != "optimal" || got.ComparedSlots != len(slots) { + t.Fatalf("shadow an hour after a timeout = %+v, want a comparison", got) + } +} + +// The same rule through real replans: Energyplan plans, a car is plugged in, +// and the shadow runs out of time. The next replan with the car records a +// skip; a replan after the car leaves gets its comparison. +func TestNativeEnergyplanSkipsEVShadowAfterTimeout(t *testing.T) { + template := nativeWorker(t, 500*time.Millisecond) + defer template.Close() + o, err := NewEnergyplanOptimizer(template.cfg.Command[0]) + if err != nil { + t.Fatal(err) + } + t.Cleanup(func() { o.Close() }) + svc := shadowTestService(t) + svc.Optimizer = o + _, fixture := nativeFixture() + car, plugged := *fixture.Loadpoint, true + svc.Loadpoint = func(int) *LoadpointSpec { + if !plugged { + return nil + } + copy := car + return © + } + replan := func(what string) *ShadowPlan { + t.Helper() + plan := svc.Replan(context.Background()) + if plan == nil || plan.Solver == nil || plan.Solver.Fallback || plan.Solver.Engine == "core" { + t.Fatalf("%s: Energyplan did not plan: %+v", what, plan) + } + if (svc.lastParams.Loadpoint != nil) != plugged { + t.Fatalf("%s: car in plan = %v, want %v", what, svc.lastParams.Loadpoint != nil, plugged) + } + svc.shadowWG.Wait() + return svc.Diagnose().DPShadow + } + + svc.shadowTimeout = -1 + if got := replan("first"); got == nil || got.Solver.Status != "rejected" { + t.Fatalf("EV shadow past its deadline = %+v, want rejected", got) + } + svc.shadowTimeout = 0 + if got := replan("second"); got == nil || got.Solver.Status != "skipped" || got.ComparedSlots != 0 { + t.Fatalf("next EV shadow = %+v, want a recorded skip", got) + } + plugged = false + if got := replan("battery"); got == nil || got.Solver.Status != "optimal" || got.ComparedSlots == 0 { + t.Fatalf("battery-only shadow = %+v, want a comparison", got) + } +} + +// Only the deadline marks a size as too slow. A newer replan or Stop cancels +// a shadow for reasons that say nothing about the box's speed. +func TestCoreDPShadowCancellationDoesNotSkip(t *testing.T) { + svc := shadowTestService(t) + slots, p := nativeBenchmarkFixture(true) + p.SoCLevels, p.ActionLevels = 101, 201 + running := Plan{DecisionID: "cancelled"} + svc.last = &running + svc.startCoreDPShadow(running, slots, p, "test", 0) + svc.mu.Lock() + svc.shadowCancel() + svc.mu.Unlock() + svc.shadowWG.Wait() + got := publishAndShadow(t, svc, "next", slots[:4], p) + if got == nil || got.Solver.Status != "optimal" || got.ComparedSlots != 4 { + t.Fatalf("same-size shadow after a cancellation = %+v, want a comparison", got) + } +} diff --git a/go/internal/mpc/service.go b/go/internal/mpc/service.go index d3730c598..f06a15839 100644 --- a/go/internal/mpc/service.go +++ b/go/internal/mpc/service.go @@ -245,6 +245,8 @@ type Service struct { shadowCancel context.CancelFunc shadowWG sync.WaitGroup pendingCoreShadow *coreDPShadowRequest + shadowSkip coreDPShadowSkip + shadowTimeout time.Duration // zero uses coreDPShadowTimeout; tests shorten it stop chan struct{} done chan struct{} diff --git a/optimizer/native/README.md b/optimizer/native/README.md index ab4687a98..2a1bd9b94 100644 --- a/optimizer/native/README.md +++ b/optimizer/native/README.md @@ -66,6 +66,10 @@ Its result appears in `dp_shadow`, tied to the same decision ID. It cannot change the active actions. Both plans use Core's grid cost model, with a separate terminal-energy-adjusted comparison. A failed comparison reports `rejected`, without a cost verdict. +After a shadow runs out of time, Core skips shadows with at least as much DP +work per slot for an hour. Each skip reports `skipped`, with the reason and the +time of the next try. Smaller shadows still run: a battery-only plan keeps its +comparison while shadows with a car are skipped. Energyplan plans from the measured battery energy, including starts below the reserve or above the charge limit. Each action must hold or reduce any existing From fc25ba82462c7ae56d05837f4f3a5ac186895e47 Mon Sep 17 00:00:00 2001 From: Fredrik Ahlgren Date: Sat, 3 Oct 2026 15:18:44 +0200 Subject: [PATCH 2/2] fix(mpc): keep a shadow skip within an hour of a stepped clock A Pi can boot with a wrong time and step it back later. The skip deadline came from the old clock, so a step back stretched the skip by the size of the step. Treat a deadline more than an hour ahead as expired. Co-Authored-By: Claude Opus 5.5 Signed-off-by: Fredrik Ahlgren --- go/internal/mpc/core_dp_shadow.go | 3 ++- go/internal/mpc/core_dp_shadow_test.go | 14 ++++++++++++++ 2 files changed, 16 insertions(+), 1 deletion(-) diff --git a/go/internal/mpc/core_dp_shadow.go b/go/internal/mpc/core_dp_shadow.go index 9f3d34da3..d58e8af09 100644 --- a/go/internal/mpc/core_dp_shadow.go +++ b/go/internal/mpc/core_dp_shadow.go @@ -56,7 +56,8 @@ func (s *Service) startCoreDPShadow(champion Plan, slots []Slot, p Params, reaso s.mu.Unlock() return } - if skip := s.shadowSkip; work >= skip.work && s.planningNow().Before(skip.until) { + // A clock stepped back after boot must not stretch the skip past an hour. + if skip, now := s.shadowSkip, s.planningNow(); work >= skip.work && now.Before(skip.until) && skip.until.Sub(now) <= coreDPShadowRetry { s.mu.Unlock() block := &ShadowPlan{ForecastBasis: coreDPShadowBasis, Solver: coreSolverInfo(p, 0)} block.Solver.Status = "skipped" diff --git a/go/internal/mpc/core_dp_shadow_test.go b/go/internal/mpc/core_dp_shadow_test.go index e3dd7967a..b489bfce5 100644 --- a/go/internal/mpc/core_dp_shadow_test.go +++ b/go/internal/mpc/core_dp_shadow_test.go @@ -150,6 +150,20 @@ func TestCoreDPShadowRetriesAfterAnHour(t *testing.T) { } } +// A Pi can boot with a wrong time and step it back later. The skip must not +// last more than an hour of the new clock. +func TestCoreDPShadowSkipIgnoresClockStepBack(t *testing.T) { + svc, now, slots, _, ev := shadowSkipFixture(t) + svc.shadowTimeout = -1 + publishAndShadow(t, svc, "slow", slots, ev) + svc.shadowTimeout = 0 + *now = now.Add(-3 * time.Hour) + got := publishAndShadow(t, svc, "stepped", slots, ev) + if got == nil || got.Solver.Status != "optimal" || got.ComparedSlots != len(slots) { + t.Fatalf("shadow after the clock stepped back = %+v, want a comparison", got) + } +} + // The same rule through real replans: Energyplan plans, a car is plugged in, // and the shadow runs out of time. The next replan with the car records a // skip; a replan after the car leaves gets its comparison.