Time that never passed
※ laptop fan, a long night
Rime's guest tests are 47 small programs that boot together under QEMU, run side by side on two virtual CPUs and print one line each. A full run takes about half a minute on the Mac. After a long session of filesystem speed work, with 64 KB transfers between programs and the filesystem server, a new path through stdio and a larger buffer in cp, the suite started failing now and then. One run lost the output of fsstattest, and another reported that a shell inside spawntest had ended with status 0x8b, a segmentation fault. The run after each of them passed.
New code that moves memory around in bigger pieces is the first thing anyone would suspect, and I did. But a failure that comes once in ten runs can't be judged from one run or from three, so before reading any code I let the suite run in a loop and kept every log.
working tree, 23 runs fsstattest 2, reticulumtest 1
That showed the rate, but not where the failures came from, so I checked out the commit from before the speed work into a second directory and ran it the same way.
older commit, 12 runs fsstattest 1, spawntest 1, 60 second stall 1
Everything I had seen on the new tree also happened on the old one. The speed work was off the hook, and I had several old bugs to find instead of one new one.
fsstattest runs a three line script through the shell and then reads the file it wrote:
fsstat > out
fsstat --help >> out
fsstat unexpected >> out 2>&1
When it failed, the file held the output of the first two commands and nothing from the third. Rime gives a program pipes for its standard streams and never a file. When the shell redirects to a file, the filesystem server starts a thread, which I call a pump, that reads the pipe and writes what it gets into the file. If the program writes its last line and exits straight away, those bytes may still be in the pipe when the test asks for the file.
I had the test wait half a second after a failure and read the file again, and by then the third command's output was there. A pump now reads its pipe only while it holds the filesystem lock, and the server empties all the pumps into their files before it handles any request. Once a program has exited, whatever it wrote is in the file for the next reader, as anyone used to Unix would expect.
I also wanted a test that would catch this every time, so I wrote one that copies 64 KB through cat with a redirection, five rounds in a row. With the fix taken out it still passed six runs out of six. I removed it again and left fsstattest to guard the fix, since it does catch the race now and then.
reticulumtest failed once in those runs as well, for a smaller reason. It makes two announces and checks that both carry the same timestamp, which is in whole seconds, so a second limit between the two calls was enough. The check now allows one second of difference.
The worst failure didn't look like either of those. Every so often five or six tests never finished, and init gave up on them after 60 seconds. They were always from the same group: gittest, memtest, spawntest, killtest, reticulumtest and sometimes certutiltest. The first two times, the laptop was running on battery and I put it down to that, until it happened on the old commit with the laptop plugged in.
memtest was in the list each time, and it relies on the pager server, which also grows every program's stack. The pager drops a request without an answer when it can't share a page, which looked like a good way to freeze everything at once. I put logging on that path and on the kernel watchdog that reports tasks waiting too long, and the next stall printed nothing from either. The watchdog only runs when a time slice ends, which is rare on a CPU with little to do, so its silence told me absolutely nothing.
I replaced it with a dump of every task, set to print 40 seconds after boot, a point a normal run never reaches. The first stall after that produced no dump at all, and that turned out to be the really useful part. QEMU had been running for less than 40 seconds, and the log in front of me said:
test: memtest did not finish status 0 reason 0 in 69849 ms
No task was stuck. The guest's clock had jumped about a minute ahead, so init saw its deadline pass and wrote off every test still running as unfinished. That's why it was always the same handful of slow tests, and why those runs ended sooner than the good ones.
The clock counts PIT interrupts, one per millisecond. The kernel sometimes runs with interrupts off for a while and loses ticks, so each interrupt read the CPU's timestamp counter and counted any ticks that had gone missing since the previous one. For that it needed to know how many counter cycles make one tick. It learned the number from the spacing of the interrupts as they came in, moving an eighth of the way towards each new gap.
That holds up on the Booklet, where the PIT keeps at most one late tick, but QEMU behaves differently. When its own thread falls behind, it hands the guest the ticks it owes in a burst a few cycles apart, and each one pulls the learned number down. This is one line of logging from a run that passed:
pit ticks=28 delta=13654000 cpt=482670 tscms=1000100
13.65 ms had gone by and the kernel counted 28 ticks. It had learned that a tick was 482,670 cycles long, when the counter runs at 1,000,100 cycles a millisecond, and in the stalled runs the number had fallen much further.
The rate is already measured once at boot against the PIT, so the kernel now uses that measurement and stops learning. Each interrupt counts the whole ticks of counter time since the last tick it counted, which is zero for a tick that turns up early in a burst and several for one that comes late. The Booklet idles with hlt, which leaves its counter running at a fixed rate, so the rule works the same way there.
That left the shell. For a while, a build of this site on the Booklet had sometimes gone back to the prompt halfway through without an error, and I had never looked into it. I ran it five times over SSH and printed the status after each run:
run1 status=0 Build complete in 21s
run2 status=0 Build complete in 24s
run3 status=139 Building site...
run4 status=139 Building site...
run5 status=139 Building site...
139 is 128 plus 11, the same segmentation fault spawntest had shown. Nothing reached the log, because the shell catches its own faults with a handler that ends the process with that status and prints nothing.
Rime has no fork, so the shell runs $(...) and here documents on threads inside its own process, each on a stack the shell allocates. A finished thread signals a notification, and the side waiting for it then frees the stack. In the compiled shell, the thread's function goes on like this after the signal:
int $0x80 ; the notification: I am done
add $0x10,%esp
lea -0xc(%ebp),%esp
pop %ebx
pop %esi
pop %edi
pop %ebp
ret ; return address read from the stack
Those six instructions still use a stack that the other side is allowed to free. Usually the memory hasn't been reused yet and ret finds the right address, but when it has been, the shell jumps somewhere random and dies.
The thread now calls exit straight after the notification, and the waiting side frees the stack only once the kernel says the thread is gone. Ice[1]'s HTTP worker already did it this way, with a comment above its join saying that completion alone does not prove the worker has left its stack. I copied the new shell to the Booklet on its own first, and six builds out of six finished. Six more finished after the new image went on.
The builds had one more problem, and this one was in Nordr. Every build left files in /Media/User, and there were 118 of them by the time I looked. A crashed build can't run its cleanup, which explains some, but a build that finished still left six behind. All six came from build_fragments, which loops over the fragments like this:
cut -d'|' -f1 "$TMP_FRAGMENTS" | sort -u | while read -r f_slug; do
...
TMPFILES+=("$tmp_c")
done
A while at the end of a pipeline runs in a subshell, in Bash as well as in Rime's shell. The files it adds to TMPFILES are gone when the loop ends, so the cleanup never sees them, two for each of the three fragments here. Reading the loop's input from a process substitution keeps it in the main shell:
while read -r f_slug; do
...
done < <(cut -d'|' -f1 "$TMP_FRAGMENTS" | sort -u)
Ten builds after the change left /Media/User empty.
The suite has since passed twenty runs in a row, and two things are still open. In one run out of about sixty, httpservertest's own server stopped answering partway through, and I haven't looked at that yet. Over the last ten builds the build time also went from 34 seconds to 45, rising a little each time with nothing else running, and I don't know yet what is growing.
[1] That's not a typo, Ice is not a different name for Rime.