Hunting a delayed deadlock that hid for two years in Namespace's tiered Bazel cache

This is a glimpse into engineering at Namespace, where performance and reliability drive everything we do. It's the story of a bug that sat dormant for two years before triggering a severe performance regression in our Bazel caches, and how we tracked it down and fixed it.

How does Namespace do Bazel?

At Namespace, we operate two Bazel products: Remote Bazel Caches and Remote Build Execution (RBE).

A remote Bazel Cache contains two logical stores: The Content Addressable Store (CAS) stores blobs by their content digest. The Action Cache (AC) maps a build action to its results. If Bazel finds both an action result and its output files in the cache, it can reuse them instead of running the action again.

Remote Build Execution builds on the same model. Instead of only storing and retrieving previous results, Namespace executes the Bazel actions themselves on its own compute platform. The inputs, outputs, and action results still pass through the same caching mechanism mentioned above.

Our Bazel Caches use a tiered storage model and run as specialized Namespace instances. The hot tier stores blobs on a local disk backed by a Cache Volume. When a cache instance terminates, a replacement instance can attach the same Cache Volume and continue using the existing data. This works well for most reads, but we observed high tail latency when an instance sees a cache miss. Such rare cases force Bazel to repeat expensive build actions. We therefore added a warm tier backed by our distributed object storage: new blobs are first written to the local disk. Once a write completes, the cache adds the blob to an internal queue and asynchronously uploads it to our in-cluster object storage. Reads check the local disk first and if a blob is missing, the cache retrieves it from object storage and writes it back to disk. This also allows caches in different regions to reuse data when customers run jobs on more than one continent.

This cache implementation had been running in production for around two years. The bug described in this post only appeared when a particular combination of large uploads, slow clients, and multiplexed gRPC streams occurred at the same time.

A well-meant rate limit wreaking havoc

The disk cache performs filesystem operations using blocking system calls. A large number of blocked filesystem calls can cause Go to create a large number of operating system threads. Go defaults to a limit of 10,000 threads after which the process crashes.

The cache used a weighted semaphore to stay below that limit. Before starting a filesystem write, a request acquired one of 5,000 available slots. It released the slot once the write had completed. The simplified code looked like this:

if err := diskWaitSem.Acquire(context.Background(), 1); err != nil {
	return err
}
defer diskWaitSem.Release(1)

if _, err := io.Copy(file, requestBody); err != nil {
	return err
}

return file.Sync()

The intention was reasonable: we wanted to limit the number of simultaneous blocking filesystem operations so that the cache cannot exhaust Go's thread limit. In the above snippet it's also very tempting to think that the io.Copy would be a short operation that takes a few seconds at most. However, that was not what the code actually did: The requestBody passed to io.Copy was the client's gRPC upload stream. The semaphore was therefore held while the cache waited for the client to send the whole blob. The slot would not be held for the duration of the disk operation but rather for the duration of the entire upload. For a small blob on a fast connection, the difference did not matter. For a 300 MiB build output sent by a slower client, the slot could be held for several minutes. At an upload rate of 2 MiB/s, copying the request body alone takes 150 seconds. The semaphore was also shared with the warm-tier read path. When a blob was missing from the local disk, the cache acquired a slot while downloading and storing the blob from object storage. A large number of slow uploads could therefore block cache-miss reads as well.

There was one more problem in the code example: The semaphore was acquired with context.Background() rather than the context of the client request. If a client cancelled its request while waiting for a slot the wait continued leading to a resource leak.

None of these details caused the cache to fail immediately. They only made the semaphore increasingly expensive as the number of concurrent uploads grew.

The first clue: The cache slows down

The first report came from a customer whose builds had become extremely slow. The cache process was still running and requests were not returning any obvious errors. CPU and disk utilization were low and did not indicate an immediate problem.

Our first suspicion was the warm tier: uploads to object storage appeared to have slowed down and some cache-miss reads were also stuck. Since both operations involved object storage it looked like a likely bottleneck. The metrics did not show a corresponding object storage problem though. The cache also was not running out of disk space or spending its time evicting old entries. It was mostly idle, despite having a large backlog of work. We eventually captured a goroutine dump from the affected cache. A large number of goroutines were waiting to acquire a semaphore and other goroutines had acquired slots and were blocked inside io.Copy waiting for more data from their gRPC streams.

This explained why the cache had stopped starting new writes, but not why the existing uploads were making almost no progress. The clients were still connected and trying to send data. The missing piece was HTTP/2 flow control.

The final clue: How HTTP/2 completed the deadlock

Bazel uploads blobs using gRPC which runs on top of HTTP/2. A single TCP connection can carry many gRPC streams concurrently and Bazel uses this to upload several blobs in parallel without opening separate connections for each blob.

HTTP/2 uses flow-control windows to limit how much unprocessed data a peer may send. Our server allowed up to 1 MiB of unprocessed data per stream and 4 MiB across the whole connection:

grpc.InitialWindowSize(1 << 20)
grpc.InitialConnWindowSize(4 << 20)

When a handler reads data from its gRPC stream, the server returns flow-control credit to the client. The client can then send more data. A handler waiting for the disk semaphore does not read from its stream and the gRPC transport may buffer some data for that stream but the handler never consumes it and therefore does not return the corresponding flow-control credit.

With a 1 MiB stream window and a 4 MiB connection window, a few blocked streams could consume all of the connection's available credit. That produced a circular dependency:

1. Some streams held disk slots while waiting for the client to send the rest of their blobs.
2. Other streams on the same connection were waiting to acquire disk slots.
3. The waiting streams stopped reading and consumed the connection's flow-control window.
4. The client could no longer send data to the streams that already held disk slots, essentially starving them.
5. Those streams could not finish their uploads and release their slots.
6. The waiting streams could not acquire a slot and start reading.

The semaphore and HTTP/2 connection window had become two bounded resources that depended on each other in a circular fashion. The cache did not crash during this and the TCP connections remained healthy, keepalives continued, and there was little CPU or disk activity.

This also explains why the problem appeared after the cache had been running normally for some time. Uploads continued as long as enough semaphore slots and connection-window credit remained available but once enough slow streams accumulated, the system's throughput dropped abruptly. When some client jobs eventually terminated their connections and the affected reads returned then the remaining uploads immediately started moving again.

The Fix

Our first change was to use the request context when acquiring the semaphore. If the client disconnects or cancels the request, the request gives back the slot that it acquired immediately. We also introduced a time based limit to the wait. If the cache cannot acquire a slot within that time it returns a retryable error to the client instead of waiting indefinitely:

func acquireDiskSlot(ctx context.Context) error {
	waitCtx, cancel := context.WithTimeout(ctx, time.Minute)
	defer cancel()

	if err := diskWaitSem.Acquire(waitCtx, 1); err != nil {
		if ctx.Err() != nil {
			return ctx.Err()
		}

		return tooManyRequests()
	}

	return nil
}

We also looked more closely at whether the semaphore was actually needed. It protected against a theoretical operating system thread limit but it did so by holding a global slot across client-paced network I/O. On our cache instances, this was not a useful tradeoff. We made the semaphore configurable and disabled it for this workload. We retained context-aware acquisition and the timeout for environments where the operating system thread limit still needs to be enforced. As an initial safeguard, we also bounded the number of concurrent streams on a connection and increased the connection window. This made it harder for parked streams to starve streams that were still capable of making progress.

Conclusion

This is some of the work behind Namespace's production systems. We'll tell you a lot more over the coming months and years. If you'd rather use that infrastructure than debug it yourself, try Namespace.