Cutting Claude Code's first response from 16 seconds to 10 and freezes to zero — taking four kinds of waste apart with a profiler

AI Claude Code RAG プロファイリング パフォーマンスチューニング Operations 検証

Introduction

My personal AI coding assistant has a mechanism built into it that I have written about here before. It catches every conversational input and automatically inserts past records likely to bear on the current topic — an “activation layer”.

Injecting ‘What to Recall Right Now’ into AI Every Turn — An Activation Layer for Personal RAG

Useful, but it is also a checkpoint the AI passes through, without fail, before it starts writing a response. Any waste at that checkpoint comes straight back as slowness in the first response.

Using it for a while, I noticed two different symptoms. One was a gentle sense that things were “somehow slow”. The other was of a different kind: nothing coming back at all, minutes after sending, with even the stop control unresponsive. This article is the record of not lumping the latter under the single word “slow”, but taking the breakdown with a profiler, splitting it into four concrete causes, and closing them with measurements.


Turning “slow” into something measurable

Chase a felt sense of “slow” as it stands and you can detour anywhere. In fact my first investigation detoured into measuring “the time the AI spends presenting options for confirmation and waiting for a human reply”. That is time spent waiting on a human, not slowness in the assistant itself.

The moment I noticed the detour, I narrowed the metric back down to one.

A-2: the number of seconds from the user sending input to the AI’s first output coming back (median).

I fixed how it is measured, too. Scan the session records (logs in JSON Lines format) and take the difference from the timestamp of a “user utterance” record to the timestamp of the immediately following “assistant response” record. Anything over 600 seconds may mean the person stepped away, so it is excluded from the ordinary median and counted separately.

Having fixed that definition first, I wrote a checklist of “what has to be true before this counts as solved”. Taking the after measurement is part of the same set — a promise to myself, so that I could verify my own claim later rather than stopping at “it should have improved”.


Taking the breakdown — the profiler’s output

With the metric settled, the next job was measuring what was eating the 16 seconds. I ran Python’s standard profiler (cProfile) over the search processing itself and took the cumulative-time breakdown. One call after warm-up came to about 34.8 seconds in total.

SectionCumulative time (one call under the profiler)Share
Query to the relevance critic22.27 s64%
Re-ranking of search results (diversification)9.29 s27%
Embedding computation (of which connection setup 2.042 s)2.08 s6%
Score computation0.82 s2%

Every number in this table is the value for one call with the profiler attached. The “27.399 seconds” that appears later is a different measurement of the same processing (a dedicated benchmark with the item count fixed at 120), under different conditions, so the two are not directly comparable. When the same process name comes back with a different number of seconds, first suspect that the measurement conditions differ.

The “relevance critic” is a small model that narrows what search retrieves down to what is actually relevant; I have written about that before as well.

Placing a Small Relevance Critic in Front of RAG — Not Passing Along Everything Retrieved

The “re-ranking of search results (diversification)” is the processing (MMR) that reorders results so that near-identical records do not fill the top; the search build-out itself follows on from the measurement-driven tuning I wrote about in another article.

A RAG with only vector search “forgets when it matters most” — taking recall from 0.2 to 1.0 with hybrid search + measurement

Drawing that breakdown out shows what was actually being waited on before the first response.

user sends


[the checkpoint every turn passes through (the activation-layer hook)]

      ├─▶ starting the search client
      │     import                       2.409 s
      │     creating the HTTP client     1.337 s
      │       └─ of which loading SSL certificates alone 0.958 s ◀── unnecessary: the traffic is plaintext HTTP
      │     (about 3.7 s per turn in total)

      ├─▶ re-ranking of search results (diversification, MMR)
      │     the reordering                9.29 s ◀── the implementation scaled with the square of the item count
      │       └─ in the dedicated measurement with the count fixed at 120: 27.399 s (a different number, different conditions)

      ├─▶ query to the relevance critic
      │     consumes 22–60 s even when startup fails, unnoticed ◀── 64% of the cProfile breakdown
      │        └── on detecting two consecutive failures, open the circuit and pass straight through from then on
      │              └────────────── retry exactly once after 1,800 s ─────┘


the AI's first output

