View source for Pymate-cycle-timing

{{PYMATE-HEADER}}

== PLC Cycle time ==
In Programmable Logic Controller (aka automation world), the PLC cycle time is the total duration taken by the PLC software to:
# scan the inputs
# execute user logic
# update the output.

Typical execution time goes from 1 to 20ms. Very high-speed may requires sub-millisecond execution time. 

The continuous mainloop execution '''cycle time''' determines response speed of your project.

Keeping low '''cycle time''' is crucial to ensure quick response to event which in turn ensure the Stability and Safety.

== Good Practices ==

One simple and unique rule is enough

{{dbox-red|<br />'''NEVER USE BLOCKING INSTRUCTION''' in the mainloop<br /></br />}}

This means no {{fname|time.sleep()}} instruction within the mainloop.

Also avoids blocking functionalities like libraries waiting response forever or for a period of time long enough. As an example, WiFi/Ethernet access is typically the kind of media that can block execution for seconds or minutes.

{{underline|Remarks:}}

Using {{fname|asyncio}} programming is a great way to avoids unresponsive/blocking situation.

This cooperative multitasking alike programming approach. Asyncio runs in a single thread, and tasks must voluntarily yield control to the event loop.

== Measuring Cycle timing ==

The PymateIO {{fname|tool}} library contains the {{fname|'''TimeIt'''}} class.

The {{fname|TimeIt}} class will automatically measure the execution statistics of a function (or the mainloop).

The timing statistic can be send to REPL with {{fname|print()}} method --OR-- or automatically printed-out thanks to the {{fname|trigger}} property.

{{underline|Note:}} keep in mind that cycle timing measurement represent some execution overhead.

=== Measurement in Milliseconds ===

In the following example, the measurement is done on the mainloop. So only the {{fname|begin()}} call il required!

The calculation of timing will be done between the consecutive call of {{fname|begin()}}.

<syntaxhighlight lang="python" line>
from pymate.pymateio import PymateIO
from pymate.board import Board
from pymate.tool import TimeIt
from machine import Pin
import time

brd = Board() # Access to LEDs
t = TimeIt('MainLoop')

# Trigger automatic REPL output
#   every 100 iterations => about 2sec when Cycle Time is 20ms
#   every 1000 iteration => about 1sec when Cycle Time is ~1ms
t.trigger = 1000

i1 = PymateIO( "In1", Pin.IN )
i2 = PymateIO( "In2", Pin.IN )
i3 = PymateIO( "In3", Pin.IN )
i4 = PymateIO( "In4", Pin.IN )
i5 = PymateIO( "In5", Pin.IN )
i6 = PymateIO( "In6", Pin.IN )
i7 = PymateIO( "In7", Pin.IN )
i8 = PymateIO( "In8", Pin.IN )

o1 = PymateIO( "Out1", Pin.OUT )
o2 = PymateIO( "Out2", Pin.OUT )
o3 = PymateIO( "Out3", Pin.OUT )
o4 = PymateIO( "Out4", Pin.OUT )
o5 = PymateIO( "Out5", Pin.OUT )
o6 = PymateIO( "Out6", Pin.OUT )
o7 = PymateIO( "Out7", Pin.OUT )
o8 = PymateIO( "Out8", Pin.OUT )

while True:
    t.begin()
    brd.led1.on()
    o1.write( not(i1.read()) )
    o2.write( not(i2.read()) )
    o3.write( not(i3.read()) )
    o4.write( not(i4.read()) )
    o5.write( not(i5.read()) )
    o6.write( not(i6.read()) )
    o7.write( not(i7.read()) )
    o8.write( not(i8.read()) )
    brd.led1.off()
</syntaxhighlight>

which produce the following result where mainloop '''cycle timing is below 1 millisecond'''!

 <nowiki>[ MainLoop ] Iterations: 0 Total: 0.0 Last: None Min: 0.0 Max: 0.0 Mean: None
[ MainLoop ] Iterations: 1000 Total: 604.0 Last: 0 Min: 0 Max: 1 Mean: 0.604
[ MainLoop ] Iterations: 2000 Total: 1202.0 Last: 1 Min: 0 Max: 1 Mean: 0.601
[ MainLoop ] Iterations: 3000 Total: 1785.0 Last: 0 Min: 0 Max: 1 Mean: 0.595
[ MainLoop ] Iterations: 4000 Total: 2384.0 Last: 1 Min: 0 Max: 1 Mean: 0.596
[ MainLoop ] Iterations: 5000 Total: 2979.0 Last: 0 Min: 0 Max: 1 Mean: 0.5958
[ MainLoop ] Iterations: 6000 Total: 3582.0 Last: 1 Min: 0 Max: 1 Mean: 0.597
[ MainLoop ] Iterations: 7000 Total: 4208.0 Last: 1 Min: 0 Max: 1 Mean: 0.6011429
[ MainLoop ] Iterations: 8000 Total: 4818.0 Last: 1 Min: 0 Max: 1 Mean: 0.60225</nowiki>

=== Measurement in Microseconds ===

The measurement can also be performed in microsecond (the default being "millisecond" measurement).

