Rewind VM: a flaky build you only catch once

If a test fails on CI and nobody can reproduce it, did it really fail? 🧘

Nix gives me a build that is a function of its inputs via the extensional model. The same derivation, produces the same store path, and if I am lucky, the same bytes. What Nix does not give me is the same run.¹1A run is the sequence of events that happen in a process to produce a result. A build is a run of a derivation. A test suite with a race in it may pass on my laptop, fail once on CI, and when I rebuild it to look, it passes again.

If you have experienced bugs like this, you know that it can be frustrating. You are effectively at times trying to find the needle in the haystack.

I wrote recently that the Nix sandbox is a hidden input to a derivation. The same is true of the thread schedule. The order the kernel happens to run your processes in decides whether some builds pass, and nothing within the derivation records it.

These are the hidden inputs to a build that can make it flaky.

Are we left to hoping that we will find the needle in the haystack? Or is there a way to make the run a function of its inputs too?

I built Rewind VM to make the schedule an input too. It runs a Nix build, a test suite or any Linux command inside a KVM virtual machine whose every run is a function of its inputs. The same inputs give the same run, at the same steps, every time. You can replay a failure, scrub through it, read any file as it was at any point, and fork it under a different thread interleaving. ✨

Confused? Yes it sounds like magic. The best way to explain it is with short demo.

§A textbook deadlock

Let’s investigate the dining philosophers problem. The problem is that the five philosophers sit at a round table with a fork between each of them. A philosopher needs both forks beside them to eat. A philosopher may pick up one fork at a time.²2The world is a metaphor for the thread scheduler. Each philosopher is a thread and each fork a mutex.

The philosophers take turns, until all five pick up their left fork at once.

/* The fork on the left first, then the fork on the right. */
int first = left;
int second = right;

/* Eat MEALS times, holding both forks for each meal. */
for (int meal = 0; meal < MEALS; meal++) {
  pthread_mutex_lock(&forks[first]);
  printf("philosopher %d picks up fork %d\n", id, first);
  pthread_mutex_lock(&forks[second]);
  printf("philosopher %d picks up fork %d and eats\n", id, second);
  pthread_mutex_unlock(&forks[second]);
  pthread_mutex_unlock(&forks[first]);
}

If all five pick up their left fork before any of them reaches for a right one, every fork is taken and every philosopher waits on a neighbor who is also waiting. Deadlock.³3The program stops making progress and never exits, so the check phase runs it under timeout 10, which kills it and exits with status 124.

On my laptop 14 of 100 rebuilds deadlocked. 💣

$ nix build --rebuild -L github:fzakaria/rewindvm#philosophers
...
philosophers> philosopher 3 picks up fork 3
philosophers> philosopher 0 picks up fork 0
philosophers> philosopher 4 picks up fork 4
philosophers> philosopher 2 picks up fork 2
philosophers> philosopher 1 picks up fork 1
philosophers> make: *** [Makefile:14: check] Error 124
error: Cannot build '/nix/store/fp2dx8yh62kik2nknqmjzrga0d9yd75s-philosophers-0.1.0.drv'.

rewind nix builds the same derivation the way the Nix sandbox would, inside the deterministic VM.

