To me, it looks like the timestamps are way off... like the test ROM is just syncing improperly. I'd guess you're "wrong" method is working because it's offsetting the timestamp of the read by the same number of cycles the ROM is off in its sync (coincidence? or maybe you made a similar mistake twice and only corrected one of them?)
Here's a quick log I made... maybe it'll help. My timestamps are a little different -- I start my frame with the idle scanline (scanline after rendering, before VBL), so VBL starts at PPU cycle 341. Additionally -- the timestamp in this log is 1 more than you'd expect (suppresses on 341 not on 340)... as for why, don't ask ;P
Code:
-- frame $7E and earlier read $2002 every 21
ppu cycles -- presumably to sync --
frame: 0000007E -- cyc: 226 --- VBL supress: No
frame: 0000007E -- cyc: 247 --- VBL supress: No
frame: 0000007E -- cyc: 268 --- VBL supress: No
frame: 0000007E -- cyc: 289 --- VBL supress: No
frame: 0000007E -- cyc: 310 --- VBL supress: No
frame: 0000007E -- cyc: 331 --- VBL supress: No
frame: 0000007E -- cyc: 352 --- VBL supress: No
-- by this frame, it's synced and reads once per frame
for so many frames until it hits the time right before VBl raises --
frame: 00000080 -- cyc: 330 --- VBL supress: No
frame: 00000081 -- cyc: 331 --- VBL supress: No
frame: 00000082 -- cyc: 332 --- VBL supress: No
frame: 00000083 -- cyc: 333 --- VBL supress: No
frame: 00000084 -- cyc: 334 --- VBL supress: No
frame: 00000085 -- cyc: 335 --- VBL supress: No
frame: 00000086 -- cyc: 336 --- VBL supress: No
frame: 00000087 -- cyc: 337 --- VBL supress: No
frame: 00000088 -- cyc: 338 --- VBL supress: No
frame: 00000089 -- cyc: 339 --- VBL supress: No
frame: 0000008A -- cyc: 340 --- VBL supress: No
frame: 0000008B -- cyc: 341 --- VBL supress: Yes
frame: 0000008C -- cyc: 342 --- VBL supress: No
frame: 0000008E -- cyc: 341 --- VBL supress: Yes
frame: 0000008E -- cyc: 401 --- VBL supress: No
these times are the time of the $2002 read (last cycle in the LDA $2002 instruction). I didn't see any point in logging the PPU timestamp since my emu syncs up on $2002 reads anyway, so it'd be redundant.
EDIT
yeah, see? after comparing our logs, it looks to me like your timestamp is always off by 3 CPU cycles.
Code:
CPUCycles = 89330 - miniCycles= 9 - PPUCycles = 89339/ 89342
This is the first 'once-per-frame' read performed. If you notice, the read SHOULD be happening on cycle 89330, but it's happening 9 cycles later.
So the ROM seems to be synced up improperly and is off by 3 cpu cycles somehow.
EDIT AGAIN
To be honest... I'm baffled as to how it's making it to test 8... since if it's off by 3 cycles it should be failing some of the earlier tests.
Only thing I can think of is you're not syncing up your PPU to the right time on $2002 reads. Like if you were syncing up to 'CPUCycles' and not 'CPUCycles + (minicycles * 15)' -- that would probably explain all the behavior you're getting.
Last edit, I swear:
Now that I think of it... that's a very distinct possibility. Considering what you said before:
Quote:
Of course, I call PPU->Run( CPUCycles + cycles ); before doing that check..
if 'cycles' is 3 or some other low value there (like if you didn't multiply it by 15 or 16 depending on NTSC/PAL mode)... you're effectively adding 0, since 3 isn't even enough to push it to the next PPU cycle (which would need at least 5)
so if you ARE doing PPU->Run( CPUCycles + cycles );... you
want to be doing PPU->Run( CPUCycles + (cycles * CPUCycleBase) );
Hopefully that's the problem