hatari_profile - Post-processor for Hatari profiler data
hatari_profile.py [options] <datafiles>
A Python script to post-process data produced by Hatari profiler
"save" commands, both for CPU and DSP:
profile save <filename>
dspprofile save <filename>
It can provide function level (CPU and DSP) processor usage information for
anything Hatari profiler records: instruction counts, processor cycles and
depending on processor, also instruction cache misses or cycle differences.
This information can be provided as ASCII list of heaviest functions, as
callgraphs (if profile data includes caller information), or as callgrind
format export which can be viewed in (Linux) Kcachegrind GUI.
Invoking
hatari_profile without arguments lists all of its options.
Regardless of whether profile data contains some symbol information, you should
always give script all relevant debug symbols, otherwise costs might not get
correctly assigned to symbols preceding those costs.
This post-processes profile data for EmuTOS (ROM), with symbol file having
fixed/absolute addresses (-a), shows statistics (-s) and top lists (-t), but
limits list output to anything taking over 2% (-l 2) and includes
"propagated" subroutine call costs (-p):
-------------------------------------------------------------
$ hatari_profile.py -a etos1024k.sym -st -l 2 -p etos-boot.txt
Hatari profile data processor
Parsing absolute symbol address information from etos1024k.sym...
WARNING: replacing '_os_header' at 0xe00000 with '__text'
WARNING: replacing '_instruction_cache_kludge' at 0xe00660 with '_invalidate_instruction_cache'
1806 lines with 1187 code symbols/addresses parsed, 0 unknown.
Parsing profile information from etos-boot.txt...
18900 lines processed with 531 functions.
...
Of all 38474 switches, ignored 3731 for type(s) ['r', 'u', 'x'].
CPU profile information from 'etos-boot.txt':
- Hatari v2.3.1, WinUAE CPU core
Time spent in profile = 6.72122s.
Visits/calls:
- max = 1768, in _memcpy at 0xe46ea0, on line 7944
- 40800 in total
Executed instructions:
- max = 140992, in _timeout_gpip+22 at 0xe0b484, on line 4393
- 2566629 in total
Used cycles:
- max = 23997200, in _stop_until_interrupt+38 at 0xe4724a, on line 8213
- 53912568 in total
Visits/calls:
4.33% 4.38% 1768 1786 _memcpy
3.55% 0.40% 1450 165 _gsx2
3.55% 24.78% 1449 10112 _GSX_ENTRY
3.55% 3.58% 1449 1459 _get_vwk_by_handle
3.55% 21.17% 1449 8636 _screen
3.45% 27.77% 1407 11329 gemgsxif.o
2.98% 3.00% 1214 1222 _bconstat2
2.95% 2.95% 1203 1203 _kbshift
2.78% 2.79% 1134 1137 _bcostat4
2.51% 1024 vdi_blit.o
2.35% 3.25% 959 1327 _cputc
2.35% 5.60% 957 2283 _bconout2
2.29% 936 _just_rte
2.27% 927 kprint.o
2.23% 7.48% 911 3052 _biostrap
2.10% 2.10% 858 858 gemdosif.o
2.10% 2.12% 858 867 _enable_interrupts
Executed instructions:
32.96% 33.10% 33.19% 846043 849564 851784 _timeout_gpip
10.61% 10.66% 10.72% 272360 273633 275161 _blank_out
8.74% 8.81% 8.88% 224230 226006 227862 _draw_rect_common
5.94% 5.96% 5.96% 152525 152895 153039 _run_calibration
5.63% 144385 _ascii_out
3.52% 3.55% 22.77% 90398 91014 584547 _screen
2.62% 67293 ikbd.o
Used cycles:
44.62% 44.62% 45.46% 24057296 24057392 24509580 _stop_until_interrupt
18.87% 19.01% 19.06% 10171140 10248940 10277724 _timeout_gpip
4.77% 4.82% 4.85% 2571980 2597744 2616824 _blank_out
3.83% 3.89% 3.93% 2065076 2096668 2121104 _draw_rect_common
2.82% 1521072 _ascii_out
2.58% 2.60% 2.60% 1391076 1400236 1402000 _run_calibration
2.19% 2.21% 11.51% 1181264 1193784 6203852 _screen
-------------------------------------------------------------
This creates GraphViz callgraph files (-g) and Kcachegrind callgrind data file
(-k) from Bad Mood (Doom BSP viewer) profile. Symbols for the program are TEXT
section relative (-r), calls to some interrupt routines in the program are
ignored as they aren't real calls, callgraph nodes using over 2% are
highlighted, and there are some options to limit and simplify the graph:
-------------------------------------------------------------
$ hatari_profile.py -r bmsym.sym \
-k -g -p --emph-limit 2.0 --limit 0.5 \
--ignore-to framecounter,new_vbi,stabilizer_b \
--compact --no-leafs --no-intermediate \
badmood-profile.txt
Hatari profile data processor
Parsing TEXT relative symbol address information from bmsym.sym...
1023 lines with 392 code symbols/addresses parsed, 0 unknown.
Parsing profile information from badmood-profile.txt...
1420 lines processed with 63 functions.
Ignoring 29 switches to framecounter
Ignoring 9 switches to stabilizer_b
Ignoring 8 switches to new_vbi
Of all 1562 switches, ignored 56 for type(s) ['r', 'u', 'x'].
Generating callgrind file 'badmood-profile.cg'...
Generating 'badmood-profile-0.dot' DOT callgraph file...
Generating 'badmood-profile-1.dot' DOT callgraph file...
Generating 'badmood-profile-2.dot' DOT callgraph file...
Generating 'badmood-profile-3.dot' DOT callgraph file...
CPU profile information from 'badmood-profile.txt':
- Hatari v1.6.2+ (Apr 10 2013), WinUAE CPU core
-------------------------------------------------------------
hatari(1),
gst2ascii(1),
hconsole(1) hatariui(1)
Written by Eero Tamminen <oak at helsinkinet fi>.
This program is free software; you can redistribute it and/or modify it under
the terms of the GNU General Public License as published by the Free Software
Foundation; either version 2 of the License, or (at your option) any later
version.
This program is distributed in the hope that it will be useful, but WITHOUT ANY
WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR
A PARTICULAR PURPOSE. See the GNU General Public License for more
details.