The vertical flow is “from send to first response”, the horizontal branches are “the four kinds of waste acting in parallel inside the checkpoint”, and the nesting at the bottom is the loop that “detects the critic’s failure and bypasses it from then on”.


The four kinds of waste found, and what they became

All four were closed one at a time, on the evidence of the breakdown numbers.

#What was donebeforeafter
1Replaced the re-ranking (diversification) with an implementation using a matrix library (numpy)27.399 s (dedicated measurement with input fixed at 120 items)0.009 s (same 120 items, same conditions; all 15 cross-checks against the old implementation agreed)
2Pinned the embedding server address from localhost to 127.0.0.12.042 s for connection setup aloneclose to 0
3Implemented a circuit breaker on the relevance critic22–60 s consumed unnoticed on every startup failuretwo consecutive failures open the circuit and it passes straight through from then on (one retry after 1,800 seconds)
4Changed the way the checkpoint hook creates a search client, to a lightweight implementation speaking HTTP directly with the standard libraryimport 2.409 s + client creation 1.337 s (of which SSL-certificate loading alone 0.958 s) = about 3.7 s per turnabout 3.1 s saved per turn

Cause 2, “pin the address”, is unglamorous but has a reason. Resolve the name localhost and, in some environments, a connection to an IPv6 address is tried first and fails, costing the wait until it falls back to IPv4. Skip name resolution and specify the address to use directly from the start, and that wait disappears entirely.

The SSL-certificate loading in cause 4 is less waste in itself than “diligently doing processing that was never needed”. Traffic with the search server is plaintext HTTP, unencrypted. Even so, because a general-purpose client library was in use, a full set of TLS certificates was being loaded every time. It was like carrying around a keyring you never use.

Two of the four were changes that swapped an implementation out for something else entirely. In both cases I confirmed first that the new one returned the same inputs and outputs as the old before switching. #1 (the numpy re-ranking) came to 15 checks — agreement of ordering confirmed at four different item counts, plus boundary conditions lined up: the empty list, a single item, all vectors identical (ties), the zero vector, and negative correlation. #4 (the swap to the lightweight client) came to 24 checks — confirming that the embedding values match the old implementation exactly (maximum absolute difference 0) and that the classification results agree for both normal and abnormal cases. The more a change is meant to improve a number, the more it needs confirming that it broke nothing before it goes in.


The day the effect refused to show, after I had supposedly closed them

On the day I put in the first two of the four (the faster re-ranking and the pinned address), I re-measured the A-2 metric. Over the previous two weeks, 13 days of ordinary operation (n=680), the median was 16.04 seconds. That day’s median was 15.85 seconds. Barely moved.

At a glance it looks like there was no effect. I was about to conclude “it isn’t working” — and instead went back and questioned the way I was measuring.


Changing the granularity of the aggregation overturned the conclusion

A daily median mixes “exchanges from before the fix went in” and “exchanges from after” into one average within the same day. I had been putting the four fixes in incrementally over that day, so a daily aggregate diluted the improvement until it was invisible.

So I re-cut the day at the times the fix commits actually went in, and re-measured A-2 per interval.

the day (one day of logs)
 00:00 ────────────────────────────────────────── 24:00
   │           │              │              │
 no fixes   #1・#2 in      #3 in         #4 in (all reflected)
(15.68 s)   01:31            09:22          14:07
              │                │              │
              ▼                ▼              ▼
           12.03 s          14.18 s       10.48 s ★

  "Looking only at the daily median" flattens these four intervals into
  one average (15.85 s), and the improvement disappears.
IntervalFixes reflectednmedianp75p90
Ordinary operation (13 days)none68016.04 s26.9341.10
That day 00:00–01:31none1415.68 s21.9731.05
That day 01:31–09:22#1, #2812.03 s15.9129.38
That day 09:22–14:07#1, #2, #33414.18 s22.0935.58
That day 14:07–all of #1–#41910.48 s11.6331.14

From 16.04 seconds in ordinary operation to 10.48 seconds in the interval where all four were in place: −35% on the median, and on p75 (the boundary of the slowest quarter) from 26.93 seconds to 11.63, −57%. That p75 falls further than the median shows the four fixes bit harder on “the cases that occasionally run badly late”.

