diff --git a/core/node_timing.py b/core/node_timing.py index c13bd9d4..376e1f4a 100644 --- a/core/node_timing.py +++ b/core/node_timing.py @@ -44,14 +44,12 @@ def observe(event, data, now=None): def _steps(run, now): """The sampler's own step times, once its node is over: how long until step 1 was done (loading and - first-call setup included), how long step 2 took, and what the later steps average.""" + first-call setup included), then how long each later step took.""" marks, run["marks"] = run.get("marks") or [], [] if len(marks) < STEPS: return - first, second = marks[0] - run["at"], marks[1] - marks[0] - rest = (marks[-1] - marks[1]) / (len(marks) - 2) - log.info("FunUI Timing", f"{run['node']}: step 1 done {first:.1f}s after the node started, step 2 took " - f"{second:.1f}s, the {len(marks) - 2} after that average {rest:.1f}s") + later = ", ".join(f"step {i + 1} {marks[i] - marks[i - 1]:.1f}s" for i in range(1, len(marks))) + log.info("FunUI Timing", f"{run['node']}: step 1 done {marks[0] - run['at']:.1f}s after the node started; {later}") def install(server): diff --git a/core/tests/test_node_timing.py b/core/tests/test_node_timing.py index 0f9c64b7..7665db83 100644 --- a/core/tests/test_node_timing.py +++ b/core/tests/test_node_timing.py @@ -22,7 +22,7 @@ def test_a_run_is_split_by_node_and_logged_once_at_the_end(): assert seen == ["status"], "messages still go out" -def test_a_sampler_reports_its_first_steps_apart_from_the_rest(): +def test_a_sampler_reports_step_one_from_the_node_start_and_every_later_step(): log._reset() obs = node_timing.observe obs("execution_start", {"prompt_id": "p"}, now=0.0) @@ -31,5 +31,5 @@ def test_a_sampler_reports_its_first_steps_apart_from_the_rest(): obs("progress", {"prompt_id": "p", "value": i + 1, "max": 4}, now=at) obs("execution_success", {"prompt_id": "p"}, now=38.0) lines = [r["message"] for r in log.history() if r["source"] == "FunUI Timing"] - assert lines[0] == "sampler: step 1 done 30.0s after the node started, step 2 took 2.0s, the 2 after that average 2.0s" + assert lines[0] == "sampler: step 1 done 30.0s after the node started; step 2 2.0s, step 3 2.0s, step 4 2.0s" assert len(lines) == 2, "the per-node total still follows"