Re: [hatari-devel] Bogus profiler CPU cycles values

[Eero Tamminen <oak@xxxxxxxxxxxxxx>]

Hi,

On perjantai 15 helmikuu 2013, Douglas Little wrote:
> On 15 February 2013 13:51, Eero Tamminen <oak@xxxxxxxxxxxxxx> wrote:
> > Data header and post-processor changes come later.
....
> Great stuff. I'll soon be looking at cycle-level information again - not
> quite yet, but soon. Will revisit all of this at that point and will
> report back.

I've now done the profiling data update and post-processing changes
(+ fixed annoying thing in cycles validity check):
	http://hg.tuxfamily.org/mercurialroot/hatari/hatari/

There's still the zero CPU cycles WinUAE CPU core issue I mentioned
in another mail thread that needs to be investigated.

The post-processor output looks now like in the attached files.

(As I mentioned, IMHO XDot Python program is best for viewing .dot files.)


I'm still going to refactor the post-processor code a bit and try
adding callgrind format output for viewing the data in Kcachegrind:
	http://kcachegrind.sourceforge.net/

The main advantage of latter (if it works as I hope) would be having
lists of functions processor usage and clicking on a function name
showing corresponding part of the profile disassembly and part of
the callgraph related to that function (Kcachegrind can generate
callgraphs by itself).


	- Eero

Time spent in profile = 1.31626s.

Executed instructions:
- max = 508313, in _timeout_gpip at 0xe06f22
- 4786912 in total
Used cycles:
- max = 3052562, in _timeout_gpip at 0xe06f2c
- 21116114 in total
Cache misses:
- max = 11526, in ___udivsi3 at 0xe60782
- 870167 in total

Calls:
 14.13%      8967 ___mulsi3                   (0xe6075c)
  9.08%      5764 ___udivsi3                  (0xe60780)
  9.03%      5731 ___divsi3                   (0xe607dc)
  9.00%      5708 ___modsi3                   (0xe6080c)
  8.27%      5245 _getclnum                   (0xe11078)
  4.53%      2876 _biostrap                   (0xe00668)
  4.50%      2857 _blkdev_mediach             (0xe04214)
  4.50%      2856 _getrec                     (0xe10d00)
  4.50%      2856 _flop_mediach               (0xe073d4)
  4.49%      2850 _cl2rec                     (0xe10ee4)
  4.49%      2850 _ixread                     (0xe116ea)
  4.49%      2850 _ixlseek                    (0xe115b2)
  4.49%      2847 _getrealcl                  (0xe10fd4)
  4.49%      2847 _protect_w                  (0xe00732)
  4.48%      2846 _mediach                    (0xe049a2)

Executed instructions:
 63.87%   3057419 _timeout_gpip               (0xe06f06)
  5.84%    279549 _xgetfree                   (0xe11172)
  4.10%    196190 _ixlseek                    (0xe115b2)
  2.22%    106301 _getrec                     (0xe10d00)
  2.06%     98637 ___mulsi3                   (0xe6075c)
  2.05%     97988 ___udivsi3                  (0xe60780)
  1.98%     94908 _biostrap                   (0xe00668)
  1.90%     91104 _getrealcl                  (0xe10fd4)
  1.85%     88563 _blkdev_mediach             (0xe04214)
  1.85%     88557 _flop_mediach               (0xe073d4)
  1.79%     85620 ___modsi3                   (0xe6080c)
  1.69%     80999 _text_blt                   (0xe01fce)
  1.68%     80234 ___divsi3                   (0xe607dc)
  1.31%     62895 _abline                     (0xe32974)
  1.19%     56998 _ixread                     (0xe116ea)
  1.07%     51416 _draw_rect                  (0xe31e38)

Used cycles:
 53.14%  11221382 _timeout_gpip               (0xe06f06,  0.69948s)
  7.41%   1564624 _xgetfree                   (0xe11172,  0.09753s)
  4.66%    983136 _ixlseek                    (0xe115b2,  0.06128s)
  4.21%    888582 _getrec                     (0xe10d00,  0.05539s)
  3.74%    789626 ___mulsi3                   (0xe6075c,  0.04922s)
  3.65%    771276 _biostrap                   (0xe00668,  0.04808s)
  2.90%    612320 ___udivsi3                  (0xe60780,  0.03817s)
  2.40%    507164 _getrealcl                  (0xe10fd4,  0.03161s)
  2.22%    468314 ___modsi3                   (0xe6080c,  0.02919s)
  2.00%    423098 _flop_mediach               (0xe073d4,  0.02637s)
  1.96%    413038 ___divsi3                   (0xe607dc,  0.02575s)
  1.71%    360424 _blkdev_mediach             (0xe04214,  0.02247s)
  1.58%    333158 _text_blt                   (0xe01fce,  0.02077s)
  1.49%    313800 _ixread                     (0xe116ea,  0.01956s)

Cache misses:
 19.67%    171179 _xgetfree                   (0xe11172)
 11.52%    100247 _ixlseek                    (0xe115b2)
  8.23%     71601 _getrec                     (0xe10d00)
  6.24%     54280 _blkdev_mediach             (0xe04214)
  6.24%     54268 _flop_mediach               (0xe073d4)
  5.91%     51421 ___modsi3                   (0xe6080c)
  5.73%     49825 _getrealcl                  (0xe10fd4)
  5.61%     48801 ___divsi3                   (0xe607dc)
  5.35%     46552 ___mulsi3                   (0xe6075c)
  4.96%     43137 _biostrap                   (0xe00668)
  4.69%     40805 ___udivsi3                  (0xe60780)
  3.27%     28495 _ixread                     (0xe116ea)
  2.12%     18430 _text_blt                   (0xe01fce)
  1.96%     17075 _protect_w                  (0xe00732)
  1.64%     14251 _cl2rec                     (0xe10ee4)

Attachment: etos-fileinfo-falcon.dot.gz
Description: GNU Zip compressed data