Skip to content

Commit ae83086

Browse files
authored
Merge pull request #11 from harshabose/feat/run-logging
Run logging: progress hook, worker logs, run printer, --status
2 parents 7e95c1e + e64a7e2 commit ae83086

16 files changed

Lines changed: 1461 additions & 106 deletions

‎README.md‎

Lines changed: 45 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -68,6 +68,9 @@ python run.py --fresh-cache delete the task cache of this run, then compute
6868
python run.py --serial one process (easier to debug)
6969
python run.py --verify also run the test suite and feed the release gate
7070
python run.py --view [FOLDER] open existing results as report.html (+ tables.xlsx); runs nothing
71+
python run.py --status [FOLDER] what a running (or the last) study is doing; runs nothing
72+
python run.py --log-level quiet|normal|verbose how much a run prints (default normal)
73+
python run.py --heartbeat SECONDS seconds between heartbeats (default 60)
7174
```
7275

7376
`--view` is a viewer: it reads a results folder that already exists (default: `output_dir/run_name` of
@@ -77,6 +80,48 @@ python run.py --view [FOLDER] open existing results as report.html (+ tables.
7780
Results are cached per task and keyed by a hash of every result-relevant input, so an unchanged re-run
7881
only rebuilds the report and changing one value only re-runs what depends on it.
7982

83+
## Watching a run
84+
85+
A full study takes hours, so it reports what it is doing. Every line is plain ASCII, `HH:MM:SS message`
86+
(no colour, no `\r` progress bars, flushed), so it reads the same in PyCharm, in Git Bash and in a file
87+
(`python run.py > study_console.txt 2>&1`).
88+
89+
| line | meaning |
90+
|---|---|
91+
| banner | git commit (`dirty` = tracked files differ), Python and library versions, mode, workers, the cache folder, tasks to run and cached, the time estimate, and the wave plan (which tasks wait for which) |
92+
| `wave 2 starts: ...` / `wave 2 ends ...` | a wave is the set of tasks that run together; the next one is planned from the results of the last |
93+
| `start`, `done`, `cached`, `FAILED <task>` | one line per task, with its seconds; `start` is when the worker opened its state file |
94+
| `FT_grid:12000 seed 3/3 done J=0.7741 96 evals 18.4 min` | one finished CMA-ES seed (`search done` adds the seed spread) |
95+
| `B1:S-03 9/17 S-03 solve attached ...: verified E=25.5 kJ (41 s)` | progress of a task that works in steps (B1 solves, sensitivity samples), printed at each quarter; `verbose` prints every one |
96+
| `heartbeat 1.2 h elapsed tasks: 9 done, 22 running, 3 waiting` | followed by one line per running task: phase, seed `k/n`, iteration, best `J`, the task's elapsed time and a rough `~N min left` (from the pace so far, so only an estimate), or `no update for N min` when it has been silent for 5 min |
97+
| summary | every task with its seconds, the slowest task and the critical path (the slowest task of each wave, added), wall time against the estimate, failed tasks with the path of their log, and the next command |
98+
99+
"Silent" means no progress event of any kind: a search reports every cost evaluation (the
100+
state file takes it at once, the log at most every 5 s), so a long first generation no longer
101+
looks stuck. The banner's time estimate is built from the times observed in the last full run
102+
(`TASK_COST` in `io/stages.py`): the longest task of the first wave plus the follow-up waves.
103+
104+
The terminal shows a heartbeat block every 15 minutes at `normal` (every heartbeat at `verbose`, none at
105+
`quiet`), so a full clean study prints a few hundred lines. This is a deliberate limit: a line every
106+
60 s for 3.5 h would be 210 lines on its own. The heartbeat itself still runs every `--heartbeat` seconds
107+
and goes to the files below, and `--status` shows the same thing at any moment.
108+
109+
Where things are (`<run>` is `output_dir/run_name`, `results/study` by default):
110+
111+
* `<run>/_logs/run_<date>_<time>.log` the parent's whole timestamped log, everything the terminal got and
112+
more (every heartbeat, in full); its path is the first line printed;
113+
* `<run>/_logs/<task>.log` one task's events with times, every search iteration included;
114+
* `<run>/_logs/<task>.state.json` the latest state of a task (replaced atomically about every 5 s);
115+
* `<run>/_logs/status.json` the whole run, written at every heartbeat.
116+
117+
`python run.py --status [FOLDER]` reads these from any other terminal and prints what is going on now;
118+
with no logs in the folder it prints `no status in <folder>`, exits 2 and writes nothing. It cannot be
119+
combined with a run (`--only`, `--force`, ...), like `--view`. None of `--log-level`, `--heartbeat` and
120+
`--status` is part of any hash: another level is the same cache key.
121+
122+
A task that fails prints the last lines of its traceback and the path of its log. If a worker process is
123+
killed (usually out of memory) the run prints one line saying so; use fewer `--workers`.
124+
80125
## Acceptance run
81126

82127
A full study from nothing, then the viewer. From a fresh clone (the commands are the same in the

‎pyproject.toml‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -63,7 +63,7 @@ ignore_missing_imports = true
6363
root_package = "sagetrans"
6464

6565
[[tool.importlinter.contracts]]
66-
name = "Layering: analysis > control > dynamics > physics > atmosphere > config"
66+
name = "Layering: analysis > control > dynamics > physics > atmosphere > config > progress"
6767
type = "layers"
6868
layers = [
6969
"sagetrans.io",
@@ -73,6 +73,7 @@ layers = [
7373
"(sagetrans.physics)",
7474
"sagetrans.atmosphere",
7575
"sagetrans.config",
76+
"sagetrans.progress", # imports nothing; every layer may report progress through it
7677
]
7778

7879
# docs/OUTPUTS_spec.md 1: the viewer reads a results folder; it imports no analysis code.

‎src/sagetrans/analysis/forward.py‎

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -25,7 +25,7 @@
2525

2626
import numpy as np
2727

28-
from sagetrans import atmosphere
28+
from sagetrans import atmosphere, progress
2929
from sagetrans.analysis import restricted, runs
3030
from sagetrans.analysis.common import RunRecord, Scenario, make_record
3131
from sagetrans.analysis.ensemble import (
@@ -436,17 +436,18 @@ def lattice_descent(
436436
`cost` scores a full parameter dict; each distinct point is evaluated once.
437437
"""
438438
seen: dict[tuple[float, ...], float] = {}
439+
rounds = 0
439440

440441
def score(p: dict[str, float]) -> float:
441442
key = tuple(round(p[n], 10) for n in LATTICE_NAMES)
442443
if key not in seen:
443444
seen[key] = float(cost(p))
445+
progress.phase(f"lattice descent: round {rounds + 1}, {len(seen)} point(s) scored")
444446
return seen[key]
445447

446448
cur = snap_ft(start, bounds)
447449
first = cur
448450
f_cur = f_first = score(cur)
449-
rounds = 0
450451
while rounds < max_rounds:
451452
scored = [(score(c), c) for c in lattice_neighbours(cur, bounds)]
452453
if not scored:
@@ -497,7 +498,7 @@ def cost(u: np.ndarray) -> float:
497498
return ensemble_cost(metrics(bounds.to_physical(u)), weights)
498499

499500
u0 = bounds.to_unit({n: start[n] for n in bounds.names})
500-
res = cma_minimise(cost, u0, seeds, popsize=popsize, maxiter=maxiter)
501+
res = cma_minimise(cost, u0, seeds, popsize=popsize, maxiter=maxiter, name="ft")
501502
best = full(bounds.to_physical(res.best_x))
502503
record: RunRecord = make_record(
503504
vp, scens, "ft", cfg, weights, bounds, pin, seeds, popsize, maxiter, start

‎src/sagetrans/analysis/restricted.py‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -222,7 +222,7 @@ def cost(u: np.ndarray) -> float:
222222
return ensemble_cost(metrics(bounds.to_physical(u)), weights)
223223

224224
u0 = bounds.to_unit({**DEFAULT_PARAMS, **(start or {})})
225-
res = cma_minimise(cost, u0, seeds, popsize=popsize, maxiter=maxiter)
225+
res = cma_minimise(cost, u0, seeds, popsize=popsize, maxiter=maxiter, name=scope)
226226
best = bounds.to_physical(res.best_x)
227227
return RestrictedResult(
228228
scope, best, res.best_f, res.f_start, metrics(best), res,
@@ -410,7 +410,7 @@ def cost(u: np.ndarray) -> float:
410410
return ensemble_cost(metrics(bounds.to_physical(u)), weights)
411411

412412
u0 = bounds.to_unit({"q": C_Q_START, **start})
413-
res = cma_minimise(cost, u0, seeds, popsize=popsize, maxiter=maxiter)
413+
res = cma_minimise(cost, u0, seeds, popsize=popsize, maxiter=maxiter, name="c")
414414
best = bounds.to_physical(res.best_x)
415415
return RestrictedResult(
416416
"c", best, res.best_f, res.f_start, metrics(best), res,

‎src/sagetrans/analysis/search.py‎

Lines changed: 20 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -6,12 +6,15 @@
66

77
from __future__ import annotations
88

9+
import time
910
from collections.abc import Callable
1011
from dataclasses import dataclass
1112

1213
import cma
1314
import numpy as np
1415

16+
from sagetrans import progress
17+
1518

1619
@dataclass(frozen=True)
1720
class SeedResult:
@@ -60,25 +63,33 @@ def cma_minimise(
6063
popsize: int = 8,
6164
maxiter: int = 30,
6265
tolfun: float = 1e-6,
66+
name: str = "search",
6367
) -> SearchResult:
64-
"""Minimise fn over [0, 1]^n starting at u0; results are cached per rounded vector."""
68+
"""Minimise fn over [0, 1]^n starting at u0; results are cached per rounded vector.
69+
70+
`name` only labels the progress events (`sagetrans.progress`); it does not change the search.
71+
"""
6572
cache: dict[tuple[float, ...], float] = {}
6673

6774
def cached(u: np.ndarray) -> float:
6875
key = tuple(np.round(np.clip(u, 0.0, 1.0), 9).tolist())
6976
if key not in cache:
7077
cache[key] = float(fn(np.clip(u, 0.0, 1.0)))
78+
progress.search_eval(len(cache))
7179
return cache[key]
7280

81+
t_search = time.perf_counter()
82+
progress.search_start(name, len(seeds), maxiter)
7383
f_start = cached(u0)
7484
out: list[SeedResult] = []
75-
for seed in seeds:
85+
for k, seed in enumerate(seeds, start=1):
86+
t_seed = time.perf_counter()
7687
opts = {
7788
"seed": seed, "popsize": popsize, "maxiter": maxiter, "bounds": [0.0, 1.0],
7889
"verbose": -9, "tolfun": tolfun, "tolx": 1e-6,
7990
} # fmt: skip
8091
es = cma.CMAEvolutionStrategy(list(u0), sigma0, opts)
81-
best_u, best_f, n = np.array(u0), f_start, 0
92+
best_u, best_f, n, it = np.array(u0), f_start, 0, 0
8293
while not es.stop():
8394
xs = es.ask()
8495
fs = [cached(np.array(x)) for x in xs]
@@ -87,6 +98,11 @@ def cached(u: np.ndarray) -> float:
8798
i = int(np.argmin(fs))
8899
if fs[i] < best_f:
89100
best_f, best_u = fs[i], np.clip(np.array(xs[i]), 0.0, 1.0)
101+
it += 1
102+
progress.search_iter(k, it, n, best_f)
90103
out.append(SeedResult(seed, best_u, best_f, n))
104+
progress.search_seed_done(k, best_f, n, time.perf_counter() - t_seed)
91105
best = min(out, key=lambda s: s.f)
92-
return SearchResult(out, best.x, best.f, f_start)
106+
res = SearchResult(out, best.x, best.f, f_start)
107+
progress.search_done(res.best_f, res.spread, time.perf_counter() - t_search)
108+
return res

‎src/sagetrans/analysis/sensitivity.py‎

Lines changed: 13 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -24,7 +24,7 @@
2424
from SALib.sample import sobol as sobol_sample
2525
from scipy.stats import spearmanr
2626

27-
from sagetrans import atmosphere
27+
from sagetrans import atmosphere, progress
2828
from sagetrans.analysis import braking, energy, restricted
2929
from sagetrans.analysis.common import RunRecord, Scenario, make_record
3030
from sagetrans.analysis.descent import DescentLimits
@@ -280,7 +280,8 @@ def oat(model: HeadlineModel) -> list[OATRow]:
280280
"""Each input alone at +-50 % and +-100 % of its half-range (nominal elsewhere)."""
281281
base = model({})
282282
rows: list[OATRow] = []
283-
for inp in model.inputs:
283+
progress.phase("sensitivity: one at a time")
284+
for n_in, inp in enumerate(model.inputs, start=1):
284285
pts = {
285286
"lo": inp.nominal - inp.half_range, "hi": inp.nominal + inp.half_range,
286287
"lo_half": inp.nominal - 0.5 * inp.half_range,
@@ -292,6 +293,7 @@ def oat(model: HeadlineModel) -> list[OATRow]:
292293
OATRow(inp.name, out, inp.status, base[out], res["lo"][out], res["hi"][out],
293294
res["lo_half"][out], res["hi_half"][out])
294295
) # fmt: skip
296+
progress.step(f"one at a time: {inp.name}", n_in, len(model.inputs))
295297
return rows
296298

297299

@@ -322,13 +324,18 @@ def _problem(inputs: Sequence[UncertainInput]) -> dict[str, Any]:
322324
}
323325

324326

325-
def _evaluate(model: HeadlineModel, x: np.ndarray) -> tuple[dict[str, np.ndarray], int]:
327+
def _evaluate(
328+
model: HeadlineModel, x: np.ndarray, label: str = "sampling"
329+
) -> tuple[dict[str, np.ndarray], int]:
326330
names = [i.name for i in model.inputs]
327331
ys: dict[str, list[float]] = {o: [] for o in model.outputs}
328-
for row in x:
332+
every = max(1, len(x) // 30) # a progress step per few percent of the sample
333+
for i, row in enumerate(x, start=1):
329334
out = model(dict(zip(names, row.tolist(), strict=True)))
330335
for o in model.outputs:
331336
ys[o].append(out[o])
337+
if i % every == 0 or i == len(x):
338+
progress.step(f"{label}: {i} of {len(x)} samples", i, len(x))
332339
arr = {o: np.array(v) for o, v in ys.items()}
333340
n_failed = int(np.sum(np.isnan(np.column_stack(list(arr.values()))).any(axis=1)))
334341
better_high: frozenset[str] = getattr(model, "higher_is_better", frozenset())
@@ -343,7 +350,7 @@ def global_morris(model: HeadlineModel, r: int, seed: int = 0, levels: int = 4)
343350
"""Morris elementary effects with `r` trajectories: index = mu_star."""
344351
prob = _problem(model.inputs)
345352
x = morris_sample.sample(prob, N=r, num_levels=levels, seed=seed)
346-
ys, n_failed = _evaluate(model, x)
353+
ys, n_failed = _evaluate(model, x, f"Morris r={r}")
347354
index, detail = {}, {}
348355
for o, y in ys.items():
349356
res = morris_analyze.analyze(prob, x, y, num_levels=levels, seed=seed)
@@ -356,7 +363,7 @@ def global_sobol(model: HeadlineModel, n: int, seed: int = 0) -> GlobalResult:
356363
"""Sobol first- and total-order indices from a Saltelli sample of base size `n` (power of 2)."""
357364
prob = _problem(model.inputs)
358365
x = sobol_sample.sample(prob, n, calc_second_order=False, seed=seed)
359-
ys, n_failed = _evaluate(model, x)
366+
ys, n_failed = _evaluate(model, x, f"Sobol n={n}")
360367
index, detail = {}, {}
361368
for o, y in ys.items():
362369
res = sobol_analyze.analyze(prob, y, calc_second_order=False, seed=seed)

‎src/sagetrans/io/README.md‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@ absolute imports mean it does not shadow the standard library.)
1717
| `recommended.py` | `settings_recommended.csv`: the ArduPilot parameters, the register, the recommended and the default values |
1818
| `assemble.py` | turns task results into tables, figures, `report.md`, `inputs_used.md`, the run record and the gate verdict |
1919
| `study.py` | `run_study`: load, check, run tasks in a spawn process pool with a per-task disk cache, assemble |
20+
| `runlog.py` | run logging: `WorkerLog` (a worker's progress sink: task log and state file), `RunLog` (the terminal lines, heartbeat, `status.json`, summary), `read_status` (`--status`) |
2021
| `cli.py` | `python run.py` / `python -m sagetrans`: `--check --mode --only --force --serial --verify`, and `--view [FOLDER] --no-open` |
2122
| `view/` | the results viewer (below): `report.html` and `tables.xlsx` from a results folder |
2223
| `ci_check.py` | `python -m sagetrans.io.ci_check junit.xml`: fails CI if any of T-01…T-15 is missing or failing |

‎src/sagetrans/io/cli.py‎

Lines changed: 43 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,9 @@
1010
python run.py --serial # one process (easier to debug)
1111
python run.py --verify # also run the test suite and feed the release gate
1212
python run.py --view [FOLDER] # open the results as report.html (+ tables.xlsx); no run
13+
python run.py --status [FOLDER] # what a running (or the last) study is doing; no run
14+
python run.py --log-level verbose # quiet | normal (default) | verbose
15+
python run.py --heartbeat 30 # seconds between heartbeats (default 60)
1316
1417
Exit codes: 0 ok, 1 a task failed, 2 the inputs are unusable (or release mode refused),
1518
3 release mode finished but the release gate blocked the result.
@@ -22,6 +25,7 @@
2225
from collections.abc import Sequence
2326
from pathlib import Path
2427

28+
from sagetrans.io import runlog
2529
from sagetrans.io.inputs import InputError, load_inputs
2630
from sagetrans.io.settings import ALL_ANALYSES
2731
from sagetrans.io.study import EXIT_INPUTS, EXIT_OK, preflight, run_study
@@ -54,13 +58,43 @@ def build_parser() -> argparse.ArgumentParser:
5458
"study.yaml): writes report.html and tables.xlsx there and opens the page; "
5559
"runs nothing")
5660
p.add_argument("--no-open", action="store_true", help="with --view: do not open the browser")
61+
p.add_argument("--log-level", choices=runlog.LEVELS, default="normal",
62+
help="how much a run prints: quiet (banner, failures, summary), normal, or "
63+
"verbose (every search iteration); the files always have everything")
64+
p.add_argument("--heartbeat", type=float, default=60.0, metavar="SECONDS",
65+
help="seconds between heartbeats (status.json and the run log; the terminal "
66+
"block at `normal` comes every 15 min, at `verbose` every heartbeat)")
67+
p.add_argument("--status", nargs="?", const="", default=None, metavar="FOLDER",
68+
help="print what a running (or the last) study in FOLDER is doing, from "
69+
"another terminal (default: output_dir/run_name of study.yaml); runs and "
70+
"writes nothing; exit 2 when there is no status")
5771
return p
5872

5973

6074
def main(argv: Sequence[str] | None = None) -> int:
6175
parser = build_parser()
6276
args = parser.parse_args(argv)
6377
config = Path(args.config)
78+
if args.heartbeat <= 0:
79+
parser.error("--heartbeat must be a positive number of seconds")
80+
if args.status is not None:
81+
clash = [f for f, on in (("--only", args.only), ("--force", args.force),
82+
("--verify", args.verify), ("--check", args.check),
83+
("--fresh-cache", args.fresh_cache),
84+
("--view", args.view is not None), ("--serial", args.serial),
85+
("--workers", args.workers)) if on]
86+
if clash:
87+
parser.error(f"--status only reads a running or finished study; it cannot be "
88+
f"combined with {', '.join(clash)}")
89+
from sagetrans.io.view import default_folder
90+
91+
folder = Path(args.status) if args.status else default_folder(config, args.out)
92+
lines = runlog.read_status(folder)
93+
if lines is None:
94+
print(f"no status in {folder}")
95+
return EXIT_INPUTS
96+
print("\n".join(lines))
97+
return EXIT_OK
6498
if args.view is not None:
6599
clash = [f for f, on in (("--only", args.only), ("--force", args.force),
66100
("--verify", args.verify), ("--check", args.check),
@@ -95,17 +129,19 @@ def main(argv: Sequence[str] | None = None) -> int:
95129
outcome = run_study(
96130
config, mode=args.mode, only=only, force=args.force, fresh_cache=args.fresh_cache,
97131
workers=1 if args.serial else args.workers, out_dir=args.out, junit=args.junit,
98-
verify=args.verify,
132+
verify=args.verify, log_level=args.log_level, heartbeat=args.heartbeat,
99133
) # fmt: skip
100134
for m in outcome.messages:
101-
print(m, file=sys.stderr)
135+
print(runlog.ascii_line(m), file=sys.stderr)
102136
if outcome.folder is not None:
103-
print(f"\nresults: {outcome.folder}")
104-
print(f" report: {outcome.folder / 'report.md'}")
105-
print(f" run record: {outcome.folder / 'run_record.json'} [{outcome.label}]")
137+
out = [f"\nresults: {outcome.folder}",
138+
f" report: {outcome.folder / 'report.md'}",
139+
f" run record: {outcome.folder / 'run_record.json'} [{outcome.label}]"]
106140
if outcome.gate is not None:
107-
print(outcome.gate.summary())
108-
print(f"done in {outcome.seconds / 60:.1f} min")
141+
out.append(outcome.gate.summary())
142+
out.append(f"done in {outcome.seconds / 60:.1f} min")
143+
for line in out:
144+
print(runlog.ascii_line(line))
109145
return outcome.exit_code
110146

111147

0 commit comments

Comments
 (0)