Measuring (M2) PICaxe Execution speed using NO additional hardware

AllyCat

Senior Member
Hi,

This is based on a program that I wrote in 2012 which became somewhat "lost" in a thread with a rather unmemorable title (at least for me). I've used the program many times over the years, so have now "tidied it up" and added a few more features. However, I won't repeat much of the detail from the original thread, but just point to post #12 of this thread. The program can estimate the execution time of almost any single instruction, simple algorithm, or through to quite large subroutines, etc. on any M2 PICaxe, by comparing the internal "Timer 1" values, immediately before and after execution of the instruction(s) under test. Thus, no external hardware is required, except for a powered M2 PICaxe connected to the Program Editor / Terminal Emulator.

But first a disclaimer: It's been discussed numerous times that PICaxe program instructions do not have an absolute execution time, because the interpreter "tokens" do not (necessarily) fit neatly within the program memory byte boundaries. This means that the slightest change to the program structure can alter the execution time of the component instructions. These variations occur at the Program Editing stage so the program itself cannot "investigate" the variations which might occur, and ultimately the Programmer/User must identify any inconsistencies. However, the same program, if run multiple times, appears to give exactly the same results, which suggests that the internal System Interrupts become synchronised to the program instructions (or vice versa).

Timer 1 is primarily used by the PICaxe Operating System to time the Servo pulses, so the program may disturb the operation of these (because it increases the timing period to 65 ms). The new program also pauses the Timer between reading its Low and High bytes, which seems to have eliminated some of the occasional inconsistencies with the original program. Normally, Timer 1 appears to "always" count through 20,000 cycles, but its period is 20 ms with a SETFREQ of only m4 or m16.

The new version includes three operating modes: MODE 1 gives a similar output to the original program, indicating the number of PIC Instruction Cycles (which each take 1 microsecond to execute with a 4 MHz clock), up to a maximum time of about 60 ms (i.e. 60,000 Instruction Cycles). MODE 2 increases the clock to 16 MHz, but the maximum measurement period is unchanged, thus up to about 250,000 PIC instructions can be counted. The displayed result is still in us, which needs to be multiplied by 4 to give Instruction Cycles. MODE 3 also uses 16 MHz, but the displayed result is divided by 2.50 (with two decimal places) to give a direct indication of the execution time in ms (up to 255.99 ms at 4 MHz) or Instruction Cycles up to 250,000+. The loss of the lowest digit (units of microseconds or Instruction Cycles) is insignificant due to the interpreter variations.

The program uses only variables b22 - b27 (w11 - w13) but these can be reclaimed by using the system variables s_w2 - s_w6 instead. The sanity check "seed" is probably unnecessary now, but can be useful for evaluating commands such as PAUSE and WRITE. Almost any number of instructions can be inserted into the program (between the calls to "start" and "measure"), or even multiple nested calls to subroutines, etc.. Obviously, unconditional DO .. LOOPs cannot be analysed (unless they enclose a Conditional Exit of some type) but the despised "GOTO main" type of structure can be "unrolled" by jumping instead to the end of the test block. For this reason a "test N:" label is available at the END of each block. Most other instructions can be included and the sample code shows how a GOSUB and RETURN can be analysed individually, but some input / blocking commands may be unsuitable. There are also a few instructions that aren't directly determined by the SETFREQ value, for example READADC{10}, WRITE and READTEMP, etc.. Incidentally, WRITE is the "slowest" single instruction I've encountered so far, at around 10,000 PIC cycles (10ms at 4 MHz).

Code:
; Program to Estimate the Execution speed of most M2 PICaxe Instructions
; AllyCat, 2012, Updated August 2019

#picaxe 08m2       ; Or any other M2 but *CANNOT USE THE SIMULATOR*
#no_data           ; No data to load into EPROM
#terminal 4800     ; 4800 baud at setfreq m4 (*Also X2s require SFR changes*)

