Re: [hatari-devel] Hatari profiler updates and CPU cycle questions

[Eero Tamminen <oak@xxxxxxxxxxxxxx>]

Hi,

On torstai 31 tammikuu 2013, Douglas Little wrote:
> Here is a snapshot of output from the profiler (with the patch applied to
> prevent the crash).
> 
> The 'count' column looks sensible but the cycles column looks pretty
> random, with negative or overflow values in there.

Make sure you get the latest debugger code from Mercurial, in one
version I had signed / unsigned mismatch for cycle counter.

I'm not sure what the CPU cycle counter in cycles.c does when it
wraps around, but at least with unsigned values used in profiler,
there shouldn't be negative values. :-)

As to overflow in profiler's own code, counters should stop counting
when they reach maximum values and not wrap around.


> The test I profiled
> only ran for a few seconds so I doubt the total cycle count could be
> responsible. There are also zeroes all over the place.
> 
> 
> $01ee32 : 9242                                 sub.w     d2,d1
>          0.00% (34, 4294967295, 34)

Something like this "shouldn't" happen with anything else
than stop instruction (or some similar instruction) now.

....
> I did play with the post processor python file and got some output but I
> think the results are invalid because the profiler output is wrong. One
> problem I did notice is that it collects statistics under symbols for
> functions which are inactive/unused. e.g.
> 
> Executed instructions:
>  97.35%  18904938  add_upper_partition  (at 0x2210a)   <- this function
> is defined, but is never used by the test
>   1.51%    293593  HATARI_PROFILE_BEGIN

This is suspicious.  Don't you have any symbol where the execution
begins after profiling start?

(TODO: I could assign HATARI_PROFILE_BEGIN info afterwards to whatever
symbol is in address preceeding that, if there is such symbol.)


>   0.44%     85170  add_upper    (at 0x21dd6)
>   0.37%     71598  add_lower    (at 0x21d28)
>   0.33%     64828  Display_Player_Position      (at 0x24612)  <- this
> function is only called if the map is opened, which it was not

If it's the last symbol, it could get also all code run within
TOS assigned to it, if you didn't given symbols for TOS, and
your code called OS routines.

(TODO: I could add symbol marking TOS start to get them assigned properly,
and one for Cartridge start, to prevent cartridge code being marked for
last TOS symbol...)


> When I get a bit more time I'll check the symbols to make sure they were
> allocated to the right addresses, in case it was an import error on my
> part etc.

I haven't really tested profiling user code yet, just (Emu)TOS,
and a quick tests that post-processor accepts DSP disassembly.
I.e. there may be bugs still, I'll check that tomorrow.


Note that you have two ways to give symbol information:

* load it to Hatari debugger before exporting profile info:
  - supports only single symbol file at the same time
  - user can specify separate offsets for text (T), data (D)
    and bss (B) data types.  If no offset is given, addresses
    are assumed to be absolute

* give it to post-processor:
  - one can give arbitrary number of symbol files,
    for example for TOS and user-space program
  - assumes user-space program text (T) addresses
    (addresses that are below ROM TOS area)
    to be relative to the program text section address,
    which is output by profiler to the beginning of
    the profiler data

If post-processor should work in some other way, it's easy
to change.


> I think the main problems though are the crash (?) and the
> cycle counts. The two problems may even be related?

Very unlikely, but everything's possible.


> I'll try to test with an un-optimized build as well to see
> if anything different happens.


	- Eero