P2 Taqoz V2.8: A Profiler Utility Using Interrupts

Christof Eb.

Hi,
sometimes it ist interesting to know, where in the code most time is spent. In this case, we use a timer interrupt to peek into the system and explore then all the contents of the Forth return stack. We count, how often which return address is found on any level of the stack. The interrupt routine uses reserved cog registers of the tracer. (Which won't be used in parallel) The cog register "traceL" is used to control the interrupt frequency. Lower=more often. If counter overflow would occur, the interrupts are stopped at 65535.

The tool works for cog0. and uses a BIG array of 32K 16bit counter words in parallel to the code-words, so any code word address has a corresponding bin in that array. Only a few bins are used. After the test has run, the word "prtOccur" will print out used bins word-address and their counted number, a percentage, and the name of the word, if this can be found.
This automatic name decoding must be taken with a grain of salt: There are some words, which don't have names in the name-dictionary but can be found in the file taqoz.lst .
Some other entries can be misleading: On the stack we do not find the address of the called word but already the next word's address, so the interrupt service routine subtracts 2 to hopefully find the actual address. It can happen, that this is not a valid wordcode address.
The percentage is calculated relative to the maximum of occurrences. As occurrences are counted on any level of the stack, their sum is greater than 100%. The sum of subroutine's occurrences should fit into their parent's.
The interrupt frequency can be varied: If it is too often, only a part of a longer execution will be evaluated until stop by overflow is reached. If it is too seldom, small routines might not be taken into account. Also there might be the case, that the regular timer interrupt could have aliasing effects with small routines, which are used at the same intervals.
Have fun Christof

\ TestCase #################################################################

code dummyCode
   mov r1,##200
   .l1 djnz r1,#l1
   ret
end    

code dummyCodeFor
   mov r1,##200
   FOR:
      nop
   NEXT: r1
   ret
end   

: dummyLoop
   200 for
   next
;

: dummydummy ;

: prtCalc ( -- )
   2000 for
      dummydummy
      I 250 + 300 - 
      i sqrt drop \ .

      dummyLoop
      dummyCode
      dummyCodeFor
   next
;


: profPrtCalc \ profile the word prtCalc
   startOccure 64 KB ERASE \ here is at ~ 48k, plenty of space
   startIsr
   prtCalc
   stopIsr
   prtOccur
;

5001 traceL cog! \ cycles between interrupts
profPrtCalc
TAQOZ# profPrtCalc ---

02020    5,648  96.34% ?????
0C2C6    1,358  23.16% dummyCode
0C2D4    1,495  25.50% dummyCodeFor
0C2E6    2,841  48.46% dummyLoop
0C2EE      168   2.86% dummydummy
0C2F0    5,862 100.00% prtCalc
0C312    5,862 100.00% profPrtCalc ok