feat(trace): add JSONL timing traces to helix evolve

CHANGELOG.md

@@ -7,6 +7,13 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 
 ## [Unreleased]
 
+### Added
+- `helix evolve --trace PATH` / `helix resume --trace PATH` (or `HELIX_TRACE=PATH`)
+  append a JSON Lines timing trace of the run: `start`/`end` records for
+  every `run`, `proposal`, `evaluate`, `validate`, `agent`, and `seed` span,
+  with `duration_seconds`, `outcome`, and candidate identity.  A trace whose
+  last line is not the `run` span's `end` record was cut short.
+
 ### Changed
 - **BREAKING**: Removed the `evaluator.score_parser` configuration field. The built-in
   `helix_result` parser is now implicit; configurations that still provide the

README.md

@@ -803,6 +803,43 @@ stderr as fallback debug context.
 --backend BACKEND   Override the mutation backend [claude|codex|cursor|gemini|opencode]
 --model TEXT        Override the backend model (backend-specific naming)
 --effort LEVEL      Reasoning effort: low | medium | high | xhigh | max
+--trace PATH        Append a JSONL timing trace of the run to PATH (off by default)
+```
+
+#### Tracing a run
+
+`--trace PATH` (on `helix evolve` and `helix resume`, or `HELIX_TRACE=PATH` in
+the environment) appends a JSON Lines timing trace: one object per line,
+flushed as it is written, so a killed run leaves every record it completed.
+Each traced operation is a *span* with a `start` and an `end` record:
+
+```json
+{"event": "start", "span": "evaluate", "span_id": 7, "wall_time": 1757400000.1, "monotonic": 1234.5, "thread_id": 6199, "attrs": {"candidate_id": "g1-s2", "split": "train", "evaluation_phase": null}}
+{"event": "end",   "span": "evaluate", "span_id": 7, "wall_time": 1757400012.3, "monotonic": 1246.7, "thread_id": 6199, "attrs": {...}, "duration_seconds": 12.2, "outcome": "ok"}
+```
+
+`wall_time` is Unix epoch seconds (for lining up with external logs);
+`monotonic` never jumps backwards, and `duration_seconds` is the difference
+between a span's two `monotonic` values.  `outcome` is `"ok"` or `"error"`;
+on error `error_type` names the exception class (never its message, so a
+trace is safe to attach to an issue).  Match `start` to `end` on `span_id`
+— proposals run concurrently, so records from different threads interleave.
+
+| span | one call of | measures |
+| --- | --- | --- |
+| `run` | `run_evolution` | the whole run; its `end` is always the last line |
+| `proposal` | `_run_proposal_worker` | one proposal slot: parent eval, mutation, child eval |
+| `evaluate` | `run_evaluator` | one evaluator invocation (`attrs.split`) |
+| `validate` | `_run_full_val_eval` | one sequential full-validation stage |
+| `agent` | `invoke_claude_code` | one agent-backend call — inside a `proposal` it is a mutation, inside a `seed` it is seed generation, otherwise a merge |
+| `seed` | `generate_seed` | seedless-mode seed generation |
+
+A trace is complete only if its last line is `{"event": "end", "span": "run", ...}`;
+anything else means the process died mid-run and later spans are missing.
+Per-generation wall time, from the `proposal` spans' `attrs.generation`:
+
+```console
+$ jq -s 'map(select(.event=="end" and .span=="proposal")) | group_by(.attrs.generation) | map({gen: .[0].attrs.generation, seconds: (map(.duration_seconds) | add)})' .helix/trace.jsonl
 ```
 
 ---

src/helix/cli.py

@@ -30,10 +30,28 @@
 from helix.lineage import load_lineage
 from helix.population import EvalResult, FrontierType, ParetoFrontier, Candidate
 from helix.state import load_state, save_state
+from helix.trace import enable as enable_trace
 from helix.worktree import remove_worktree
 
 logger = logging.getLogger(__name__)
 
+_trace_option = click.option(
+    "--trace",
+    "trace_path",
+    default=None,
+    type=click.Path(dir_okay=False, path_type=Path),
+    help="Append a JSONL timing trace of the run to this path (or set HELIX_TRACE).",
+)
+
+
+def _enable_trace(trace_path: Path | None) -> None:
+    """Start the span trace before evolution; an unopenable path fails loudly."""
+    try:
+        enable_trace(trace_path)
+    except OSError as exc:
+        print_error(f"Cannot open trace file: {exc}")
+        raise SystemExit(2)
+
 
 # ---------------------------------------------------------------------------
 # Helpers
@@ -603,6 +621,7 @@ def sandbox_logout(
         "that does not support it)."
     ),
 )
+@_trace_option
 def evolve(
     config_path: str,
     project_dir: Path | None,
@@ -613,6 +632,7 @@ def evolve(
     backend: str | None,
     model: str | None,
     effort: str | None,
+    trace_path: Path | None,
 ) -> None:
     from helix.evolution import run_evolution
 
@@ -675,6 +695,7 @@ def evolve(
 
     base_dir = _helix_dir(project_root)
     setup_file_logging(base_dir)
+    _enable_trace(trace_path)
     try:
         run_evolution(config, project_root, base_dir)
     except ResumeIncompatibleError as exc:
@@ -1171,7 +1192,10 @@ def attempts_cmd(
     type=click.Path(exists=True, file_okay=False, path_type=Path),
     help="Project root directory (defaults to current working directory).",
 )
-def resume(config_path: str, project_dir: Path | None) -> None:
+@_trace_option
+def resume(
+    config_path: str, project_dir: Path | None, trace_path: Path | None
+) -> None:
     """Resume from the last completed generation of an evolution run.
 
     In-flight proposal batches are reconciled rather than resumed slot-by-slot.
@@ -1222,6 +1246,7 @@ def resume(config_path: str, project_dir: Path | None) -> None:
         raise SystemExit(1)
 
     print_info(f"Resuming from generation {state.generation if state else 0}…")
+    _enable_trace(trace_path)
     try:
         run_evolution(config, project_root, base_dir)
     except ResumeIncompatibleError as exc:

src/helix/evolution.py

@@ -88,7 +88,7 @@
     save_eval_cache,
     save_state,
 )
-from helix.trace import TRACE, EventType
+from helix.trace import TRACE, EventType, traced
 from helix.worktree import (
     create_seed_worktree,
     create_empty_seed_worktree,
@@ -1049,6 +1049,7 @@ def _evaluator(
     return merged, num_actual_evals
 
 
+@traced("validate")
 def _run_full_val_eval(
     candidate: Candidate,
     state: EvolutionState,
@@ -1446,6 +1447,7 @@ def _plan_proposals(
 # upstream's ``ReflectiveMutationProposer.propose``, though upstream
 # batches these stages across all sampled tasks per iteration instead
 # of running one call per proposal slot.
+@traced("proposal")
 def _run_proposal_worker(
     pre_ctx: ProposalContext,
     *,
@@ -1695,6 +1697,7 @@ def _dispatch_proposals(
     return worker_results
 
 
+@traced("run")
 def run_evolution(
     config: HelixConfig,
     project_root: Path,

src/helix/executor.py

@@ -23,7 +23,7 @@
     current_evaluator_sidecar_runtime,
     run_sandboxed_commands,
 )
-from helix.trace import TRACE, EventType
+from helix.trace import TRACE, EventType, traced
 
 logger = logging.getLogger(__name__)
 
@@ -182,6 +182,7 @@ def _collect_asi(
     return asi
 
 
+@traced("evaluate")
 def run_evaluator(
     candidate: Candidate,
     config: HelixConfig,

src/helix/mutator.py

@@ -22,6 +22,7 @@
 )
 from helix.executor import _scrub_environment
 from helix.sandbox import resolve_sandbox_image, run_sandboxed_command
+from helix.trace import traced
 from helix.worktree import clone_candidate, snapshot_candidate, remove_worktree  # noqa: F401
 
 logger = logging.getLogger(__name__)
@@ -291,6 +292,7 @@ def build_seed_generation_prompt(
     )
 
 
+@traced("seed")
 def generate_seed(
     worktree_path: str,
     prompt: str,
@@ -1547,6 +1549,7 @@ def _write_backend_artifacts(
         )
 
 
+@traced("agent")
 def invoke_claude_code(
     worktree_path: str,
     prompt: str,

src/helix/trace.py

@@ -1,5 +1,9 @@
 """HELIX TraceBus — lightweight runtime event stream for differential testing.
 
+The second half of this module (``traced`` / ``enable``) is the JSONL timing
+trace behind ``helix evolve --trace PATH``; it shares nothing with the bus
+except this file.
+
 Zero overhead when disabled: ``TRACE.emit(...)`` short-circuits on a single
 attribute check (``self.enabled``) before building any event payload.
 
@@ -13,11 +17,20 @@
 """
 from __future__ import annotations
 
+import functools
 import inspect
+import itertools
+import json
+import logging
+import os
+import threading
+import time
 from contextlib import contextmanager
 from dataclasses import dataclass
 from enum import Enum
-from typing import Any, Iterator
+from typing import Any, Callable, Iterator, ParamSpec, TextIO, TypeVar
+
+logger = logging.getLogger(__name__)
 
 
 class EventType(str, Enum):
@@ -99,3 +112,142 @@ def record(self) -> Iterator[list[Event]]:
 
 
 TRACE = TraceBus()
+
+
+# ---------------------------------------------------------------------------
+# JSONL timing spans — ``helix evolve --trace PATH`` / ``HELIX_TRACE=PATH``
+# ---------------------------------------------------------------------------
+#
+# One JSON object per line, appended and flushed per record.  A span is one
+# whole decorated function call: a ``start`` record on entry, an ``end``
+# record on exit carrying ``duration_seconds`` and ``outcome``.  The last
+# line of a complete trace is the ``end`` record of the ``run`` span; a
+# file whose last line is anything else was cut short.
+
+P = ParamSpec("P")
+R = TypeVar("R")
+AttrsFn = Callable[[tuple[Any, ...], dict[str, Any]], dict[str, Any]]
+
+_enabled = False
+_sink: TextIO | None = None
+_sink_lock = threading.Lock()
+_span_ids = itertools.count(1)
+_sink_failed = False
+
+# Cheap identity attrs per span, keyed by span name.  Each receives the
+# decorated call's ``(args, kwargs)``; anything it raises is dropped.
+_ATTRS: dict[str, AttrsFn] = {
+    "evaluate": lambda a, k: {
+        "candidate_id": a[0].id,
+        "split": k.get("split", a[2] if len(a) > 2 else "val"),
+        "evaluation_phase": k.get("evaluation_phase"),
+    },
+    "validate": lambda a, k: {"candidate_id": a[0].id},
+    "proposal": lambda a, k: {"candidate_id": a[0][3], "generation": k.get("gen")},
+    "agent": lambda a, k: {"prompt_artifact": k.get("prompt_artifact_name")},
+}
+
+
+def enable(path: str | os.PathLike[str] | None = None) -> bool:
+    """Open *path* (or ``$HELIX_TRACE``) for appending and turn spans on.
+
+    Returns whether tracing is now enabled.  Raises ``OSError`` when the
+    file cannot be opened, so the caller can fail loudly up front rather
+    than run untraced by accident.
+    """
+    global _enabled, _sink, _sink_failed
+    target = path if path is not None else os.environ.get("HELIX_TRACE")
+    if not target:
+        return False
+    with _sink_lock:
+        if _sink is not None:
+            _sink.close()
+        _sink = open(target, "a", encoding="utf-8")
+        _sink_failed = False
+        _enabled = True
+    return True
+
+
+def disable() -> None:
+    """Turn spans off and close the sink (tests; not needed at process exit)."""
+    global _enabled, _sink
+    with _sink_lock:
+        _enabled = False
+        if _sink is not None:
+            _sink.close()
+            _sink = None
+
+
+def _write(record: dict[str, Any]) -> None:
+    """Append one record; a failing sink is reported once and never raises."""
+    global _sink_failed
+    try:
+        line = json.dumps(record, default=str)
+        with _sink_lock:
+            if _sink is not None:
+                _sink.write(line + "\n")
+                _sink.flush()
+    except Exception as exc:
+        if not _sink_failed:
+            _sink_failed = True
+            logger.error("Trace unavailable: %s: %s", type(exc).__name__, exc)
+
+
+def traced(
+    span: str, attrs: AttrsFn | None = None
+) -> Callable[[Callable[P, R]], Callable[P, R]]:
+    """Record a ``start``/``end`` span around every call of the decorated function.
+
+    Signature-preserving passthrough (``functools.wraps``); when tracing is
+    disabled the only cost is one global check.  An exception raised by the
+    wrapped function is classified (``outcome="error"``, ``error_type``)
+    and re-raised untouched — ``KeyboardInterrupt`` included — and a broken
+    sink can never mask it.
+    """
+    extract = attrs if attrs is not None else _ATTRS.get(span)
+
+    def decorate(fn: Callable[P, R]) -> Callable[P, R]:
+        @functools.wraps(fn)
+        def wrapper(*args: P.args, **kwargs: P.kwargs) -> R:
+            if not _enabled:
+                return fn(*args, **kwargs)
+            span_id = next(_span_ids)
+            extracted: dict[str, Any] = {}
+            if extract is not None:
+                try:
+                    extracted = extract(args, kwargs)
+                except Exception:
+                    pass
+            started = time.monotonic()
+            record: dict[str, Any] = {
+                "event": "start",
+                "span": span,
+                "span_id": span_id,
+                "wall_time": time.time(),
+                "monotonic": started,
+                "thread_id": threading.get_ident(),
+                "attrs": extracted,
+            }
+            _write(record)
+            outcome, error_type = "ok", None
+            try:
+                return fn(*args, **kwargs)
+            except BaseException as exc:
+                outcome, error_type = "error", type(exc).__name__
+                raise
+            finally:
+                now = time.monotonic()
+                record.update(
+                    event="end",
+                    wall_time=time.time(),
+                    monotonic=now,
+                    duration_seconds=now - started,
+                    outcome=outcome,
+                )
+                if error_type is not None:
+                    record["error_type"] = error_type
+                _write(record)
+
+        return wrapper
+
+    return decorate