3,418 Tool Calls, One Week, One Boring Lesson: Where My OpenClaw Agent's Time Actually Went

I instrumented every tool call on my OpenClaw agent for one full week. Across 3,418 calls spanning 41 crons and 9 sub-agents, I expected to find a hot loop or a runaway retry storm. Instead I found something more boring and more useful: my agent was spending 38% of its wall time on six tools I'd written months ago and never re-evaluated. This post is what I logged, what I learned, and the 12-line wrapper you can drop in tonight.

The instrument: 12 lines, one file, zero framework changes

I almost reached for OpenTelemetry. Then I remembered I run an OpenClaw agent with maybe nine concurrent cron jobs, not a microservice mesh. I needed log lines, not spans. So I wrote this:

# telemetry.py — wraps any OpenClaw tool call with structured logging
import json, time, os, hashlib
from datetime import datetime, timezone

LOG = os.path.expanduser("~/.openclaw/logs/agent-tools.jsonl")

def wrap(tool_name, fn):
    def inner(*args, **kwargs):
        t0 = time.monotonic()
        err = None
        try:
            result = fn(*args, **kwargs)
            return result
        except Exception as e:
            err = f"{type(e).__name__}: {e}"
            raise
        finally:
            rec = {
                "ts": datetime.now(timezone.utc).isoformat(),
                "tool": tool_name,
                "args_hash": hashlib.sha256(repr((args, kwargs)).encode()).hexdigest()[:12],
                "wall_ms": int((time.monotonic() - t0) * 1000),
                "ok": err is None,
                "err": err,
                "pid": os.getpid(),
                "ppid": os.getppid(),
            }
            with open(LOG, "a") as f:
                f.write(json.dumps(rec) + "\n")
    return inner

Then in each tool module:

from telemetry import wrap
import my_tool

my_tool.run = wrap("my_tool.run", my_tool.run)

That's it. Two lines per tool. After seven days I had a 1.1 GB newline-delimited JSON file with one record per call. No external services. No new dependencies. The wrapper costs roughly 0.4 ms per call — well under the noise floor for any tool that talks to a network.

What the logs actually said

Once the JSONL file existed, the rest of the week was jq and a small notebook. Three findings jumped out.

Finding 1: 38% of wall time lived in six forgotten tools

I sorted by total wall_ms summed across the week. The top six tools — three filesystem walkers, two JSON pretty-printers, one regex-based date parser I wrote in March — consumed 38% of all wall time. None of them were on any critical path. Two were called by a single daily cron that ran every 6 hours "just in case." I had been paying the latency tax for months because the calls were quiet and slow rather than loud and broken.

The fix wasn't clever. I either cached the result (filesystem walker → run once per hour, not every call) or replaced them with pathlib / datetime.fromisoformat / stdlib equivalents. After the rewrite, the same workload ran 24% faster end-to-end with no functional change.

Finding 2: 11% of calls were retries of identical work

Because the wrapper hashes (args, kwargs) with SHA-256, I could count duplicate args_hash values inside a 60-second window. Result: 376 calls in one week were retries of an identical tool call that already succeeded within the last minute. Most came from one cron that ran twice in parallel when a heartbeat drifted. The second invocation re-read every file the first one had just written.

I added a one-line if recent_cache.has(args_hash): return recent_cache.get(args_hash) check before each tool body. The retry storms stopped. Wall time dropped another 9%.

Finding 3: Three "fast" tools were actually slow when they failed

This was the surprise. The p99 wall time on three tools — all of them marked "fast" in my head — was 47× the median. When they failed, they hung on a 30-second socket timeout that I had never configured explicitly. So the tools weren't slow. They were occasionally slow, in a way that dragged down any cron that depended on them.

I added per-tool timeout configuration and a circuit breaker that skips the call after three consecutive timeouts within five minutes:

def wrap(tool_name, fn, timeout_s=10, breaker_threshold=3):
    state = {"fails": 0, "open_until": 0}
    def inner(*args, **kwargs):
        if time.monotonic() < state["open_until"]:
            raise CircuitOpen(f"{tool_name} breaker open")
        # ... existing timing/error logic ...
        if err:
            state["fails"] += 1
            if state["fails"] >= breaker_threshold:
                state["open_until"] = time.monotonic() + 300
    return inner

After this, the worst-case wall time for any cron dropped from 47× median to a clean 2.1× median. The crons that used to occasionally time out at the parent level stopped doing that.

What the logs did not say (and what I had to add)

Two things I missed in the first 24 hours and had to instrument later.

Sub-agent fan-out cost. When a cron spawned a sub-agent, the wrapper caught the tool calls the sub-agent made, but not the wall time between the spawn and the sub-agent's first response. That gap was enormous — sometimes 4–8 seconds of pure round-trip with zero tool activity. I added a subagent_spawn wrapper that records t0 at spawn and wall_ms at first tool call from the child PID. After a week of that data, the median "time to first useful work" for a sub-agent was 3.1 seconds. Most of that was model cold-start. I now batch sub-agent spawns.

Cache hits that look like misses. Two of my tools call an LLM with a prompt that varies by maybe 5% per call (timestamps, a fresh file path). The args_hash was different every time, so I never saw them as duplicates. I added a prompt_normalize step that strips volatile substrings before hashing. Suddenly the retry-detection graph lit up: 22% of LLM calls were near-duplicates I could have deduplicated by a similarity threshold instead of exact match.

What I'd do differently if I started over

Three things.

1. Log to stdout and a file. I used a file because I assumed I'd batch-process it nightly. In practice, I wanted to tail -f it during debugging. Now I tee to both.
2. Hash (args, kwargs) after a normalization step, not before. Exact-match dedupe catches 11% of retries. Normalized dedupe catches another 22% on LLM prompts specifically.
3. Record caller automatically. OpenClaw tools can be invoked from a cron, a sub-agent, or the main session. Knowing who called a tool changes the entire interpretation. I ended up adding a thread-local current_caller set by the dispatcher. Took 20 minutes, saved hours of forensic work.

The 12-line wrapper is not the lesson

The wrapper is trivial. The lesson is that I had been operating my OpenClaw agent for months on the assumption that the slow tools were the ones I could feel (the LLM calls, the network requests) and the fast tools were the ones I could ignore. The logs said the opposite. The expensive tools were the boring ones, the retries were hiding in identical-looking calls, and the slow paths were the failure paths, not the happy paths.

If you run any agent long enough to forget which tools you wrote, instrument it for a week. You don't need a framework. You don't need a vendor. You need time.monotonic(), json.dumps, and the willingness to look at 1.1 GB of your own logs on a Saturday morning.

The boring stuff is where the time goes.