Propeller Code Execution Time

coryco2

This may be a complete novice question, but is there an easy way to figure out exactly how much time Spin/PASM code takes to execute? I realize that it will depend on the clock, but do each of the commands take a specific number of clock cycles to execute, for example? And is this consistent, or in a multi-cog program, does the hub action cause the timing to vary somewhat?

Thric

i asked this question once too and I found this information really helpful: http://www.parallax.com/portals/0/propellerqna/
of more specifically the Code Execution Time section: http://www.parallax.com/portals/0/propellerqna/

JonnyMac

The great thing about the Propeller is that it can time itself as the links above illustrate -- I use this feature all the time, particularly when refining code. A recent "real world" example: I wrote a piece of industrial control code that has to process (low bandwidth) messages from CAN and MODBUS inputs. The customer wanted the main code loop to run every second. I found, though, that the loop really only took about 280ms so I bumped most of it to 3x per second (every 333.33ms), with a very small update to call the sensors every second as desired. The result was that the device is much more responsive to CAN and MODBUS inputs.

Do read the material referenced above, though here's a quick bit of code to show you how it works.

pub main | elapsed

  term.start(RX1, TX1, %0000, 115_200)
  pause(1)

  term.str(string(CLS, "Timing Test", CR, CR))
  

  elapsed := -cnt                                               ' start the timer

  ' code to test here
  
  elapsed += cnt - 544                                          ' stop timer (remove instruction offset)

  term.dec(elapsed)
  

  repeat
    waitcnt(0)

Publison

Another source of the document can be found in the Applications Notes as a PDF:
http://www.parallaxsemiconductor.com/an009

All current Application Notes can be found at:
http://www.parallaxsemiconductor.com/appnotes

coryco2

Great! Thanks.

coryco2

Does the code JonnyMac and the Application Notes describe work with Spin code containing method calls, or just for code within a single method? It seems logical that if I place the "start timer" code just before the method call and the "stop timer" code right after, that the time measured should be how long it takes to jump to that method, execute it, and return. But what actually happens if I instead place the start/stop code directly in the method that I'm calling is that I get a much longer time reading. Why would this be?


That is, why doesn't this:

PUB MainMethod

    Time := -cnt         'Read System Counter for code timing measurement (Start)

    MethodCall

    Time += cnt -544     'Read System Counter for code timing measurement (End)


PUB MethodCall

    MethodCallCode

...just give me a slightly longer time value than this:

PUB MainMethod

    MethodCall


PUB MethodCall

    Time := -cnt         'Read System Counter for code timing measurement (Start)

    MethodCallCode

    Time += cnt -544     'Read System Counter for code timing measurement (End)

kuroneko

coryco2 wrote: »

But what actually happens if I instead place the start/stop code directly in the method that I'm calling is that I get a much longer time reading. Why would this be?

You tell us. I just tried and it works as advertised, measuring at top level I get $005B97E0 cycles, one level lower (without call overhead) it's $005B9590. MethodCallCode is a private method waiting for half a second. Can you cut down your code to a sample case and post it here?

coryco2

Oops. Forgot I had an IF statement at the beginning of the method I was calling that was returning before completing all the called method's code (duh...).

(The timing code actually works fine.)