; *Select MODE here*    ; MODE 1 = Number of PIC Instruction cycles (= time in us)
symbol MODE = 3         ; MODE 2 = Measure times with Setfreq M16 (up to 64,000 us)
                        ; MODE 3 = Calculate 4MHz execution times up to 255.99ms
symbol TMR1L     = $16  ; Timer 1 Low byte SFR address
symbol TMR1H     = $17  ; Timer 1 High byte SFR address
symbol T1CON     = $18  ; Control Register: Prescaler = %--nn---- (PS = 2^nn)
symbol seed     = b22   ; or s_w3 "Dither" on start time to check timer results
symbol tempb    = b23   ; or s_w4 Temporary byte for MODE3, etc.
symbol exec     = w12   ; or s_w5 16-bit execution cycles or time
symbol nul      = w13   ; or s_w6 Overhead for Call/Return,etc.with no instructions

main:
for seed = 0 to 256 step 32      ; Sanity check for timer handling (STEP optional)
  seed = seed and 255            ; Allows use of S_W variable (optional)
  nul = 0
  sertxd(cr,lf,"Mode= ",#MODE)
  sertxd(" | Time= ",#time,cr,lf)    ; Optional
  sertxd("Seed= ",#seed," | Nul=")
  gosub start                          ; Start the NUL measurement
  gosub measure                        ; Shows and Returns timer value in us or ms
  nul = exec                           ; Store for subsequent calculations
    gosub runtests            ;* Update any of the target code as required *
  sertxd(cr,lf,"Check=")               ; Re-measure the NUL (or another) value
  gosub start
  gosub measure
  if exec > 50 then
    sertxd(" ***")                    ; Mark inaccurate nul result
  endif
  sertxd(cr,lf)
  pause 5000
next seed                             ; Never finishes if STEP = 2^integer
  sertxd(cr,lf,"Finished")
  end
    
runtests:
  sertxd(cr,lf,"Test1 IF.THEN true=")    ; Report the first test
  gosub start                            ;*--------------------------------------*
  if seed = seed then                    ;* INSERT TARGET CODE BETWEEN ...       *
  endif                                  ;*    CALLS TO  "start" and "measure"   *
test1:                                   ;* END of target (exit label if needed) *
  gosub measure                          ;*--------------------------------------*
  sertxd(cr,lf,"Test2 IF.THEN false=")   ; Report the second test, etc.
  gosub start
    if seed <> seed then                 ; Equivalent to "IF (true) GOTO test2"
    endif 
test2:
  gosub measure
  sertxd(cr,lf,"Test3 PEEKSFR=")
  gosub start
    peeksfr T1CON,tempb
test3:
  gosub measure
  sertxd(cr,lf,"Test4 PULSOUT seed=") 
  gosub start
    pulsout c.2,seed                     ; Very similar to PAUSEUS
test4:
  gosub measure
  sertxd(cr,lf,"Test5 GOSUB (only)=")
  gosub start
    gosub callandreturn            ;* This test separates the CALL and RETURN times
test5:
  gosub measure     
  sertxd(cr,lf,"Test6 CALL+RETURN=")   
  gosub start
    call retn                            ; To return immediately
test6:
  gosub measure
  return
    
callandreturn:            ;* This is a TEST TARGET subroutine being measured!
  gosub measure
  sertxd(cr,lf,"  Test5a   RETURN=")
  gosub start
retn:
    RETURN
    
; REQUIRED SUBROUTINES
start:          ; Setup the Mode and Reset Timer 0
  tempb = MODE                       ; At least one variable is needed in IF.THEN
  if tempb > 1 then
    setfreq m16                      ; For modes 2 and 3
    pause 100                        ;* 25 ms to allow 20 ms timer to update *
  endif
  gosub setup                        ; Only needed to initialise target code
  peeksfr T1CON,tempb
  pokesfr T1CON,0                    ; Stop the timer
  pokesfr TMR1H,0                    ; Clear High byte
  pokesfr TMR1L,seed                 ; Sanity check byte    
  pokesfr T1CON,tempb                ; Restore the timer (1 / 33 at 4 / 16 MHz)
  return

measure:       ; Reads Timer 0, calculates and displays timed delay 
  pokesfr T1CON,0                    ; Stop the timer to read both bytes
  peeksfr TMR1L,tempb                ; Read Low byte (S_W variables only words) 
  peeksfr TMR1H,exec                 ; Read High byte
  pokesfr T1CON,1                    ; Restart timer (can ignore frequency)
  exec = exec * 256 + tempb          ; Allows use of S_W variable
  exec = exec - nul - seed           ; Estimate execution time of target code
  setfreq m4                         ; Ensure serial comms are at default again
  if exec > 64000 then               ; Correctly display negative values (near zero)
    sertxd(" -")
    exec = - exec
  else
    sertxd(" +")
  endif
  tempb = MODE
  if tempb < 3 then                  ; Check the MODE
    sertxd (#exec," us ")    
  else                               ; Display in ms to 2 decimal places 
    tempb = exec ** 26214 / 100      ; *4/10 = 26214 / 65536 then /100
    sertxd(#tempb,".")               ; Units of ms
    tempb = exec ** 26214 // 100 / 10
    sertxd(#tempb)                   ; Tenths of ms
    tempb = exec  ** 26214 // 10
    sertxd(#tempb," ms")             ; Hundredths of ms
  endif
  return
    
setup:           ; Initialise values required for the test targets (only)
  return

#rem TERMINAL RESULT:
Mode= 3 | Time= 193
Seed= 96 | Nul= +3.59 ms
Test1 IF.THEN true= +0.73 ms
Test2 IF.THEN false= +1.20 ms
Test3 PEEKSFR= +0.58 ms
Test4 PULSOUT seed= +1.44 ms
Test5 GOSUB (only)= +0.87 ms
Test5a    RETURN= +2.17 ms
Test6 CALL+RETURN= +3.05 ms
Check= -0.01 ms
#endrem

Well, that's just at the forum's 10,000 character limit again. ;)

Cheers, Alan.
 

depeet

New Member
Just a program I needed to measure a routine in my own program. I only had to change to #picaxe 20x2, delete all the tests and insert my own routine to test. Mind you, the line sertxd(" | Time= ",#time,cr,lf) gave an error since TIME doesn't apply to X2.

Now I can test the time difference between IF THEN and DO WHILE LOOP

Anyway, thanks for this snippet
 

AllyCat

Senior Member
Hi,

Are you sure it works with an X2 ? I thought the SFR addresses for Timer 1 were different in all the X2s . Also, for correct calibration, I believe you should change the m4 and m16 to m8 and m32 , which are the only Servo (Timer) frequencies that are "valid" for the X2s. But if you do get good results with an X2, would you please post some examples together with an X2 version of the code?

Personally, I prefer the IF xx THEN {GOTO} .. structure because the timing is completely predictable (and fastest). I think that you will find that DO <code> LOOP WHILE xx may execute significantly faster than DO WHILE xx <code> LOOP (even taking into account that the bounds are different) and probably similarly with the different DO LOOP UNTIL structures.

Cheers, Alan.
 

hippy

Technical Support
Staff member
I think that you will find that DO <code> LOOP WHILE xx may execute significantly faster than DO WHILE xx <code> LOOP
The main gain in the 'LOOP conditional' is that it doesn't have an extra GOTO overhead which a 'DO conditional' will have, and it will perform one less IF test before exiting the loop -
Code:
Do While <exp>        loop:   IF NOT <exp> THEN exit
  something                   something
Loop                          GOTO loop
                      exit:
Code:
Do
  something           loop:   something
Loop While <exp>              IF <exp> THEN loop
                      exit:
In most cases it won't matter which is used, the extra GOTO and IF test will often be only a small amount of all which is being done.

Note that the compiler optimises the conditional expression so it is always a single "IF-THEN exit/loop". This means that WHILE and UNTIL conditional testings will take the same time, whether used with DO or LOOP.
 
Top