The latency was in the serialiser (it usually is)

A tail-latency investigation that went through the network stack, the scheduler, and the garbage collector before finding the answer in the least interesting layer in the system.

The symptom was a p99.9 of 340 milliseconds against a p50 of four [1]. That ratio is the signature of something categorical rather than gradual — not a system under load, but a system doing an entirely different thing on a small fraction of requests. The investigation took nine days, and eight of them were spent in the wrong layer.

The wrong answers, in order#

Tail latency investigations have a standard suspect list, and there is a strong temptation to work through it in order of how interesting each suspect would be. This is precisely backwards [2], and it is worth writing down why each candidate looked right and was not.

1. Garbage collection. The pause histogram had a tail in roughly the right place. It was not correlated with the slow requests — collection was frequent enough that the overlap was coincidental, which took two days and a joint histogram to establish.
2. Scheduler preemption. Plausible on a busy host, and the involuntary context-switch counter was high. It was high on every request, including fast ones.
3. Head-of-line blocking. The connection pool was small enough to be suspicious. Enlarging it changed nothing except memory use.
4. DNS. It is never DNS, except when it is. It was not.

What eventually broke the investigation open [3] was giving up on hypotheses and taking a wall-clock profile of the slow requests specifically, rather than of the process as a whole. Aggregate profiles are actively misleading for tail problems: the slow path is by construction 0.1% of samples, and it disappears into the noise floor of the fast path.

# Filtered flame profile, slow requests only (n=1,284)
  87.2%  encode_response
    84.9%  serialise_field
      81.1%  reflect.TypeOf            <-- here
       2.4%  appendString
    1.8%   growSlice
   6.1%  write_socket
   4.3%  handler

What it actually was#

The serialiser cached type descriptors in a map keyed by reflected type. The cache was correct, fast, and had a lock. Under nearly all conditions the lock was uncontended and the whole thing cost nothing. But one response type was constructed dynamically, so it produced a fresh type identity on every request, so it never hit the cache, so every one of those requests took the slow path through reflection while holding the lock — and blocked every other serialisation on the host for the duration.

A cache with a 99.9% hit rate and a global lock is not a cache with a 99.9% hit rate. It is a lock with a 0.1% duty cycle.

The fix was four lines: give the dynamic type a stable identity so it caches like everything else. The p99.9 fell to eleven milliseconds. The p50 did not move, which is the tell — a genuine tail fix should be invisible in the median, and any change that improves both was probably measuring something else.

The transferable part#

Three things generalise. Profile the slow population, not the population. Suspect the boring layer before the interesting one, because the boring layer is where nobody has looked recently. And treat any lock held across a variable-cost operation as a latency amplifier by default — it converts one slow request into every concurrent request being slow, which is exactly the shape of a tail that appears from nowhere.