Re: [hatari-devel] Spinloop detection in emulated code

[Eero Tamminen <oak@xxxxxxxxxxxxxx>]

Hi,

On tiistai 06 elokuu 2013, Eero Tamminen wrote:
> I was thinking that I could add profile command for setting "spinloop"
> output file.  CPU and DSP profiling functionality could then append to
> that file information about detected spinloops, each time a loop is
> exited.
> 
> If spinloop goes through without looping, no information is saved.
> 
> 
> Information for each line in the file could be:
>   <address> <number of iterations> <VBLs[1]> <branched instruction>
> 
> [1] VBLs since boot, at loop exit, when info on that spin is saved.

I've commited first version of this.

You can enable it with:
	profile loops <filename> [CPU limit] [DSP limit]

When (CPU and/or DSP) profiling is enabled, it will by default save
information on all inner loops repeated more than once.

If you are not interested about longer loops, you can specify loop start
& end instruction address difference limits.  For CPU the limit isn't
very exact as longest CPU instruction can be many (10?) bytes long, but
I don't think that's really a problem as one can just ignore them.


Disassembly looked too ugly in the output (and one can grep that from
the normal "profile save" files), so the final output format is:
-----------
 <processor> <VBLs from boot> <address> <size> <loops>
DSP 5704 0x0d2d 2 3
CPU 5704 0x03291a 2 2
DSP 5704 0x0d2d 2 3
CPU 5704 0x03291a 2 2
-----------


> Number of iterations + address allows calculating iteration min/max/avg
> counts in post-processing, and sorting & grepping that info easily.
> 
> VBLs information is useful for knowing both whether (e.g. CPU + DSP)
> spinning happens within same frame and from iteration-count sorted
> output seeing in which order the spinloops were done.

I also added initial post-processor, its output looks like this:
-------------------------
CPU loop statistics
   max: at VBL:    min: at VBL: times:  stddev: addr:   size:
   2592    7570       4    5841     382   528.3  052a1c      4
   2396    7810       2    5769    2608   208.0  053aae      4
   1023    8814      11    7310     167   323.9  052b34      4
    724    8090       2    7316    3252    27.1  054638      2
    645    5737     116    5737       4   228.6  048f64    198
    563    8759       2    7031     223   169.8  052afc      4
    495    5732       4    6678       3   281.5  053c0a      2
    287    8814       3    7810     198    84.7  03e6ca      8
....
-------------------------

"max" is largest looping count for given adress, "times" is how
many times code goes to that particular spinloop.


Due to heuristics used, in some cases Hatari can list different sized
spinloops for the same loop (start) address. This can be because:
- code in question changed, or
- outer loop was sometimes repeated several times in succession
  without repeating the inner loop, and outer loop used the same
  start address as inner loop


> Having each spin listed separately allows checking in detail in which
> order things actually happened, what kind of spins there are within
> frame, and even providing VBL metrics about spinloops.
> 
> 
> The contents of this file will be reseted each time profiling is
> re-started.  This allows using it with Hatari's recent "worst frame"
> profiling support, i.e. in case of Bad Mood, one can get spinloop
> information that is specific for the worst frame.

I needed to add file "rename" command to debugger to get correct
spinloop file put aside for worst frame profiling.

I already tested that with BadMood and it seems to be working OK
with worst frame profiling.


	- Eero