A 400ms Latency Spike That Turned Out to Be DNS

The alert was narrow, which is what made it interesting. One service, checkout-api. p99 request latency up from 120ms to 540ms. p50 completely unchanged at 38ms.

That shape matters. When p50 and p99 rise together, something is uniformly slower: more load, a slower dependency, CPU throttling. When p99 rises alone, most requests are fine and a small fraction are hitting something specific. You are looking for a conditional slow path, not general degradation.

What was fine

I checked the obvious dependencies first, in the order that costs least time.

The database. pg_stat_statements showed no change in mean or p99 execution time for any statement from this service. The connection pool had headroom.

Downstream HTTP services. The payment provider and the inventory service both reported normal latency from their side, and our client side timers agreed with them.

The node. No CPU throttling, with container_cpu_cfs_throttled_seconds_total flat. No memory pressure. No disk saturation.

Deploys. Nothing had shipped in four days. The spike started at 09:14 on a Tuesday with no corresponding change event.

So the service was slow and nothing it talked to was slow. Which usually means time is being spent somewhere nobody instrumented.

The flame graph pointed at nothing

We had continuous profiling, so I pulled a CPU profile from a slow pod and compared it against a healthy one.

Nearly identical. Same shape, same proportions, no new hot frames. Total CPU time per request had not moved.

That feels like a dead end and it is actually a strong signal. If latency went up and CPU did not, the time is being spent waiting rather than computing. A CPU profiler samples on CPU stacks, and a thread blocked in a syscall is invisible to it. The 400ms was off CPU time.

Which narrows things considerably. Off CPU waiting means a lock, disk I/O, or the network.

Getting an off CPU view

We did not have off CPU profiling set up. The quickest substitute was to look at what the process was actually doing at the syscall level, on a live pod, during a slow request.

kubectl debug -it checkout-api-7f9c-x2ktp --image=nicolaka/netshoot --target=api
strace -f -T -p 1 -e trace=network,poll 2>&1 | grep -v EAGAIN

The -T flag prints time spent in each syscall, which is the whole point. Within a few seconds:

sendto(31, "\27\3\3\0\34...", 60, 0, NULL, 0) = 60 <0.000042>
recvfrom(31, 0x7f2c1c0, 2048, 0, NULL, NULL) = -1 EAGAIN <0.000011>
poll([{fd=31, events=POLLIN}], 1, 5000) = 0 (Timeout) <5.000891>
sendto(31, "\27\3\3\0\34...", 60, 0, NULL, 0) = 60 <0.000038>
poll([{fd=31, events=POLLIN}], 1, 5000) = 1 <0.402118>
recvfrom(31, "\27\3\3\1\34...", 2048, 0, NULL, NULL) = 284 <0.000024>

A poll that times out after five seconds, a retransmit, then a response after 402 milliseconds.

Which socket is fd 31?

ls -l /proc/1/fd/31
# socket:[418822]
ss -anp | grep 418822
# udp UNCONN 0 0 10.244.3.17:54331 10.96.0.10:53

Port 53. UDP. To the cluster DNS service address.

DNS.

Why it was invisible

Nothing in our instrumentation covered name resolution. The HTTP client span started when the request was dispatched, and in most client libraries resolution happens before the span opens, or inside a connection acquisition step that is not separately timed. Our "outbound HTTP call took 45ms" metric was measuring the part after the hostname had already become an address.

This is a general and underappreciated instrumentation gap. If you time HTTP calls but not DNS, a resolver problem shows up as unexplained latency in the caller while every dependency reports healthy. The gap between "time spent in my handler" and "time accounted for by my spans" is exactly where this lives.

Why 400ms, and why only sometimes

Two mechanisms compounding.

First, ndots search domain amplification. Kubernetes writes a resolv.conf like this:

search default.svc.cluster.local svc.cluster.local cluster.local ec2.internal
nameserver 10.96.0.10
options ndots:5

