stat calculator python script and example files

1. profiler stat calculator

#!/usr/bin/env python
# -*- coding: utf-8 -*-
# vim: sts=4 sw=4 et
# Description: profile calculator
# Author: Tony Pavlov (untoxa)
# SPDX-License-Identifier: MIT

import sys

symbols = {}
stat = {}  
  
def load_symbols(filename):
    with open(filename) as f:
        line = f.readline()
        while line:
            if line[0] != ';':
                decoded_line = [x.strip() for x in line.split(' ')]
                addr = decoded_line[0].split(':')
                addr = (int(addr[0], 16) << 16) | int(addr[1], 16)
                symbols[addr] = decoded_line[1]
            line = f.readline()
  
def calculate_timings(filename, double_speed):
    stack = [] 
    path =  []
    profile_addend = 18 if double_speed else 36
    with open(filename) as f:
        line = f.readline()
        while line:
            decoded_line = [x.strip() for x in line.split(',')]
            if decoded_line[0] == "PROFILE":
                if int(decoded_line[3], 16) == 3:
                    caller = ((int(decoded_line[2], 16) << 8) | int(decoded_line[1], 16)) - 3
                    path.append(symbols.get(caller, hex(caller)))
                    stack.append({'caller':caller, 'addend':profile_addend, 'clk':int(decoded_line[4], 16)})
                elif int(decoded_line[3], 16) == 4:
                    itm = stack.pop()

                    clk = int(decoded_line[4], 16) - itm['clk'] - itm['addend']
                    clk = int(clk if double_speed else clk / 2)
                    caller = itm['caller'];
                    
                    # update statistics item
                    statitm = stat.setdefault(':'.join(path), {'min':clk, 'max':clk})
                    statitm['ncalls'] = statitm.setdefault('ncalls', 0) + 1
                    statitm['totalclk'] = statitm.setdefault('totalclk', 0) + clk
                    statitm['min'] = min(statitm.setdefault('min', 0), clk)
                    statitm['max'] = max(statitm.setdefault('max', 0), clk)                    
                    
                    # shorten the path
                    path.pop()
                    
                    # make a correction for underlying function
                    if len(stack) > 0:
                        itm = stack[-1]
                        itm['addend'] = itm['addend'] + (profile_addend * 2)
            line = f.readline()


#for arg in sys.argv[1:]:
#    load_symbols(arg)

if len(sys.argv) < 2:
    exit('USAGE: profile.py <profiler_log> <symbols>')

if len(sys.argv) > 2: 
    load_symbols(sys.argv[2])
    
calculate_timings(sys.argv[1], False)

for k,v in stat.items():
    print('{:50s} MIN:{:-8d} AVG:{:-10.2f} MAX:{:-8d}'.format(k, v['min'], v['totalclk'] / v['ncalls'], v['max']))

2. example.c

void test_profile2(char i) {
   if (i & 4) 
       for (char i = 0; i < 0x10; i++);
}

void test_profiler() {
   for (char i = 0; i < 0x40; i++) test_profile2(i);    
}

void main() {
    test_profiler();
}

3. example.sym symbols file