And one more thing: I recounted the “complete non-responses over 600 seconds (10 minutes)” that I had excluded from the A-2 aggregate.

DayCount over 600 sMaximum
08-117828.0 s
08-122728.9 s
08-211612.5 s
08-223645.7 s
08-237971.3 s
That day0

The non-responses over ten minutes that had been happening almost daily for two weeks came to zero on the day the four fixes went in. The identity of “somehow slow” was mainly the waste inside this checkpoint; but for “stops completely”, one of them — diligently waiting out the relevance critic’s startup failure every time — was most likely the chief culprit.

That said, the interval on the day is small at n=19, and the sample is skewed toward one continuous stretch of work. The disappearance of the over-600-second cases is a single day’s observation. In fact, non-responses in an AI coding assistant have occurred through a route other than this checkpoint as well (waiting on child tasks launched in parallel, for instance), and these four fixes did not close that side. I can say it improved, but what I fixed is part of the inside of this checkpoint — that is the accurate statement, and the next time I go through the logs I need to raise n and confirm.


A by-product — the checking mechanism false-flagged itself

Separately from the four fixes, I made one more change. From a request — “mix-ups over connection port numbers and character encodings keep happening; build something that checks mechanically before execution” — I built a guard that cuts in immediately before a command runs and inspects where its values came from. This follows on from the “from advice to enforcement” idea I wrote about earlier.

Building a mechanism that makes an AI coding assistant “not do it” — from advice to enforcement, and the side-door left open in the gate itself

While building it out, I hit an unglamorous but interesting defect twice: the guard pulled itself into its own inspection scope.

the guard that inspects where values came from

   ├─▶ inspects the body of the command about to run
   │     └─ ends up inspecting the contents of the syntax that
   │         "passes the following lines through as data" (heredoc) as well
   │           └─ mistakes explanatory prose in a commit message written inside it
   │               for "code that will be executed", and stops ①

   └─▶ detects "values of unknown origin" by grepping the whole repository
         └─ ends up including the verification test code itself in scope
               └─ its own grep hits the "deliberately origin-less values for verification"
                   written in that test code, and treats the test as always failing ②

① was mistaking the contents of the multi-line data syntax for code that will be executed. What is being passed is not “instructions to be run” but “plain data handed to the shell”, so I excluded the contents of that syntax from the inspection scope. ② was that inside the test code written to confirm the guard’s correctness I had deliberately placed “origin-unknown” values, and the guard’s own grep hit that test code too, invalidating the test itself. I fixed it by excluding the directory the tests live in from the inspection scope.

Both have the same root: I had drawn the boundary between “the checker” and “the checked” purely by path and directory, without looking at the nature of the content (data or code, production or test). I rewrote 24 checks assuming adversarial input and confirmed they all pass in the environment as actually deployed before starting to use it (the same number, 24, as #4 above, but this is a separate set of tests specific to the guard, unrelated in content).


The part of the 16 seconds I have not measured

Even with the four kinds of waste closed, the first response sits in the ten-second range. It does not become zero. Taking just the search processing inside the checkpoint and measuring it, most calls in fact finish in a few seconds.

search processing alone, measured (5 runs, separate process)
import                2.02 s
run 1                 72.38 s   ← the first run, including loading the critic's model
run 2                 13.48 s
run 3                  4.83 s
run 4                  5.04 s
run 5                  3.99 s
median 5.04 s  min 3.99 s  max 72.38 s  mean 19.94 s

In the pre-fix history (256 measurements), the median for this search processing alone was 65.93 seconds, with p90 at 117.14. Read that far and it looks as though “the more you fix search, the faster it gets”; but line the measured first response (10.48 seconds) up against search alone (median 5.04 seconds) and the reading becomes that making search faster still would have only limited effect on the first response overall. Past the checkpoint, there is still a section I have not measured.

What to separate out next is the model-side processing time itself, up to the point where the response body starts being generated. Closing the four kinds of waste is what finally put me in a position to suspect the outside of the checkpoint.

Feel free to send a message

Job offers, project referrals, feedback, questions — anything is welcome. I sincerely hope to connect with people who share high ambitions. I will keep taking on the challenges I have staked my life on. Thank you very much.