Measure the Hop You Are About to Argue About

The best logging in this codebase exists to settle a specific argument before it turned into a rewrite.

Our chat reaches its tools by asking the provider to call them. So a single tool invocation crosses the public internet twice more than it needs to: browser → provider → us → provider → browser. There is an obvious architectural fix, and it is a week of work.

Nobody had measured the hop.

/**
 * Record how long this service takes to answer an MCP call.
 *
 * The number this exists to produce is not our own speed — it is the cost of
 * the hop. merchants can time the whole round-trip but cannot see how much of
 * it was us, so the two numbers only mean something together.
 *
 * suggest-options-tool and suggest-palettes-tool are the useful probes. They
 * perform no I/O at all — they validate their input and hand back a reshaped
 * copy — so whatever merchants observes for one of those iterations, minus
 * what we report here, is inference plus transport and nothing else.
 */

Three things make this a good instrument rather than a number.

It names a probe. Not "measure the tools" — measure these two, which do no I/O, so the subtraction isolates transport. Designing the measurement is most of the work.

It logs two clocks, and explains which to use:

// Time inside the handler. Small for every tool that does no I/O,
// which is exactly why it is not the number to subtract.
'duration_ms' => (int) round((hrtime(true) - $started) / 1_000_000),

// Time since the request entered PHP. This is the one to subtract from what
// merchants observed: middleware timing starts after the framework has
// booted, and locally that gap was 80ms against 2ms of actual work — so
// `duration_ms` alone would flatter us badly and make the hop look far more
// expensive than it is.
'request_ms' => defined('LARAVEL_START')
    ? (int) round((microtime(true) - LARAVEL_START) * 1000)
    : null,

Eighty milliseconds of framework boot against two milliseconds of work. Log only the handler time and you would conclude the hop costs eighty milliseconds more than it does — and then spend a week removing it on the strength of your own measurement error.

It separates your traffic from everyone else's:

// Distinguishes our own widget's traffic (which arrives via the provider's
// connector on a valid token) from third-party agents, whose latency profile
// is somebody else's network.
'via_token' => $request->bearerToken() !== null,

A public tool endpoint is called by people you have never met, over networks you cannot see. Mixing their latency into your percentiles produces a number that describes nobody.

The principle: measure before you rebuild. Guessing at that hop would have been a poor reason to rebuild the agent loop, and an equally poor reason not to.

Log the Question You Will Be Asked

Every field in this chapter exists because someone asked something specific.

Why is this slow? → duration_ms, request_ms, iterations. Why is this expensive? → the token counts, tool_count. Why did it stop there? → stop_reason, and the reported cap. Is prompt caching working? → cache_read_input_tokens. Is this our traffic? → via_token. Is it worth rebuilding the loop? → the probe.

Logging everything is not observability; it is a bill and a haystack. Write down the questions you expect to be asked about a feature you cannot reproduce, then log exactly the fields that answer them — and delete fields nobody has ever queried.

What This Chapter Argued

• Reproduction is unavailable. What you logged at the time is all you will ever have.
• Names and sizes, never inputs or results. Tool arguments are the user's own words.
• Log character counts instead of text to separate a long reply from a slow one without storing it.
• One structured line per round trip, carrying the iteration number, so a turn can be reconstructed.
• Design the probe, don't just add a timer. Pick the operations that do no I/O so a subtraction means something.
• Log two clocks and say which to subtract. Framework boot dwarfed the actual work and would have flattered the result.
• Separate your own traffic from third parties' before quoting a percentile.
• Measure before you rebuild. A guess is a bad reason to do a week of work, and an equally bad reason not to.