To do so, append the {{fname|1=measure=time.ticks_us}} parameter when creating the {{fname|'''TimeIt'''}} object.

<syntaxhighlight lang="python" line>
from pymate.pymateio import PymateIO
from pymate.board import Board
from pymate.tool import TimeIt
from machine import Pin
import time

brd = Board() # Access to LEDs
# Append  to get measurement in MicroSeconds
t = TimeIt('MainLoop', measure=time.ticks_us)  
t.trigger = 1000
...
</syntaxhighlight>

This time, the script will produce the following result with values are '''microseconds'''.

 <nowiki>[ MainLoop ] Iterations: 0 Total: 0.0 Last: None Min: 0.0 Max: 0.0 Mean: None
[ MainLoop ] Iterations: 1000 Total: 597458.0 Last: 597 Min: 596 Max: 1366 Mean: 597.458
[ MainLoop ] Iterations: 2000 Total: 1194124.0 Last: 596 Min: 596 Max: 1366 Mean: 597.062
[ MainLoop ] Iterations: 3000 Total: 1790836.0 Last: 597 Min: 596 Max: 1366 Mean: 596.9453
[ MainLoop ] Iterations: 4000 Total: 2387490.0 Last: 597 Min: 596 Max: 1366 Mean: 596.8725
</nowiki>

== Measuring a function ==

Lets say that we have a function name {{fname|calculate()}} that we want to monitor.

The following scripts, monitor the {{fname|calculate()}}, print the current statistic then pause the execution for 250ms. 

As demonstration purpose, the statistics are cleared/restarted every 10 monitoring cycle.

<syntaxhighlight lang="python" line>
from pymate.board import Board
from pymate.tool import TimeIt
from machine import Pin
from math import sqrt
from random import randint
import time

brd = Board() # Access to LEDs
t_calc = TimeIt('Calculate')  

def calculate():
    # Perform heavy calculation
    _r = 0
    for i in range( randint(100,500) ):
        for j in range( randint(100,250) ):
            _r += sqrt( i/(j+1) )
    return _r

brd.led1.off()
while True:
    brd.led1.write( not(brd.led1.read()) )
    # Monitor the calculate()
    t_calc.begin()
    print( 'calculate=', calculate() )
    t_calc.end()
    # Print the statistics
    t_calc.print()
    if t_calc.iteration==10:
        print( 'Clear Stat' )
        t_calc.clear()
    time.sleep_ms( 250 )
</syntaxhighlight>

This script produce the following output in the REPL.

 <nowiki>calculate= 132025.7
[ Calculate ] Iterations: 1 Total: 1721.0 Last: 1721 Min: 1721 Max: 1721 Mean: 1721.0
calculate= 130767.1
[ Calculate ] Iterations: 2 Total: 3468.0 Last: 1747 Min: 1721 Max: 1747 Mean: 1734.0
calculate= 51670.27
[ Calculate ] Iterations: 3 Total: 4403.0 Last: 935 Min: 935 Max: 1747 Mean: 1467.667
calculate= 99956.81
[ Calculate ] Iterations: 4 Total: 5855.0 Last: 1452 Min: 935 Max: 1747 Mean: 1463.75
calculate= 165046.6
[ Calculate ] Iterations: 5 Total: 7887.0 Last: 2032 Min: 935 Max: 2032 Mean: 1577.4
calculate= 89604.13
[ Calculate ] Iterations: 6 Total: 9228.0 Last: 1341 Min: 935 Max: 2032 Mean: 1538.0
calculate= 36086.37
[ Calculate ] Iterations: 7 Total: 9954.0 Last: 726 Min: 726 Max: 2032 Mean: 1422.0
calculate= 91359.18
[ Calculate ] Iterations: 8 Total: 11321.0 Last: 1367 Min: 726 Max: 2032 Mean: 1415.125
calculate= 93796.05
[ Calculate ] Iterations: 9 Total: 12713.0 Last: 1392 Min: 726 Max: 2032 Mean: 1412.556
calculate= 40873.95
[ Calculate ] Iterations: 10 Total: 13510.0 Last: 797 Min: 726 Max: 2032 Mean: 1351.0
Clear Stat
calculate= 97873.63
[ Calculate ] Iterations: 1 Total: 1417.0 Last: 1417 Min: 1417 Max: 1417 Mean: 1417.0
calculate= 18697.21
[ Calculate ] Iterations: 2 Total: 1883.0 Last: 466 Min: 466 Max: 1417 Mean: 941.5
calculate= 61655.25
[ Calculate ] Iterations: 3 Total: 2934.0 Last: 1051 Min: 466 Max: 1417 Mean: 978.0
calculate= 132888.2
[ Calculate ] Iterations: 4 Total: 4670.0 Last: 1736 Min: 466 Max: 1736 Mean: 1167.5
...</nowiki>

== Enforcing with WatchDog ==

{{ttuto-begin}}

{{ttuto
  |label=Watchdog
  |descr=Re-inforce Cycle Time with WatchDog
  |img=tlogo-watchdog.png
  |link=PymateIO-watchdog
}}

{{ttuto-end}}

{{PYMATE-TRAILER}}