; no$gmb format .sym file
; Generated automagically by ASxxxx linker V01.75 (SDK 3.0.0)
; Area: .  .ABS.
00:0000 s__HEADERf
00:0000 s__CABS
00:0000 s__HEADER0
00:0000 s__DABS
00:0000 s__HEADER1
00:0000 s__HEADER2
00:0000 s__HEADER3
00:0000 s__HEADER4
00:0000 s__HEADER5
00:0000 s__HEADER6
00:0000 s__HEADER7
00:0000 s__HEADER8
00:0000 s__HEADER9
00:0000 s__HEADER
00:0000 .init
00:0000 s__HEADER10
00:0000 s__HEADERa
00:0000 s__HEADER11
00:0000 s__HEADERb
00:0000 s__HEADER12
00:0000 s__HEADERc
00:0000 s__HEADER13
00:0000 s__HEADERd
00:0000 s__HEADERe
00:0200 s__CODE
00:026C s__HOME
00:0417 s__BASE
00:0417 s__GSINITTAIL
00:0417 s__LIT
00:0417 s__GSINIT
00:0418 s__GSFINAL
00:C000 .OAM
00:C0A0 s__DATA
00:C0A0 s__BSS
00:C0F9 s__HEAP
00:E000 .STACK
00:FF80 .refresh_OAM
; Area: _CODE
00:0200 _test_profile2
00:0216 _test_profiler
00:022F _main
; Area: _HEADER0
; Area: _HEADER1
; Area: _HEADER2
; Area: _HEADER3
; Area: _HEADER4
; Area: _HEADER5
; Area: _HEADER6
; Area: _HEADER7
; Area: _HEADER8
; Area: _HEADER9
; Area: _HEADERa
; Area: _HEADERb
; Area: _HEADERc
; Area: _HEADERd
; Area: _HEADERe
; Area: _HEADERf
; Area: _HEADER10
; Area: _HEADER11
; Area: _HEADER12
00:01D2 _exit
; Area: _HEADER13
; Area: _HOME
00:026C .set_mode
00:027C .remove_VBL
00:0282 .remove_LCD
00:0288 .remove_TIM
00:028E .remove_SIO
00:0294 .remove_JOY
00:029A .add_VBL
00:02A0 .add_LCD
00:02A6 .add_TIM
00:02AC .add_SIO
00:02B2 .add_JOY
00:02B8 .remove_int
00:02D7 .add_int
00:02F3 .wait_vbl_done
00:02F3 _wait_vbl_done
00:030A _display_off
00:030A .display_off
00:032B .serial_IO
00:035A _mode
00:0363 _get_mode
00:0368 _enable_interrupts
00:036A _disable_interrupts
00:036C _reset
00:036C .reset
00:0372 _set_interrupts
00:037D _remove_VBL
00:0388 _remove_LCD
00:0393 _remove_TIM
00:039E _remove_SIO
00:03A9 _remove_JOY
00:03B4 _add_VBL
00:03BF _add_LCD
00:03CA _add_TIM
00:03D5 _add_SIO
00:03E0 _add_JOY
00:03EB _clock
00:03F4 __printTStates
00:03F5 banked_call
00:040E banked_ret
; Area: _BASE
; Area: _LIT
; Area: _GSINIT
00:0417 gsinit
; Area: _GSINITTAIL
; Area: _GSFINAL
; Area: _DATA
; Area: _BSS
00:C0A0 __cpu
00:C0A1 .mode
00:C0A2 __io_out
00:C0A3 __io_in
00:C0A4 __io_status
00:C0A5 .vbl_done
00:C0A6 __current_bank
00:C0A7 _sys_time
00:C0A7 .sys_time
00:C0A9 .int_0x40
00:C0B9 .int_0x48
00:C0C9 .int_0x50
00:C0D9 .int_0x58
00:C0E9 .int_0x60
; Area: _HEAP
00:C0F9 _malloc_heap_start
; Area: .  .ABS.
00:0000 .__.ABS.

4. debugmsg.txt BGB "debug messages" log

