v1.8.3
Every tool a task hands the model now records how long it took, without its author doing anything.
Two documented rules are reversed to make that true, and both reversals have the same cause.
Fixed
-
duration_sexisted only where its author remembered, which is thesub_callfailure one
field over. Six of the kit's tool sources measured themselves; the filesystem and knowledge tools —
27record_tool_callsites acrossfs.py,edit.py,archive.pyandskills.py— did not. So
metrics.compute_tool_waste's*_secondsreadNonefor them everywhere, andToolWasteis
explicit thatNonemeans "nothing measured" rather than zero.A consumer could not fix it either. One whose
read_file/grep_repo/read_skillare
pure delegation to these factories has no seam of its own; wrapping the callable to add a
duration would emit a SECONDtool_calland doubletool_calls,tool_okand everything
derived from them. It was right to refuse, and the only place to fix it was here.RLMTask._build_rlmnow wraps every tool it hands the model — the same seam and the same reason
as 1.7.0's automaticsub_callwrapper. The wrapper publishes a start time and records nothing
itself, so it cannot double-count;record_tool_callfillsduration_sfrom it only when the
caller passed none. A tool that measures itself keeps its own figure, because it scopes the window
more tightly —fetch_urlstarts its clock after the SSRF check,run_commandkeeps a
runner-reported number alongside. A consumer's own tools are covered with no work.What it deliberately does not reach, each failing back to an absent field rather than a wrong
one. Adspy.ToolOBJECT is passed through untouched —mcp._make_toolreturns one, and it is a
pydantic model with no__name__, so wrapping it would leave the wrapper calledtimed: two MCP
tools would abort the task with "Duplicate tool name", one would register astimedwith its
args collapsed to{"kwargs": {}}. MCP records its own duration anyway. A coroutine function is
passed through too, because dspy branches oninspect.iscoroutinefunction, which does not follow
__wrapped__— deleting that one line turns a run that completes intoRLMTaskError: You are calling __call__ on an async tool. So are a callable class instance and afunctools.partial,
neither of whichfunctools.wrapscan wrap without changing what dspy registers. And a GENERATOR FUNCTION -- one whose body
contains ayield-- is wrapped like any other yet records nothing: calling it only builds the
generator object, and the wrapper releases the start time before the body, and the
record_tool_callinside it, ever runs. (A plain function that merely RETURNS a generator
expression is a different shape and is timed normally; the distinguishing word is function,
not returns.)Note the
dspy.Toolpassthrough is safe for MCP because MCP records its own duration; a
dspy.Toola CONSUMER builds does not, and must passduration_sitself.The fill is matched on the tool's name, and that is load-bearing. Only what the task hands
the model is wrapped, so a COMPOSITE tool — a consumer's tool calling a kit tool inside itself —
would otherwise charge its whole window to every event recorded beneath it. Measured before the
check existed: two zero-costread_filecalls inside a 0.25 s tool each reported 0.25 s, which
triplescompute_tool_waste.total_seconds. That is worse than theNoneit replaces —Noneis
an honest unknown, that was a confident wrong answer — so a mismatch fills nothing.Applied at the task seam rather than inside each factory, which is safe for the annotations
DESPITE the distance rather than because of it: everytools/*.pyuses
from __future__ import annotations, so the annotationsfunctools.wrapscopies are strings
that only resolve in the defining module — and they survive only becausetyping.get_type_hints
walks__wrapped__to find those globals. A factory-local wrapper would have resolved them
trivially; this one depends on a CPython behaviour, which is why it is tested rather than assumed.
Verified against dspy 3.3.1 on the 3.11 floor, where aToolconstruction failure would abort
registration for every tool on the task, not just the wrapped one.
Changed
-
A refused call now carries a duration. It used to record none, on the argument that a blocked
URL never touched the network so a ~0 would be noise.Nonemeans "nobody measured", so spending
it on "measured, and it was instant" makes the two indistinguishable — the mistake 1.7.0 shipped
a release to correct. The reversal is stated in the guide, inmake_fetch_tooland
make_web_search_tool, and in the test that used to pin the old rule. -
grep_filesis no longer exempt from timing, reopened by its own terms. Its exemption rested
on a measurement — n=146, median 0.029s, max 0.746s — and named "a pathological regex over a
large tree" as what would reopen it. Re-measured on a consumer deployment across nine real
repositories, 7 patterns x 3 runs each: median 744 ms, p95 4.8 s, max 6.3 s on a 2,110-file
repository. It does not scale with file count — a 102-file repo measured slower than a
1,210-file one — so the driver is bytes and match count. Against that corpus the tool alone is
about 40% of all sandbox execution time. The old number was not wrong; it was taken on a corpus
with no large repository in it. -
Do not average a
compute_tool_wastefigure across this upgrade. A tool that reportedNone
before reports a real number after, so a corpus spanning the boundary mixes "unmeasured" with
"measured" in the same denominator — the same warning the 1.7.0sub_callnote carries, and
run_start.rlm_harnessis what separates the cohorts.