Accurate logging of port input / output in openMSX

By Louthrax

Paragon (1258)

Louthrax's picture

27-07-2016, 13:27

I'd like to get a log of all access to a specific MSX port with openMSX (let's say printer port 091h). Ideally, I'd like to have that in a text file, and I'd prefer to have the "delta-time" between 2 access (rather than the absolute time for each access).

Purpose of this is to adjust "R800-patch" delays accurately (running the Z80 version first, logging the timing, then launching the R800 version and adjust the delays until the timings match). Maybe someone has already done something similar ? (admitting some lazyness here, and I'm not familiar with TCL stuff...).

Login or register to post comments

By Grauw

Enlighted (5502)

Grauw's picture

27-07-2016, 13:59

A TCL script which logs I/O (debug set_watchpoint write_io) and time stamps (machine_info time):

https://bitbucket.org/grauw/vgmplay-msx/src/f6fd53e4f0/tools...

It’ll need modification to suit your specific needs but all the necessary building blocks should be in there, so hopefully a useful example.

By Louthrax

Paragon (1258)

Louthrax's picture

27-07-2016, 14:14

Grauw wrote:

A TCL script which logs I/O (debug set_watchpoint write_io) and time stamps (machine_info time):

https://bitbucket.org/grauw/vgmplay-msx/src/f6fd53e4f0/tools...

It’ll need modification to suit your specific needs but all the necessary building blocks should be in there, so hopefully a useful example.

Yeaaaaaaaaaaah, exactly what I was looking for, thanks Grauw :) !

By NYYRIKKI

Enlighted (4498)

NYYRIKKI's picture

27-07-2016, 15:30

I did the timing by using debug port... You can define the output format from MSX side.

By Louthrax

Paragon (1258)

Louthrax's picture

27-07-2016, 18:25

NYYRIKKI wrote:

I did the timing by using debug port... You can define the output format from MSX side.

Thanks Nyyrikki, but I need to log timings on an existing application (MIDRY.COM, a MIDI player). Timings seems really picky here when using the printer/TADA output. My plan is first have a log of existing Z80 timings (with no changes at all in the code), then try to reproduce them in R800 mode using pre and post delay loops. I already have the delays implemented, but finding the good values by trial and error has not worked very well so far...

By NYYRIKKI

Enlighted (4498)

NYYRIKKI's picture

28-07-2016, 06:36

Louthrax wrote:

Thanks Nyyrikki, but I need to log timings on an existing application

When I have two options: 1) Write a TCL-script 2) Binary patch the program... I think I'll take the 2) Smile Luckily Grauw already did the hard part, so now you can now take his project as a template.

... and then a little warning: Although openMSX is the most accurate emulator out there, please don't expect the R800 timing to be 100% correct. The real R800 is quite a weird beast. Because of memory refresh it runs the programs in bursts instead of fixed speed and also things like changing value in upper byte of PC causes some delay etc... I don't expect the difference to cause problems in this case, but it's good to know there is some difference between real life & emulation.

By Grauw

Enlighted (5502)

Grauw's picture

28-07-2016, 09:43

Another example script that may be useful for your purposes:

https://bitbucket.org/grauw/gunzip/src/ec14caca8d/tools/prof...

By Louthrax

Paragon (1258)

Louthrax's picture

30-07-2016, 01:39

Thanks guys, it worked with this script:

namespace eval profile {
	variable previous_time 0

	debug set_watchpoint write_io 0x91 {} {profile::start}

	proc start {} {
		variable previous_time
		set chan [open timings.txt a]
		puts $chan "[format %04X [reg pc]],[format %02X [reg a]] : [expr [machine_info time] - $previous_time]"
		close $chan
		set previous_time [expr [machine_info time]]
	}
}

namespace import profile::*

This logs all write to printer port, with PC address and register A in a log file:

F46D,01 : 0.43956955423105626
F483,01 : 3.296508354821981e-5
F483,01 : 3.4920639350843885e-5
F483,01 : 3.1568257981007264e-5
F483,00 : 3.128889285619607e-5
F483,00 : 3.1568257981007264e-5
F483,00 : 3.1568257981007264e-5
F483,00 : 3.128889285619607e-5
F483,00 : 3.1568257981007264e-5
F440,00 : 3.268571843761947e-5
F46D,01 : 0.020822478834602975
F483,01 : 3.324444865882015e-5
F483,01 : 3.1568257981007264e-5

So I now have a patched MIDRY.COM MIDI player that works on turboR Smile (some complex files were slowed down in Z80 mode).

MIDI transfer must be done at 3.125KBauds, and only accept a 1% difference in the baudrate, so that was tricky.

NYYRIKKI, there was indeed a small difference in the values I computed using openMSX and a real turboR.

By Manuel

Ascended (13001)

Manuel's picture

30-07-2016, 15:43

If anyone of you finds out any more details on R800 timing, we're all ears! Please tell us.

By Louthrax

Paragon (1258)

Louthrax's picture

30-07-2016, 16:06

Can't really say something that makes sense from my MIDI experiments. I had a measured 31.25kbauds rate on openMSX, but I had to change is slightly so that it works on a real turboR. Differences could be anywhere...

By ricbit

Champion (334)

ricbit's picture

01-08-2016, 15:13

Let me add, if you want precise timing on r800, then any kind of busy wait is asking for trouble, due to the refresh. The safe alternative is using the timer. The bios use the following loop to temporize FM calls:

out to 7C
ld a,3
call wait
out to 7D
ld a, 0xD
call wait

wait:
in a, (E6)
ld h,a
1:
in a,(E6)
sub h
cp l
jp c, 1b
ret

My MSX profile