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..d58e8af09 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,58 @@ 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 } + // 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" + 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 +94,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..b489bfce5 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,181 @@ 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) + } +} + +// 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. +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