Receiving debugdevice stdout or stderr messages through socket connection?

Page 1/2
| 2

By Sandy Brand

Master (229)

Sandy Brand's picture

08-03-2015, 15:45

Hello everyone!

I was thinking about trying to make a very rudimentary profiling tool using the debugdevice extension and ports 0x2E and 0x2F.

I have based most of my code on the openMSX debug viewer. So I got the basics for connecting with openMSX and everything to work. However, after some more experimentation I ran into the following issues and questions (I am running on a Windows machine, btw).

  • The data outputted on port 0x2F is never shown in Catapult's Status Info window. Only when I 'set outputdebug stderr' will it become visible there (could be a Windows only issue, maybe?)
  • When set to stderr, focus will be set to the Status Info tab everytime something is printed in there. If I happen to output data very regularly (say on an interrupt handler), this basically means I can't click on anything in catapult anymore apart from the Stop button which happens to remain visible. It would be nice if the 'auto focus' could be an optional feature somewhere because it is very nice to have, ... but not always Smile
  • Is there a way to receive these log messages through a socket connection? From reading through the documentation it seems it should be possible because there is a <log> message. I never seem to receive these though.
  • In fact, the documentation states that one of the very first messages that is sent from openMSX over the socket should be something like this: "<log level="info">Using default machine: Boosted_MSX2_EN</log>". I never get that message either. Do I perhaps need to tell openMSX to send me the log messages as well? Something like <command>openmsx_update ????</command>
  • Can anyone tell me what units of time are represented with "emutime: xxxxx"? Is there an easy way to convert this into say seconds or something?

Sorry for the long list of questions, but any help on this would be much appreciated Smile

Login or register to post comments

By Manuel

Ascended (17868)

Manuel's picture

08-03-2015, 23:00

Hi,

Just a quick reaction here:
1. indeed, only stderr is... stdio isn't output to when there's a -control option used, because one of the -control options is to use stdio for control. Probably this could be improved by only disabling logging on stdout if stdout is actually used for the -control option...
2. I don't think using Catapult for this purpose was ever thought of... Just don't Smile
3. Nope, it sends it to the file mentioned in the debugoutput setting. (So, use a real file and not stderr or stdout.) You could modify openMSX a bit though, it's adding a few lines in DebugDevice.cc.
4. Thanks for mentioning that! This log line was actually removed by myself in 2009, but it seems I forgot to update a document Smile Fixed now. The stuff will work fine by default, but there's nothing in the debug device that will use it.
5. Emutime is a counter with a frequency of 960 * 3579545 Hz.

If you want to do profiling, wouldn't it be a lot easier to not use the debug device, but directly some debug commands, which are much more powerful and will not influence the timing of your MSX code?
You could for instance put a breakpoint on point A, which stores the current time and then a breakpoint at point B, which subtracts that stored time from the current time, so you have the exact duration of execution between point A and B.

The debug device originates from (just) before we implemented the debug command. And a lot of work was done on it to make it very powerful in the years following that, while the debug device is essentially the same as in 2003 Smile

By sd_snatcher

Prophet (3448)

sd_snatcher's picture

08-03-2015, 23:50

Profiling on openMSX & debugger will be a very welcome feature! I wish you success with this project!

By Sandy Brand

Master (229)

Sandy Brand's picture

10-03-2015, 00:58

Hello Manuel,

First of all thank you for your quick and detailed reply.

So I guess that using the debug device is a dead-end for what I need Smile

Your suggestion of using break points is interesting but I think that it will be 'hard' to implement this for 'easy profiling' without injecting some sort of support code into the binaries. Take, for example, this common pattern in assembly code:

AAA:
; Do some stuff.
  JP  Z,BBB ; (Call and return).
; Do other stuff.
  JP CCC ; (Call and return).

This function is now 'impossible' to profile using memory break-points because it has multiple return paths which are also sometimes conditional. For the call to BBB it will be impossible to place a break-point that still allows us to measure the 'inclusive' time that was spent in function AAA.

Also, the code for my project can reside in any of the memory pages and slots. I guess it is possible to extract the required information (address, slot, memory page) from the assembly output of course but this can be quite cumbersome. Not to mention that I have some very special cases in which code is temporary swapped out into all sorts of unused VRAM gaps. Also, using a memory mapper means that I cannot exactly know up-front where my code will physically reside.

So, my initial idea was to inject little pieces of assembly code for target functions using some sort of pre-processor. Something like this:

AAA:
 PUSH AF
 LD   A,1   ; 1 = Enter scope for function AAA.
 OUT  (DEBUG_DEVICE_PORT),A
 POP  AF

 CALL AAA_ORIGINAL

 PUSH AF
 LD   A,2   ; 2 = Leave scope for function AAA.
 OUT  (DEBUG_DEVICE_PORT),A
 POP  AF
 
 RET

AAA_ORIGINAL:
 ; Do whatever crazy jumps and calls you want to do here.
 RET

This pre-processor would generate the unique scope numbers, inject it into the source code and store it somewhere for the profiler to be picked up later on.

