TT Lab
Get started
Learn Learning paths Courses

It Wasn't One Request - Everything Got Slow

Count the Slots in the Thread Pool

Continue in TT Lab

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

  1. In /root/work/blocking/probe.mjs, record the place of each API with classify(name).
  2. In the same file, create pct(samples, p) and withLag(fn, options).
  3. Measure crypto.pbkdf2Sync and crypto.pbkdf2, and write them into /root/work/blocking/report.json, under runs.pbkdf2Sync and runs.pbkdf2Async.
  4. Measure while parsing a large JSON string and record it in runs.jsonParse.
  5. Create /root/work/blocking/wave.mjs, send several jobs of the same kind at once, and record them in runs.pool4 and runs.pool8.
  6. Run the same program with UV_THREADPOOL_SIZE=8 and record it in runs.pool8big.
  7. Apply the same method once more with zlib.gzipSync and zlib.gzip.

Notes

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.