PROFILE,32,2,03,00B46BF2
PROFILE,19,2,03,00B46C38
PROFILE,3,2,03,00B46C8A
PROFILE,15,2,04,00B46CC2
PROFILE,3,2,03,00B46D2A
PROFILE,15,2,04,00B46D62
PROFILE,3,2,03,00B46DCA
PROFILE,15,2,04,00B46E02
PROFILE,3,2,03,00B46E6A
PROFILE,15,2,04,00B46EA2
PROFILE,3,2,03,00B46F0A
PROFILE,15,2,04,00B4704C
PROFILE,3,2,03,00B470B4
PROFILE,15,2,04,00B471F6
PROFILE,3,2,03,00B4725E
PROFILE,15,2,04,00B473A0
PROFILE,3,2,03,00B47408
PROFILE,15,2,04,00B4754A
PROFILE,3,2,03,00B475B2
PROFILE,15,2,04,00B475EA
PROFILE,3,2,03,00B47652
PROFILE,15,2,04,00B4768A
PROFILE,3,2,03,00B476F2
PROFILE,15,2,04,00B4772A
PROFILE,3,2,03,00B47792
PROFILE,15,2,04,00B477CA
PROFILE,3,2,03,00B47832
PROFILE,15,2,04,00B47974
PROFILE,3,2,03,00B479DC
PROFILE,15,2,04,00B47B1E
PROFILE,3,2,03,00B47B86
PROFILE,15,2,04,00B47CC8
PROFILE,3,2,03,00B47D30
PROFILE,15,2,04,00B47E72
PROFILE,3,2,03,00B47EDA
PROFILE,15,2,04,00B47F12
PROFILE,3,2,03,00B47F7A
PROFILE,15,2,04,00B47FB2
PROFILE,3,2,03,00B4801A
PROFILE,15,2,04,00B48052
PROFILE,3,2,03,00B480BA
PROFILE,15,2,04,00B480F2
PROFILE,3,2,03,00B4815A
PROFILE,15,2,04,00B4829C
PROFILE,3,2,03,00B48304
PROFILE,15,2,04,00B48446
PROFILE,3,2,03,00B484AE
PROFILE,15,2,04,00B485F0
PROFILE,3,2,03,00B48658
PROFILE,15,2,04,00B4879A
PROFILE,3,2,03,00B48802
PROFILE,15,2,04,00B4883A
PROFILE,3,2,03,00B488A2
PROFILE,15,2,04,00B488DA
PROFILE,3,2,03,00B48942
PROFILE,15,2,04,00B4897A
PROFILE,3,2,03,00B489E2
PROFILE,15,2,04,00B48A1A
PROFILE,3,2,03,00B48A82
PROFILE,15,2,04,00B48BC4
PROFILE,3,2,03,00B48C2C
PROFILE,15,2,04,00B48D6E
PROFILE,3,2,03,00B48DD6
PROFILE,15,2,04,00B48F18
PROFILE,3,2,03,00B48F80
PROFILE,15,2,04,00B490C2
PROFILE,3,2,03,00B4912A
PROFILE,15,2,04,00B49162
PROFILE,3,2,03,00B491CA
PROFILE,15,2,04,00B49202
PROFILE,3,2,03,00B4926A
PROFILE,15,2,04,00B492A2
PROFILE,3,2,03,00B4930A
PROFILE,15,2,04,00B49342
PROFILE,3,2,03,00B493AA
PROFILE,15,2,04,00B494EC
PROFILE,3,2,03,00B49554
PROFILE,15,2,04,00B49696
PROFILE,3,2,03,00B496FE
PROFILE,15,2,04,00B49840
PROFILE,3,2,03,00B498A8
PROFILE,15,2,04,00B499EA
PROFILE,3,2,03,00B49A52
PROFILE,15,2,04,00B49A8A
PROFILE,3,2,03,00B49AF2
PROFILE,15,2,04,00B49B2A
PROFILE,3,2,03,00B49B92
PROFILE,15,2,04,00B49BCA
PROFILE,3,2,03,00B49C32
PROFILE,15,2,04,00B49C6A
PROFILE,3,2,03,00B49CD2
PROFILE,15,2,04,00B49E14
PROFILE,3,2,03,00B49E7C
PROFILE,15,2,04,00B49FBE
PROFILE,3,2,03,00B4A026
PROFILE,15,2,04,00B4A168
PROFILE,3,2,03,00B4A1D0
PROFILE,15,2,04,00B4A312
PROFILE,3,2,03,00B4A37A
PROFILE,15,2,04,00B4A3B2
PROFILE,3,2,03,00B4A41A
PROFILE,15,2,04,00B4A452
PROFILE,3,2,03,00B4A4BA
PROFILE,15,2,04,00B4A4F2
PROFILE,3,2,03,00B4A55A
PROFILE,15,2,04,00B4A592
PROFILE,3,2,03,00B4A5FA
PROFILE,15,2,04,00B4A73C
PROFILE,3,2,03,00B4A7A4
PROFILE,15,2,04,00B4A8E6
PROFILE,3,2,03,00B4A94E
PROFILE,15,2,04,00B4AA90
PROFILE,3,2,03,00B4AAF8
PROFILE,15,2,04,00B4AC3A
PROFILE,3,2,03,00B4ACA2
PROFILE,15,2,04,00B4ACDA
PROFILE,3,2,03,00B4AD42
PROFILE,15,2,04,00B4AD7A
PROFILE,3,2,03,00B4ADE2
PROFILE,15,2,04,00B4AE1A
PROFILE,3,2,03,00B4AE82
PROFILE,15,2,04,00B4AEBA
PROFILE,3,2,03,00B4AF22
PROFILE,15,2,04,00B4B064
PROFILE,3,2,03,00B4B0CC
PROFILE,15,2,04,00B4B20E
PROFILE,3,2,03,00B4B276
PROFILE,15,2,04,00B4B3B8
PROFILE,3,2,03,00B4B420
PROFILE,15,2,04,00B4B562
PROFILE,2E,2,04,00B4B5AC
PROFILE,6B,2,04,00B4B5D8