It Wasn't One Request - Everything Got Slow
Four Letters at the End of a Name Decide the Outage
In one line
crypto.pbkdf2 and crypto.pbkdf2Sync do the same computation for the same amount of time.
The only difference is where it runs, and that difference separates "only this request is slow" from "everything
is slow." And not everything asynchronous sits in the same place, either.
Why this was needed
"Just make it asynchronous" is too vague. In reality there are three places, and the three have different properties.
First, work that runs on the event loop. JSON.parse, regular expressions, sorting a large array,
and everything whose name ends in Sync live here. While this work runs, it stops everything else
in that process.
Second, the libuv thread pool. File reads, compression, and asynchronous cryptographic operations go here. The loop is free, but the slots are limited. The default is four slots, so if you send five heavy jobs at once, the fifth cannot even start until one of the first ones finishes.
Third, the kernel. Socket reads and writes, and dns.resolve*(), are here. Until the operating system
tells it "ready," the loop simply waits. It uses neither a thread nor the CPU.
If you cannot tell these three places apart, strange things happen. For example, you make image compression asynchronous and save the loop, but after that file reads become slow. The two share the same four slots. Looking only at the code, the two features have nothing to do with each other.
How it works
Which APIs use the thread pool is not something to memorize; it is written in the documentation. In Node's
command-line options documentation, the
UV_THREADPOOL_SIZE section lists them itself: every fs API except file watching and the explicitly synchronous
functions, asynchronous cryptographic APIs such as crypto.pbkdf2()·crypto.scrypt()·
crypto.randomBytes()·crypto.randomFill()·crypto.generateKeyPair(), dns.lookup(), and every
zlib API except the explicitly synchronous versions.
The same document gives the default size as 4, and the libuv documentation gives the absolute upper limit as
1024 (libuv thread pool).
The split between dns.lookup and dns.resolve4 is the most confusing spot in this list.
Both turn a name into an address, but the former calls the operating system's getaddrinfo(3) on the thread pool,
and the latter queries the network directly. Node's
DNS documentation states about the latter that
"this network communication is always done asynchronously and does not use libuv's thread
pool." That is why, in a service that does many name lookups, file reads getting slow
really does happen.
The fact that there are four slots shows up right away when you measure. If you send four asynchronous jobs of the same weight, all four finish at almost the same time, and if you send eight, they split into two batches. Measured on Node 22.11.0 in the lab image with 2 CPU cores, it comes out like this.
4개: 298 301 302 307 ms — 함께 끝난다
8개: 315 317 321 325 | 700 703 703 704 ms — 뒤 네 개는 한 바퀴를 기다린다
So would adding slots solve it? If you measure again with UV_THREADPOOL_SIZE=8, all eight finish
around 710ms. The waves disappear, but the time at which everything finishes stays the same.
What grew is the number of jobs that can start at the same time, not the CPU that does the computing.
A warning the same document adds is also important: changing this value from inside the program
through process.env is not guaranteed to work, because the thread pool is created long before
user code runs.
What it looks like in the field
The most common case is work that has no asynchronous version at all. JSON.parse is the typical example.
Even if you read a file asynchronously with fs.readFile, turning that string into an object happens on the
loop. Parsing a 12.9MB JSON on Node 22.11.0 took 76ms, and during that time the loop was stalled for 58ms. There is nowhere to move it to,
so the only choice left is to limit the body size.
That is why the request body limit becomes the latency budget.
The second is the last four letters of the name. On the same image, compressing 8MB with zlib.gzipSync stalls
the loop for 183ms, while compressing with zlib.gzip stalls it for 9ms. The work itself is similar, 178ms and
219ms respectively. This is why, in a code review, looking for Sync is the first line of a performance improvement.
In particular, a readFileSync that reads a configuration file at startup is fine, while a readFileSync on the
request-handling path is an incident: even the same function changes the judgment depending on where it is called.
What you will do in the next lab
You will move the list from the official documentation into a table and measure to confirm that the table is correct.
You will run the same computation once synchronously and once asynchronously and measure the loop delay, confirm with
JSON.parse, which has no asynchronous version, that there is nowhere to move the work, and send eight jobs of the same weight to count
the slots of the thread pool. You will raise UV_THREADPOOL_SIZE and measure both that the waves disappear and that the total
time stays the same, and finally apply the same method to zlib.