Five ways my benchmarks lied to me

I spent a few weeks benchmarking two things: five parallel kernels in C with OpenMP, and seven concurrent data structures in Java, lock-based and lock-free, timed from 1 to 16 threads. Both ran on the same 4-core i5-7500 under macOS. The Java side alone is 1,890 timed runs.

None of the bugs below crashed anything or printed an error. Each one produced numbers that looked reasonable, sometimes better than reasonable, and each would have gone into the report if I hadn't gotten suspicious. That's the part worth writing down.

1. I was benchmarking the clock

The Java harness runs each structure for a fixed time and counts operations. The first version checked the deadline after every operation:

// roughly what the first version did
while (System.nanoTime() < deadline) {
    doOneOperation();
    count++;
}

Every fast structure hit the same ceiling, about 29 million operations per second, whatever the thread count. A read-only peek on a stack should scale with cores, and it sat flat at 29 MOPS.

So I timed the clock on its own. On macOS, HotSpot keeps nanoTime() monotonic with a compare-and-swap on one shared word, so every call from every thread fights over the same cache line. One thread got about 30 million calls per second, and four threads got 26 million between them. My benchmark had found the throughput of System.nanoTime().

It's right there in HotSpot's macOS port, os_bsd.cpp:

jlong os::javaTimeNanos() {
  const uint64_t tm = mach_absolute_time();
  const uint64_t now = (tm * Bsd::_timebase_info.numer) / Bsd::_timebase_info.denom;
  const uint64_t prev = Bsd::_max_abstime;
  if (now <= prev) {
    return prev;   // same or retrograde time;
  }
  const uint64_t obsv = Atomic::cmpxchg(&Bsd::_max_abstime, prev, now);
  ...
  // Avoiding excessive CAS operations to hot RW locations is critical.

Every call that sees time move forward tries a compare-and-swap on _max_abstime, a single global. The comment two lines below even warns about the exact thing my benchmark did. Aleksey Shipilëv's Nanotrusting the Nanotime covers the cost of timers in much more depth.

The fix is to look at the clock less often:

while (System.nanoTime() < dl) {
    for (int j = 0; j < CHECK_EVERY; j++) {   // CHECK_EVERY = 64
        int e = w[i++ & MASK], k = e >>> 2;
        switch (e & 3) {
            case 0: ds.read(k); break;
            case 1: ds.insert(k); break;
            default: ds.delete(k);
        }
    }
    c += CHECK_EVERY;
}

peek went from a flat 29 MOPS to over 1,400.

2. The garbage collector was keeping my queues alive

Next, the two linked queues (a two-lock queue and Michael-Scott) started overshooting their 2-second runs by up to 0.8 seconds. GC logs showed 125 to 160 ms pauses and a live heap growing from 95 MB to 290 MB. A queue that keeps half its operations as dequeues shouldn't grow.

It wasn't growing. Its history was being kept alive. When you dequeue from a linked queue, the old sentinel node becomes garbage, but it still points at the next node. If that dead sentinel has survived long enough to be promoted to the old generation, a young collection treats its next pointer as a root. The node it points to survives and gets copied, along with everything after it. Each young GC was copying the entire chain of dequeued nodes.

The fix is one line: point the dead node at itself, so it holds nothing alive.

} else if (head.compareAndSet(first, next)) {
    first.next.set(first);   // self-link: a stale reader sees this and fails its head check
    return next.value;
}

I found out afterwards that java.util.concurrent.ConcurrentLinkedQueue does the same thing, for the same reason.

3. Sleep stops the clock

A full sweep takes about an hour, long enough for the Mac to fall asleep partway through. System.nanoTime() stops while macOS sleeps, so a run that straddles a sleep comes back looking short and slow, which reads as a performance result and not as a broken run.

caffeinate -i wasn't enough to prevent it. Now the sweep runs under caffeinate -dims on AC power, and before any results are accepted, a script rejects every raw file with an elapsed time above 2.05 seconds.

4. OpenMP made my loop 5.5x slower

This one was in the C kernels: squaring a matrix whose entries are all −1, 0 or 1. The hot loop is just c[j] += b[j] over a row. With Apple clang, that loop written inside an omp parallel for ran in 0.48 s at N = 1024. The same loop in a build without OpenMP ran in 0.087 s, 5.5 times faster, on one thread in both cases.

The disassembly explained it. The sequential build had 108 vpaddd instructions in the kernel and the OpenMP build had 36. OpenMP moves the body of a parallel region into a separate function, and in that function the loop was vectorised but barely unrolled.

The fix is to give the compiler a small function with no aliasing questions, and to stop it inlining that function back into the parallel region:

NOINLINE static void row_add(int32_t *restrict c,
                             const int32_t *restrict b, int n)
{
    for (int j = 0; j < n; j++) c[j] += b[j];
}

After that, the OpenMP binary on one thread is within 2% of the sequential binary on all five problems.

