Reply 180 of 198, by superfury
I've just adjusted the logging method during the cycle logging(simplified, common log format, single-line, state logging enabled). The results are... interesting(just when the XT BIOS starts running):
00:00:33:92.08636: BIU T1 Physical(p):000ffff0=ea(ê); Paged(p):000ffff0=ea(ê); Normal(p):00000000=ea(ê)
00:00:33:92.09388: BIU T2
00:00:33:92.09536: BIU T3
00:00:33:92.09676: BIU T4
00:00:33:92.09828: BIU T1 Physical(p):000ffff1=5b([); Paged(p):000ffff1=5b([); Normal(p):00000001=5b([)
00:00:33:92.09972: BIU T2
00:00:33:93.00112: BIU T3
00:00:33:93.00252: BIU T4
00:00:33:93.00400: BIU T1 Physical(p):000ffff2=e0(à); Paged(p):000ffff2=e0(à); Normal(p):00000002=e0(à)
00:00:33:93.00540: BIU T2
00:00:33:93.00684: BIU T3
00:00:33:93.00820: BIU T4
00:00:33:93.00972: BIU T1 Physical(p):000ffff3=00( ); Paged(p):000ffff3=00( ); Normal(p):00000003=00( )
00:00:33:93.01112: BIU T2
00:00:33:93.01252: BIU T3
00:00:33:93.01628: BIU T4
00:00:33:93.01740: BIU T1 Physical(p):000ffff4=f0(ð); Paged(p):000ffff4=f0(ð); Normal(p):00000004=f0(ð)
00:00:33:93.01836: BIU T2
00:00:33:93.01936: BIU T3
00:00:33:93.02032: BIU T4
00:00:33:93.02180: BIU T1 ffff:0000 (EA5BE000F0)JMP F000:E05B Physical(p):000fe05b=fa(ú); Paged(p):000fe05b=fa(ú); Normal(p):0000e05b=fa(ú)
00:00:33:93.02276: BIU T2
00:00:33:93.02376: BIU T3
00:00:33:93.02960: BIU T4
00:00:33:93.03092: BIU T1 Physical(p):000fe05c=fc(ü); Paged(p):000fe05c=fc(ü); Normal(p):0000e05c=fc(ü)
00:00:33:93.03188: BIU T2
00:00:33:93.03284: BIU T3
00:00:33:93.03388: BIU T4
00:00:33:93.03496: BIU T1 Physical(p):000fe05d=b0(°); Paged(p):000fe05d=b0(°); Normal(p):0000e05d=b0(°)
00:00:33:93.03596: BIU T2
00:00:33:93.03700: BIU T3
00:00:33:93.03804: BIU T4
00:00:33:93.03916: BIU T1 Physical(p):000fe05e=00( ); Paged(p):000fe05e=00( ); Normal(p):0000e05e=00( )
00:00:33:93.04028: BIU T2
00:00:33:93.04148: BIU T3
00:00:33:93.04268: BIU T4
00:00:33:93.04392: BIU T1 Physical(p):000fe05f=e6(æ); Paged(p):000fe05f=e6(æ); Normal(p):0000e05f=e6(æ)
00:00:33:93.04508: BIU T2 f000:e05b (FA)CLI
00:00:33:93.04644: BIU T3
00:00:33:93.04812: BIU T4
00:00:33:93.04928: BIU T1 Physical(p):000fe060=a0( ); Paged(p):000fe060=a0( ); Normal(p):0000e060=a0( )
00:00:33:93.05100: BIU T2 f000:e05c (FC)CLD
00:00:33:93.05244: BIU T3
00:00:33:93.05420: BIU T4
00:00:33:93.05584: BIU T1 Physical(p):000fe061=ba(º); Paged(p):000fe061=ba(º); Normal(p):0000e061=ba(º)
00:00:33:93.05712: BIU T2
00:00:33:93.05880: BIU T3 f000:e05d (B000)MOV AL,00
00:00:33:93.06004: BIU T4
00:00:33:93.06140: BIU T1 Physical(p):000fe062=d8(Ø); Paged(p):000fe062=d8(Ø); Normal(p):0000e062=d8(Ø)
00:00:33:93.06260: BIU T2
00:00:33:93.06360: BIU T3
00:00:33:93.06460: BIU T4
00:00:33:93.06572: BIU T1 Physical(p):000fe063=03(); Paged(p):000fe063=03(); Normal(p):0000e063=03()
00:00:33:93.06672: BIU T1
00:00:33:93.06772: BIU T2
00:00:33:93.06872: BIU T3
00:00:33:93.06972: BIU T4
00:00:33:93.07080: BIU T1
00:00:33:93.07180: BIU T2
00:00:33:93.07276: BIU T3
00:00:33:93.07376: BIU W
00:00:33:93.07476: BIU T4
00:00:33:93.07576: BIU T4
00:00:33:93.07688: BIU T1 Physical(p):000fe064=ee(î); Paged(p):000fe064=ee(î); Normal(p):0000e064=ee(î)
00:00:33:93.07788: BIU T2
00:00:33:93.07884: BIU T3
00:00:33:93.07988: BIU T4
00:00:33:93.08096: BIU T1 Physical(p):000fe065=b2(²); Paged(p):000fe065=b2(²); Normal(p):0000e065=b2(²)
00:00:33:93.08204: BIU T2 f000:e061 (BAD803)MOV DX,03D8
00:00:33:93.08304: BIU T3
00:00:33:93.08408: BIU T4
00:00:33:93.08516: BIU T1 Physical(p):000fe066=b8(¸); Paged(p):000fe066=b8(¸); Normal(p):0000e066=b8(¸)
00:00:33:93.08620: BIU T2
00:00:33:93.08720: BIU T3
00:00:33:93.08820: BIU T4
00:00:33:93.08920: BIU T1
00:00:33:93.09020: BIU T2
00:00:33:93.09132: BIU T3
00:00:33:93.09236: BIU W
00:00:33:93.09336: BIU T4
00:00:33:93.09436: BIU T4
00:00:33:93.09548: BIU T1 Physical(p):000fe067=fe(þ); Paged(p):000fe067=fe(þ); Normal(p):0000e067=fe(þ)
00:00:33:93.09644: BIU T2
00:00:33:93.09744: BIU T3
00:00:33:93.09844: BIU T4
00:00:33:93.09964: BIU T1 f000:e065 (B2B8)MOV DL,B8 Physical(p):000fe068=c0(À); Paged(p):000fe068=c0(À); Normal(p):0000e068=c0(À)
00:00:33:94.00112: BIU T2
00:00:33:94.00220: BIU T3
00:00:33:94.00320: BIU T4
00:00:33:94.00428: BIU T1 Physical(p):000fe069=ee(î); Paged(p):000fe069=ee(î); Normal(p):0000e069=ee(î)
00:00:33:94.00528: BIU T2
00:00:33:94.00640: BIU T3 f000:e067 (FEC0)INC AL
00:00:33:94.00740: BIU T4
00:00:33:94.00848: BIU T1 Physical(p):000fe06a=b0(°); Paged(p):000fe06a=b0(°); Normal(p):0000e06a=b0(°)
00:00:33:94.00952: BIU T2
00:00:33:94.01056: BIU T3
00:00:33:94.01160: BIU T4
00:00:33:94.01260: BIU T1
00:00:33:94.01360: BIU T2
00:00:33:94.01464: BIU T3
00:00:33:94.01704: BIU W
00:00:33:94.01808: BIU T4
00:00:33:94.01908: BIU T4
00:00:33:94.02020: BIU T1 Physical(p):000fe06b=99(™); Paged(p):000fe06b=99(™); Normal(p):0000e06b=99(™)
00:00:33:94.02120: BIU T2
00:00:33:94.02220: BIU T3
00:00:33:94.02316: BIU T4
00:00:33:94.02428: BIU T1 Physical(p):000fe06c=e6(æ); Paged(p):000fe06c=e6(æ); Normal(p):0000e06c=e6(æ)
00:00:33:94.02540: BIU T2 f000:e06a (B099)MOV AL,99
00:00:33:94.02636: BIU T3
00:00:33:94.02736: BIU T4
00:00:33:94.02844: BIU T1 Physical(p):000fe06d=63(c); Paged(p):000fe06d=63(c); Normal(p):0000e06d=63(c)
00:00:33:94.02944: BIU T2
00:00:33:94.03048: BIU T3
00:00:33:94.03148: BIU T4
00:00:33:94.03260: BIU T1 Physical(p):000fe06e=b0(°); Paged(p):000fe06e=b0(°); Normal(p):0000e06e=b0(°)
00:00:33:94.03360: BIU T1
00:00:33:94.03460: BIU T2
00:00:33:94.03560: BIU T3
00:00:33:94.03668: BIU T4
00:00:33:94.03768: BIU T1
00:00:33:94.03864: BIU T2
00:00:33:94.03996: BIU T3
00:00:33:94.04096: BIU W
00:00:33:94.04192: BIU T4
00:00:33:94.04288: BIU T4
00:00:33:94.04396: BIU T1 Physical(p):000fe06f=a5(¥); Paged(p):000fe06f=a5(¥); Normal(p):0000e06f=a5(¥)
00:00:33:94.04488: BIU T2
00:00:33:94.04584: BIU T3
00:00:33:94.04700: BIU T4
00:00:33:94.04828: BIU T1 Physical(p):000fe070=e6(æ); Paged(p):000fe070=e6(æ); Normal(p):0000e070=e6(æ)
00:00:33:94.04956: BIU T2 f000:e06e (B0A5)MOV AL,A5
00:00:33:94.05068: BIU T3
00:00:33:94.05164: BIU T4
00:00:33:94.05276: BIU T1 Physical(p):000fe071=61(a); Paged(p):000fe071=61(a); Normal(p):0000e071=61(a)
00:00:33:94.05372: BIU T2
00:00:33:94.05468: BIU T3
00:00:33:94.05564: BIU T4
00:00:33:94.05676: BIU T1 Physical(p):000fe072=b0(°); Paged(p):000fe072=b0(°); Normal(p):0000e072=b0(°)
00:00:33:94.05772: BIU T1
00:00:33:94.05864: BIU T2
00:00:33:94.05992: BIU T3
00:00:33:94.06128: BIU T4
00:00:33:94.06228: BIU T1
00:00:33:94.06344: BIU T2
00:00:33:94.06444: BIU T3
00:00:33:94.06540: BIU W
00:00:33:94.06636: BIU T4
00:00:33:94.06732: BIU T4
00:00:33:94.06840: BIU T1 Physical(p):000fe073=54(T); Paged(p):000fe073=54(T); Normal(p):0000e073=54(T)
00:00:33:94.06940: BIU T2
00:00:33:94.07036: BIU T3
00:00:33:94.07132: BIU T4
00:00:33:94.07240: BIU T1 Physical(p):000fe074=e6(æ); Paged(p):000fe074=e6(æ); Normal(p):0000e074=e6(æ)
00:00:33:94.07348: BIU T2 f000:e072 (B054)MOV AL,54
00:00:33:94.07444: BIU T3
00:00:33:94.07540: BIU T4
00:00:33:94.07648: BIU T1 Physical(p):000fe075=43(C); Paged(p):000fe075=43(C); Normal(p):0000e075=43(C)
00:00:33:94.07744: BIU T2
00:00:33:94.07840: BIU T3
00:00:33:94.07948: BIU T4
00:00:33:94.08092: BIU T1 Physical(p):000fe076=b0(°); Paged(p):000fe076=b0(°); Normal(p):0000e076=b0(°)
00:00:33:94.08204: BIU T1
00:00:33:94.08316: BIU T2
00:00:33:94.08420: BIU T3
00:00:33:94.08524: BIU T4
00:00:33:94.08648: BIU T1
00:00:33:94.08776: BIU T2
00:00:33:94.08888: BIU T3
00:00:33:94.09040: BIU W
00:00:33:94.09164: BIU T4
00:00:33:94.09264: BIU T4
00:00:33:94.09376: BIU T1 Physical(p):000fe077=12(); Paged(p):000fe077=12(); Normal(p):0000e077=12()
00:00:33:94.09476: BIU T2
00:00:33:94.09604: BIU T3
00:00:33:94.09712: BIU T4
00:00:33:94.09868: BIU T1 Physical(p):000fe078=e6(æ); Paged(p):000fe078=e6(æ); Normal(p):0000e078=e6(æ)
00:00:33:95.00012: BIU T2 f000:e076 (B012)MOV AL,12
It's now actually logging the instruction line on the actual cycle the instruction starts executing, instead of the line when the instruction finishes executing(for cycle logging only, all other logs should be unaffected and log when the instruction is finished).
One interesting thing I see is that on some times, the emulated bus is sometimes applying waitstates(the "BIU W" lines). But when said waitstate (RAM probably) access is performed, somehow the actual memory access is somehow missing from the T1 state?
Edit: Just confirmed. Those are IN/OUT instructions executing. But they aren't logged somehow?
Edit: Some debugger bugfixing later(still checking executed while it shouldn't):
00:00:07:13.05335: BIU T1 Physical(p):000ffff0=ea(ê); Paged(p):000ffff0=ea(ê); Normal(p):00000000=ea(ê)
00:00:07:13.06876: BIU T2
00:00:07:13.07019: BIU T3
00:00:07:13.07157: BIU T4
00:00:07:13.07337: BIU T1 Physical(p):000ffff1=5b([); Paged(p):000ffff1=5b([); Normal(p):00000001=5b([)
00:00:07:13.07475: BIU T2
00:00:07:13.07612: BIU T3
00:00:07:13.07749: BIU T4
00:00:07:13.07926: BIU T1 Physical(p):000ffff2=e0(à); Paged(p):000ffff2=e0(à); Normal(p):00000002=e0(à)
00:00:07:13.08073: BIU T2
00:00:07:13.08231: BIU T3
00:00:07:13.08368: BIU T4
00:00:07:13.08515: BIU T1 Physical(p):000ffff3=00( ); Paged(p):000ffff3=00( ); Normal(p):00000003=00( )
00:00:07:13.08652: BIU T2
00:00:07:13.08788: BIU T3
00:00:07:13.09116: BIU T4
00:00:07:13.09248: BIU T1 Physical(p):000ffff4=f0(ð); Paged(p):000ffff4=f0(ð); Normal(p):00000004=f0(ð)
00:00:07:13.09346: BIU T2
00:00:07:13.09445: BIU T3
00:00:07:13.09541: BIU T4
00:00:07:13.09697: BIU T1 ffff:0000 (EA5BE000F0)JMP F000:E05B Physical(p):000fe05b=fa(ú); Paged(p):000fe05b=fa(ú); Normal(p):0000e05b=fa(ú)
00:00:07:13.09796: BIU T2
00:00:07:13.09893: BIU T3
00:00:07:13.09990: BIU T4
00:00:07:14.00098: BIU T1 Physical(p):000fe05c=fc(ü); Paged(p):000fe05c=fc(ü); Normal(p):0000e05c=fc(ü)
00:00:07:14.00224: BIU T2
00:00:07:14.00330: BIU T3
00:00:07:14.00446: BIU T4
00:00:07:14.00641: BIU T1 Physical(p):000fe05d=b0(°); Paged(p):000fe05d=b0(°); Normal(p):0000e05d=b0(°)
00:00:07:14.00750: BIU T2
00:00:07:14.00858: BIU T3
00:00:07:14.00977: BIU T4
00:00:07:14.01151: BIU T1 Physical(p):000fe05e=00( ); Paged(p):000fe05e=00( ); Normal(p):0000e05e=00( )
00:00:07:14.01282: BIU T2
00:00:07:14.01383: BIU T3
00:00:07:14.01504: BIU T4
00:00:07:14.01641: BIU T1 Physical(p):000fe05f=e6(æ); Paged(p):000fe05f=e6(æ); Normal(p):0000e05f=e6(æ)
00:00:07:14.01769: BIU T2 f000:e05b (FA)CLI
00:00:07:14.01867: BIU T3
00:00:07:14.01965: BIU T4
00:00:07:14.02072: BIU T1 Physical(p):000fe060=a0( ); Paged(p):000fe060=a0( ); Normal(p):0000e060=a0( )
00:00:07:14.02193: BIU T2 f000:e05c (FC)CLD
00:00:07:14.02464: BIU T3
00:00:07:14.02564: BIU T4
00:00:07:14.02672: BIU T1 Physical(p):000fe061=ba(º); Paged(p):000fe061=ba(º); Normal(p):0000e061=ba(º)
00:00:07:14.02769: BIU T2
00:00:07:14.02876: BIU T3 f000:e05d (B000)MOV AL,00
00:00:07:14.02973: BIU T4
00:00:07:14.03082: BIU T1 Physical(p):000fe062=d8(Ø); Paged(p):000fe062=d8(Ø); Normal(p):0000e062=d8(Ø)
00:00:07:14.03200: BIU T2
00:00:07:14.03297: BIU T3
00:00:07:14.03395: BIU T4
00:01:59:54.09208: BIU T1 f000:e05f (E6A0)OUT A0,AL Physical(p):000fe063=03(); Paged(p):000fe063=03(); Normal(p):0000e063=03()
00:04:06:34.00144: BIU T1
00:05:36:98.02816: BIU T2
00:05:49:13.05808: BIU T3
00:05:50:61.00688: BIU T4
00:06:56:58.04352: BIU T1
00:07:10:39.09040: BIU T2
00:07:10:39.09296: BIU T3
00:07:10:39.09552: BIU W
00:07:10:39.09744: BIU T4
00:07:10:39.09968: BIU T4
00:07:14:70.06592: BIU T1 Physical(p):000fe064=ee(î); Paged(p):000fe064=ee(î); Normal(p):0000e064=ee(î)
00:07:14:70.06784: BIU T2
00:07:14:70.06912: BIU T3
00:07:14:70.07008: BIU T4
00:07:14:70.07104: BIU T1 Physical(p):000fe065=b2(²); Paged(p):000fe065=b2(²); Normal(p):0000e065=b2(²)
00:07:14:70.07264: BIU T2 f000:e061 (BAD803)MOV DX,03D8
00:07:14:70.07360: BIU T3
00:07:15:87.05936: BIU T4
00:07:15:87.06160: BIU T1 Physical(p):000fe066=b8(¸); Paged(p):000fe066=b8(¸); Normal(p):0000e066=b8(¸)
00:07:15:87.06256: BIU T2 f000:e064 (EE)OUT DX,AL
00:07:15:87.06352: BIU T3
00:07:15:87.07024: BIU T4
00:07:15:87.07120: BIU T1
00:07:15:87.07216: BIU T2
00:07:15:87.07344: BIU T3
00:07:15:87.07440: BIU W
00:07:15:87.07536: BIU T4
00:07:15:87.07632: BIU T4
00:07:16:44.05536: BIU T1 Physical(p):000fe067=fe(þ); Paged(p):000fe067=fe(þ); Normal(p):0000e067=fe(þ)
00:07:16:44.05760: BIU T2
00:07:16:44.05856: BIU T3
00:07:16:44.05952: BIU T4
00:07:16:44.06176: BIU T1 f000:e065 (B2B8)MOV DL,B8 Physical(p):000fe068=c0(À); Paged(p):000fe068=c0(À); Normal(p):0000e068=c0(À)
Now that makes more sense. Still, why would it be logging T1 twice when starting the first OUT instruction. And again double T4 when ending that last OUT DX,AL instruction... Weird?
Edit: OK. After looking at the BIU's code I now see what's happening: that's one cycle active(T1?) then two cycles stalling. But it looks like it's somehow misbehaving? It looks like a 1 cycle stall only and no cycles ticked?
Edit: OK. T1 is ticked normally. On T2, a stall for 2 cycles is requested. The CPU records it, but doesn't see that the BIU needs to be ticked in that case!
Edit: Ah. Bug found in the CPU. When a bus stall was requested(the 2nd cycle of the OUT instructions), it's now waiting for T1 again(when not T1 already), then stalls the bus for 2 cycles, then starts the port transfer.
00:00:55:09.08580: BIU T1 Physical(p):000ffff0=ea(ê); Paged(p):000ffff0=ea(ê); Normal(p):00000000=ea(ê)
00:00:55:09.09980: BIU T2
00:00:55:10.00124: BIU T3
00:00:55:10.00788: BIU T4
00:00:55:10.00940: BIU T1 Physical(p):000ffff1=5b([); Paged(p):000ffff1=5b([); Normal(p):00000001=5b([)
00:00:55:10.01076: BIU T2
00:00:55:10.01216: BIU T3
00:00:55:10.01376: BIU T4
00:00:55:10.01524: BIU T1 Physical(p):000ffff2=e0(à); Paged(p):000ffff2=e0(à); Normal(p):00000002=e0(à)
00:00:55:10.01664: BIU T2
00:00:55:10.01800: BIU T3
00:00:55:10.01948: BIU T4
00:00:55:10.02100: BIU T1 Physical(p):000ffff3=00( ); Paged(p):000ffff3=00( ); Normal(p):00000003=00( )
00:00:55:10.02240: BIU T2
00:00:55:10.02396: BIU T3
00:00:55:10.02748: BIU T4
00:00:55:10.02860: BIU T1 Physical(p):000ffff4=f0(ð); Paged(p):000ffff4=f0(ð); Normal(p):00000004=f0(ð)
00:00:55:10.02956: BIU T2
00:00:55:10.03072: BIU T3
00:00:55:10.03176: BIU T4
00:00:55:10.03328: BIU T1 ffff:0000 (EA5BE000F0)JMP F000:E05B Physical(p):000fe05b=fa(ú); Paged(p):000fe05b=fa(ú); Normal(p):0000e05b=fa(ú)
00:00:55:10.03444: BIU T2
00:00:55:10.03636: BIU T3
00:00:55:10.03740: BIU T4
00:00:55:10.03848: BIU T1 Physical(p):000fe05c=fc(ü); Paged(p):000fe05c=fc(ü); Normal(p):0000e05c=fc(ü)
00:00:55:10.03948: BIU T2
00:00:55:10.04084: BIU T3
00:00:55:10.04188: BIU T4
00:00:55:10.04296: BIU T1 Physical(p):000fe05d=b0(°); Paged(p):000fe05d=b0(°); Normal(p):0000e05d=b0(°)
00:00:55:10.04396: BIU T2
00:00:55:10.04492: BIU T3
00:00:55:10.04604: BIU T4
00:00:55:10.04712: BIU T1 Physical(p):000fe05e=00( ); Paged(p):000fe05e=00( ); Normal(p):0000e05e=00( )
00:00:55:10.04808: BIU T2
00:00:55:10.04904: BIU T3
00:00:55:10.05004: BIU T4
00:00:55:10.05116: BIU T1 Physical(p):000fe05f=e6(æ); Paged(p):000fe05f=e6(æ); Normal(p):0000e05f=e6(æ)
00:00:55:10.05216: BIU T2 f000:e05b (FA)CLI
00:00:55:10.05312: BIU T3
00:00:55:10.05600: BIU T4
00:00:55:10.05708: BIU T1 Physical(p):000fe060=a0( ); Paged(p):000fe060=a0( ); Normal(p):0000e060=a0( )
00:00:55:10.05820: BIU T2 f000:e05c (FC)CLD
00:00:55:10.05920: BIU T3
00:00:55:10.06012: BIU T4
00:00:55:10.06120: BIU T1 Physical(p):000fe061=ba(º); Paged(p):000fe061=ba(º); Normal(p):0000e061=ba(º)
00:00:55:10.06216: BIU T2
00:00:55:10.06316: BIU T3 f000:e05d (B000)MOV AL,00
00:00:55:10.06508: BIU T4
00:00:55:10.06632: BIU T1 Physical(p):000fe062=d8(Ø); Paged(p):000fe062=d8(Ø); Normal(p):0000e062=d8(Ø)
00:00:55:10.06728: BIU T2
00:00:55:10.06816: BIU T3
00:00:55:10.06912: BIU T4
00:00:55:10.07028: BIU T1 f000:e05f (E6A0)OUT A0,AL Physical(p):000fe063=03(); Paged(p):000fe063=03(); Normal(p):0000e063=03()
00:02:27:55.06272: BIU T2
00:02:35:86.05984: BIU T3
00:03:11:41.07088: BIU T4
00:03:20:61.05120: BIU --
00:04:16:45.04432: BIU --
00:04:37:01.09904: BIU T1
00:04:39:49.08272: BIU T2
00:04:39:49.08592: BIU T3
00:04:39:49.08848: BIU W
00:04:39:49.09104: BIU T4
00:04:39:49.09360: BIU T4
00:04:39:49.09648: BIU T1 Physical(p):000fe064=ee(î); Paged(p):000fe064=ee(î); Normal(p):0000e064=ee(î)
00:04:39:49.09904: BIU T2
00:04:39:50.00192: BIU T3
00:04:39:50.00512: BIU T4
00:04:39:50.00896: BIU T1 Physical(p):000fe065=b2(²); Paged(p):000fe065=b2(²); Normal(p):0000e065=b2(²)
00:04:39:50.01216: BIU T2 f000:e061 (BAD803)MOV DX,03D8
00:04:39:50.01472: BIU T3
00:04:39:50.01728: BIU T4
00:04:39:50.01984: BIU T1 Physical(p):000fe066=b8(¸); Paged(p):000fe066=b8(¸); Normal(p):0000e066=b8(¸)
00:04:39:50.02272: BIU T2 f000:e064 (EE)OUT DX,AL
00:04:39:50.02496: BIU T3
00:04:39:50.02752: BIU T4
00:04:39:50.03008: BIU T1
00:04:39:50.03232: BIU T2
00:04:39:50.03488: BIU T3
00:04:39:50.03744: BIU W
00:04:39:50.03968: BIU T4
00:04:39:50.04224: BIU T4
00:04:39:50.04576: BIU T1 Physical(p):000fe067=fe(þ); Paged(p):000fe067=fe(þ); Normal(p):0000e067=fe(þ)
00:04:39:50.04896: BIU T2
00:04:39:50.05152: BIU T3
00:04:39:50.05408: BIU T4
00:04:39:50.05728: BIU T1 f000:e065 (B2B8)MOV DL,B8 Physical(p):000fe068=c0(À); Paged(p):000fe068=c0(À); Normal(p):0000e068=c0(À)
So now the bus stall is working properly again.
Now there's still those strange double T4 states there, at the end of the OUT instructions?
Edit: After some investigation, it's a new case that wasn't there before. This is the specific case where the execution state handler of the OUT instruction is called once more for making it terminate the instruction normally. But since it does nothing more than read the result from the BIU and finishing the instruction, said operation ends in the same cycle as the last cycle that was executed(only UniPCemu has to return to the instruction handler because it doesn't know it's finished doing it's job). And once the instruction handler finishes up(reading the result from the BIU), it returns to the BIU without any cycles spent(it doesn't emulate any cycles in that case).
Then the CPU core sees that and finishes up without calling the BIU cycle timing(since there are no cycles to spend on it). The debugger then came by to log whatever the CPU/BIU was doing(in this case the BIU) and blindly logged the cycle that the BIU was executing the last time(which was the T4 cycle). So it just logs a second T4 cycle, while in effect only one T4 cycle has occured(which was the previous cycle, before the instruction was in it's finish up and be terminated state).
Now, adjusting the CPU for that was easy(simply keep a flag if the BIU is actually ticked or not). Then the debugger can act based on that, sees that it didn't actually tick anything, thus don't log anything invalid.
This is the new result:
00:00:03:87.00358: BIU T1 Physical(p):000ffff0=ea(ê); Paged(p):000ffff0=ea(ê); Normal(p):00000000=ea(ê)
00:00:03:87.01457: BIU T2
00:00:03:87.01599: BIU T3
00:00:03:87.01736: BIU T4
00:00:03:87.01935: BIU T1 Physical(p):000ffff1=5b([); Paged(p):000ffff1=5b([); Normal(p):00000001=5b([)
00:00:03:87.02159: BIU T2
00:00:03:87.02319: BIU T3
00:00:03:87.02456: BIU T4
00:00:03:87.02604: BIU T1 Physical(p):000ffff2=e0(à); Paged(p):000ffff2=e0(à); Normal(p):00000002=e0(à)
00:00:03:87.02741: BIU T2
00:00:03:87.02877: BIU T3
00:00:03:87.03013: BIU T4
00:00:03:87.03180: BIU T1 Physical(p):000ffff3=00( ); Paged(p):000ffff3=00( ); Normal(p):00000003=00( )
00:00:03:87.03317: BIU T2
00:00:03:87.03453: BIU T3
00:00:03:87.03789: BIU T4
00:00:03:87.03901: BIU T1 Physical(p):000ffff4=f0(ð); Paged(p):000ffff4=f0(ð); Normal(p):00000004=f0(ð)
00:00:03:87.04000: BIU T2
00:00:03:87.04098: BIU T3
00:00:03:87.04223: BIU T4
00:00:03:87.04367: BIU T1 ffff:0000 (EA5BE000F0)JMP F000:E05B Physical(p):000fe05b=fa(ú); Paged(p):000fe05b=fa(ú); Normal(p):0000e05b=fa(ú)
00:00:03:87.04465: BIU T2
00:00:03:87.04562: BIU T3
00:00:03:87.04659: BIU T4
00:00:03:87.04766: BIU T1 Physical(p):000fe05c=fc(ü); Paged(p):000fe05c=fc(ü); Normal(p):0000e05c=fc(ü)
00:00:03:87.04863: BIU T2
00:00:03:87.05436: BIU T3
00:00:03:87.05533: BIU T4
00:00:03:87.05640: BIU T1 Physical(p):000fe05d=b0(°); Paged(p):000fe05d=b0(°); Normal(p):0000e05d=b0(°)
00:00:03:87.05737: BIU T2
00:00:03:87.05834: BIU T3
00:00:03:87.05931: BIU T4
00:00:03:87.06038: BIU T1 Physical(p):000fe05e=00( ); Paged(p):000fe05e=00( ); Normal(p):0000e05e=00( )
00:00:03:87.06136: BIU T2
00:00:03:87.06232: BIU T3
00:00:03:87.06332: BIU T4
00:00:03:87.06438: BIU T1 Physical(p):000fe05f=e6(æ); Paged(p):000fe05f=e6(æ); Normal(p):0000e05f=e6(æ)
00:00:03:87.06542: BIU T2 f000:e05b (FA)CLI
00:00:03:87.06640: BIU T3
00:00:03:87.06737: BIU T4
00:00:03:87.06844: BIU T1 Physical(p):000fe060=a0( ); Paged(p):000fe060=a0( ); Normal(p):0000e060=a0( )
00:00:03:87.06947: BIU T2 f000:e05c (FC)CLD
00:00:03:87.07046: BIU T3
00:00:03:87.07144: BIU T4
00:00:03:87.07250: BIU T1 Physical(p):000fe061=ba(º); Paged(p):000fe061=ba(º); Normal(p):0000e061=ba(º)
00:00:03:87.07347: BIU T2
00:00:03:87.07452: BIU T3 f000:e05d (B000)MOV AL,00
00:00:03:87.07549: BIU T4
00:00:03:87.07656: BIU T1 Physical(p):000fe062=d8(Ø); Paged(p):000fe062=d8(Ø); Normal(p):0000e062=d8(Ø)
00:00:03:87.07753: BIU T2
00:00:03:87.07850: BIU T3
00:00:03:87.07947: BIU T4
00:00:03:87.08063: BIU T1 f000:e05f (E6A0)OUT A0,AL Physical(p):000fe063=03(); Paged(p):000fe063=03(); Normal(p):0000e063=03()
00:00:03:87.08188: BIU T2
00:00:03:87.08284: BIU T3
00:00:03:87.08381: BIU T4
00:00:03:87.08478: BIU --
00:00:03:87.08575: BIU --
00:00:03:87.08677: BIU T1
00:00:03:87.08774: BIU T2
00:00:03:87.08871: BIU T3
00:00:03:87.08968: BIU W
00:00:03:87.09065: BIU T4
00:01:00:61.01596: BIU T1 Physical(p):000fe064=ee(î); Paged(p):000fe064=ee(î); Normal(p):0000e064=ee(î)
00:01:00:61.02060: BIU T2
00:01:00:61.02392: BIU T3
00:01:00:61.02712: BIU T4
00:01:00:61.03064: BIU T1 Physical(p):000fe065=b2(²); Paged(p):000fe065=b2(²); Normal(p):0000e065=b2(²)
00:01:00:61.03448: BIU T2 f000:e061 (BAD803)MOV DX,03D8
00:01:00:61.03772: BIU T3
00:01:00:61.04100: BIU T4
00:01:00:61.04524: BIU T1 Physical(p):000fe066=b8(¸); Paged(p):000fe066=b8(¸); Normal(p):0000e066=b8(¸)
00:01:00:61.04888: BIU T2 f000:e064 (EE)OUT DX,AL
00:01:00:61.05212: BIU T3
00:01:00:61.05564: BIU T4
00:01:00:61.05904: BIU T1
00:01:00:61.06224: BIU T2
00:01:00:61.06556: BIU T3
00:01:00:61.06876: BIU W
00:01:00:61.07196: BIU T4
00:01:00:61.07568: BIU T1 Physical(p):000fe067=fe(þ); Paged(p):000fe067=fe(þ); Normal(p):0000e067=fe(þ)
00:01:00:61.07888: BIU T2
00:01:00:61.08208: BIU T3
00:01:00:61.08536: BIU T4
00:01:00:61.08920: BIU T1 f000:e065 (B2B8)MOV DL,B8 Physical(p):000fe068=c0(À); Paged(p):000fe068=c0(À); Normal(p):0000e068=c0(À)
As can be seen, the OUT A0,AL instruction starts executing, lets the BIU tick one clock(starting a memory read into the PIQ), then waits for T1, performs 2 idle bus cycles and finally executes the normal port access on the bus.
Is that correct behaviour?
Edit: 8088 MPH now reports 1588 metric cycles.
Author of the UniPCemu emulator.
UniPCemu Git repository
UniPCemu for Android, Windows, PSP, Vita and Switch on itch.io