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.
 

lbenson

Senior Member
Looking at this very useful program with a goal of figuring out how to use a picaxe to implement "soft start" of an AC mains well pump using this (or similar with heftier triac): https://www.amazon.com/Genuine-Programmable-Light-Dimmer-110V/dp/B0893K6ZPK

I'm looking at timing at SETFREQ m32 of the following: readadc, pauseus 1, pause 1 (and various other PAUSE and PAUSEUS times)

I added a mode 4 for 32mHz. These are the timings I got. Do they seem rational?
Code:
Mode= 4 | Time= 0
Seed= 0 | Nul= +886 us 
Test1 32mHz READADC=  +163 us 
Test1 32mHz PAUSE 1=  +323 us 
Test1 32mHz PAUSE 10=  +2570 us 
Test1 32mHz PAUSEUS 1=  +112 us 
Test1 32mHz PAUSEUS 10=  +135 us 
Test1 32mHz PAUSEUS 100=  +369 us 
Test1 32mHz PAUSEUS 500=  +1403 us 
Check= -2 us
I ran it again with mode 2 (16mHz) and got the exact same numbers, so I did something wrong in trying to measure at SETFREQ M32:
Code:
Mode= 2 | Time= 11
Seed= 64 | Nul= +892 us 
Test1 16mHz READADC=  +159 us 
Test1 16mHz PAUSE 1=  +312 us 
Test1 16mHz PAUSE 10=  +2565 us 
Test1 16mHz PAUSEUS 1=  +121 us 
Test1 16mHz PAUSEUS 10=  +138 us 
Test1 16mHz PAUSEUS 100=  +375 us 
Test1 16mHz PAUSEUS 500=  +1403 us 
Check= +0 us
Here's the code I used:
Code:
' M2Speed.bas
; 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 = 4         ; MODE 2 = Measure times with Setfreq M16 (up to 64,000 us)
                        ; MODE 3 = Calculate 4MHz execution times up to 255.99ms
                        ; MODE 4 = Measure times with Setfreq M16 (up to 64,000 us)
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 speed    = b21   ; 4 or 16 or 32mHz
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:
if tempb = 2 then: speed = 16: elseif tempb = 4 then: speed=32: else: speed=4: endif
  sertxd(cr,lf,"Test1 ",#speed,"mHz READADC= ")    ; Report the first test
  gosub start
  readadc C.4,b1
  gosub measure
  
  sertxd(cr,lf,"Test1 ",#speed,"mHz PAUSE 1= ")    ; Report the test
  gosub start
  pause 1
  gosub measure
  
  sertxd(cr,lf,"Test1 ",#speed,"mHz PAUSE 10= ")    ; Report the test
  gosub start
  pause 10
  gosub measure
  
  sertxd(cr,lf,"Test1 ",#speed,"mHz PAUSEUS 1= ")    ; Report the test
  gosub start
  pauseus 1
  gosub measure
  
  sertxd(cr,lf,"Test1 ",#speed,"mHz PAUSEUS 10= ")    ; Report the test
  gosub start
  pauseus 10
  gosub measure
  
  sertxd(cr,lf,"Test1 ",#speed,"mHz PAUSEUS 100= ")    ; Report the test
  gosub start
  pauseus 100
  gosub measure
  
  sertxd(cr,lf,"Test1 ",#speed,"mHz PAUSEUS 500= ")    ; Report the test
  gosub start
  pauseus 500
  gosub measure
  return  
  
  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
  if tempb = 4 then
    setfreq m32                      ; For modes 2 and 3
    pause 200                        ;* 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 or tempb = 4 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
Also at 4mHz:
Code:
Mode= 1 | Time= 0
Seed= 0 | Nul= +3570 us 
Test1 4mHz READADC=  +634 us 
Test1 4mHz PAUSE 1=  +1248 us 
Test1 4mHz PAUSE 10=  +10272 us 
Test1 4mHz PAUSEUS 1=  +451 us 
Test1 4mHz PAUSEUS 10=  +551 us 
Test1 4mHz PAUSEUS 100=  +1498 us 
Test1 4mHz PAUSEUS 500=  +5609 us 
Check= +16 us
(By the way, the timings show that I can probably achieve what I want at SETFREQ 16.)
 
Last edited:

AllyCat

Senior Member
Hi,
I added a mode 4 for 32mHz. These are the timings I got. Do they seem rational?
Sorry, I don't actually know. ;)

The problem is that although T1 "always" counts through 20,000 cycles (I believe), the frequency (or period) is varied by the PICaxe Operating System, and not in an entirely "logical" (or at least expected) manner (the description of the Time variable gives some clues). Timer 1 is basically used by the Servo Command and that says:

"On X2 parts servo will only function at 8MHz or 32MHz. On M2 and X1 parts servo will only function at 4MHz or 16MHz. On all other parts servo will only function at 4MHz."

So those are the only frequencies that I'm prepared to support for my program :)

Personally, I prefer to "normalise" all my timing measurements to a 4 MHz SETFREQ, but the 16 MHz Modes were a useful "trick" to increase the maximum number of PIC Instruction Cycles to 250,000. And a measurement in ms, somehow seems more "meaningful" than one in microseconds. So for example, if I was designing for an "event" to last 1ms, but was going to use the PICaxe at 32 MHz, then I would still use the existing Mode 1 (or maybe Mode 3), but consider the event to be lasting 8,000 PIC Instruction Cycles, or 8,000 us, or 8.00 ms.

Cheers, Alan.

PS: READADC is rather a complication because it has its own "clock". But it appears that the PICaxe Operating System does NOT change it in unison with SETFREQ. The Microchip Data Sheet seemed to imply that the timings used by PICaxe are rather "marginal" with a SETFREQ of M32 (or M64).
 

lbenson

Senior Member
Thanks. My problem is that I'm trying to vary the delay in turning on a triac within the 8.33ms window I have per zero-crossing of an AC sine wave at 60Hz (so as to test providing a "soft start" to a pump motor when running off of a generator). It looks like 16mHz will provide a good many increment periods--PAUSEUS 1 is 112us. I tried PAUSE 4 and got 1075us, so a little over a millisecond, so that looks good--4 milliseconds nominal divided by 4 for the 16mHz clock speed, plus a bit for decoding of the statement.

From PAUSE 1, every increment (PAUSE 2, PAUSE 3, etc.) adds very close to 250us, so I pretty conveniently have 32 steps to full on (actually starting with PAUSE 32 and decrementing (after experimentally making sure I'm not overrunning the next zero crossing)). If I want to go to full on over the course of 2 seconds or thereabouts, that's 120 zero crossings times 2, or 240 half cycles, so if I repeat each PAUSE n over 8 cycles, I'll come out about right.
 

AllyCat

Senior Member
Hi,

(From my records) : Rather un-intuitively, the "overhead" on PAUSEUS appeared to be greater than for PAUSE (normalised 700 us versus 300 us), so PAUSEUS 0 took longer than PAUSE 0 ! But this isn't relevant to the delays you require; from 1 onwards they both increment "as specified" (i.e. 2.5 us versus 0.25 ms at 16 MHz). However, there is almost no penalty with PICaxe in using Words, so you could get 2.5 microsecond resolution up to 16.4 ms, with a 16 MHz clock, if required.

You might find that a 0.25 ms step gives a significant load increase near the peak of the sine-wave, but if this is just for a soft-start (i.e. an improvement on simply closing a hard switch) then it should be fine.

Cheers, Alan.
 
Top