fix: make sim_warp_factor real-hardware-safe and sud logs forecast-reproducible
sim_warp_factor was scaling DT_TASK unconditionally, including against real hardware, and was leaking into recorded sample timestamps via wall-clock time - both violate its intended meaning (a reciprocal scale on task wait time only). Clamp it to 1.0 whenever Heater.type isn't "sim", and track elapsed time via tick-counted accumulators (Sud.elapsed for SudLogTask, a matching one for ServerLogTask) instead of time.monotonic(). Sud/server logs now also carry HeaterPowers, the effective SimWarpFactor, the raw Doc, a correct Name, and ForecastAnchors (one entry per real _reanchor_forecast() trigger) - enough for utils/analyze_log.py to rebuild a SudForecastEstimator and replay the exact same splice-per-transition forecast correction offline that a live client sees, replacing the old (always-dead) forecast_*.json sidecar lookup. Two bugs found and fixed along the way: - ServerLogTask's periodic wall-clock checkpoint had no way to know a SudLogTask run had just ended, so it would immediately re-write the just-completed log with PlantParams/ForecastAnchors cleared back to empty. Gated the checkpoint on _should_sample(). - _reanchor_forecast() truncated the old forecast against real elapsed time, which can end up numerically less than the old forecast's own (very wrong) speculative timestamps once a WAIT_USER confirmation runs long - leaving a "ghost" segment instead of a clean cut. Truncate against forecast_step_starts[index] instead, which lives in the same coordinate space as the forecast being cut. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_01JFDeoTKBDkXRhPfnyDEoBt
This commit is contained in:
@@ -253,6 +253,13 @@ pip install -r client/requirements.txt
|
|||||||
./brewpi.py --sim-warp-factor 50 # 50x speedup, e.g. for dev/testing
|
./brewpi.py --sim-warp-factor 50 # 50x speedup, e.g. for dev/testing
|
||||||
./brewpi.py --http-port 8888 # change the browser client's port
|
./brewpi.py --http-port 8888 # change the browser client's port
|
||||||
```
|
```
|
||||||
|
|
||||||
|
`--sim-warp-factor` only ever reciprocally scales the *wait* time
|
||||||
|
between task ticks (`DT_TASK`) - it never scales `--dt` itself, and has
|
||||||
|
no effect at all against real hardware (`Heater.type` other than
|
||||||
|
`"sim"`): real hardware ticks at its own physical pace regardless of
|
||||||
|
this flag, so a real run is always paced at `DT_TASK == 1.0` (true real
|
||||||
|
time) no matter what `--sim-warp-factor` is set to.
|
||||||
3. Either connect with the desktop GUI:
|
3. Either connect with the desktop GUI:
|
||||||
|
|
||||||
```bash
|
```bash
|
||||||
@@ -480,13 +487,27 @@ moment the schedule actually reaches the next real step boundary, not just
|
|||||||
at a user confirmation: `tasks/sud.py`'s `SudTask._reanchor_forecast()`,
|
at a user confirmation: `tasks/sud.py`'s `SudTask._reanchor_forecast()`,
|
||||||
called from `on_step_changed()` on *every* transition (a full step change
|
called from `on_step_changed()` on *every* transition (a full step change
|
||||||
and a step's own ramp→hold phase switch alike), truncates the forecast
|
and a step's own ramp→hold phase switch alike), truncates the forecast
|
||||||
back to right now and splices in a freshly anchored simulation of the
|
and splices in a freshly anchored simulation of the rest of the schedule -
|
||||||
rest of the schedule - anchored at the real elapsed time and the real
|
anchored at the real elapsed time and the real current temperature
|
||||||
current temperature (`TempControllerBase.get_theta_ist()` - trustworthy
|
(`TempControllerBase.get_theta_ist()` - trustworthy here, unlike at Load,
|
||||||
here, unlike at Load, since a real run has been actively ticking for a
|
since a real run has been actively ticking for a while by the time this
|
||||||
while by the time this runs). The corrected forecast is sent in full each
|
runs). The corrected forecast is sent in full each time, so the GUI's
|
||||||
time, so the GUI's `SudForecastPlot.show_forecast()` simply redraws the
|
`SudForecastPlot.show_forecast()` simply redraws the (faded) forecast line
|
||||||
(faded) forecast line outright rather than patching it up itself.
|
outright rather than patching it up itself.
|
||||||
|
|
||||||
|
The truncation point is `forecast_step_starts[index]` (the *old* forecast's
|
||||||
|
own belief of where step `index` begins), not the real elapsed time itself
|
||||||
|
- those can diverge badly for exactly the `user_wait_for_continue` case
|
||||||
|
above: if a human's real confirmation takes far longer than the zero-delay
|
||||||
|
guess assumed, the old forecast's entire speculative remainder (which
|
||||||
|
raced straight through the rest of the schedule) still carries timestamps
|
||||||
|
numerically *less than* the now-much-larger real elapsed time, so cutting
|
||||||
|
against real elapsed time directly would find nothing to discard and just
|
||||||
|
append the fresh, correct simulation after it - a doubled-back, self-
|
||||||
|
overlapping curve instead of a clean cut. `forecast_step_starts[index]`
|
||||||
|
lives in the same (speculative) coordinate space as the forecast being
|
||||||
|
truncated, so it isn't fooled by how far real and speculated time have
|
||||||
|
drifted apart.
|
||||||
|
|
||||||
Two transitions can fire in close succession (a step whose hold duration
|
Two transitions can fire in close succession (a step whose hold duration
|
||||||
is already `0` advances right through it within a single tick, and a
|
is already `0` advances right through it within a single tick, and a
|
||||||
@@ -729,3 +750,29 @@ to `logs/log_<date>T<time>_<sud-name>.log`.
|
|||||||
`print()`-based status/debug output) to a plain text log,
|
`print()`-based status/debug output) to a plain text log,
|
||||||
`logs/brewpi.<timestamp>.log`, alongside those JSON logs - useful for
|
`logs/brewpi.<timestamp>.log`, alongside those JSON logs - useful for
|
||||||
post-mortems without needing to have been watching the console live.
|
post-mortems without needing to have been watching the console live.
|
||||||
|
|
||||||
|
Both JSON logs also carry `dt`, the effective `SimWarpFactor` (already
|
||||||
|
clamped to `1.0` for real hardware - see above), `Config` (the whole
|
||||||
|
`config.json` this run used), and `HeaterPowers` (`heater.get_powers()`,
|
||||||
|
queried live since it can't be reconstructed offline for real hardware
|
||||||
|
like `HeaterHendi`, which opens a serial port on construction) - enough to
|
||||||
|
rebuild a `SudForecastEstimator` for that exact run without needing
|
||||||
|
`config.json`, a live server, or any hardware at all. A `SudLogTask`'s own
|
||||||
|
log additionally carries `Name` (the Sud's name), `Doc` (the raw sud.json
|
||||||
|
document as loaded, via `Sud.save()`) and `ForecastAnchors` (one
|
||||||
|
`{t, index, theta_ist}` entry per real `_reanchor_forecast()` trigger -
|
||||||
|
see "Forecast vs. actual duration" above).
|
||||||
|
|
||||||
|
`utils/analyze_log.py` uses all of this to render the same forecast-vs-
|
||||||
|
actual comparison the GUI's Automatic tab shows live, purely offline:
|
||||||
|
`build_forecast()` re-simulates the logged `Doc` with
|
||||||
|
`SudForecastEstimator`, then replays every logged `ForecastAnchors` entry
|
||||||
|
through the exact same splice-per-transition correction
|
||||||
|
`_reanchor_forecast()` applies live, so the reconstructed forecast matches
|
||||||
|
what a connected client would actually have seen throughout the run -
|
||||||
|
not just the single, uncorrected cold-start estimate.
|
||||||
|
|
||||||
|
```bash
|
||||||
|
python utils/analyze_log.py <date_time> <sud_name> # e.g. 20260701T192824 Sud-0010
|
||||||
|
python utils/analyze_log.py path/to/log_*.json # or a direct path
|
||||||
|
```
|
||||||
|
|||||||
+10
-4
@@ -76,9 +76,14 @@ if __name__ == '__main__':
|
|||||||
taskmgr = TaskManager()
|
taskmgr = TaskManager()
|
||||||
|
|
||||||
DT = args.dt
|
DT = args.dt
|
||||||
DT_TASK = 1.0 / args.sim_warp_factor
|
|
||||||
theta_amb = config['ambient_temperature']
|
theta_amb = config['ambient_temperature']
|
||||||
plant_sim = config['Heater'].get('type', 'sim') == 'sim'
|
plant_sim = config['Heater'].get('type', 'sim') == 'sim'
|
||||||
|
# sim_warp_factor only reciprocally scales *wait* time between task
|
||||||
|
# ticks (DT_TASK) - it has no meaning against real hardware, which
|
||||||
|
# ticks at its own physical pace regardless of how this flag is set,
|
||||||
|
# so real runs are always paced at DT_TASK == 1.0 (true real time).
|
||||||
|
sim_warp_factor = args.sim_warp_factor if plant_sim else 1.0
|
||||||
|
DT_TASK = 1.0 / sim_warp_factor
|
||||||
|
|
||||||
# Mash schedule - starts out empty; a client loads one of sude/*.json's
|
# Mash schedule - starts out empty; a client loads one of sude/*.json's
|
||||||
# several schedules onto it later (see components/sud.py's Sud).
|
# several schedules onto it later (see components/sud.py's Sud).
|
||||||
@@ -127,7 +132,7 @@ if __name__ == '__main__':
|
|||||||
# see components/sud_forecast.py.
|
# see components/sud_forecast.py.
|
||||||
forecast_estimator = SudForecastEstimator(
|
forecast_estimator = SudForecastEstimator(
|
||||||
DT, theta_amb, config['TempCtrl']['pid_type'], config['TempCtrl'],
|
DT, theta_amb, config['TempCtrl']['pid_type'], config['TempCtrl'],
|
||||||
heater.get_powers(), args.sim_warp_factor, config.get('Pot', {}))
|
heater.get_powers(), sim_warp_factor, config.get('Pot', {}))
|
||||||
sud_task = SudTask(sud, tc, stirrer, pot, DT, DT_TASK, dispatcher.msgio_get("Sud"), forecast_estimator)
|
sud_task = SudTask(sud, tc, stirrer, pot, DT, DT_TASK, dispatcher.msgio_get("Sud"), forecast_estimator)
|
||||||
taskmgr.add(sud_task)
|
taskmgr.add(sud_task)
|
||||||
|
|
||||||
@@ -141,7 +146,7 @@ if __name__ == '__main__':
|
|||||||
# Continuous server-session log - records from startup to shutdown
|
# Continuous server-session log - records from startup to shutdown
|
||||||
# regardless of Sud state; written to logs/log_{date_time}.json on exit
|
# regardless of Sud state; written to logs/log_{date_time}.json on exit
|
||||||
# and every log_interval seconds in between.
|
# and every log_interval seconds in between.
|
||||||
server_log_task = ServerLogTask(tc, heater, heater_task, DT_TASK, args.logdir, config=config, dt=DT, log_interval=log_interval)
|
server_log_task = ServerLogTask(tc, heater, heater_task, DT_TASK, args.logdir, config=config, dt=DT, log_interval=log_interval, sim_warp_factor=sim_warp_factor)
|
||||||
if startup_params is not None:
|
if startup_params is not None:
|
||||||
server_log_task.log_plant_params(0, startup_params)
|
server_log_task.log_plant_params(0, startup_params)
|
||||||
taskmgr.add(server_log_task)
|
taskmgr.add(server_log_task)
|
||||||
@@ -149,12 +154,13 @@ if __name__ == '__main__':
|
|||||||
# Per-run log - only records while a Sud is actually playing; written to
|
# Per-run log - only records while a Sud is actually playing; written to
|
||||||
# logs/log_{date_time}_{sud_name}.log on Stop (or natural completion) and
|
# logs/log_{date_time}_{sud_name}.log on Stop (or natural completion) and
|
||||||
# every log_interval seconds in between.
|
# every log_interval seconds in between.
|
||||||
sud_log_task = SudLogTask(tc, heater, heater_task, sud, DT_TASK, args.logdir, config=config, dt=DT, log_interval=log_interval)
|
sud_log_task = SudLogTask(tc, heater, heater_task, sud, DT_TASK, args.logdir, config=config, dt=DT, log_interval=log_interval, sim_warp_factor=sim_warp_factor)
|
||||||
taskmgr.add(sud_log_task)
|
taskmgr.add(sud_log_task)
|
||||||
|
|
||||||
sud_task.set_on_plant_params(lambda elapsed, params: (
|
sud_task.set_on_plant_params(lambda elapsed, params: (
|
||||||
server_log_task.log_plant_params(elapsed, params),
|
server_log_task.log_plant_params(elapsed, params),
|
||||||
sud_log_task.log_plant_params(elapsed, params)))
|
sud_log_task.log_plant_params(elapsed, params)))
|
||||||
|
sud_task.set_on_reanchor(sud_log_task.log_reanchor)
|
||||||
|
|
||||||
# Assign data flow
|
# Assign data flow
|
||||||
# Assign tc control value to heater
|
# Assign tc control value to heater
|
||||||
|
|||||||
+50
-8
@@ -16,7 +16,7 @@ class ServerLogTask(ATask):
|
|||||||
Sud state — useful for verifying controller and heater behaviour
|
Sud state — useful for verifying controller and heater behaviour
|
||||||
outside of a scheduled brew."""
|
outside of a scheduled brew."""
|
||||||
|
|
||||||
def __init__(self, tc: APid, heater: AHeater, heater_task, interval, path='./logs', config=None, dt=None, log_interval=None):
|
def __init__(self, tc: APid, heater: AHeater, heater_task, interval, path='./logs', config=None, dt=None, log_interval=None, sim_warp_factor=None):
|
||||||
ATask.__init__(self, interval)
|
ATask.__init__(self, interval)
|
||||||
self.tc = tc
|
self.tc = tc
|
||||||
self.heater = heater
|
self.heater = heater
|
||||||
@@ -25,14 +25,15 @@ class ServerLogTask(ATask):
|
|||||||
self.config = config
|
self.config = config
|
||||||
self.dt = dt
|
self.dt = dt
|
||||||
self.log_interval = log_interval
|
self.log_interval = log_interval
|
||||||
|
self.sim_warp_factor = sim_warp_factor
|
||||||
self._samples = []
|
self._samples = []
|
||||||
self._param_events = []
|
self._param_events = []
|
||||||
self._t0 = time.monotonic()
|
self._elapsed_total = 0.0
|
||||||
self._run_id = time.strftime("%Y%m%dT%H%M%S", time.localtime())
|
self._run_id = time.strftime("%Y%m%dT%H%M%S", time.localtime())
|
||||||
self._last_write = self._t0
|
self._last_write = time.monotonic()
|
||||||
|
|
||||||
def log_plant_params(self, elapsed, params):
|
def log_plant_params(self, elapsed, params):
|
||||||
self._param_events.append({'t': time.monotonic() - self._t0, 'params': params})
|
self._param_events.append({'t': elapsed, 'params': params})
|
||||||
|
|
||||||
async def on_process(self):
|
async def on_process(self):
|
||||||
while True:
|
while True:
|
||||||
@@ -40,20 +41,42 @@ class ServerLogTask(ATask):
|
|||||||
self._samples.append(self._take_sample())
|
self._samples.append(self._take_sample())
|
||||||
# Periodically checkpoints to disk (same file, overwritten whole
|
# Periodically checkpoints to disk (same file, overwritten whole
|
||||||
# each time - see write()) so a hard crash/power loss only loses
|
# each time - see write()) so a hard crash/power loss only loses
|
||||||
# up to log_interval seconds, not the whole session/run.
|
# up to log_interval seconds, not the whole session/run. This
|
||||||
|
# checkpoint cadence is deliberately real (wall-clock) time,
|
||||||
|
# unlike _elapsed() below - it's bounding real data-loss risk,
|
||||||
|
# not tracking brew progress.
|
||||||
now = time.monotonic()
|
now = time.monotonic()
|
||||||
if self.log_interval and now - self._last_write >= self.log_interval:
|
# Gated on _should_sample(): for SudLogTask, a completed run's
|
||||||
|
# stop_run() already wrote the correct final state and cleared
|
||||||
|
# _param_events for the *next* run - an unguarded checkpoint
|
||||||
|
# here would otherwise fire on the very next iteration (once
|
||||||
|
# log_interval real seconds have passed since the last one,
|
||||||
|
# regardless of the run having ended in between) and clobber
|
||||||
|
# that already-correct file with _samples unchanged but
|
||||||
|
# _param_events now empty.
|
||||||
|
if self.log_interval and self._should_sample() and now - self._last_write >= self.log_interval:
|
||||||
self.write()
|
self.write()
|
||||||
self._last_write = now
|
self._last_write = now
|
||||||
await asyncio.sleep(self.interval)
|
await asyncio.sleep(self.interval)
|
||||||
|
self._elapsed_total += self.dt
|
||||||
|
|
||||||
def _should_sample(self):
|
def _should_sample(self):
|
||||||
return True
|
return True
|
||||||
|
|
||||||
|
def _elapsed(self):
|
||||||
|
"""Simulated seconds elapsed since this task started sampling -
|
||||||
|
tick-counted (advances by self.dt once per on_process() iteration),
|
||||||
|
never derived from wall-clock time: under sim_warp_factor, real and
|
||||||
|
simulated time diverge (see components/sud.py's Sud.elapsed, and
|
||||||
|
the README's "Forecast vs. actual duration" section, for the same
|
||||||
|
reasoning), so a wall-clock 't' would desync from the forecast's
|
||||||
|
own tick-counted timeline it's meant to be compared against."""
|
||||||
|
return self._elapsed_total
|
||||||
|
|
||||||
def _take_sample(self):
|
def _take_sample(self):
|
||||||
power_set = max(self.heater_task.power_soll, self.heater_task.power_actor)
|
power_set = max(self.heater_task.power_soll, self.heater_task.power_actor)
|
||||||
return {
|
return {
|
||||||
't': time.monotonic() - self._t0,
|
't': self._elapsed(),
|
||||||
'timestamp': time.time(),
|
'timestamp': time.time(),
|
||||||
'temp_ist': self.tc.theta_ist,
|
'temp_ist': self.tc.theta_ist,
|
||||||
'temp_soll': self.tc.theta_soll_set,
|
'temp_soll': self.tc.theta_soll_set,
|
||||||
@@ -66,19 +89,38 @@ class ServerLogTask(ATask):
|
|||||||
def _filename(self):
|
def _filename(self):
|
||||||
return 'log_{}.json'.format(self._run_id)
|
return 'log_{}.json'.format(self._run_id)
|
||||||
|
|
||||||
|
def _extra_log_data(self):
|
||||||
|
"""Hook for subclasses (SudLogTask) to contribute additional keys
|
||||||
|
to write()'s output - see there."""
|
||||||
|
return {}
|
||||||
|
|
||||||
|
def _log_name(self):
|
||||||
|
"""Hook for subclasses (SudLogTask) - a server-session log covers
|
||||||
|
the whole process lifetime rather than one named run, so it has
|
||||||
|
none of its own."""
|
||||||
|
return ''
|
||||||
|
|
||||||
def write(self):
|
def write(self):
|
||||||
if not self._samples:
|
if not self._samples:
|
||||||
return
|
return
|
||||||
os.makedirs(self.path, exist_ok=True)
|
os.makedirs(self.path, exist_ok=True)
|
||||||
filename = self._filename()
|
filename = self._filename()
|
||||||
path = os.path.join(self.path, filename)
|
path = os.path.join(self.path, filename)
|
||||||
log_data = {'Name': ''}
|
log_data = {'Name': self._log_name()}
|
||||||
if self.dt is not None:
|
if self.dt is not None:
|
||||||
log_data['dt'] = self.dt
|
log_data['dt'] = self.dt
|
||||||
|
if self.sim_warp_factor is not None:
|
||||||
|
log_data['SimWarpFactor'] = self.sim_warp_factor
|
||||||
if self.config is not None:
|
if self.config is not None:
|
||||||
log_data['Config'] = self.config
|
log_data['Config'] = self.config
|
||||||
|
# Queried live from the connected device rather than reconstructed
|
||||||
|
# offline (utils/analyze_log.py has no hardware to ask) - needed to
|
||||||
|
# reproduce this run's SudForecastEstimator (see components/
|
||||||
|
# sud_forecast.py) for a post-hoc forecast-vs-actual comparison.
|
||||||
|
log_data['HeaterPowers'] = self.heater.get_powers()
|
||||||
if self._param_events:
|
if self._param_events:
|
||||||
log_data['PlantParams'] = self._param_events
|
log_data['PlantParams'] = self._param_events
|
||||||
|
log_data.update(self._extra_log_data())
|
||||||
log_data['Samples'] = self._samples
|
log_data['Samples'] = self._samples
|
||||||
with open(path, 'w') as f:
|
with open(path, 'w') as f:
|
||||||
json.dump(log_data, f, indent='\t')
|
json.dump(log_data, f, indent='\t')
|
||||||
|
|||||||
+35
-4
@@ -113,6 +113,7 @@ class SudTask(ATask):
|
|||||||
self._on_end = None
|
self._on_end = None
|
||||||
self._on_start = None
|
self._on_start = None
|
||||||
self._on_plant_params = None
|
self._on_plant_params = None
|
||||||
|
self._on_reanchor = None
|
||||||
msg_handler.set_recv_handler(self.recv)
|
msg_handler.set_recv_handler(self.recv)
|
||||||
|
|
||||||
def set_on_plant_params(self, callback):
|
def set_on_plant_params(self, callback):
|
||||||
@@ -120,6 +121,16 @@ class SudTask(ATask):
|
|||||||
so external observers (e.g. SudLogTask) can record each change."""
|
so external observers (e.g. SudLogTask) can record each change."""
|
||||||
self._on_plant_params = callback
|
self._on_plant_params = callback
|
||||||
|
|
||||||
|
def set_on_reanchor(self, callback):
|
||||||
|
"""Register a callback invoked with (elapsed, index, theta_ist)
|
||||||
|
every time _reanchor_forecast() fires (see on_step_changed()) -
|
||||||
|
lets an external observer (SudLogTask) record the exact anchor
|
||||||
|
points a live client's forecast got corrected at, so an offline
|
||||||
|
re-simulation (utils/analyze_log.py) can reproduce the same
|
||||||
|
splice-per-transition forecast instead of just the single,
|
||||||
|
uncorrected cold-start one."""
|
||||||
|
self._on_reanchor = callback
|
||||||
|
|
||||||
def apply_plant_params(self, grain_mass, water_mass):
|
def apply_plant_params(self, grain_mass, water_mass):
|
||||||
"""Keeps the real plant's and the controller's internal model's
|
"""Keeps the real plant's and the controller's internal model's
|
||||||
plant params in sync with this Sud's own doc - L/Td come straight
|
plant params in sync with this Sud's own doc - L/Td come straight
|
||||||
@@ -215,6 +226,12 @@ class SudTask(ATask):
|
|||||||
# (a malt fill-in's actual cooldown, a longer/shorter ramp than
|
# (a malt fill-in's actual cooldown, a longer/shorter ramp than
|
||||||
# modeled, ...) at the next opportunity, not just at the next
|
# modeled, ...) at the next opportunity, not just at the next
|
||||||
# user confirmation.
|
# user confirmation.
|
||||||
|
if self._on_reanchor:
|
||||||
|
# Read synchronously, right here - the same values
|
||||||
|
# _reanchor_forecast() itself will read moments later, off
|
||||||
|
# the same unyielded call stack, before anything else can
|
||||||
|
# mutate them.
|
||||||
|
self._on_reanchor(self.sud.elapsed, self.sud.index, self.tc.get_theta_ist())
|
||||||
asyncio.create_task(self._reanchor_forecast())
|
asyncio.create_task(self._reanchor_forecast())
|
||||||
|
|
||||||
asyncio.create_task(self.send({'Step': {
|
asyncio.create_task(self.send({'Step': {
|
||||||
@@ -373,16 +390,30 @@ class SudTask(ATask):
|
|||||||
self._forecast_generation += 1
|
self._forecast_generation += 1
|
||||||
generation = self._forecast_generation
|
generation = self._forecast_generation
|
||||||
real_elapsed = self.sud.elapsed
|
real_elapsed = self.sud.elapsed
|
||||||
|
schedule = self.sud.schedule
|
||||||
|
index = self.sud.index
|
||||||
# Drop the now-stale tail (everything beyond right now) - it's
|
# Drop the now-stale tail (everything beyond right now) - it's
|
||||||
# about to be replaced by a freshly anchored simulation.
|
# about to be replaced by a freshly anchored simulation. Cut at
|
||||||
cut = bisect.bisect_right(self.forecast_t, real_elapsed)
|
# forecast_step_starts[index], the old forecast's own (possibly
|
||||||
|
# very wrong) belief of where step `index` begins - not at
|
||||||
|
# real_elapsed directly: a step whose real timing blew way past
|
||||||
|
# what its zero-delay guess assumed (a long WAIT_USER confirm,
|
||||||
|
# above all - see SudForecastEstimator.estimate()'s docstring)
|
||||||
|
# leaves the old forecast's *entire* speculative remainder sitting
|
||||||
|
# at timestamps still numerically less than real_elapsed, so
|
||||||
|
# bisecting against real_elapsed itself would find nothing to
|
||||||
|
# discard and just tack the fresh, correct simulation on after it
|
||||||
|
# - a doubled-back, self-overlapping curve instead of a clean cut.
|
||||||
|
# forecast_step_starts[index] doesn't have this problem: it lives
|
||||||
|
# in the same (speculative) coordinate space as forecast_t itself,
|
||||||
|
# so the cut lands in the right place regardless of how far real
|
||||||
|
# and speculated time have diverged by now.
|
||||||
|
cut = bisect.bisect_right(self.forecast_t, self.forecast_step_starts.get(index, real_elapsed))
|
||||||
forecast_t = self.forecast_t[:cut]
|
forecast_t = self.forecast_t[:cut]
|
||||||
forecast_theta = self.forecast_theta[:cut]
|
forecast_theta = self.forecast_theta[:cut]
|
||||||
# Steps already passed (< index) have their real, now-immutable
|
# Steps already passed (< index) have their real, now-immutable
|
||||||
# start time; anything from index on is about to be resimulated
|
# start time; anything from index on is about to be resimulated
|
||||||
# fresh below and must not keep a stale prediction around.
|
# fresh below and must not keep a stale prediction around.
|
||||||
schedule = self.sud.schedule
|
|
||||||
index = self.sud.index
|
|
||||||
forecast_step_starts = {i: tt for i, tt in self.forecast_step_starts.items() if i < index}
|
forecast_step_starts = {i: tt for i, tt in self.forecast_step_starts.items() if i < index}
|
||||||
|
|
||||||
if not (0 <= index < len(schedule)):
|
if not (0 <= index < len(schedule)):
|
||||||
|
|||||||
+40
-4
@@ -14,10 +14,12 @@ class SudLogTask(ServerLogTask):
|
|||||||
logs/log_{date_time}_{sud_name}.log. A Pause/resume doesn't start a new
|
logs/log_{date_time}_{sud_name}.log. A Pause/resume doesn't start a new
|
||||||
file - only a fresh Play (from IDLE/DONE) does."""
|
file - only a fresh Play (from IDLE/DONE) does."""
|
||||||
|
|
||||||
def __init__(self, tc: APid, heater: AHeater, heater_task, sud, interval, path='./logs', config=None, dt=None, log_interval=None):
|
def __init__(self, tc: APid, heater: AHeater, heater_task, sud, interval, path='./logs', config=None, dt=None, log_interval=None, sim_warp_factor=None):
|
||||||
ServerLogTask.__init__(self, tc, heater, heater_task, interval, path, config, dt, log_interval)
|
ServerLogTask.__init__(self, tc, heater, heater_task, interval, path, config, dt, log_interval, sim_warp_factor)
|
||||||
self.sud = sud
|
self.sud = sud
|
||||||
self._active = False
|
self._active = False
|
||||||
|
self._doc = None
|
||||||
|
self._reanchors = []
|
||||||
|
|
||||||
def _should_sample(self):
|
def _should_sample(self):
|
||||||
return self._active
|
return self._active
|
||||||
@@ -26,13 +28,46 @@ class SudLogTask(ServerLogTask):
|
|||||||
name_part = _safe_filename_part(self.sud.name or 'Sud')
|
name_part = _safe_filename_part(self.sud.name or 'Sud')
|
||||||
return 'log_{}_{}.log'.format(self._run_id, name_part)
|
return 'log_{}_{}.log'.format(self._run_id, name_part)
|
||||||
|
|
||||||
|
def _log_name(self):
|
||||||
|
return self.sud.name
|
||||||
|
|
||||||
|
def _elapsed(self):
|
||||||
|
# The Sud's own tick-counted ground truth (see components/sud.py's
|
||||||
|
# Sud.elapsed) rather than the base class's own tick counter -
|
||||||
|
# already resets to 0 on every fresh Play (Sud.start()), so samples
|
||||||
|
# line up with SudForecastEstimator's t=0 the same way Sud.elapsed
|
||||||
|
# does everywhere else it's consumed (e.g. SudTask's forecast
|
||||||
|
# re-anchoring).
|
||||||
|
return self.sud.elapsed
|
||||||
|
|
||||||
|
def log_reanchor(self, elapsed, index, theta_ist):
|
||||||
|
# One entry per real _reanchor_forecast() trigger (see SudTask.
|
||||||
|
# set_on_reanchor()) - lets utils/analyze_log.py replay the exact
|
||||||
|
# same splice-per-transition forecast correction a live client
|
||||||
|
# would have seen, instead of just the single, uncorrected
|
||||||
|
# cold-start estimate() run - see build_forecast() there.
|
||||||
|
self._reanchors.append({'t': elapsed, 'index': index, 'theta_ist': theta_ist})
|
||||||
|
|
||||||
|
def _extra_log_data(self):
|
||||||
|
# The raw sud.json doc this run was playing, exactly as loaded (see
|
||||||
|
# Sud.save()) - lets utils/analyze_log.py re-simulate this run's own
|
||||||
|
# SudForecastEstimator forecast for comparison against Samples,
|
||||||
|
# without depending on the sude/*.json file it came from still
|
||||||
|
# existing or being unchanged.
|
||||||
|
data = {}
|
||||||
|
if self._doc is not None:
|
||||||
|
data['Doc'] = self._doc
|
||||||
|
if self._reanchors:
|
||||||
|
data['ForecastAnchors'] = self._reanchors
|
||||||
|
return data
|
||||||
|
|
||||||
def start_run(self):
|
def start_run(self):
|
||||||
if self._active:
|
if self._active:
|
||||||
return
|
return
|
||||||
self._samples = []
|
self._samples = []
|
||||||
self._t0 = time.monotonic()
|
self._last_write = time.monotonic()
|
||||||
self._last_write = self._t0
|
|
||||||
self._run_id = time.strftime("%Y%m%dT%H%M%S", time.localtime())
|
self._run_id = time.strftime("%Y%m%dT%H%M%S", time.localtime())
|
||||||
|
self._doc = self.sud.save()
|
||||||
self._active = True
|
self._active = True
|
||||||
|
|
||||||
def stop_run(self):
|
def stop_run(self):
|
||||||
@@ -41,3 +76,4 @@ class SudLogTask(ServerLogTask):
|
|||||||
self._active = False
|
self._active = False
|
||||||
self.write()
|
self.write()
|
||||||
self._param_events = []
|
self._param_events = []
|
||||||
|
self._reanchors = []
|
||||||
|
|||||||
+78
-9
@@ -5,16 +5,19 @@ Usage:
|
|||||||
python analyze_log.py <date_time> <sud_name> [--log-dir <dir>]
|
python analyze_log.py <date_time> <sud_name> [--log-dir <dir>]
|
||||||
python analyze_log.py <path/to/log_*.json>
|
python analyze_log.py <path/to/log_*.json>
|
||||||
|
|
||||||
The two-argument form loads logs/<date_time>_<sud_name>.json and its paired
|
The two-argument form loads logs/<date_time>_<sud_name>.json; the
|
||||||
forecast file. The single-argument form accepts a direct path to any
|
single-argument form accepts a direct path to any log_*.json (e.g. a
|
||||||
log_*.json (e.g. a server-session log without a Sud name); the forecast panel
|
server-session log without a Sud name). The forecast-vs-actual panel is
|
||||||
is shown only if a matching forecast_*.json exists alongside it.
|
shown only for a Sud log (one carrying a 'Doc', 'Config' and 'HeaterPowers'
|
||||||
|
- see tasks/sud_log.py), by re-simulating that run's own schedule with
|
||||||
|
SudForecastEstimator, the same as the live server does at Play.
|
||||||
|
|
||||||
Renders the 3-panel realtime strip chart and, when available, the
|
Renders the 3-panel realtime strip chart and, when available, the
|
||||||
forecast-vs-actual comparison.
|
forecast-vs-actual comparison.
|
||||||
"""
|
"""
|
||||||
|
|
||||||
import argparse
|
import argparse
|
||||||
|
import bisect
|
||||||
import json
|
import json
|
||||||
import sys
|
import sys
|
||||||
from pathlib import Path
|
from pathlib import Path
|
||||||
@@ -24,6 +27,11 @@ matplotlib.use("TkAgg")
|
|||||||
import matplotlib.pyplot as plt
|
import matplotlib.pyplot as plt
|
||||||
from matplotlib.ticker import AutoMinorLocator
|
from matplotlib.ticker import AutoMinorLocator
|
||||||
|
|
||||||
|
sys.path.insert(0, str(Path(__file__).parent.parent))
|
||||||
|
|
||||||
|
from components.sud import SudState
|
||||||
|
from components.sud_forecast import SudForecastEstimator
|
||||||
|
|
||||||
|
|
||||||
def _style_axis(ax):
|
def _style_axis(ax):
|
||||||
ax.set_facecolor('white')
|
ax.set_facecolor('white')
|
||||||
@@ -102,6 +110,70 @@ def plot_forecast(forecast, samples, name):
|
|||||||
return fig
|
return fig
|
||||||
|
|
||||||
|
|
||||||
|
def build_forecast(log):
|
||||||
|
"""Re-simulates the schedule a Sud log's own 'Doc' recorded, the same
|
||||||
|
way the live server does at Play (see components/sud_forecast.py) -
|
||||||
|
returns a {'T', 'Theta', 'Finished'} dict matching plot_forecast()'s
|
||||||
|
expected shape, or None if log isn't a Sud log (no 'Doc'/'Config'/
|
||||||
|
'HeaterPowers' - e.g. a server-session log with no run playing).
|
||||||
|
|
||||||
|
Replays every real _reanchor_forecast() trigger recorded in the log's
|
||||||
|
'ForecastAnchors' (see tasks/sud.py's SudTask.set_on_reanchor()), in
|
||||||
|
order, splicing a freshly anchored simulation of the remaining
|
||||||
|
schedule onto the truncated forecast at each one - the exact same
|
||||||
|
correction a live client's forecast plot goes through as a run
|
||||||
|
progresses. Without this, the single cold-start estimate() below is
|
||||||
|
all a client ever saw at Load - it can't have anticipated things like
|
||||||
|
a WAIT_USER confirmation's real timing (estimate() can only ever model
|
||||||
|
that as zero-delay - see its own docstring), so a plot comparing it
|
||||||
|
straight against Samples would show a small, spurious gap at every
|
||||||
|
such step that isn't actually a forecast error."""
|
||||||
|
if 'Doc' not in log or 'Config' not in log or 'HeaterPowers' not in log:
|
||||||
|
return None
|
||||||
|
doc = log['Doc']
|
||||||
|
config = log['Config']
|
||||||
|
tempctrl = config['TempCtrl']
|
||||||
|
# Old logs predate 'SimWarpFactor' being recorded - 1.0 (real time) is
|
||||||
|
# the right fallback for those, since it's also what every real-hardware
|
||||||
|
# run already used (see server/brewpi.py's plant_sim check).
|
||||||
|
estimator = SudForecastEstimator(
|
||||||
|
log['dt'], config['ambient_temperature'], tempctrl['pid_type'], tempctrl,
|
||||||
|
log['HeaterPowers'], log.get('SimWarpFactor', 1.0), config.get('Pot', {}))
|
||||||
|
|
||||||
|
t, theta, state, step_starts = estimator.estimate(doc)
|
||||||
|
finished = (state == SudState.DONE)
|
||||||
|
|
||||||
|
for anchor in log.get('ForecastAnchors', []):
|
||||||
|
real_elapsed = anchor['t']
|
||||||
|
index = anchor['index']
|
||||||
|
if not (0 <= index < len(doc['steps'])):
|
||||||
|
continue
|
||||||
|
# Cut at step_starts[index], the old forecast's own (possibly very
|
||||||
|
# wrong) belief of where step `index` begins - not at real_elapsed
|
||||||
|
# directly: a step whose real timing blew way past its zero-delay
|
||||||
|
# guess (a long WAIT_USER confirm, above all) leaves the old
|
||||||
|
# forecast's entire speculative remainder sitting at timestamps
|
||||||
|
# still numerically less than real_elapsed, so bisecting against
|
||||||
|
# real_elapsed itself would find nothing to discard and just tack
|
||||||
|
# the fresh, correct simulation on after it - see tasks/sud.py's
|
||||||
|
# SudTask._reanchor_forecast(), which this mirrors exactly.
|
||||||
|
cut = bisect.bisect_right(t, step_starts.get(index, real_elapsed))
|
||||||
|
t, theta = t[:cut], theta[:cut]
|
||||||
|
step_starts = {i: tt for i, tt in step_starts.items() if i < index}
|
||||||
|
sub_doc = {**doc, 'steps': doc['steps'][index:]}
|
||||||
|
sub_t, sub_theta, sub_state, sub_step_starts = estimator.estimate(sub_doc, anchor['theta_ist'])
|
||||||
|
if t and t[-1] < real_elapsed:
|
||||||
|
t.append(real_elapsed)
|
||||||
|
theta.append(anchor['theta_ist'])
|
||||||
|
t.extend(real_elapsed + seconds for seconds in sub_t)
|
||||||
|
theta.extend(sub_theta)
|
||||||
|
step_starts.update((index + local_index, real_elapsed + local_t)
|
||||||
|
for local_index, local_t in sub_step_starts.items())
|
||||||
|
finished = (sub_state == SudState.DONE)
|
||||||
|
|
||||||
|
return {'T': t, 'Theta': theta, 'Finished': finished}
|
||||||
|
|
||||||
|
|
||||||
def main():
|
def main():
|
||||||
parser = argparse.ArgumentParser(description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter)
|
parser = argparse.ArgumentParser(description=__doc__, formatter_class=argparse.RawDescriptionHelpFormatter)
|
||||||
parser.add_argument('date_time_or_path',
|
parser.add_argument('date_time_or_path',
|
||||||
@@ -118,12 +190,10 @@ def main():
|
|||||||
if args.sud_name is None:
|
if args.sud_name is None:
|
||||||
log_path = Path(args.date_time_or_path)
|
log_path = Path(args.date_time_or_path)
|
||||||
stem = log_path.stem[len('log_'):] if log_path.stem.startswith('log_') else log_path.stem
|
stem = log_path.stem[len('log_'):] if log_path.stem.startswith('log_') else log_path.stem
|
||||||
forecast_path = log_path.parent / 'forecast_{}.json'.format(stem)
|
|
||||||
else:
|
else:
|
||||||
log_dir = Path(args.log_dir)
|
log_dir = Path(args.log_dir)
|
||||||
stem = '{}_{}'.format(args.date_time_or_path, args.sud_name)
|
stem = '{}_{}'.format(args.date_time_or_path, args.sud_name)
|
||||||
log_path = log_dir / 'log_{}.json'.format(stem)
|
log_path = log_dir / 'log_{}.json'.format(stem)
|
||||||
forecast_path = log_dir / 'forecast_{}.json'.format(stem)
|
|
||||||
|
|
||||||
if not log_path.exists():
|
if not log_path.exists():
|
||||||
print('Error: file not found: {}'.format(log_path), file=sys.stderr)
|
print('Error: file not found: {}'.format(log_path), file=sys.stderr)
|
||||||
@@ -136,9 +206,8 @@ def main():
|
|||||||
samples = log['Samples']
|
samples = log['Samples']
|
||||||
|
|
||||||
plot_realtime(samples, name)
|
plot_realtime(samples, name)
|
||||||
if forecast_path.exists():
|
forecast = build_forecast(log)
|
||||||
with open(forecast_path) as f:
|
if forecast is not None:
|
||||||
forecast = json.load(f)
|
|
||||||
plot_forecast(forecast, samples, name)
|
plot_forecast(forecast, samples, name)
|
||||||
|
|
||||||
plt.show()
|
plt.show()
|
||||||
|
|||||||
Reference in New Issue
Block a user