|Re: [hatari-devel] Hatari profiler updates and CPU cycle questions|
[ Thread Index |
| More lists.tuxfamily.org/hatari-devel Archives
- To: hatari-devel@xxxxxxxxxxxxxxxxxxx
- Subject: Re: [hatari-devel] Hatari profiler updates and CPU cycle questions
- From: Douglas Little <doug694@xxxxxxxxxxxxxx>
- Date: Thu, 31 Jan 2013 09:32:53 +0000
- Dkim-signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=googlemail.com; s=20120113; h=mime-version:x-received:in-reply-to:references:date:message-id :subject:from:to:content-type; bh=VVE6UWKX/zWX+GJp9xV5JNmHjaT6D25iFkduHGm5ZGw=; b=kEnmzKIk4kXaiX0H3Dh2hTLGS+Rbz+jxKjf8/Uf3S/Yk/iIk1U3rV+6WnEoNudulqT BY7gfPdRmPRXwqlsGoT/vwJE8UwltUmInCjTMWEG+kvtxRNzuQrzpNRcSqyrTUqTeZw4 hEV0ussXVPjdJ4VtmKU/nrj4bPqYQ30+H+zQUufVIkijfN7os6YY8ACIqYeVyPnHDwpx DNzdUpoHrCrfI04B6W4Gb4XLzM/UuBUj7+UK0w9serL6/BmyxroPvSOXDO8yZ4Ig3vex uwQn1/2YUOxIthwrnTIwqr7rsN9HyLTkZAY1a0AAGAjH72T9t2rU6VkSHBX9j74dFaeq Sn9A==
Make sure you get the latest debugger code from Mercurial, in one
version I had signed / unsigned mismatch for cycle counter.
I am on rev #4668dded703c which appears to be the latest one.
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. :-)
I don't think it got an opportunity to wrap around in my test - it was only a few seconds long.
Something like this "shouldn't" happen with anything else
than stop instruction (or some similar instruction) now.
The same extreme value is repeated lots of times in all areas of the code (and I don't use the stop instruction at all).
> 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?
The profiling was conducted from an interrupted run. The program was launched and ran for a few seconds, I interrupted it with the debugger and enabled profiling, then it was allowed to continue for a few seconds, then I interrupted again and captured the results. This was to ensure profiling took place for the mainloop only and not the texture cache initialization code (which is large and costly)
However there are plenty of symbols in the program, and the most expensive 'large' function block consumes 60% cpu in total (i.e. my own profiler shows a different and more familiar pattern of functions) so either the symbols did not import as expected or something else has happened.
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.
It does seem that your results indicate the system is working, and my results look completely different!
It's probably worth trying an un-optimized build here with cycle counts to see if the compiler / code _expression_ details have anything to do with it.