Namespace: Hunting a delayed deadlock that hid for two years in Namespace's tiered Bazel cacheLog inContact Us

Namespace Blog<br>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:

disk_cache.go<br>if err := diskWaitSem.Acquire(context.Background(), 1); err != nil {<br>return err<br>defer diskWaitSem.Release(1)

if _, err := io.Copy(file, requestBody); err != nil {<br>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...