Performance Profiler - A first attempt

Champion (295)

27-04-2015, 01:22

(Continued from receiving-debugdevice-stdout-or-stderr-messages-through-socket-connection)

Hello everyone,

I needed to get a better understanding of why the performance of my current project was not so good and came to the conclusion that I needed some tools to be able to profile the application while it is running in the openMSX emulator. As a result I wrote a fairly straightforward application using C# (UI) and some C++ (setting up socket connections and such) that can interface with openMSX and listen in on some special events that are generated through injection of special pieces of profiling code (for more information on how this is done I refer you to the documentation).

Although the resulting profiler is certainly not perfect, it suffices for my current needs and I can now spent my limited amount of time on other things again. This means I will probably not be able to support the further development of the tool, but I think it might still be very useful for other coders. This is why I want to make the tool available to all, also hoping that it may provide a first tentative step into writing a full-scale profiler for openMSX at some point in the future.

You can find the Windows binaries here, including some documentation and some examples on how to use/configure the profiler:

Google Drive: openMSX_Profiler_0.11.rar

Again, many thanks to all the people that helped with the TCL scripting side! I think it is fantastic that the MSX scene is still going strong, and it feels good to be actively contributing to it again after such a long time! :)

By Manuel

Ascended (19303)

27-04-2015, 15:39

Great to read this Sandy! Congratulations

By Grauw

Ascended (10707)

27-04-2015, 16:27

Very interesting, the profiler.html document and examples in the archive elaborate on the methodology and are pretty extensive.

In my code I often enclose my procedures in PROC / ENDP markers (a Glass assembler feature), mostly for the purpose of introducing a local scope for labels, however I’m also thinking whether I could perhaps use this to aid with profiling.

p.s. Is the source code available somewhere? I don’t use Windows, and I spot a BSD license .

By ARTRAG

Enlighted (6932)

29-04-2015, 22:00

Very interesting! going to test it very soon. Thanks for releasing, if you do not plan to maintain and extend the project, it could be a good thing to release the source as open

By Grauw

Ascended (10707)

25-07-2020, 02:40

For measuring function performance in gunzip I made this profiler script: profile.tcl

It’s not a fully automated profiler, you have to manually set it up to profile a single function in a run, but it’s easy to set up/use, and produces useful output. It counts the time spent between two specific out instructions, and in the console you can issue a command to report the time spent. With it, I produced this data.

By sd_snatcher

Prophet (3645)

06-04-2017, 03:41

Sorry, Graw, but I couldn't get how to use it.

1) I copied the profile.tcl to the openmsx/scripts folder
2) I included the OUT (2Ch),a before my function and the OUT (#2D) after it
3) When I run the profiler script without parameters in the console, it gives me a time and a counter. Every time I run the profiler script, the time and the counter increase. "Time" started with 0.09 and after many runs its already at 41.04.

How exactly am I supposed to interpret this?

By Grauw

Ascended (10707)

06-04-2017, 18:39

It measures the total time spent (in seconds) between the block specified by the OUTs from the start of emulation, and how often it has encountered the block. Type the profile command to get the current results. If the ignored count goes up it means your code isn't fully enclosed.

Sounds like your function is looping. If you want an average, divide the total time by the count.

If you want to know the running time during a certain period, simply invoke profile twice and subtract the numbers.

If you want the numbers during a single frame, remember openMSX has commands to pause and run for one frame that you can use.

If you want a number of Z80 clock cycles, multiply time by 3579544.

By sd_snatcher

Prophet (3645)

07-04-2017, 01:59

Thanks! I'll try again.

By santiontanon

Paragon (1770)

11-04-2017, 05:23

I have been using a customized version of Grauw's script for profiling my code for a few months and it works very well! My edited version is here: https://dl.dropboxusercontent.com/u/3303662/profile.tcl

By Grauw

Ascended (10707)

25-07-2020, 02:43

I updated my profiler script for openMSX: profile.tcl

New features:

Profile up to 257 sections at once
Frame synchronisation
OSD display

Note that the usage instructions changed a little.

By sd_snatcher

Prophet (3645)

27-10-2018, 15:57

Gauw, here a small contribution for your nifty profile.tcl script. I did the following modifications:

It doesn't install the watchpoints until requested. This way you can always keep the profile.tcl file in your ~/.openMSX/share/scripts folder. Before that, the automatic watchpoints tended to get in the way when I was just trying to do other types of debugging. The profile_io_start function was implemented to add the watchpoints when necessary.
Created the profile_callset_start function. This one is similar to the profile_io_start function, but it will scan a range of addresses for CALL instructions, and add breakpoints as necessary. I had to create this one because I mostly work on patches, and the I/O approach was more targeted to when you have full control over the source code and can add OUTs wherever you want

The new profile_callset_start allows the programmer to, for example, specify the range that contains the main loop of a Konami game (composed mostly by CALLS instructions), and it will show him where to focus the optimisation efforts.