$ rewind nix github:fzakaria/rewindvm#philosophers
rewind: packing 62 store paths for philosophers-0.1.0
...
rewind: run 1b21bf17737bcb37 exited:0 after 4583 steps, 0.126s virtual, 6.146s wall (poweroff)
# the hash of the output tree, compared against the host's build
/nix/store/g0zkyzprrlhrnw8sf42xl49gjn2lzq62-philosophers-0.1.0 fad5714e2ad61159 (same as the host's build)

Oh darn, it passed! That means it will pass forever right? Not quite. The VM is deterministic, but the guest kernel’s scheduler is not. It can reschedule threads at different points in the program, and that can change the outcome.

To find the other interleavings, rewind check runs the build again under perturbed schedules, we effectively ask the guest kernel to reschedule at different steps which causes a different sequence of events.

$ rewind check github:fzakaria/rewindvm#philosophers
schedule   0: exited:0             4583 steps  fad5714e2ad6  run 1b21bf17737bcb37
schedule   1: exited:2             6483 steps    run 83be7294525ddb91
schedule   2: exited:0             5396 steps  fad5714e2ad6  run 6d76063661b1010b
schedule   3: exited:2             7503 steps    run 800c0f86aef3116b
# 13 more schedules omitted
...

schedule 1 ends differently; narrowing the steps it perturbs
perturbing only steps 1748..3461 still ends differently

passing: run 1b21bf17737bcb37
failing: run b0739df0eacce572

rewind check runs one VM per core by default and stops after the first batch of schedules where the exit code differs.

Note A failing schedule on its own is not that super helpful. Schedule 1 which had deadlocked likely perturbs every step from the start of the build to the end, and most of those perturbations have nothing to do with the deadlock. To help with this, check narrows it: it shrinks the window of steps the schedule may perturb, first pulling in the end and then the start, reruns the build for each candidate window, and keeps the smallest one that still deadlocks.

For our deadlock problem, it might be easier to see the last few lines of the log and see that all five philosophers have picked up their left fork and are waiting for the right one.

$ rewind log b0739df0 | tail -6
philosopher 0 picks up fork 0
philosopher 3 picks up fork 3
philosopher 4 picks up fork 4
philosopher 1 picks up fork 1
philosopher 2 picks up fork 2
make: *** [Makefile:14: check] Error 124

We can also inspect the events, which are the same as the log but with timestamps and thread IDs.

$ rewind events b0739df0 | grep -A1 'philosopher 2 picks up fork 2'
      3470   140/143   write(1, "philosopher 2 picks up fork 2\n")
      4243   139/139   SIGALRM code=-2 addr=0x0

What if I’m not familiar with the VM? Can we look around? Yes!

rewind shell drops you into a shell inside the VM at any step, in a process’s working directory, with the build’s environment, while everything else in the VM stays stopped. We can use --with nixpkgs#gdb to bring gdb into that shell, and gdb can attach to the stuck process.⁴4There is actually native support for gdb in the VM already. You can also use --with to bring in any other tool you want to use.

$ rewind shell b0739df0 3471 --pid 140 --with nixpkgs#gdb
rewind: a shell at step 3471 of b0739df0eacce572; exit it to leave
[rewind] /build/philosophers # gdb -q -batch -p 140 -ex 'thread apply all -q frame function dine' -ex 'python print([int(gdb.parse_and_eval(f"forks[{i}].__data.__owner")) for i in range(5)])' 2>/dev/null
...
#2  0x0000560d082a0237 in dine (arg=<optimized out>) at philosophers.c:27
27			pthread_mutex_lock(&forks[second]);
#2  0x0000560d082a0237 in dine (arg=<optimized out>) at philosophers.c:27
27			pthread_mutex_lock(&forks[second]);
#2  0x0000560d082a0237 in dine (arg=<optimized out>) at philosophers.c:27
27			pthread_mutex_lock(&forks[second]);
#2  0x0000560d082a0237 in dine (arg=<optimized out>) at philosophers.c:27
27			pthread_mutex_lock(&forks[second]);
#2  0x0000560d082a0237 in dine (arg=<optimized out>) at philosophers.c:27
27			pthread_mutex_lock(&forks[second]);
[141, 142, 143, 144, 145]

All five philosophers are on line 27, waiting for their second fork.

rewind cat, rewind shell and rewind gdb each work on a “throwaway” fork of the run at a step, so nothing they do changes the recording.

You can use rewind to do a “real” fork: it branches a run at a step under another schedule.

$ rewind fork 1b21bf17 1748 --schedule 1 --quiet
rewind: run 0c8d8aa42424941d exited:2 after 6213 steps, 10.111s virtual, 16.938s wall (poweroff)
rewind: the fork first differs from its parent at step 1770

A recording does not have to stay on the machine that made it. rewind export --replayable packs a run into a single .rwd file, with the VM’s kernel, its input image and the keyframes, so another machine with the same CPU vendor can replay it.⁵5Without --replayable, rewind export writes only the run’s trace, its events and output, and leaves out the kernel, the input image and the keyframes. The file is much smaller and enough to read the run with rewind log and rewind events. It can’t be replayed or forked, though, so rewind cat, rewind shell and rewind gdb need the full export.

$ rewind export b0739df0 --replayable -o deadlock.rwd
rewind: wrote deadlock.rwd (176.4 MB)

# on another machine
$ rewind import deadlock.rwd
b0739df0eacce572  exited:2          4299 steps  philosophers-0.1.0
$ rewind replay b0739df0
identical: 1427 events over 4299 steps

You are no longer beholden to a random flake on CI.

Run the tests under rewind check on a CI machine with KVM, upload the failing run’s .rwd as a build artifact, and you can reproduce the bug perfectly on your machine.

How do we fix the deadlock?

We number the forks and always pick up the lower numbered one first. The last Philosopher now reaches for fork 0 before fork 4, so the waits can never cause a deadlock.

-	/* The fork on the left first, then the fork on the right. */
-	int first = left;
-	int second = right;
+	/* The lower numbered fork first, then the other one. */
+	int first = left < right ? left : right;
+	int second = left < right ? right : left;

We can then run rewind check --all to test the fix.

$ rewind check --all .#philosophers
...
0 of 64 perturbed schedules ended differently
same result under all 65 schedules

Before the fix, 9 of the same 64 schedules deadlocked.

Rewind VM includes some tutorials with more examples of using rewind to find and fix bugs if you want to explore further.

§What is Rewind VM?

The VM has a single vCPU on stock KVM, so guest code runs on the real CPU at close to native speed.⁶6GNU hello build from nixpkgs takes 11.7 s in the VM vs. 14.3 s without it on the same laptop. What breaks determinism in a normal VM is everything that reaches the guest from outside its instruction stream: timer interrupts, clocks, random numbers, I/O completions, and any other event

Rewind removes each of those or replaces it with a value it controls. Keeping account of every event and the step it happened at, it can replay the same run.

If you squint, a run is a derivation. Its inputs are the kernel, the initramfs, a root filesystem (a Nix closure packed into a read-only image), the command, a seed and a schedule. Change any of them and you get a different run. Change none of them and you get the same one.

The rewind command is open source under the MIT license.⁷7The guest kernel patch is GPL-2.0 alongside Linux.

There is also a desktop app that gives a friendlier view of a recorded run. You can drag the playhead, view the build log, the process tree and the files at any event. “Open shell” and “Attach gdb” open a terminal pane on a fork at the playhead.

§Footguns

One vCPU. Threads interleave but never run in parallel, so races that need two cores at once are out of reach.
No preemption between system calls. A thread spinning on a flag without yielding stalls the VM.
AMD needs sudo rewind pmu enable once per boot for the exact clock.⁸8The NixOS module can do it automatically for you and without the setting Rewind falls back to a coarser clock.
A run replays only on the CPU vendor it was made on, AMD from Zen 2 on.
No network besides loopback, and x86_64 Linux hosts with KVM only.

§Rewind in the wild

I pointed Rewind at some tools I use every day to see what we can find. Each of these is reported upstream with a fix.

Nix: gc-closure.sh dies of SIGPIPE when head -n1 exits between two writes. It never failed in 20,000 runs on my laptop and failed on the first run in Rewind. #16546, fixed by #16547 (case study).
Nix: several processes creating a new store at once fail with “database is busy”, as seen on Hydra. #15987, fixed by #16554.
nixd: formatter output over 64 KiB hangs the language server. #899, fixed by #900.
jujutsu: three tests fail about half the time on tmpfs, because operations ending in the same millisecond are ordered by a random id. #10306, fixed by #10307.

§Try it

$ curl -fsSL https://rewindvm.dev/install | sh
# or
$ nix run github:fzakaria/rewindvm -- check github:fzakaria/rewindvm#philosophers

On NixOS there is a module:

inputs.rewind.url = "github:fzakaria/rewindvm";

# with inputs.rewind.nixosModules.default imported
programs.rewind.enable = true;
programs.rewind.app.enable = true;
# AMD only: make the branch counter exact at every boot
programs.rewind.amdBranchCounterWorkaround = true;

If you have a test that fails on CI once a week, I would like to hear whether Rewind catches it and helped you debug it.

Don’t just add a sleep and paper over your concurrecy failures anymore, replay them. 🔁