This bug flatters you. Speedup is time at one thread divided by time at t threads, so a slow one-thread baseline makes every speedup look better. My speedup plots would have improved while the code got slower.

5. zsh ran the default algorithm six times

The sweep script passed options through a variable:

args="--algo bmm --block 4"
prog $args

Bash splits $args into four arguments. zsh doesn't, so the program received one argument, "--algo bmm --block 4", matched no option, and quietly ran the default unblocked kernel. I got a table of six "block sizes" that were all the same algorithm. They were, unsurprisingly, identical.

Now any unrecognised option is a hard error, with a hint when the argument contains a space. I'd rather the program refuse to run than report a confident wrong number.

What was left once the numbers were honest

With all five fixed, the stacks showed something I didn't expect. Under a write-heavy load (half pushes, half pops), the lock-free Treiber stack falls from 51 MOPS at one thread to 9.6 at four. Every thread fights over the same top pointer, and failed compare-and-swaps add more traffic to that one contended cache line. The plain lock-based stack holds 19.5, twice as much. The elimination stack is the outlier: pushes and pops that collide cancel each other in a side array and never touch top, which gives it 3.3 to 4.4 times Treiber's throughput from 8 to 16 threads.

The dip at two threads

One result didn't fit. LockStack drops from 30.7 MOPS at one thread to 8.4 at two, then climbs back to 19.5 at four, and all five runs agree. The lock-free stack falls smoothly, with no dip, so I suspected the lock, not contention on top.

My guess was handoff cost. LockStack uses a non-fair ReentrantLock. With two threads, the waiting thread is usually parked, so nearly every unlock has to wake it up, which costs a system call. With more threads, a running thread can barge in and take the lock before the woken one gets scheduled, so most handoffs skip the wake-up.

Both halves of that are visible in the JDK source. The non-fair lock's first move is an unconditional compare-and-swap, while the fair one checks the queue first (ReentrantLock.java):

// NonfairSync.initialTryLock()
if (compareAndSetState(0, 1)) { // first attempt is unguarded

// FairSync.initialTryLock()
if (!hasQueuedThreads() && compareAndSetState(0, 1)) {

And every unlock that finds a queued waiter wakes it (AbstractQueuedSynchronizer.java):

public final boolean release(int arg) {
    if (tryRelease(arg)) {
        signalNext(head);          // -> LockSupport.unpark(s.waiter)
        return true;
    }
    return false;
}

A woken waiter that loses the race to a barging thread spins briefly and then calls LockSupport.park(this) again, so one handoff can cost an unpark, a wake-up and another park on top of the work itself.

So I made three copies of LockStack that differ only in the lock and ran them all again:

With barging forbidden, every handoff has to wake someone, and throughput collapses to 0.2 MOPS. With parking removed, the dip disappears. The spin lock never recovers, though, because spinning only gets worse as you add threads, so the recovery from three threads up has to come from parked threads staying parked while running threads barge past them. Java Flight Recorder agrees: two threads park about 0.15 times per operation, four threads about 0.023, roughly 6.6 times less often.

A fourth copy counted how often the optimistic read of top goes stale and the lock has to be taken again. That happens on 7.5% of acquisitions at two threads and 0.7% from three up. That's ten times higher, but far too small to cause a 3.5x drop on its own. It does fit the picture: at two threads the threads strictly alternate, and at three or more one barging thread takes the lock several times in a row.

What I still don't understand is why the switch is so sharp, all of it between two and three threads and none of it gradual. That's the next thing I want to take apart, on Linux, where I can pin threads to cores. The variants, the park counter and the raw results are in lockstep/experiments/lockstack-dip. If you know why it switches at three, I'd like to hear it.

What I do differently now

Each of these produced a believable number, so "does the output look reasonable" was never going to catch them. What caught them was cross-checking things that should agree: the clock's own throughput against the benchmark's, the requested run time against the measured one, the OpenMP binary on one thread against the sequential binary, and six configurations that should have differed and didn't. The C harness now prints a checksum on every run and refuses to report a time for a result it couldn't verify against the sequential version.

Everything is in parallel-universe: the code, every raw run, the gnuplot scripts and both reports. If you rerun it on Linux, I'd like to know whether the nanoTime ceiling disappears. Email me.

References

• OpenJDK 17, os_bsd.cpp: os::javaTimeNanos() on macOS.
• OpenJDK 17, ReentrantLock.java and AbstractQueuedSynchronizer.java.
• OpenJDK 17, ConcurrentLinkedQueue.java, which self-links dequeued nodes for the same GC reason.
• Aleksey Shipilëv, Nanotrusting the Nanotime (2014).
• Maged M. Michael and Michael L. Scott, Simple, Fast, and Practical Non-Blocking and Blocking Concurrent Queue Algorithms, PODC 1996. The two-lock queue and the Michael-Scott queue.
• Danny Hendler, Nir Shavit and Lena Yerushalmi, A Scalable Lock-free Stack Algorithm, SPAA 2004. The elimination stack.
• JMH, the harness I should have used, and now understand why.