where the time goes
Here’s a program that does exactly one interesting thing. It opens a file and adds up every byte.
// sum_byte.c
#include <fcntl.h>
#include <unistd.h>
#include <stdio.h>
#include <stdint.h>
int main(int argc, char** argv) {
int fd = open(argv[1], O_RDONLY);
uint64_t sum = 0; unsigned char b; long n = 0;
while (read(fd, &b, 1) == 1) { sum += b; n++; }
close(fd);
printf("bytes=%ld sum=%llu\n", n, sum);
}I pointed it at a 64 MiB slice of random bytes and timed it:
$ /usr/bin/time -l ./sum_byte slice64.bin
bytes=67108864 sum=8556984108
20.89 real 4.61 user 15.59 sysTwenty-one seconds to add up 67 million numbers. My phone can add 67 million numbers in a blink. And look at the split: 4.61 user is time my code spent running, 15.59 sys is time spent inside the kernel. Three-quarters of the program’s life was spent somewhere I didn’t write a single line.
Now the same arithmetic, one line different, read into a buffer instead of one byte at a time:
// sum_buf.c, only the loop changed
unsigned char buf[65536];
uint64_t sum = 0; long n = 0; ssize_t r;
while ((r = read(fd, buf, sizeof buf)) > 0)
for (ssize_t i = 0; i < r; i++) { sum += buf[i]; n++; }$ /usr/bin/time -l ./sum_buf slice64.bin
bytes=67108864 sum=8556984108
0.00 real 0.00 user 0.00 sysSame file. Same sum=8556984108, byte for byte. Under ten milliseconds instead of twenty-one seconds. The addition didn’t change, I proved that, the sum is identical, so those twenty-one seconds weren’t arithmetic. They were something else, and finding out what that something is turns out to be the whole skill of making programs fast. This post is one file, sped up and slowed down until I can point at exactly where each version’s time went.
The machine, because every number below is real and this is the machine that produced them: an Apple M4, 10 cores, 16 GiB, macOS 15.7.7, Apple clang 15. You need to be able to read the C above, a loop, a buffer, read(), and nothing else. Everything past that gets built up as the file runs into it.
The 4,560 instructions I didn’t write
Start with the number that should be impossible. I asked time -l for instruction counts on both versions of the same 67-million-byte job:
byte-at-a-time: 306,223,366,387 instructions retired
buffered: 99,141,440 instructions retiredThree hundred billion against ninety-nine million, for identical output. That’s 3,088 times more machine instructions to compute the same sum. Divide the big number by the work: 306 billion instructions over 67 million bytes is about 4,560 instructions per byte. My loop body is maybe five instructions, load a byte, add it, bump two counters, branch. So roughly 4,555 instructions per byte are not mine. They belong to whatever read(fd, &b, 1) sets in motion.
What it sets in motion is a trip across a wall. Your program doesn’t get to touch the disk, or the file, or really any hardware directly, that would be a security and stability catastrophe, every program able to scribble on every device. Instead the operating system kernel owns all of that, and your program is a tenant in userspace. When userspace needs the kernel to do something privileged, read a file, open a socket, allocate memory from the OS, it makes a syscall: it puts a number in a register saying which service it wants, and executes a special instruction that traps into the kernel. The CPU switches privilege level, the kernel does the work, then control comes back. That round trip is the wall, and read() is a syscall.
The byte-at-a-time version crosses that wall 67,108,864 times. Once per byte. The buffered version crosses it 1,024 times, once per 64 KiB buffer, and does the byte-adding in a plain userspace loop where it belongs.
I wanted to know what one crossing costs, so I timed the cheapest syscall I could find. getpid() just returns the process ID; it does almost no work, so timing it in a loop measures mostly the wall itself:
// 50 million raw getpid traps
for (long i = 0; i < N; i++) syscall(SYS_getpid);$ ./sysbench
50000000 raw getpid syscalls: 89.0 ns eachEighty-nine nanoseconds to cross the wall and come back, doing nothing on the far side. That’s the floor. Sixty-seven million of those is about six seconds of pure boundary-crossing, before read does any actual reading, and read does much more than getpid (it looks up the file descriptor, checks permissions, finds the next byte, copies it to my variable), which is why the measured kernel time was 15.59 seconds, not six. But the shape of the disaster is already clear from the floor. The program spent its life paying a toll, 89-plus nanoseconds at a time, tens of millions of times, to fetch one byte per trip.
Eighty-nine nanoseconds sounds tiny. It is tiny. It’s also the entire problem, because I asked for it 67 million times.
Don’t guess. Sample.
I could have reasoned my way to “it’s the syscalls” from the sys time alone, and I did. But reasoning is how you convince yourself of the wrong thing confidently, so the actual method is to make the machine tell you. macOS ships a sampling profiler called sample. It attaches to a running process and, every millisecond, writes down where the program counter is, which function is executing right now. Do that a few thousand times and the functions that show up most are where the time goes. No guessing.
(Small stumble: my first sample run failed with a Python traceback, because an Anaconda install had shoved its own script named sample earlier in my PATH. The one I wanted is /usr/bin/sample. Worth knowing your $PATH before you trust a tool’s name.)
I ran the slow version and sampled it for three seconds:
$ ./sum_byte big.bin &
$ /usr/bin/sample <pid> 3
Call graph:
2572 Thread ... main-thread
2572 start (in dyld) + 6076
2568 main (in sum_byte) + 92
+ 2563 read (in libsystem_kernel.dylib) + 8,4
...
Sort by top of stack, same collapsed:
read (in libsystem_kernel.dylib) 2565Two thousand five hundred sixty-five samples out of two thousand five hundred seventy-two landed inside read. That’s 99.7% of the program’s life spent in one kernel function. If you’ve ever seen a flamegraph, those horizontal stacked-bar pictures where width means time, this is what one looks like before it’s drawn: a single bar labeled read, stretching across the entire width, with a sliver of main on top. There’s nothing to optimize in my arithmetic because my arithmetic barely runs. The profiler didn’t have an opinion; it had a tally, and the tally said read.
This is the first and most reliable move in performance work: before you change anything, sample the thing and find out where it actually spends time. Programmers are wrong about this constantly, I’ve “known” exactly which line was slow and been wrong by a mile.
The one line that bought 65,536x
The fix follows directly from the diagnosis. If crossing the wall is expensive and I’m crossing it per byte, cross it per buffer instead. One read() fills 64 KiB, 65,536 bytes, and then a normal userspace loop adds them up with no kernel involvement at all. That’s the buffered version from the top, and on the full gigabyte:
$ /usr/bin/time -l ./sum_buf big.bin
bytes=1073741824 sum=136901655725
0.11 real 0.05 user 0.05 sysThe whole 1 GiB in 0.11 seconds. I made 16,384 read calls instead of a billion, cut the syscall count by four orders of magnitude, and the “where does the time go” answer changed completely: it’s now split evenly between my code (user) and the kernel (sys), both small. This is what buffering is, underneath the word, it’s amortizing the cost of the boundary over many bytes. Every buffered I/O library you’ve ever used, every BufferedReader and stdio FILE*, exists to make this one trade for you so you don’t write sum_byte by accident. (It’s the same trick as reading a whole shelf of books in one library trip instead of walking back for each page.)
So the first version was syscall-bound: its bottleneck was the user/kernel boundary. Naming the bottleneck is the point, because a syscall-bound program can’t be fixed by a faster CPU or more cores or better arithmetic, none of those touch the wall. Only doing fewer crossings helps. Diagnose the wrong bottleneck and you optimize the wrong thing.
How big should the buffer be?
Sixty-four kilobytes was a number I picked from habit. The reader who just watched buffering win by 65,000x is entitled to ask whether a bigger buffer wins more, so I made the buffer size a command-line argument and swept it across the full gigabyte, warm, counting the read calls each size costs:
bufsize=4096 read_calls=262144 174.3 ms
bufsize=16384 read_calls=65536 120.8 ms
bufsize=65536 read_calls=16384 109.4 ms
bufsize=262144 read_calls=4096 107.9 ms
bufsize=1048576 read_calls=1024 108.3 ms
bufsize=16777216 read_calls=64 122.2 msIt’s a valley. Coming down from the small sizes, every time I quadruple the buffer I quarter the syscall count, and the time drops, 174 ms to 121 to 109, because I’m still paying off the boundary cost. Then around 256 KiB it flattens: 107.9 ms, and 1 MiB is no better. The syscalls have stopped mattering; there are only 4,096 of them left and they’re lost in the noise. And then, at 16 MiB, it gets worse again, 122 ms with only 64 syscalls.
That upturn is a second bottleneck sneaking in behind the first. A 16 MiB buffer is far too big to live in the fast per-core caches, so every pass over it streams the buffer itself out to main memory and back, on top of streaming the file. The small buffers were slow because of the kernel; the huge buffer is slow because of the memory system. The bottom of the valley, a wide plateau from about 64 KiB to 1 MiB, is where the buffer is big enough to amortize the syscall but small enough to stay hot in cache. That’s why every buffered-I/O library defaults to something in that range and stops thinking about it, and it’s why “just make the buffer huge” is a real way to make a program slower. The lower bound of the valley is the syscall wall; the upper bound is the cache. There’s no single right answer, only a range where neither wall is close.
(The extreme confirms the shape. On the 64 MiB slice, a 16-byte buffer takes 1,309 ms; a 256-byte buffer, 86 ms; a 4 KiB buffer, 11 ms. Each rung is roughly the previous syscall count divided down, and the time follows it. The per-byte version at the top of the post was just the leftmost, most catastrophic point on this same curve.)
The compiler already made the arithmetic free
There’s something hiding in that valley I glossed over: even at the plateau, the whole gigabyte takes 108 milliseconds, which is only about 10 GB/s. Why isn’t a loop this trivial faster? The addition is one instruction. Where does that time go?
I looked at what clang actually compiled the sum loop into. I expected a scalar loop, load a byte, add it, repeat. It’s not:
ldp q24, q27, [x8, #-16] ; load 32 bytes into two vector registers
uaddw.2d v1, v1, v24 ; widen 8 bytes to 64-bit and add into accumulator
uaddw2.2d v5, v5, v24 ; the other 8 bytes into a second accumulator
uaddw.2d v2, v2, v25
uaddw2.2d v7, v7, v25
...ldp q24, q27 loads 32 bytes in one instruction. uaddw takes bytes, widens them to 64-bit integers, and adds them into a running vector total, eight lanes at a time. And there are more than a dozen of these accumulators, v0 through v22, running in parallel so no single one becomes a dependency bottleneck. Clang saw my one-add-per-byte loop and rewrote it as a wide vector reduction chewing dozens of bytes per iteration. (This is the same SIMD machinery I watched it emit for a matrix multiply in the GPU post, doing the job here without being asked.)
Which resolves the puzzle. The reason the fast sum runs at 10 GB/s and not faster isn’t that the arithmetic is slow, the compiler made the arithmetic nearly free, packing 32 bytes into a single load and widening them eight lanes at a time. There’s almost no math left to do. The only thing the loop does now is pull bytes out of memory, as fast as memory will hand them over. Which raises a question I can’t answer yet: how fast is that, and what sets the limit? The file has one more layer to give up first, and it changes where the bytes even come from.
The file that becomes memory
There’s a way to read a file that makes no read calls at all, no boundary crossings on the data path whatsoever. It’s called mmap, and it’s a genuinely different idea: instead of asking the kernel to copy file bytes into my buffer, I ask the kernel to map the file into my address space, so the file’s contents simply appear as memory I can point at.
// sum_mmap.c
struct stat st; fstat(fd, &st);
unsigned char* p = mmap(0, st.st_size, PROT_READ, MAP_PRIVATE, fd, 0);
uint64_t sum = 0;
for (long i = 0; i < st.st_size; i++) sum += p[i];p now behaves like a pointer to a gigabyte-long array. No read, no buffer, no per-chunk syscall. I just walk the array. The result:
$ /usr/bin/time -l ./sum_mmap big.bin
bytes=1073741824 sum=136901655725
0.10 real 0.07 user 0.02 sys
65779 page reclaims
1 page faultsSame sum, 0.10 seconds, and almost no kernel time. But two new numbers appeared that weren’t in the buffered run: page reclaims and page faults.
Here’s the sleight of hand mmap is performing. When I called it, the kernel did not read the file. It set up some bookkeeping that says “the memory from address p onward corresponds to this file” and returned. Nothing was loaded. The gigabyte is still on disk (or, as we’ll see, in a cache). The loading happens lazily, the first time I actually touch each region, and the mechanism for “I touched memory that isn’t loaded yet” is a page fault.
16 kilobytes at a time
To follow that, you need the unit the whole memory system works in, and it’s not the byte. Your program thinks in bytes; the kernel and the hardware think in pages, fixed-size chunks of memory, moved and tracked as indivisible units. Everyone’s tutorial says a page is 4 KiB, because that’s what x86 has used forever. This machine disagrees:
printf("getpagesize() = %d\n", getpagesize());getpagesize() = 16384Sixteen kilobytes. Apple Silicon uses 16 KiB pages, four times bigger than the x86 default, and it matters more than it sounds, it means fewer, larger units to track, which is part of how these chips stay fast. If you carry the “4 KiB” number in your head, every page calculation you do on this machine is off by 4x.
Now the magic number resolves. A gigabyte in 16 KiB pages is:
1,073,741,824 bytes / 16,384 bytes per page = 65,536 pagesAnd the mmap run reported 65,779 page reclaims, 65,536 of them the file’s pages, the rest the program’s own stack and heap. The page-fault machinery ran essentially once per page of the file. Each time my loop’s pointer crossed into a fresh 16 KiB region the kernel hadn’t loaded yet, the CPU trapped, a page fault, the kernel found the page, made it present, and my loop continued without knowing anything happened. Sixty-five thousand invisible interruptions, and the whole thing still finished in a tenth of a second. The page-fault count is the page count. That’s not a coincidence; it’s the mechanism showing its work.
A “reclaim” versus a “fault” is a distinction worth one sentence: a hard fault means the kernel had to go get the data from somewhere slow; a reclaim (or soft fault) means the data was already sitting in memory and the kernel just had to hand it over. The mmap run showed 65,779 reclaims and only 1 hard fault, which tells you the gigabyte wasn’t on the disk at all when I read it. It was already in RAM.
The disk you only touch once
I’d been running these programs over and over on big.bin, and somewhere along the way the answer to “where’s the file?” quietly changed. The first time anything reads a file, the kernel pulls it off the SSD and, this is the important part, keeps a copy in spare RAM, in what’s called the page cache. The disk is slow; RAM is fast; so the OS uses whatever memory you’re not otherwise using as a giant cache of recently-touched file data. Every read after the first one is served from RAM, and the disk is never touched again.
You can watch it happen if you use a file the cache hasn’t seen. I made a fresh 512 MiB file and summed it twice:
run 1 (cold): 0.46 real 12040 page faults
run 2 (warm): 0.05 real 1 page faultsNine times slower the first time, and the reason is written right there in the fault counts. Cold, thousands of hard faults, each one waiting on the SSD to deliver a page. Warm, one fault, everything served from the page cache in RAM. The arithmetic was identical both times, same 512 MiB of adds, and the runtime moved 9x based purely on whether the bytes were already in memory. (I couldn’t force a fully cold read for the big file; truly evicting the cache needs sudo purge, which this machine wouldn’t give me without a password. The fresh-file trick is the honest version: some pages were still warm from writing it, which is why it’s 12,040 faults and not the full 32,768.)
This is why benchmarks lie. Run a file-reading program twice, report the second number, and you’ve measured your RAM, not your disk. Report the first, and you’ve measured a cold cache you’ll never see again in production where the file’s always warm. “Where does the time go” has a different answer on the first run than every run after, and if you don’t know which one you measured, you don’t know anything.
So: warm, the sum is served entirely from RAM, no disk, almost no kernel. Where does that time go? For the first time in this post, the answer is going to be “the actual work”, but not the work I thought.
Am I short on math, or short on bytes?
The warm mmap sum moves a gigabyte in 0.10 seconds. That’s about 10.7 GB/s of bytes flowing through my loop. The M4’s memory system can deliver something like 120 GB/s. So my loop is running at roughly a tenth of the machine’s memory bandwidth, and the vectorized assembly already told me the arithmetic is nearly free, so I suspect the answer is “waiting for bytes.” But suspecting is guessing, and the whole discipline of this post is refusing to guess. Is the loop slow because the arithmetic is slow, or because the bytes can’t arrive fast enough?
This is the question in performance work, and it has a name: the roofline. (I spent a whole post on it chasing a matrix multiply across this same chip; it’s the sibling idea to the bandwidth walls in the networking post, physics setting a ceiling you can measure.) Every loop is limited either by how fast the arithmetic units can compute (compute-bound) or by how fast memory can feed them (memory-bound), and the two failures look identical from the outside, a slow program, but have opposite fixes. Speed up a memory-bound loop’s arithmetic and nothing happens; the adder was already idle, waiting. Speed up a compute-bound loop’s memory and nothing happens; the bytes were already there.
There’s a clean way to tell them apart on this particular machine, and it’s the last piece of hardware in the post.
Two kinds of core, and the null result that means everything
The M4 doesn’t have ten identical cores. It has four performance cores and six efficiency cores. macOS decides where runnable threads execute. I used taskpolicy -b to apply background scheduling policy. That is a policy change, not a documented CPU-affinity operation. I did not capture a verified core identifier in these runs, so the P-core and E-core labels below are inferences from the timing bands and known topology, not direct placement measurements.
So here’s a cleaner experiment. Take a loop dominated by arithmetic, just multiply and add in a register with no large memory stream, then run it under the two policies:
default policy: 1189 ms, 1162 ms
taskpolicy -b (background): 3712 ms, 3867 msThe background-policy runs were about 3.1 times slower at pure arithmetic. That is consistent with execution moving to smaller cores or receiving a lower resource policy. A quality-of-service hint produced the fast timing band on an idle machine, while taskpolicy -b reproducibly produced the slow band. The result proves that scheduler policy changed available execution throughput. It does not prove the identity of every CPU that ran the thread.
Now run the byte-sum under the two controls:
default policy: 1230 ms, 1211 ms
background QoS hint: 1208 ms, 1213 msNo difference. I treated the QoS hint as if it had selected a slower core, then called this null result the most informative measurement in the whole post. If the control had really changed core throughput by a factor of three, that reasoning would have been useful: an unchanged loop would point away from arithmetic throughput and toward the bytes. But I had not measured placement, and the two controls were not equivalent. The later thread sweep forced me to come back to this result.
The method, which is the actual point
Step back and look at what the file taught, because the specific numbers matter less than the loop I kept running. Every version of the same program asked one question, where does the time go?, and there were only ever three honest answers.
It went into my code, running instructions I wrote. Diagnose it by counting instructions and by sampling; if the profiler points at your own functions, this is you.
It went into the kernel, crossing the user/kernel wall. Diagnose it by the sys time and by a profiler that points at syscalls like read. Fix it by crossing less often, buffer, batch, mmap.
It went into waiting for memory (or the disk behind it). Diagnose it by the roofline test: make the core faster and see if it helps. If it doesn’t, you’re waiting on bytes, and the fix is to move fewer of them or move them in a friendlier pattern, never a faster core.
That’s the entire debugging loop, and it’s the same whether the program is a 12-line byte-sum or a serving stack handling a million requests. Sample before you change anything. Read the split between user and kernel time. When a change doesn’t help, ask whether you fixed the wrong bottleneck. The byte-sum went from 21 seconds to 5 milliseconds across this post, a factor of about 4,000, and I never once touched the addition, every factor came from moving the bottleneck, and every move started by finding out where it was instead of guessing.
What I didn’t chase
I never got a truly cold disk read, because purging the page cache needs a password this sandbox wouldn’t give me; the fresh-file trick is close but not the real thing, and the honest number for “gigabyte straight off the SSD” is still missing from my table. I didn’t reach for DTrace, which could have counted the read syscalls exactly instead of me inferring them from the byte count. I didn’t push the warm sum toward that 120 GB/s ceiling, a vectorized loop that adds 16 bytes per instruction instead of one would move the memory-bound number, and I’d like to know how close to the roof it lands before something else gives out. And I never explained the one hard page fault in the warm mmap run when I’d have bet on zero. That last one bugs me. The whole post is about refusing to guess where the time goes, and there’s a single fault in there I can’t yet account for.
Except I couldn’t leave it alone
I wrote that list and I meant it as an ending. Then it sat there for a day and every item in it turned into an itch. The 120 GB/s ceiling was a number I’d read somewhere, not one I’d measured, and a post that spends four thousand words refusing to guess has no business closing on a borrowed number. The one hard fault I’d have bet against was still one hard fault. So I went back, and most of what I found didn’t match what I’d have guessed, which is the only reason any of it is worth writing down. This is the part of the post I didn’t plan, which is usually where the real thing is.
Start with the ceiling, because it’s the one I was most sure about.
How fast can one core pull bytes?
The warm sum runs at about 10 GB/s and I’d decided that was the memory system’s fault. The vectorized loads told me the arithmetic was nearly free, so what else could be left but the memory. But “the memory” is not one thing. Between the loop and the DRAM chips there’s a hierarchy of caches, L1 at the top, tiny and absurdly fast, then L2, then a large shared cache on the way out to main memory, and the whole point of that hierarchy is that data you’ve touched recently is close and fast and data you haven’t is far and slow. If the byte-sum is memory-bound, then where the bytes physically live should change how fast I can sum them. Data already sitting in L1 should stream through the loop far faster than data I have to drag in from DRAM.
So I stopped reading files and measured that directly. Allocate a buffer of size S, fill it, then sum it over and over enough times to move a couple of gigabytes total, and read off the throughput. Small S fits entirely in L1 and never leaves the fast cache. Big S can’t, so every pass streams the whole thing in from main memory. Sweep S from 16 KiB, comfortably inside L1, up to 64 MiB, far past any cache on the chip:
wss=16384 17.5 GB/s
wss=65536 17.8 GB/s
wss=131072 15.3 GB/s
wss=262144 16.6 GB/s
wss=1048576 17.0 GB/s
wss=2097152 16.9 GB/s
wss=4194304 16.9 GB/s
wss=8388608 16.9 GB/s
wss=16777216 16.8 GB/s
wss=67108864 16.5 GB/sI expected a staircase. A high plateau while the buffer fits in cache, then a cliff down to a lower plateau once it spills to DRAM, and the height of the cliff would be the ratio of cache bandwidth to memory bandwidth. That’s the textbook picture, and I’ve drawn it on whiteboards. What I got is a flat line. Seventeen gigabytes a second whether the data is 16 KiB living in L1 or 64 MiB living in main memory. The cache hierarchy is right there, doing its job, and my loop cannot tell the difference.
That flat line means I had the bottleneck wrong, or at least too simple. If summing L1-resident data is exactly as fast as summing DRAM-resident data, then memory bandwidth is not what’s holding the loop back, because the fastest memory on the chip produces the same number as the slowest. Something before the memory is the limit. That something is the core itself: how many bytes per second one core can issue loads for and push through the vector adders, regardless of where those bytes come from. Even L1, which can hand over data far faster than 17 GB/s, is bottlenecked down to 17 because that’s as fast as this single core can consume. The loop isn’t waiting on memory. It’s running flat out at the speed of one core, and one core tops out around 17 GB/s no matter how close the data is.
Which quietly undermines a sentence I wrote earlier, the one where I blamed the 16 MiB buffer’s slowdown on “streaming the buffer out to main memory and back.” If a single core sums 64 MiB of DRAM-resident data at the same 17 GB/s as 16 KiB of L1-resident data, then the memory system was never the thing straining under the big buffer. The real story of that upturn is murkier than I made it sound, probably about the read path and the translation hardware rather than raw bandwidth, and I stated it with more confidence than my later measurement earns. I’m leaving the earlier sentence in and telling you here that it was too tidy. That’s the honest version.
But now there’s a genuine puzzle. One core does 17 GB/s. The M4’s memory system is supposed to do several times that. If my loop is core-bound and not memory-bound, then the memory system is sitting there half-idle while one core plods along, and I should be able to prove it by throwing more cores at the same gigabyte.
It takes eight cores to fill the pipe
The test is direct. Map the file, split it into N equal ranges, hand each range to its own thread, sum them all in parallel, add up the partial sums at the end. If the ceiling is one core’s 17 GB/s, adding threads does nothing. If the ceiling is the memory system, throughput climbs with each thread until the memory system is saturated and then flattens, and the height where it flattens is the real bandwidth of this machine, measured instead of borrowed.
I made sure every page was faulted in before timing, so I’d be measuring bandwidth and not the page-fault machinery, and swept the thread count from 1 to 12 on a 10-core chip:
threads=1 59.3 ms 18.1 GB/s
threads=2 29.6 ms 36.2 GB/s
threads=3 20.0 ms 53.6 GB/s
threads=4 15.3 ms 70.3 GB/s
threads=5 16.7 ms 64.5 GB/s
threads=6 14.8 ms 72.7 GB/s
threads=7 12.9 ms 83.4 GB/s
threads=8 11.2 ms 95.5 GB/s
threads=9 12.2 ms 88.3 GB/s
threads=10 12.1 ms 89.0 GB/s
threads=11 10.9 ms 98.1 GB/s
threads=12 10.4 ms 102.8 GB/sThe first four threads scale almost perfectly. One core is 18, two is 36, three is 54, four is 70. Each core adds roughly its own 17 to 18 GB/s, which is exactly what “core-bound, not memory-bound” predicts: the cores aren’t fighting over anything yet, so they just add up. This is the proof that the flat cache-cliff line was telling the truth. If one core had been saturating memory, the second thread would have bought me almost nothing. Instead it nearly doubled.
Then look at what happens at the fifth thread. Throughput drops. Seventy gigabytes a second at four threads, down to 64 at five. Adding a worker made the program slower. The boundary is suggestive because this M4 has four performance cores, but the probe recorded neither CPU identity nor migration. The measured fact is only that the fifth runnable worker costs more than it contributes in this run. Scheduling, migration, shared-cache pressure, and the transition between core classes are all plausible mechanisms. The table does not separate them. Push past the dip and the remaining workers do add bandwidth, climbing to the mid-90s by eight threads and scraping past 100 GB/s at twelve, oversubscribed on a 10-core chip.
So the real ceiling on this machine, measured, is somewhere around 90 to 100 GB/s, not the 120 I’d borrowed. And the more important number is the ratio: one core gets 17 to 18, the whole machine gets 100, so a single-threaded byte-sum runs at roughly a sixth of what the memory system can actually deliver. My warm sum wasn’t memory-bound. It was one-core-bound, leaving five-sixths of the memory bandwidth untouched. The pipe was mostly empty and I’d been calling it full.
The dip nagged at me, so I ran the whole sweep again under background policy, which had produced the slow timing band, to see how that resource class scaled:
threads=3 10.9 GB/s
threads=4 14.7 GB/s
threads=5 17.6 GB/s
threads=6 17.7 GB/s
threads=7 17.6 GB/s
threads=8 17.2 GB/s(The one-and two-thread rows came back absurdly slow, 0.3 and 2.9 GB/s, because the background policy throttles the whole process hardest when it’s barely using the machine, so I’m reading the plateau and not those.) Under this policy, six or more threads top out around 17 to 18 GB/s, the same throughput as one default-policy thread. The four-fast-plus-six-slow topology makes an efficiency-core explanation plausible, but the probe did not record migrations or CPU IDs. The measured statement is narrower: the background resource class contributes little additional bandwidth after six threads, and the transition into that class can cost more scheduling work than its first added thread returns.
One detail I want on the record because it’s the kind of thing fabricated benchmarks never get right: the sum came back 136901655725 for every single thread count, 1 through 12. That’s not decoration. It means the range-splitting was correct at every N, no byte summed twice, none dropped, the partial sums reassembled exactly. If I’d gotten the range arithmetic wrong at, say, 7 threads, the sum would have quietly changed and the whole measurement would be garbage dressed as data. The invariant holding across every row is how I know the rows mean anything.
Which brings me back to the section I was proudest of, and least entitled to be.
The null result that didn’t survive a second look
Earlier I ran the byte-sum on performance cores and efficiency cores and got the same time on both, and I called that the most informative measurement in the post. If making the core three times faster does nothing, the core isn’t the bottleneck, so the loop must be waiting on memory. It was a clean argument. It was also, I now suspect, measuring nothing, and the cache-cliff and the thread sweep are what made me go back and check.
Because those two experiments say the opposite. They say one worker is the bottleneck, that a byte-sum with one runnable thread is limited by the resources available to that thread and remains nowhere near the whole-chip memory ceiling. If scheduler policy moves that worker into a materially slower resource class, the sum should slow down. My null result said it did not. Both things could not be right.
The tell was buried in my own earlier text. When I first tried to change placement, I set a background quality-of-service class on the thread. The timing stayed in the fast population, so I inferred that the scheduler had not materially reduced the resources available to it. I did not record CPU identifiers, so I could not say where it actually ran. I also did not go back and check whether the same weak control had poisoned the byte-sum measurement. So I checked now. Here’s the byte-sum with the QoS hint, the one I used originally, run six times:
E-hint run 1: 1675.3 ms
E-hint run 2: 1485.9 ms
E-hint run 3: 1457.8 ms
E-hint run 4: 1326.2 ms
E-hint run 5: 1412.1 ms
E-hint run 6: 1413.2 msThirteen to sixteen hundred milliseconds. Now the same loop and file under taskpolicy -b, the policy that reproducibly created the slow band:
taskpolicy run 1: 4890.9 ms
taskpolicy run 2: 4779.6 ms
taskpolicy run 3: 4980.1 msAlmost 4,900 milliseconds. Three and a half times slower. The QoS hint and the background policy were not equivalent controls, so my first comparison measured the fast timing population twice and assigned a core identity to one of them without evidence. The corrected result says the byte-sum is highly sensitive to the resources selected by scheduler policy. Without an affinity trace, it does not justify the stronger claim that every instruction stayed on one core class.
I ran it on the vectorized mmap version too, to be sure it wasn’t something peculiar to the volatile loop, prefaulted so no page faults muddied it:
default policy: 17.4 GB/s, 17.5 GB/s
background policy: 5.8 GB/s, 5.4 GB/sSame verdict. Seventeen and a half gigabytes a second under default policy, five and a half under background policy, a factor of about three. The byte-sum is not indifferent to scheduler policy. It never was. I’d built a small monument to a measurement that dissolved the moment I used a lever that produced a distinct timing population.
So what’s true about the roofline, now that the null result is gone? Something more interesting than what I’d written, actually. “Memory-bound” turns out to be a property of the whole chip, not of one loop. The gigabyte sum on one core is core-bound, capped at that core’s 17 GB/s, with the memory system idling. Gang up eight cores and now they collectively demand more than the memory system can supply, and the aggregate flattens at 100 GB/s, and only there does the program become memory-bound in the textbook sense. The same arithmetic is core-bound or memory-bound depending on how many cores you let it use. The roofline isn’t a single ceiling the program bumps into; it’s two ceilings, and which one you hit depends on how much of the machine you’ve enlisted. I drew one line and there were two.
If you’ve never seen the actual picture the word “roofline” comes from, it’s worth a paragraph now that I have real numbers to hang on it, because the shape explains why I could be so wrong. Imagine a graph. Along the bottom is arithmetic intensity: how much math you do per byte you load, in operations per byte. Up the side is how fast the program runs, in operations per second. On the far right, where you do lots of math per byte, the ceiling is flat, a horizontal line at the core’s maximum compute rate, and you’re compute-bound: bytes arrive faster than you can crunch them. On the left, where you do almost no math per byte, the ceiling is a diagonal that rises with intensity, and its slope is exactly the memory bandwidth, because when you barely compute, your speed is just how fast bytes can arrive times how much you do with each. My byte-sum lives at the far left of that graph. One add per byte is about as little math per byte as a loop can do, so I’m pinned against the diagonal, and the diagonal’s slope is a bandwidth. The only question was which bandwidth. And the answer, it turns out, is that there isn’t one line, there are two diagonals stacked on the same graph: a lower one whose slope is one core’s 17 GB/s, and a higher one whose slope is the whole chip’s 100. A single-threaded run rides the lower diagonal and never knows the upper one exists. That’s the shape I’d flattened into a single ceiling, and it’s why “speed up the core” and “add cores” are different fixes that a one-line roofline can’t tell apart.
That’s the correction. The measured version is better than the version I was proud of, which is annoying and also the entire reason to go back.
The disk I finally touched
The other borrowed number was the disk. Every read after the first came from the page cache in RAM, I’d shown that, and I’d waved at “the SSD is slow” without ever timing this SSD, because forcing a truly cold read needed a password the machine wouldn’t give me. But macOS exposes a descriptor flag I’d forgotten about. You can open a file and set F_NOCACHE. The fcntl(2) manual says this turns data caching off for that file. It does not promise that every later call waits for a physical flash transaction, and it is not equivalent to purging the system page cache. No password is required, so it still gives me a useful second path to compare with ordinary buffered reads.
int fd = open(path, O_RDONLY);
fcntl(fd, F_NOCACHE, 1); // request the uncached data path for this descriptorI summed the warm gigabyte the normal way, then again with F_NOCACHE set, same 1 MiB buffer both times:
ordinary buffered path: 105.2 ms 10.20 GB/s
F_NOCACHE path: 106.7 ms 10.06 GB/sIdentical. I stared at that for a while, because it’s the opposite of what the whole “the disk you only touch once” section led me to expect. I’d built up the page cache as this enormous speedup over the slow disk, and the uncached path kept pace with the buffered path to the tenth of a millisecond. That result alone cannot tell me how many bytes reached the SSD. It says that changing the caching policy did not change this large sequential pass.
To learn more, I leaned on how small synchronous requests expose fixed per-call and lower-layer costs. With a tiny buffer I issue far more calls and give the storage path less work per request. With a large buffer I amortize those costs over more bytes. This is not a device trace, but a strong size dependence would falsify the convenient explanation that the flag changed nothing at all. So I swept the buffer size with F_NOCACHE on:
F_NOCACHE bufsize=4096 1163.8 ms 0.92 GB/s
F_NOCACHE bufsize=65536 415.6 ms 2.58 GB/s
F_NOCACHE bufsize=1048576 146.5 ms 7.33 GB/s
F_NOCACHE bufsize=16777216 130.8 ms 8.21 GB/sThe policy change matters. At 4 KiB per read the throughput falls below a gigabyte a second. That row includes 262,144 calls, so fixed syscall, filesystem, block-I/O, and device costs have many more chances to appear. Grow the buffer and those costs are amortized over more bytes, climbing to 7 or 8 GB/s at the big sizes. The shape is consistent with sequential device I/O becoming efficient at large request sizes. It does not prove that every byte in every run came from flash. The defensible result is narrower: this F_NOCACHE path sustained roughly 6 to 8 GB/s on the large sequential runs and became much slower with small requests. That is close enough to the roughly 10 GB/s copy-and-sum loop that the two paths can produce similar whole-program times.
I’ll flag one loose end honestly, because it’s the sort of thing I’d want flagged. The first F_NOCACHE run, the one that matched the ordinary path at 10.06 GB/s, was faster than the 1 MiB point in the buffer sweep, which came in at 7.33, and reruns with large buffers wandered between 6 and 8 GB/s. Same flag, same file, different numbers by a third. The manual specifies a caching policy, not an observable count of flash transactions, and this probe collected no block-layer or device counters. Ordinary machine noise, storage state, and details of the policy are all possible contributors. The size sweep proves that request size materially changes this path. It does not let me relabel every measured byte as a physical SSD read. The honest range is the measured 6 to 8 GB/s for most large-buffer F_NOCACHE runs, plus one faster run I cannot fully explain.
The uncached path still hurts badly under random access. Sequential reads give the filesystem, block layer, controller, and device a predictable stream. Ask for one 16 KiB page at a random offset, wait for it, then ask for another, and the measured latency rises:
20000 random 16KiB F_NOCACHE reads: 28.9 us eachTwenty-nine microseconds per completed random read on this path. Compare that with a soft page fault, which maps a page already resident in memory and completed in a fraction of a microsecond in the later experiment. The access pattern changes the cost by far more than the word “disk” explains. “The disk is slow” was too blunt. Request size, ordering, queueing, cache state, and whether calls can overlap all matter.
What one read actually cost
While I had the stopwatch out, there was one more estimate in this post I’d never turned into a measurement. Right at the top I timed a bare getpid trap at 89 nanoseconds and called it the floor, then argued that read must cost more because it does more, looking up the descriptor, advancing the offset, finding the byte, copying it out. I never timed read itself. I inferred it from the sys total and moved on. So I timed it: open the file, read one byte at a time, twenty million times, and divide.
read() 1 byte from file: 327.7 ns each
read() 1 byte from /dev/zero: 270.5 ns eachAbout 320 nanoseconds for a one-byte read, against 95 for a getpid on the same run, so read costs roughly three and a half times the bare trap. That gap is read doing its actual job: the trap gets you into the kernel, and then the kernel still has to translate the file descriptor to a file, check that you’re allowed to read it, walk to the current offset, find the page the byte lives on, copy one byte across the wall into your variable, and advance the offset. Reading from /dev/zero instead of a real file shaves off about 50 nanoseconds, because /dev/zero has no file to seek through and no page to find, it just hands you a zero, so that 50 nanoseconds is roughly the cost of the file bookkeeping specifically, separated out from the raw crossing.
Then the number did something that made me happy. Three hundred and twenty nanoseconds a read, times the 67,108,864 reads in the byte-at-a-time slice from the very top of the post, is about 21 seconds. The measured wall time up there was 20.89 seconds. I derived the opening disaster from first principles, one syscall at a time, and it landed within a few percent of the number I’d actually clocked five thousand words earlier without ever intending the two to meet. The whole post is one program’s runtime taken apart, and here were two ends of it agreeing to the hundredth of a second. That’s the check I trust more than any single measurement: when a number I built up from the pieces matches a number I read off the clock, and I wasn’t trying to make them match.
The fault that arrived before the file
That leaves the one that actually bugged me: the single hard page fault in the warm mmap run, when every one of the 65,536 file pages was already in RAM and should have been a soft reclaim. One hard fault means the kernel went to a slow device for something. I couldn’t figure out what.
The way to find a fault you can’t explain is to remove everything it could possibly be until it’s still there or it’s gone. So I wrote the smallest program that could still fault, one that mmaps the file and never touches it, not a single byte read, and counted its faults. If the hard fault is about the file data, a program that never reads the data shouldn’t have it.
mmap but never touch the file: 240 page reclaims, 1 page faultStill there. So it’s not the file data. Then I went smaller still, a program that does nothing but print “hello” and exit, no mmap, no file, no gigabyte:
bare program (printf "hello"): 239 page reclaims, 1 page faultThere it is. One hard fault, in a program that opens no file of its own and maps no file explicitly. The control localizes the fault to startup or shutdown machinery shared by these two executables, rather than to the mapped data. The dynamic loader is one plausible source, but the aggregate fault count does not identify the instruction, page, or subsystem. I would need a trace that records the faulting address and stack to make that claim. What the control proves is useful enough: the single fault is present without the file experiment, so it cannot be charged to one of the mapped file’s data pages.
While I was doing this I got a scar I didn’t ask for. I ran the warm mmap sum three times in a row expecting three identical lines, and got:
run 1: 41,659 page reclaims, 24,120 page faults
run 2: 65,778 page reclaims, 1 page fault
run 3: 65,775 page reclaims, 1 page faultThe first run took twenty-four thousand hard faults. On a file I’d read dozens of times, that was supposed to be warm. What happened is that all the F_NOCACHE sweeps and the fresh files I’d been creating for the disk experiments had put the machine under memory pressure, and the page cache, which is only “spare” RAM, had quietly evicted a big chunk of my gigabyte to make room. The page cache isn’t a promise. It’s a lease, and the kernel can break it the moment something else wants the memory more. The next read had to hard-fault twenty-four thousand pages back off the SSD, which is exactly what a partially-cold read looks like, and I’d caused it myself without noticing. Two runs later it had settled back to warm. I’d been treating “warm” as a state the file was in. It’s a state the file is in right now, until it isn’t.
And since I finally had a clean way to make page faults on purpose, I measured what one costs. Map a big region of fresh anonymous memory, not backed by any file, and touch one byte in each page. Every first touch is a zero-fill fault: the kernel finds a free physical page, wipes it to zeros so it can’t leak another process’s data, and maps it in.
200000 zero-fill faults: 1280.5 ns eachAbout 1,280 nanoseconds per fault, roughly thirteen times the 95 nanoseconds a bare getpid trap costs, and the difference is real work: the kernel has to zero a whole 16 KiB page every time, which is 16 kilobytes of memory writes hiding inside each “invisible” fault. And it cross-checks against the mmap run in a way I like. The warm sum without prefaulting took about 100 ms; the same sum with every page faulted in ahead of time took about 62 ms. That 38-millisecond gap, spread over 65,536 file faults, is about 580 nanoseconds each. Cheaper than the 1,280 of a zero-fill fault, which makes sense: a file page that’s already in the cache doesn’t need zeroing, the kernel just points my mapping at the page that’s already there. Two different fault costs, one derived from a difference of two whole-program timings, the other measured directly, and they land in the same ballpark and in the right order. That’s the kind of agreement I trust, because I didn’t arrange it.
So the page faults weren’t free after all. They were about a third of the warm mmap run’s time, hidden as 65,536 sub-microsecond interruptions I’d called invisible. Invisible to my loop, which never knew they happened. Not invisible to the clock.
The stopwatch returned zero
There was still a problem with every number in the article. Most of them appeared once.
The 89 nanoseconds for getpid was one division after one long loop. The 327.7 nanoseconds for a one-byte file read was another. Those loops contained enough operations that the stopwatch itself was unlikely to dominate, but one large batch can hide drift, interruptions, and changes in scheduler behavior. It gives me an average with no account of how the individual measurements were distributed. It also leaves a more basic question unanswered: how small a duration can this stopwatch distinguish on this machine?
I measured the measuring code before trusting it again. The smallest possible timed region contains no operation at all:
using Clock = std::chrono::steady_clock;
auto start = Clock::now();
auto end = Clock::now();
double nanoseconds =
std::chrono::duration<double, std::nano>(end - start).count();I repeated that pair of clock reads 200,000 times. The first complete verifier run did not produce a small stable constant:
clock pair, 200000 samples
mean 23.3 ns
minimum 0.0 ns
p50 41.0 ns
p90 42.0 ns
p99 42.0 ns
maximum 167.0 ns
zero-valued samples: 88096Almost forty-four percent of the pairs returned the same timestamp twice. The next large population landed at 41 or 42 nanoseconds. The maximum was four times that. This does not mean two clock reads usually take zero time. It means the clock representation, the path that reads it, and the resolution visible to this process do not let me infer the duration of one tiny interval from one subtraction.
The mean is especially deceptive here. It is 23.3 nanoseconds, far below the median of 41, because 88,096 zeroes pull it down. A mean is the sum of every observation divided by the count. It is mathematically correct. It is not automatically a useful description of a distribution with two large clumps.
That immediately threatens the original syscall experiment. If a getpid call costs around 90 nanoseconds and a clock pair often reports 41 or 42, timing one syscall at a time spends a substantial fraction of the measured interval operating the stopwatch. Subtracting 41 nanoseconds afterward would not repair it. The clock cost and the operation are not independent constants, the duration is quantized, and an interrupt can land in either part.
Batching is the escape. Put many operations between the two clock reads, divide the elapsed duration by the operation count, then repeat the whole batch. The timer cost is paid once per batch:
template<class Function>
double ns_per_operation(std::size_t operations, Function&& function) {
auto start = Clock::now();
function();
auto end = Clock::now();
return std::chrono::duration<double, std::nano>(end - start).count()
/ static_cast<double>(operations);
}In that same run, I swept the batch size rather than choosing one that looked reasonable:
raw getpid calls per batch | batches | median ns per call | p99 ns per call |
|---|---|---|---|
| 1 | 200 | 84.0 | 125.0 |
| 10 | 200 | 95.8 | 100.0 |
| 100 | 200 | 93.8 | 95.4 |
| 1,000 | 200 | 92.9 | 99.6 |
| 10,000 | 200 | 91.5 | 93.4 |
The one-call row looks fastest at the median, which is a warning rather than a discovery about the kernel. The measurement interval is too close to the clock’s visible granularity. At 10,000 calls, one clock pair contributes about four thousandths of a nanosecond per call if its cost is roughly 41 nanoseconds. More importantly, the p99 has settled near the median instead of being shaped by one short timed interval.
Batching changes the question. The 91.5 nanosecond result is the average cost per call inside a batch of 10,000 calls. It is not the latency distribution of individual syscalls. If one call stalls for 50 microseconds, its cost is spread over the other 9,999 calls. That is acceptable when I want to reconstruct the twenty-one-second loop, because that loop also makes millions of calls continuously. It would be unacceptable if I were promising that 99 percent of individual requests finish below some deadline.
The compiler also has to be prevented from proving that the work does not matter. Each returned process ID is accumulated into a value printed at the end of the probe. For the read tests, every return count is checked and each byte contributes to another final value. The sinks are not business logic. They are evidence that the operations survived optimization and completed.
The stopwatch had already changed the experiment. Now the number of operations between its reads had changed what its answer meant.
One read became one hundred and twenty batches
The earlier comparison between a file and /dev/zero used two single averages:
read() 1 byte from file: 327.7 ns each
read() 1 byte from /dev/zero: 270.5 ns eachI had subtracted them and called the roughly 50 nanosecond difference file bookkeeping. That was a plausible decomposition, but two rows from one run do not show whether the difference survives repetition or whether one measurement happened during a quieter part of the run.
The replacement probe measures three operations:
- a raw
getpidsyscall, - a one-byte read from the already warmed file,
- a one-byte read from
/dev/zero.
Each sample is a batch of 20,000 operations. There are 120 samples of each kind, so every row represents 2.4 million completed calls. Before each group of three batches, I shuffle their order using a generator with a fixed seed. Sometimes the file batch comes first. Sometimes getpid does. That prevents a steady temperature or frequency change from always favoring the same operation merely because the test placed it first.
The fixed seed makes the order reproducible. It does not make the machine deterministic. Another process can wake, the scheduler can migrate this process, and power management can change frequencies. Reproducible randomization means I can reproduce which operation was offered each position. It does not promise the same nanosecond result.
The first verifier run produced these distributions:
| operation | mean ns | median ns | p90 ns | p99 ns | maximum ns |
|---|---|---|---|---|---|
raw getpid | 92.6 | 92.5 | 94.4 | 94.6 | 94.6 |
one-byte /dev/zero read | 269.8 | 269.4 | 272.6 | 273.9 | 274.0 |
| one-byte warmed file read | 304.6 | 304.0 | 307.4 | 309.1 | 323.5 |
These rows make the old explanation narrower and stronger at the same time. A one-byte file read still costs more than /dev/zero, but the difference between the medians in this run is 34.6 nanoseconds, not the roughly 50 nanoseconds from the earlier run. I should not promote either subtraction into a universal constant. The useful claim is that the warmed file path has a repeatable additional cost under the same batching and ordering scheme.
The subtraction still does not isolate one function inside the kernel. The file path and /dev/zero path differ in more than one place. Descriptor lookup occurs in both. Offset handling, vnode behavior, page lookup, copying from the backing object, and device implementation can differ. Calling the 34.6 nanoseconds “file bookkeeping” names the region of the path. It does not assign the time to a single source line.
The quantiles need a concrete definition. Sort the 120 sample values from fastest to slowest. The median, also called p50, is the middle of that ordered list. Half the batch averages are no greater than it, and half are no less. The p90 is the value near position 0.90 times 119, because the first position is zero and the last is 119. My code interpolates when the position falls between two samples:
double position = q * static_cast<double>(sorted.size() - 1);
std::size_t lower = static_cast<std::size_t>(position);
std::size_t upper = std::min(lower + 1, sorted.size() - 1);
double fraction = position - static_cast<double>(lower);
return sorted[lower] * (1.0 - fraction)
+ sorted[upper] * fraction;There are other quantile conventions, especially for small samples. Reporting the convention matters because two correct tools can disagree slightly at p99 without disagreeing about any observation.
The mean answers a different question. Add all 120 batch averages and divide by 120. If I run batches continuously, the mean helps estimate total elapsed time. The median describes a typical batch and resists a few long interruptions. The p99 tells me about the slow end of the observed batch averages. None is the one true latency.
This run happened to be quiet. The p99 for getpid was only 2.1 nanoseconds above its median. That does not entitle me to erase the distribution and publish 92.5 nanoseconds as a property of the M4. It describes this process, on this machine, under this load, with 20,000 calls averaged into each sample. I needed a control that would make the environment visibly worse.
The scheduler lived in the tail
I started one arithmetic loop for every hardware thread reported by the system and let those workers settle for 50 milliseconds. They repeatedly transformed an integer and stored the final values only after the measurement. Then I ran the same 120 getpid batches while those loops competed for CPU time. The following table is from the first verifier run.
This is a deliberate sensitivity test. It is not meant to resemble a production service or establish a useful overload level. The prediction was simple: if scheduler interference matters, some batches should be delayed even though the syscall code and batch size are unchanged.
| condition | mean ns | median ns | p90 ns | p99 ns | maximum ns |
|---|---|---|---|---|---|
| otherwise idle | 92.6 | 92.5 | 94.4 | 94.6 | 94.6 |
| arithmetic workers active | 115.6 | 95.7 | 167.4 | 320.9 | 379.7 |
The median moved from 92.5 to 95.7 nanoseconds, about 3.5 percent. If I reported only the typical batch, the loaded machine would look almost unaffected.
The p99 moved from 94.6 to 320.9 nanoseconds, about 3.4 times the idle value. The maximum reached 379.7. The mean rose to 115.6 because those slow batches contributed their full durations to the sum.
This is what it means for interference to live in the tail. Most batches still found enough CPU time to finish near the original rate. A smaller population waited much longer. The median describes the majority honestly and still misses the operational consequence if a caller cares about a deadline.
The word “tail” is spatial language for the right side of the sorted distribution, where larger durations live. It does not identify a cause by itself. The burner threads make scheduler contention plausible because contention was the variable I changed, but the probe does not record run queue length, CPU migration, frequency, or interrupts. The result falsifies the claim that the cost remains stable under CPU competition. A scheduler trace would be required to divide that extra time among mechanisms.
Batching hides individual-call tails, so these p99 values are p99 of 20,000-call averages. An isolated long pause must be large enough to move the whole average before it appears. That makes the loaded result more severe, not less: the interference persisted long enough to change the average of an entire batch.
If this were a request-serving benchmark, the batch average could be actively dangerous. Suppose 19,999 requests take 100 nanoseconds and one takes 100 microseconds. The average is about 105 nanoseconds. That number says almost nothing to the one caller who waited a thousand times longer than the others. Throughput work and latency work can use the same stopwatch while requiring different sample boundaries.
The opening file loop is throughput work. It asks how long 67 million sequential calls take together. The serving systems later in this site will need both views: total completed work per second and the distribution of time seen by individual requests. A benchmark has to choose its unit of observation before choosing a statistic.
The interval assumed the machine stood still
The distributions contain 120 samples, not every possible execution of the program. If I rerun the probe, the median changes slightly. I wanted a measure of how uncertain the estimated median was, so I used a bootstrap interval.
The bootstrap begins by treating the observed samples as a stand-in for the population that produced them. Draw 120 values from the observed set with replacement. With replacement means one original value can appear several times in a resample while another does not appear at all. Compute the median of that synthetic sample. Repeat 5,000 times. Sort the 5,000 synthetic medians and take the 2.5th and 97.5th percentiles.
That is exactly what the probe does:
for (int repetition = 0; repetition < 5000; ++repetition) {
for (double& value : sample)
value = samples[choose(random)];
std::sort(sample.begin(), sample.end());
medians.push_back(quantile_sorted(sample, 0.5));
}
std::sort(medians.begin(), medians.end());
double low = quantile_sorted(medians, 0.025);
double high = quantile_sorted(medians, 0.975);The NIST description of the bootstrap frames it as resampling observed data to study the variation of a statistic. I used a fixed pseudorandom seed so the interval calculation itself reproduces exactly for a given input vector.
For the idle getpid batches, the 95 percent bootstrap percentile interval for the median was 92.3 to 92.8 nanoseconds. /dev/zero produced 269.2 to 269.7. The warmed file read produced 303.7 to 304.3. These narrow intervals say that, given these samples and the bootstrap procedure, the location of each median is estimated precisely.
They do not say that 95 percent of future calls land inside those ranges. That is the job of a prediction statement, and even the observed p99 values describe batch averages rather than individual future calls. They also do not say there is a 95 percent probability that the fixed true median lies inside the interval. In the frequentist interpretation described by NIST’s confidence interval notes, the coverage belongs to the repeated interval-producing procedure.
There is a deeper assumption hiding beneath the resampling. The 120 values must be reasonable substitutes for one another. If the machine steadily warms, throttles, or accumulates background work, drawing an early fast value into a late synthetic position destroys the time structure that generated the data. The ordinary bootstrap treats samples as if order does not matter.
I added a crude drift check for that reason. The probe reports the median of the first 60 batches and the median of the last 60 separately. Equal halves do not prove stationarity, which means a stable data-generating process, but a large difference would expose a trend that the narrow bootstrap interval could conceal. A time plot and an autocorrelation analysis would be stronger if the series were longer.
The loaded getpid result shows another limit. Its bootstrap interval for the median was only 95.6 to 95.7 nanoseconds, even while p99 reached 320.9. There is no contradiction. The median is precisely near 95.7 because more than half the batches cluster there. The interval says nothing about how well I estimated the tail. To make a claim about p99, I would need enough tail observations and an interval for p99 itself. With 120 samples, the far tail is represented by very few points.
More samples can narrow sampling uncertainty while leaving systematic error untouched. I could collect a million batches with the process accidentally constrained by a power policy and estimate the wrong regime with many decimal places. Randomization, controls, environment records, and alternate machines attack different errors than a confidence interval does.
The interval did not make the benchmark authoritative. It forced me to state which uncertainty I had measured.
Thirty warm runs were still thirty numbers
The file experiment had the same single-number weakness. Saying the buffered 64 MiB pass took “under ten milliseconds” was enough to expose the catastrophe in the byte-at-a-time version, but it was too imprecise for detecting a smaller regression. /usr/bin/time had even printed 0.00 real for an execution that plainly took several milliseconds. Display precision had erased the result.
I warmed the file once, allocated and touched the 1 MiB user buffer, then timed 30 complete buffered passes. Every pass sought to offset zero, read to end of file, summed every byte, and checked that the sum remained 8552908975. The checked-in probe file differs from the early random slice, so its sum differs too. The invariant that matters is that all 30 passes produced the same sum for the same input.
I also read getrusage immediately before and after each pass. The prediction was that a warmed buffered read path should not incur data page faults in the measured region. If one slow pass showed thousands of major faults, cache state would be the first explanation to test.
The first verifier run produced this distribution:
passes: 30
mean: 6.8 ms
minimum: 6.5 ms
median: 6.7 ms
p90: 7.0 ms
p99: 7.9 ms
maximum: 8.2 ms
bootstrap 95% median: 6.6 to 6.8 ms
minor fault delta: 0 total
major fault delta: 0 totalMost passes landed between 6.5 and 7.1 milliseconds. The first measured pass was 8.23 milliseconds, the maximum of the run, even though the separate warmup had already read the whole file. The fault counters stayed at zero.
That negative control matters. It rules out measured minor and major page faults as the reason the first pass was slower. It does not tell me what the reason was. Scheduler delay, frequency state, branch predictor state, filesystem locking, and measurement noise remain candidates. I did not record enough data to choose among them.
It would be easy to delete the first row, call it warmup, and make the distribution look tighter. That would be dishonest because the warmup rule was decided before measurement: one unreported file pass warms the file, then all 30 measured passes count. A discard rule invented after seeing an inconvenient value is a way to tune the data rather than the program.
Warmup needs a stopping condition. “Run it a few times” gives the experimenter freedom to stop when the numbers look favorable. A better rule might require five consecutive medians over fixed windows to remain within one percent, with a maximum number of attempts and every attempt retained in the log. This probe uses the simpler fixed rule because the file is small and the page-fault counters provide an independent check. It cannot prove thermal or frequency steady state.
Now the phrase “a five percent regression” has something to push against. Five percent of the 6.7 millisecond median is 0.335 milliseconds. A new median near 7.0 milliseconds might be real, but one comparison would not establish it because the baseline itself ranged to 8.2 and a later run can occupy a different machine state. I would rerun old and new implementations in randomized alternating order, preserve each pair, and examine the distribution of paired differences. That experiment has not been run, so there is no regression result to report here.
Alternation matters for the same reason it mattered in the syscall test. Running all old binaries in the morning and all new binaries after the machine heats up assigns time to implementation. Pairing old and new close together lets each comparison share more of the surrounding conditions. Randomizing which one goes first prevents order from always favoring one side.
Statistical significance would still not decide whether the change matters. With enough repetitions I can detect a few microseconds that have no operational value. The practical threshold comes from the system around the loop. If this pass runs once at startup, 0.3 milliseconds may be irrelevant. If it runs thousands of times per request, the same difference can dominate. If a request has a 10 millisecond deadline, the p99 may matter more than the median. Units connect the benchmark to the consequence.
Then I ran the verifier again.
Every correctness assertion passed. The operations stayed ordered by cost: getpid, then /dev/zero, then the warmed file. Every file sum matched. All 30 file passes again recorded zero minor and major faults. Several performance numbers still moved:
| statistic | first verifier run | second verifier run |
|---|---|---|
| zero-valued clock pairs out of 200,000 | 88,096 | 133,736 |
| clock-pair median | 41.0 ns | 0.0 ns |
| clock-pair maximum | 167 ns | 22,458 ns |
idle getpid median | 92.5 ns | 90.7 ns |
| warmed file-read median | 304.0 ns | 305.3 ns |
loaded getpid median | 95.7 ns | 121.7 ns |
loaded getpid p99 | 320.9 ns | 358.0 ns |
| file-pass median | 6.7 ms | 6.4 ms |
| file-pass maximum | 8.2 ms | 8.2 ms |
The second clock-pair run is almost a caricature of the warning. Its median was zero because two thirds of the timestamp pairs were identical, yet one pair was delayed for 22.458 microseconds. A single statistic cannot represent both the quantization near zero and the rare interruption at the other end.
The quiet syscall and read medians moved only a few nanoseconds. Their ordering survived. The loaded median did not. Its bootstrap interval expanded from 95.6 to 95.7 nanoseconds in the first run to 96.4 to 159.6 in the second. The first interval was narrow because more than half of that run’s batches were tightly clustered. It never claimed that the next loaded run would reproduce the same cluster.
This is the distinction between uncertainty within one observed regime and variation between regimes. Resampling the first run can only draw values that occurred in the first run. It cannot invent the scheduler behavior that appeared in the second. Cross-run replication is therefore not an optional ceremony after a confidence interval. It tests a source of variation the ordinary bootstrap cannot see.
The file-pass maximum reproduced exactly to the printed precision while the median improved by about 0.3 milliseconds. That is another warning against choosing one number by habit. A throughput decision based on medians and a deadline decision based on maxima could judge the same rerun differently. Thirty samples are also too few to treat the maximum as a stable tail estimate. It is simply the largest value observed.
The article began with one impossible duration. The repeated measurements did not replace that duration with a more polished number. They forced me to identify how much work occurred between clock reads and whether the result described throughput or individual latency. The middle and the tail needed separate numbers. Drift needed a check outside the bootstrap. Each control ruled out one set of causes while leaving others open. The statistic had to match the decision the measurement would support.
The code was still summing bytes. The object being measured had become much larger than the loop.
Where it’s still going
I closed the last version of this on a list of things I hadn’t chased, and chasing them mostly meant finding out I’d been wrong in ways I could measure. The borrowed 120 GB/s ceiling became about 100 GB/s in this particular sweep, while one worker reached roughly a sixth of it. The uncached sequential path came surprisingly close to the buffered path at large request sizes and collapsed at small ones. The hard fault I couldn’t explain was already present in the empty control. And the null result I was proudest of came from treating a scheduling hint as placement evidence.
The new threads are better than the ones I tied off. I still don’t know exactly what caps one worker at 17 GB/s, whether it is the load machinery, vector execution, translation, or some shared path. The flat cache size sweep rules out a simple DRAM bandwidth story but does not select among those mechanisms. I don’t know why the fifth worker specifically loses ground instead of merely failing to help. The timing boundary is consistent with a scheduling and core class transition, but without CPU identifiers and migration events that remains an inference. And I never did get DTrace to count the read calls exactly, the same wall as the disk purge: “DTrace requires additional privileges,” system integrity protection on, no password. So the syscall counts in this post are still inferred from the byte count. I believe them. I have not observed them directly. That thread is still open, and this time I know it is the privilege boundary and not my patience that is in the way.