---
{
  "n": 14,
  "title": "A command's budget row records the work it leaves running after it answers",
  "abstract": "",
  "refs": [
    "todo:33"
  ],
  "seen": [
    "agent",
    "system"
  ],
  "data": {
    "todo": 33,
    "changed": [
      {
        "path": "src/commands/dispatch.py",
        "added": 6,
        "removed": 4,
        "created": false
      },
      {
        "path": "src/engine/events/engine.py",
        "added": 2,
        "removed": 0,
        "created": false
      },
      {
        "path": "src/engine/timing.py",
        "added": 19,
        "removed": 2,
        "created": false
      },
      {
        "path": "src/features/dev_faults/test.py",
        "added": 6,
        "removed": 0,
        "created": false
      }
    ],
    "commits": [],
    "logged": 1791707525.6343
  },
  "created": 1791707457.405001,
  "updated": 1791707540.532725,
  "deleted": 0.0,
  "completed": 1791707540.5320451,
  "outcome": "4286 done, a2706d368",
  "type": "work"
}
---
Found while measuring to-do 3981, and now traced to its source in src/commands/dispatch.py timed().

WHAT THE AFTER TIME ACTUALLY IS, since I guessed wrong twice tonight and told two agents so. timed() wraps the reply's after-chain: it starts a clock when the chain BEGINS RUNNING, runs it, and announces that duration. So the after time is real work, measured from when it started, and it is NOT a queue wait. Nor is it the spool drain: the hook's own after is bus.background('spool', drain), which starts a thread and returns at once. What it measures is the COMPOSED after-chain - dispatch.later() lets any feature append work to a reply's after - so the median 599ms and p90 9218ms on hooks is whatever the features defer, and naming it is the next measurement anyone should take.

WHY A COMMAND ROW SHOWS ZERO. A command announced through timing.measured() is a context manager around the call itself and passes no after at all; timing.reported() passes 0.0 outright. A command run through POST /api/run is measured twice - once as the inner command, once as the whole request including the after-chain - which is why transportklok saw two notices for one ticket merge disagreeing on working time, one saying 175ms and one 0ms. They are not in disagreement; they are measuring different spans and neither says so.

The fix is therefore not to copy the after time onto the command row: the command has finished before the chain runs and cannot know it. Give each measured call an id and have the inner command carry the outer request's, so a reader joins them instead of guessing, and say on each row which span it measures.

## 1 · 2026-10-11 08:32 UTC
4286: request number and within on the timing event, budget.jsonl rows and briefs say which span they measure