I spent time examining the Apple II emulator's simulated floppy disk drive, and the virtual memory implementation in the Z-code interpreter, in order to explain the
"drifting" behavior I've spoken of: a small change in one command can cause later commands to run slower or faster, by up to dozens of frames, seemingly almost at random.
I've determined, to my satisfaction, that the cause does not have anything to do with the simulated floppy drive. That part is consistent and predictable. The cause, rather, is the virtual memory paging code in the Apple II Z-code interpreter (6502 code), which behaves more like a random number generator than one would hope. The virtual memory page table is supposed to be an
LRU cache; that is, when a page of memory is needed that is not already in the page table, the page table is supposed to evict the least recently used page in order to make room for the needed page to be swapped in. But because of a flaw in the implementation (or, perhaps, a deliberate design choice for the sake of simplicity), the page that gets evicted is not always the least recently used one–in fact, it is frequently one of the
most recently used pages. When an evicted page is needed again later, it has to be swapped back in, which takes time. Sometimes, though, by chance, the wrongful eviction of a page happens to live up favorably with future disk access patterns. It is this, I believe, that gives rise to the "drift" in the timing of commands.
Floppy disk drive
In a past TAS project, I had the challenge of
dealing with a simulated floppy drive (on a PC platform). There, the challenge was that accessing the disk incurred a delay of 1.2 s to allow the drive motor to spin up—but accessing the disk while the motor was already spinning incurred no additional delay. The general strategy was to avoid accessing the disk as much as possible—but then to batch many accesses together, while the disk was still spinning, when access was unavoidable. I thought something similar might be happening here.
I also had a vague hypothesis that the emulator was simulating the rotation of the disk, or something, and that to read a sector one would have to wait until that sector spun around to arrive under the read head. Subtle changes of timing would affect the phase of the disk's rotation in a way that would make some disk accesses faster and some slower.
Neither of the above is the case. The timing of different disk accesses throughout the run is indeed variable, but it breaks down into a few isolated components that are consistent and predictable. The simulated disk drive models which track is currently under the drive head, and seeking to different tracks take different amounts of time, but other than that, individual reads from disk are independent. Changes have only local effects: if you change one disk access in a sequence of accesses, it affects the timing of that one access and the one that follows it, at most. I believe it cannot result in timing drift many accesses into the future.
Below I'll show evidence to support that claim. The directory
experiments/getdsk in the TAS's source code repository contains raw data and analysis code. My notes on the subject start
here.
The BizHawk emulator uses the
Virtu Apple II emulation core. Virtu includes a simulated
Disk II floppy drive, implemented in the files
DiskIIController.cs,
DiskIIDrive.cs, and
DiskDsk.cs. But the Disk II is software-controlled: most of the complexity of disk access lives in the program running on the Apple II, not in (simulated) hardware. The source of timing delays is, by and large, Infocom code (e.g.
"ARM MOVEMENT DELAY"), not Virtu code.
One memory page is 256 bytes, the same size as one disk sector. When the program needs to swap in a page, it calls the
GETDSK subroutine, which converts a linear address to a track and sector, then calls the low-level subroutine
DOS to read one sector from disk. I
instrumented the call to
DOS to measure the timing distribution of low-level disk reads. (In the 100% run, across all four combinations of game settings.)
A histogram, "cycles per call to DOS in GETDSK". The horizontal axis is "cycles" from 0 to 300,000 and "frames" from 0 to about 18. The vertical axis is "count" from 0 to 350. There is a prominent mode, with a count of about 350, at about 40,000 cycles. There are many sparse bars above that and a few below, with counts usually below 50.
There's a prominent mode—about 20% of calls to
DOS—that take around 40,000 CPU cycles, or 2 video frames, which is among the shortest times measured. But then there is a broad smear of times that extends up to 300,000 cycles, or 18 frames. Could this be the cause of the finicky timing of executing commands? No, I don't think so. To see why, understand that the
DOS subroutine can be decomposed into a few blocks of code that take a fixed amount of time to execute, plus a call to
SEEK and a
GETADR loop that take variable amounts of time. The sums of these component timings is what gives rise to the distribution shown above.
SEEK moves the read head to the requested track. Timing
SEEK alone yields the following timing distribution:
A histogram, "cycles per call to SEEK in DOSEEK". The horizontal axis is "cycles" from 0 to 250,000 and "frames" from 0 to about 15. The vertical axis is "count" from 0 to 600. There are 15 non-zero bins. The largest, with a count of about 600, is at approximately 0 cycles. The next is at 50,000 cycles with a count of 280. Then the bins are spaced roughly evenly at intervals of about 20,000 cycles, for the most part smoothly decreasing in count.
We see that only a few discrete timings are possible from
SEEK. It turns out that the timing of
SEEK depends entirely on how many tracks the read head has to travel over. Sometimes, the head is already over the right track; in that case the time required to seek is practically zero. The greater the absolute value of the difference between the current track (
ctrack) and the desired track (
ttrk), the more time it takes:
A scatterplot, "cycles per call to SEEK in DOSEEK, by distance". The horizontal axis is "ttrk − ctrk" from −30 to +30. The vertical axis is "cycles" from 0 to 250,000 and "frames" from 0 to about 15. The points are semitransparent but so heavily overplotted that all but the most extreme appear opaque. The plot is symmetrical about the middle. There is a point at (0, 0) at the bottom middle, and then the points increase smoothly on both sides.
So the timing of
SEEK depends only on the current track and the sought track. It cannot be the cause of long-term drift. What about
GETADR, then?
GETADR is a loop that repeatedly calls
RDADDR until the disk drive reports that the sector currently being read is the right one. The timing distribution of the
GETADR loop looks like this:
A histogram, "cycles per GETADR loop in DOS". The horizontal axis is "cycles" from 0 to 100,000 and "frames" from 0 to about 6. The vertical axis is "count" from 0 to 350. There are 16 main non-zero bins, evenly spaced at intervals of about 6,500 cycles starting from 0. The largest, with a count of about 350, is at about 20,000 cycles. The rest mostly have a count between 50 and 100. There are some shorter non-zero bins midway between some adjacent pairs of main bins.
Again we see a distribution that is highly discrete. There are 16 main peaks: this makes sense as the disk format has 16 sectors per track. The peak with the highest count is the 4th one from the left, and I think there is a good reason for that. The sectors are stored on disk, not in numerical order, but in an
"interleaved" order that means that logical sector
n + 1 is usually stored 4 physical sectors after logical sector
n. In the common case of reading sectors sequentially, the
GETADR loop has to skip over 3 physical sectors between consecutive logical sectors.
The Virtu emulator does not simulate continuous rotation of the disk. Instead,
every time the track changes, it starts over with sector 0 of the track and
serves the sectors to the application in order.
That does it for the floppy disk simulation hypothesis. Disk access times are variable, but the timing of any given disk access depends only on the current track and sector and and track and sector to be read. Making a change in the middle of a sequence of accesses does not have long-term effects.
The LRU page table that is not always LRU
The cause of the timing variations, I am convinced, is the implementation of the virtual memory page table in the Z-code interpreter.
The use of virtual memory by the Infocom interpreters is one of the most interesting facts about them, to me. The
Zork I story file is about 83 KB, small enough to fit on a floppy disk but larger than the Apple II's 16-bit address space. (Even ignoring the space required for the interpreter itself.) So the interpreter inserts a virtualization layer between the program running in memory and the Z-code on disk. When a particular byte (at a particular address) is requested from the story file, the interpreter consults the page table to see if that page has been loaded into RAM; if it has, the interpreter looks up the address where the page is stored and reads the byte from there. If it has not, the interpreter reads the page from disk into RAM, updates the page table, then returns the requested byte.
The page table has a finite size. The question is what to do when a page is requested that is not in the page table, but every slot in the page table is already occupied. The interpreter needs to evict some other page to make room for the page that is now needed. If that evicted page is needed again later, it will have to be paged back in from disk.
This file
apple/zip/npaging.h is a close match to the page table code that is present in the disk image I am using. (It's not an exact match: for example the code on the disk image lacks the
EARLY2 subroutine and calls
EARLY in its place; but it's closer than the files
paging.asm and
zpaging.asm in the same directory.) When the program fetches a byte of code (via
NEXTPC) or data (via
GETBYT), it calls the
PAGE subroutine to find the necessary page in the page table, swapping it in if necessary.
The program code intends to implement a
least recently used (LRU) cache eviction policy. This is evidenced in comments like
"TIME-STAMP PAGING ROUTINE" and labels like
LRUMAP. But, in fact, when the time comes to evict a page from the cache, the page chosen is not always the least recently used one. Frequently, the page that is evicted is actually one that was used recently and will be needed again in the near future. This is because of an integer overflow in the incrementing counter that serves as a timestamp. (Call it a bug—there's nothing in the source code, in the form of comments or otherwise, that indicates it's supposed to act the way it does.)
Here's how the page table is supposed to work. Each page table entry consists of
two data fields: a 16-bit page ID and an 8-bit timestamp. There is a global 8-bit integer,
STAMP, that
increases by 1 every time any page is accessed. Whenever a page accessed, its timestamp is set to the current value of
STAMP. The idea is that page table entries are brought up to date with the current
STAMP whenever they are used, and unused pages' timestamps are left alone, so therefore you can find the least recently used page table entry by looking for the one with the oldest (lowest) timestamp.
This is the ideal state of the page table: every entry's timestamp is less than or equal to
STAMP, and the least recently used page has the lowest timestamp. While these conditions hold, the page table is a true LRU cache, but they almost never do.
STAMP is an 8-bit counter—it can't keep increasing forever. What happens when
STAMP overflows from 255 to 0? This is where things to go wrong. The page table code tries to do something to cope with the situation, but it does not really work, and
STAMP very frequently ends up overflowing.
When
STAMP overflows, the page table
does an operation I'll call "discounting". What it tries to do is shift the whole table back in time to make room for
STAMP to continue increasing. Specifically: find the entry with the minimum timestamp, then subtract that minimum from every entry's timestamp, and from
STAMP itself. If the minimum timestamp in the page table is 10, for example, then that entry's timestamp becomes 0, all other entries' timestamps get decreased by 10, and
STAMP gets reset from 0 to 246, now with room to continue growing.
The problem is, it's very very common for the minimum timestamp in the page table to be 0. When that happens, all timestamps and
STAMP remain unchanged, and
STAMP overflows from 255 to 0. To make matters worse, whatever page was just accessed gets marked with the new
STAMP of 0—what should be the newest page in the table is instead tagged as being as old as it could possibly be! At the next page swap, the just-accessed page will be one of the leading candidates for eviction. (But it's not guaranteed to be the next page evicted: there can be ties between multiple entries with the same timestamp, and if the page continues to be accessed its timestamp will gradually increase as
STAMP climbs back up from 0.)
In the course of a run,
STAMP overflows many times, and each time it overflows, some page gets tagged with an ultra-low timestamp that makes it prone to eviction. This haphazard eviction is sometimes favorable, sometimes unfavorable—it is hard to control and predict. Below is a graph that shows what real memory pages are resident at what times throughout the 100%-80-brief run. The directory
experiments/page contains code to reproduce the graph, and my rough notes on the subject start
here. A round dot indicates that a page was accessed: ideally, this should make it the most recently used page. The vertical colored strips show the value of the timestamp field of each live page table entry: darker is older; brighter is newer.
A large wide graph, "pages loaded into virtual memory and LRU timestamp". The horizontal axis is "page" from 0x50 to 0x150. The vertical axis is "cycle" from 0 to 315,000,000 and "frame" from 1 to 18,575 (increasing downward). A continuous color axis "stamp" ranges from 0 (black) to 255 (light blue). Strips of varying blue and black run vertically downward from starting dots, with dots punctuating most of the strips more than once. Some ranges of pages—from 0x50 to 0x70, around 0x90, and around 0x100—are frequently accessed and are mostly continuous from top to bottom. Other pages are only occasionally accessed and the strips are sparser and shorter-lived.
When you see one of the vertical strips fade from bright blue to black, with no intervening dots, that's the discounting operation gradually decreasing that page table entry's timestamp. When you see a bright blue strip suddenly interrupted by a black dot, that's
STAMP overflowing and a freshly accessed page being marked with a 0 timestamp. As you can see,
STAMP overflows a
lot—it's not at all an exceptional condition.
Look at page 0x50 (at the far left) around cycle 240,000,000. The page, which had been bright blue, indicating a recent timestamp, is accessed as
STAMP overflows, and becomes black. Then page 0x50 is evicted around cycle 244,000,000. If the page table were a proper LRU cache, that eviction would not have happened, because it's easy to see other pages (e.g. 0x5c, 0x78, 0x80) that were resident at the time and that had been accessed less recently.
A demonstration of problems caused by anomalous page table eviction
This
STAMP overflow phenomenon is what makes the page table sensitively dependent on initial conditions—why small, local changes in page accesses can have accumulating, far-reaching effects. I tried an experiment with modifying just the final thief fight. I constrained the remarks after hitting the thief to be faster ones, which should only speed up the fight. And speed up the fight it does—but then unfavorable page table evictions make it slower by the end. Here's the before-and-after diff of the transcript of the thief fight:
Language: diff
Your sword has begun to glow very brightly.
-You parry a lightning thrust, and the thief salutes you with a grim nod.
+The thief tries to sneak past your guard, but you twist away.
->Hit man
+>HIt mAn
(with the sword)
-A savage blow on the thigh! The thief is stunned but can still fight!
-You parry a lightning thrust, and the thief salutes you with a grim nod.
+Slash! Your stroke connects! This could be serious!
+The thief tries to sneak past your guard, but you twist away.
->G
+>g
-A savage blow on the thigh! The thief is stunned but can still fight!
-You dodge as the thief comes in low.
+Slash! Your blow lands! That one hit an artery, it could be serious!
+You parry a lightning thrust, and the thief salutes you with a grim nod.
->g
+>G
The thief takes a fatal blow and slumps to the floor dead.
At first, the modified fight is faster by 3 frames; but it ultimately works out to be 32 frames slower.
Before frames | Before command | After frames | After command | Cumulative advantage | Per-command advantage |
|---|
15202 | s.u.w.w.u | 15202 | S.U.W.W.u | 0 | +1 |
15661 | Hit man | 15660 | HIt mAn | +1 | +2 |
15874 | G | 15871 | g | +3 | 0 |
15937 | g | 15934 | G | +3 | 0 |
16100 | drop old | 16097 | drop old | +3 | 0 |
16194 | get canary | 16191 | get canary | +3 | +7 |
16308 | temple | 16298 | temple | +10 | −5 |
16377 | d | 16372 | d | +5 | +11 |
16449 | get | 16433 | get | +16 | −26 |
16502 | u.s | 16512 | u.s | −10 | −4 |
16567 | pray | 16581 | Pray | −14 | +1 |
16653 | Wind canary | 16666 | wind canary | −13 | −16 |
16728 | get | 16757 | get | −29 | +12 |
16803 | e.s.e.w.w | 16820 | e.s.e.w.w | −17 | +1 |
17123 | drop all treasu in case | 17139 | drop all treasu in case | −16 | +12 |
17352 | w.w.u | 17356 | w.w.u | −4 | +11 |
17563 | drop all | 17556 | drop all | +7 | −39 |
17660 | Get all treasu | 17692 | get all treasu | −32 | −2 |
17821 | D | 17855 | d | −34 | +3 |
17887 | E | 17918 | E | −31 | −1 |
17935 | e | 17967 | e | −32 | 0 |
18041 | drop all in case | 18073 | drop all in case | −32 | 0 |
18280 | e.e.n.w.sw.w | 18312 | e.e.n.w.sw.w | −32 | |
The slightly changed fight results in drastic differences in the page table. The page table graph for the modified fight is
here. But it's more instructive to look at an animation that flips between the two versions:
A 2-frame looping GIF animation, showing the lower left area of the page table graph: "cycles" from 265,000,000 to 315,000,000 and "pages" from 0x50 to 0xa4. The first frame is the same as in the graph above. The second frame shows the modified thief fight. There are places where the first frame has gaps and the second is connected, and vice versa. The dots (indicating page accesses) in the modified fight are shifted upward (indicating a time savings) until about cycle 280,000,000; but after that they are generally shifted downward, indicating a time loss.
Let's look at a particular case of
STAMP overflow to see its effects on the page table. The left group of columns is the original thief fight; the right group is the modified (faster) thief fight. This table doesn't show every page access, only ones that resulted in a swap.
cycle | frame | zpage | page | STAMP | | cycle | frame | zpage | page | STAMP |
|---|
272337867 | 15991 | 16 | 0x78 | 228 | | 272287738 | 15988 | 16 | 0x78 | 224 |
272716133 | 16014 | 61 | 0xd7 | 254 | | 272663464 | 16011 | 61 | 0xd7 | 254 |
272811368 | 16019 | 24 | 0xd2 | 255 | | 272758699 | 16016 | 24 | 0xd2 | 255 |
273315572 | 16049 | 24 | 0x95 | 5 | | 273262882 | 16046 | 12 | 0x95 | 0 |
275050196 | 16151 | 12 | 0x76 | 219 | | 274999096 | 16148 | 12 | 0x76 | 213 |
275108188 | 16154 | 53 | 0x77 | 223 | | 275057076 | 16151 | 1 | 0x77 | 217 |
275255591 | 16163 | 24 | 0x92 | 225 | | 275204491 | 16160 | 61 | 0x92 | 219 |
276680776 | 16246 | 1 | 0x87 | 165 | | 276629712 | 16243 | 60 | 0x87 | 161 |
276881986 | 16258 | 25 | 0xf1 | 168 | | 276830922 | 16255 | 37 | 0xf1 | 164 |
277037566 | 16267 | 61 | 0x90 | 171 | | 277153667 | 16274 | 43 | 0x54 | 188 |
277384683 | 16288 | 37 | 0x100 | 218 | | 277981061 | 16323 | 45 | 0x8a | 23 |
278212278 | 16336 | 43 | 0x8a | 24 | | 278140336 | 16332 | 22 | 0x93 | 25 |
On the left side, notice how page 0xd2 is swapped into page table entry 24 when
STAMP is 255. Then, after
STAMP overflows, page 0xd2, despite being recently used, is swapped out in favor of page 0x95. Something similar happens on the right side, but here page 0x95 does not evict page 0xd2 but instead goes into page table entry 12. But then the newly swapped-in page 0x95 is evicted to make way for page 0x76 in entry 12. The two page tables diverge further from there.