Chasing a Go latency spike
An HTTP service of mine usually answered in a few milliseconds but occasionally took more than 100. Average latency looked healthy, which is one of the average’s less charming habits. I wanted to know whether requests were waiting on the network, the scheduler, or garbage collection.
My first attempt added timers around every handler. That established that a slow request was slow, a breakthrough unlikely to threaten the scientific establishment. I needed observations below the handler.
I started with GODEBUG=gctrace=1. A run under load printed lines resembling:
gc1(1): 0+6+1 ms, 18 -> 22 MB 12033 -> 8411 (123004-114593) objects
gc2(1): 0+9+1 ms, 25 -> 29 MB 15020 -> 9170 (171220-162050) objects
The exact format is runtime-version dependent, but the useful correlation was clear: several latency spikes lined up with collections. The Go collector at this point includes stop-the-world work. During those pauses, goroutines do not make application progress. More processors do not turn a global pause into concurrent work.
I then reduced allocation rate rather than immediately tuning the collector. A JSON path decoded first into interface{} and then into a struct. Removing that intermediate object graph reduced collection frequency. Reusing a scratch byte slice within a request also helped, provided I kept ownership local and did not retain a huge backing array for a tiny value.
Heap size and pause time are related but not identical. Setting GOGC lower collects more often with a smaller heap; setting it higher collects less often while retaining more memory. Neither setting fixes accidental allocation. I leave GOGC at its default until measurements show a reason to trade memory for collection frequency.
The scheduler was the next suspect. Go multiplexes goroutines onto operating-system threads. Runnable goroutines wait in scheduler queues; goroutines blocked in syscalls or channel operations allow others to run. GOMAXPROCS controls how many processors may execute Go code simultaneously, not how many sockets the program may hold and not a magic goroutine limit.
I had one CPU-heavy goroutine parsing a large report. Function calls provide scheduling opportunities in the current runtime, but preemption is only partial. A long computation with few safe points can delay other runnable work, particularly with a low GOMAXPROCS. Breaking the report into bounded jobs improved fairness and made cancellation by closing a work channel practical. Adding runtime.Gosched inside the innermost loop helped one test and made the algorithm uglier, so I did not keep it.
Network waiting has a different path. On supported systems, the runtime’s network poller integrates non-blocking descriptors with mechanisms such as kqueue or epoll. A goroutine waiting for socket readiness can park without consuming an operating-system thread for the duration. When the descriptor becomes ready, the poller makes the goroutine runnable again.
This is why one goroutine per connection can be practical. It does not mean each connection has a dedicated thread. It also does not mean network code is immune to thread exhaustion: file operations and syscalls that the poller cannot manage may block threads, DNS behavior varies by platform and resolver path, and cgo calls have their own costs.
I made the wait visible by taking a goroutine profile from net/http/pprof while the service was loaded. Most goroutines were parked in network reads, which was normal. The interesting stack was a growing set waiting on one mutex around a response cache. My “thread-safe map” protected JSON encoding under the lock, turning a short critical section into serialized CPU work.
The repair copied the cached value’s reference while holding the lock, unlocked, and encoded afterward. That shortened scheduler queues during bursts. I verified the data was immutable before doing this; moving mutable state outside a lock would have exchanged latency for corruption, a poor bargain even by my standards.
One test run then looked roughly like this:
before: p50=4ms p95=37ms p99=128ms
after: p50=3ms p95=11ms p99=42ms
The remaining tail still correlated with collections. This was not a proof that all pauses were GC pauses: kernel scheduling, packet loss, disk activity, and clients contribute too. I kept wall-clock request histograms beside allocation and GC observations rather than assigning every gap to the runtime.
The mechanism suggests a practical diagnostic order. First, establish whether time is spent runnable, blocked on synchronization, parked on network I/O, or stopped globally. Goroutine profiles reveal blocking locations, mutex and channel structure reveal serialization, GC traces reveal collection timing, and CPU profiles reveal actual execution. Then change the source of delay.
I also capped the work queue. Before that change, a burst created more live request state than workers could consume, raising heap size and GC cost after traffic subsided. Back pressure made overload visible to callers instead of translating it into a delayed collector problem. A goroutine waiting in a queue is still retained work.
My direct opinion is that “goroutines are cheap” is useful sales material and terrible capacity planning. Their stacks consume memory, their work must be scheduled, their objects burden the collector, and their shared locks serialize. The runtime makes concurrency remarkably approachable, but it cannot make an unbounded queue or a giant critical section reasonable. Mine was a runtime mystery only until I measured my own code.