ndots:5 means any name with fewer than five dots is treated as relative and tried against each search domain first. Our code called an external API at api.payments-provider.com, which has three dots. So the resolver dutifully tried:

api.payments-provider.com.default.svc.cluster.local   NXDOMAIN
api.payments-provider.com.svc.cluster.local           NXDOMAIN
api.payments-provider.com.cluster.local               NXDOMAIN
api.payments-provider.com.ec2.internal                NXDOMAIN
api.payments-provider.com                             answer

Five lookups. And glibc issues A and AAAA queries in parallel for each, so ten queries to resolve one external hostname. All of them going to CoreDNS and back.

That was true before the incident too. It was the amplifier, not the trigger.

Second, CoreDNS was at capacity. Another team had rolled out a new service at 09:07 that morning, and it made a lot of outbound calls to a third party host. Same ndots amplification, much higher request rate. CoreDNS pod CPU went from 15% to 94%. Queries started queueing and some responses were dropped.

When a UDP DNS response is lost there is no fast failure. glibc's resolver waits its full timeout, which defaults to five seconds, before retrying. Hit that and your request takes five seconds. The 400ms p99 we saw was the average effect of a small percentage of requests hitting partial delays plus a smaller number hitting the full timeout, smeared across the histogram.

The 09:14 alert against the 09:07 rollout is a seven minute lag, which is roughly how long the new service took to reach full replica count. That correlation was sitting in the deploy log the whole time. I had not found it because I searched for deploys to my own service.

The fixes

Immediate: scale CoreDNS. Replicas from 2 to 6, and a higher CPU limit. p99 dropped back within two minutes. This bought time and fixed nothing.

Reduce query volume with ndots:2. For services that mostly call external hosts:

dnsConfig:
  options:
    - name: ndots
      value: "2"

Any hostname with two or more dots is now tried as absolute first, so api.payments-provider.com resolves in one query instead of five. Cluster internal short names still work through the search path. This cut total DNS query volume from checkout-api by about eighty percent.

Use fully qualified names for external hosts. A trailing dot makes a name absolute and skips the search list entirely regardless of ndots:

https://api.payments-provider.com./v2/charge

Ugly, effective, and better supported than you would expect. We did this for the three highest volume external endpoints.

Enable NodeLocal DNSCache. This runs a caching resolver as a DaemonSet on every node, so pods query a local address instead of crossing the network to CoreDNS. It also upgrades the upstream connection to TCP, which eliminates the silent UDP drop plus five second timeout failure mode entirely. This was the single most valuable change we made.

Lower the resolver timeout as a backstop:

dnsConfig:
  options:
    - name: timeout
      value: "1"
    - name: attempts
      value: "3"

Three fast attempts beat one five second stall. It converts a catastrophic tail into a mild one.

Instrument DNS. We added explicit resolution timing. In Go, httptrace.ClientTrace gives you DNSStart and DNSDone for free, and most languages have an equivalent hook. It is now its own span. Next time this happens it will be a thirty second diagnosis.

Alert on CoreDNS. Request duration p99, error rate, cache hit ratio. It is infrastructure every single pod depends on and we were not watching it at all.

What I would do differently

Check shared infrastructure early when one service is slow and its dependencies are not. I spent nearly an hour inside checkout-api before looking outside it. DNS, service mesh sidecars, the CNI, and the node's conntrack table are shared, invisible, and rarely instrumented, and they produce exactly this signature.

CPU flat with latency up is a clue, not a dead end. It means off CPU time, which means waiting, which means locks, disk, or network. That deduction was available within ten minutes and I treated it as "the profiler did not help".

Correlate against all deploys, not just your own. The trigger was another team's rollout, and our change correlation tooling filtered to the alerting service by default. A sensible default that was wrong here.

strace with -T remains extraordinary. Ten minutes of reading syscall timings found what an hour of dashboards did not. It is invasive and I would not attach it casually to a busy production pod, but on one pod out of many, briefly, it is often the fastest path from unexplained latency to the exact syscall responsible.

And the folk wisdom held. It was DNS.