It Wasn't One Request - Everything Got Slow
Count the Slots in the Thread Pool
Goal
Measure and confirm that the same computation may or may not block the loop depending on where it runs, and count in numbers how many slots the libuv thread pool has.
Why it matters
crypto.pbkdf2 and crypto.pbkdf2Sync do the same computation. But one goes to
the thread pool and the other runs on the event loop. The four letters Sync at the end of the name
separate "only this request is slow" from "everything is slow."
And the thread pool is not unlimited. The default is four slots, so if you send five heavy asynchronous jobs,
the fifth cannot even start until one of the first ones finishes.
File reads, DNS lookups, and compression share the same four slots, so a compression job
delaying file reads really does happen. Conversely, socket reads and dns.resolve do not use
those slots, so they are not affected at all. This lab is not about memorizing this map, but about learning
how to confirm it by measuring.
Steps
- In
/root/work/blocking/probe.mjs, record the place of each API withclassify(name). - In the same file, create
pct(samples, p)andwithLag(fn, options). - Measure
crypto.pbkdf2Syncandcrypto.pbkdf2, and write them into/root/work/blocking/report.json, underruns.pbkdf2Syncandruns.pbkdf2Async. - Measure while parsing a large JSON string and record it in
runs.jsonParse. - Create
/root/work/blocking/wave.mjs, send several jobs of the same kind at once, and record them inruns.pool4andruns.pool8. - Run the same program with
UV_THREADPOOL_SIZE=8and record it inruns.pool8big. - Apply the same method once more with
zlib.gzipSyncandzlib.gzip.
Notes
classifyreturns one of three values:"loop"(runs on the loop),"threadpool"(libuv thread pool), or"kernel"(the loop only waits until the kernel tells it), and it returns"unknown"for a name that is not in the table.withLag(fn, {durationMs, intervalMs, startAfterMs})starts measuring first, callsfn()a little later (and waits for it if it is a promise), puts that time intoworkMs, and returns{intervalMs, durationMs, samples, workMs}.wave.mjstakes the count fromprocess.argv[2]and prints one line of{"n": .., "threadpoolSize": .., "finishMs": [..]}.finishMsis the finish times (ms) sorted in ascending order.- A common mistake: setting
process.env.UV_THREADPOOL_SIZE = "8"inside the program. The thread pool has already been created before that, so nothing happens.
Draw the map first
In /root/work/blocking/probe.mjs, export classify(name). fs.readFileSync·crypto.pbkdf2Sync·zlib.gzipSync·JSON.parse·JSON.stringify are "loop", fs.readFile·crypto.pbkdf2·crypto.randomBytes·zlib.gzip·dns.lookup are "threadpool", dns.resolve4·dns.reverse·dns.resolveMx are "kernel", and everything else is "unknown".
This list is not something to memorize; it is written in the official documentation: the UV_THREADPOOL_SIZE section of the command-line documentation and the "Implementation considerations" section of the DNS documentation.
The split between dns.lookup and dns.resolve4 is the heart of this table. The former calls the operating system's getaddrinfo on the thread pool, and the latter queries the network directly and does not use the thread pool.
A ruler that measures while work runs
In the same file, export pct(samples, p) (the same rule as in lab 1) and withLag(fn, {durationMs, intervalMs, startAfterMs}). It returns {intervalMs, durationMs, samples, workMs}.
Start measuring first; once startAfterMs has passed, call fn(). If fn() returns a promise, wait for it and put the time it took into workMs.
Keep measuring after the work is done until durationMs has elapsed, because a blocked stretch shows up as a large value in the sample after the block is released.
The same computation, a different place
Run the same computation once with crypto.pbkdf2Sync and once with crypto.pbkdf2 (asynchronous), measuring each, and in /root/work/blocking/report.json write runs.pbkdf2Sync and runs.pbkdf2Async. Each holds samples·p50·p99·max·workMs, and also write node at the top level.
Make each run take at least 150ms so the difference is visible. Raise the iteration count (for example, 300000 rounds with sha512).
The workMs of the two cases comes out similar, because the amount of work is the same. What differs is what the loop was able to do in the meantime.
Work with nowhere to move it
Create a JSON string larger than 4MB, measure while parsing it with JSON.parse, and record it in runs.jsonParse together with bytes.
JSON.parse has no asynchronous version. Even if you read the file asynchronously with fs.readFile, the parsing happens on the loop.
That is why, for an endpoint that receives large JSON, the body size limit becomes the latency budget. The numbers you measure here are the basis for deciding that limit.
Count how many slots there are
Create /root/work/blocking/wave.mjs. Send process.argv[2] asynchronous crypto.pbkdf2 calls at once, sort the finish times (ms) in ascending order, and print one line of {n, threadpoolSize, finishMs}. threadpoolSize is 4 when process.env.UV_THREADPOOL_SIZE is not set. Write the results of running with 4 and 8 to runs.pool4·runs.pool8, and for runs.pool8.waveRatio, write finishMs[7] / finishMs[3].
Each job must take at least 150ms for the slots to show up as separate batches.
Four finish at almost the same time, while eight split into two batches. The last four had not even started until the first four freed their slots.
Does adding slots solve it?
Give UV_THREADPOOL_SIZE=8, run the same wave.mjs with 8, and write the result to runs.pool8big. Along with threadpoolSize·finishMs·waveRatio, for speedup, write pool8.finishMs[7] / pool8big.finishMs[7].
The environment variable must be given when the program starts: UV_THREADPOOL_SIZE=8 node wave.mjs 8.
The waves disappear. But look at the time at which everything finishes. This Pod's CPU has only 2 cores, so what grew is the number of jobs that can start at the same time, not the number of hands that do the computing.
Apply the same method to a new API
Create a buffer larger than 4MB, measure while compressing it once with zlib.gzipSync and once with zlib.gzip (asynchronous), and record them in runs.gzipSync and runs.gzipAsync together with bytes.
The order is to first check zlib's place in the table from step 1, and then measure to confirm that the table is correct. This is exactly what you do when you meet a library for the first time.
Data that compresses well finishes quickly and the difference is not visible. If you use a buffer made with crypto.randomBytes, the compressor does real work.