Performance Profiler - A first attempt

I want to change the profiler to let the start and end points to be marked by specifying a <slot, bank, address> triplet which it then registers as a breakpoint. Then the profile start/end points can be set up either by the program during its initialisation, or externally through TCL (e.g. with lookups in a symbol table), and will not affect performance during execution.

Reason is that I have interrupts getting in the way of my measurements, and I prefer not to add those OUTs to mark the start and end points in the ISR (it is timing sensitive due to splits). Also it seems nice if it makes use of the capabilities of the emulator to live completely outside of the program execution.

MRC swallowed the <, fixed.

I updated my profiler script for openMSX: profile.tcl. You no longer need to instrument the MSX program, instead the profiler is now hooked in from openMSX TCL scripts. To assist with this, you may also be interested in the symbols.tcl script to read symbol files.

Hook up the profiler by setting up openMSX breakpoints and calling profile::section_begin and profile::section_end with a section ID to log the time under. Use the ID “frame” to delimit frames.

There are also a number of convenience functions which set up the breakpoints for you, amongst others profile::section_scope_bp which you can point to a method which starts the section, and it will automatically end the section when the method returns. There is also profile::section_irq_bp which will start and end a section when the Z80 handles an interrupt request. Note that these two rely on openMSX commit 6529495bd which is not in the 0.15.0 release, so you need to get a recent nightly build. Everything else works on the current openMSX 0.15.0 though.

Additional new functions are, you can specify section IDs to profile to limit its output, and both profile and profile_osd now have the ability to show their statistics in units of seconds (s), milliseconds (ms), clock cycles (t) or as a percentage (%). Furthermore you can use profile_break or click on the OSD to advance execution until a specific section is hit.

Last but not least, you can now exclude the time spent in one section from another, so that e.g. interrupts no longer disturb your measurements, or to omit vsync wait loops from your game loop.

A little example:

profile::section_scope_bp frame 0xFD9F  # H.TIMI
profile::section_scope_bp chput 0xA2 { [pc_in_slot 0 0] }
profile::section_irq_bp int
profile::section_exclude int chput
profile_osd t

This marks a new frame when H.TIMI is called (on the vblank interrupt), and it adds a measurement section for calls to the BIOS CHPUT routine. Another section is added for the ISR, and it is excluded from the time spent in CHPUT. Lastly we show the OSD with clock cycle (t) stats.

From this little test profile we can see exactly how long the ISR takes and how much time is spent in the H.TIMI hook. Additionally we can tell that MSX-BASIC rarely calls CHPUT, but MSX-DOS does.

See this code snippet in tiletile for a more elaborate example.

Added VDP command execution profiling thanks to this openMSX addition by wouterv_.

I want that!!!