You are right that this will influence the profiling measurements, but for my case this is okay.
I am currently mainly trying to get a rough idea of where my CPU cycles are going and how many times certain functions are being called.

So an other question: Do you think it would be possible to create custom break-points on an output port using TCL, that would then send the outputted value over the socket connection? If so, could you give me some example TCL scripting that does that?

(Come to think of it, I guess we could even use a break-point on any memory address as long is it is unused memory; I am only interested in the written value in the end).

sd_snatcher wrote:

Profiling on openMSX & debugger will be a very welcome feature! I wish you success with this project!

I am afraid I am going to have to disappoint you, because for now I am thinking of only writing some very simple tools that will help me with my personal project. Smile Otherwise it will never get done, you know what it is like Tongue

But who knows, if it works well and I find some extra time I might be able to do some open source contributions Smile

By Grauw

Ascended (9811)

Grauw's picture

10-03-2015, 09:22

I was thinking yesterday that it would be nice to have a VDP command engine profiling tool, which:

1. Shows an idle percentage.
2. Shows a colourful overlay of boxes on top of the screen which lets you see nr of copies, copy size and overdraw.
3. Shows possible optimisations by e.g. looking at which LMMM’s can be replaced by HMMM or HMMV, and which draw calls can be combined, etc.

By Manuel

Ascended (17868)

Manuel's picture

10-03-2015, 11:52

Grauw: 1 is already implemented, check the toggle_vdp_busy command.

Sandy: I'll ask Wouter to comment on this, he may have other/better ideas than I have at the moment.

Did you already check out the examples of the debug command? See http://openmsx.sourceforge.net/manual/commands.html#debug

By wouter_

Champion (456)

wouter_'s picture

10-03-2015, 13:32

Sandy Brand wrote:

So an other question: Do you think it would be possible to create custom break-points on an output port using TCL, that would then send the outputted value over the socket connection? If so, could you give me some example TCL scripting that does that?

It is possible to attach a Tcl script to IO port writes. And inside that script you do have access to the written value (and to the written address, useful in case you watch a whole range of addresses).
We have a mechanism to send messages over the socket connection, but that was meant for info, warning and error messages. So everything you send will be interpreted and shown as such. Here's an example Tcl script:

debug set_watchpoint write_io 0x2E 1 my_handler_proc
proc my_handler_proc {} {
	message "Value $::wp_last_value was written to IO port $::wp_last_address" info
}

Is there any particular reason why you want to send this information over the socket connection? Wouldn't it be much easier to process the information locally? And maybe only send the final result? And/or write the details to some log file?

By Manuel

Ascended (17868)

Manuel's picture

10-03-2015, 14:23

Wouter: how would you solve the original problem: he wants to profile his code in the way he described in his 2nd post.

By wouter_

Champion (456)

wouter_'s picture

10-03-2015, 15:33

Manuel wrote:

Wouter: how would you solve the original problem: he wants to profile his code in the way he described in his 2nd post.

What about the following script? To use it write a value to IO port 0x2C to enter a scope and write the same value to port 0x2D to leave that scope again (0x2C and 0x2D are debug-only IO ports, they don't have any function in the MSX machine). There can be multiple scopes open at the same time (they don't need to be strictly nested). And (recursively) entering the same scope multiple times is supported.
You may want to change the profile_output proc to show the results in a way that suits you (e.g. write to a log file instead of writing to stderr).

Note this is something I wrote in a couple of minutes, and I only very lightly tested it. So it may still contain bugs, and I'm sure it still can be improved.

debug set_watchpoint write_io 0x2C 1 enter_scope
debug set_watchpoint write_io 0x2D 1 leave_scope

set scopes [dict create]

proc enter_scope {} {
	set nr $::wp_last_value
	set now [machine_info time]
	dict lappend ::scopes $nr $now
	profile_output "$now: Entering scope $nr"
}

proc leave_scope {} {
	set nr $::wp_last_value
	set now [machine_info time]
	set l 
    if {[dict exists $::scopes $nr]} { set l [dict get $::scopes $nr] } if {[llength $l] == 0} { profile_output "$now: error leaving scope $nr without first entering it" return } set prev [lindex $l end] dict set ::scopes $nr [lrange $l 0 end-1] set dur [expr {$now - $prev}] profile_output "$now: Leaving scope $nr, took $dur" } proc profile_output {message} { puts stderr $message }

Edit: the script isn't rendered correctly in the MRC forum. Better directly look at the raw code.

By Manuel

Ascended (17868)

Manuel's picture

10-03-2015, 15:51

And what if you want to profile code without having an impact on the actual MSX code? (So without adding special instructions.)
The problem is probably indeed to find out which addresses you have to check for when writing the proper debug instructions in Tcl... But if you use the Debugger GUI and load the symbols, you can perhaps easily find them. Not sure how to handle the "multiple return paths issue" though.

By Sandy Brand

Master (229)

Sandy Brand's picture

11-03-2015, 21:03

Wow! Thanks for the great support guys! I will look into this stuff this weekend Smile

Page 1/2
| 2