Different timings when running the same script using the REPL vs. compiled binary

[jamesadevine]

Hi @dpgeorge and co.

from microbit import *

while True:
    pin1.write_digital(0)

    for i in range(0,100000):
        i = i

    pin1.write_digital(1)

    for i in range(0,100000):
        i = i

I've been running the above code as a test to observe the overhead of running a virtual machine on cortex m0's. The script above generates a square wave, and using an oscilloscope we can measure the positive wave to determine the time taken. Interestingly, the results differ when transferring a hex from microbit.org than through the REPL:

	hex/uf2 (s)	REPL (s)
micropython	10.32	29.1
CircuitPython	5.701	7.361

The version of micropython I am running on the microbit is version1, sha c5e84ec37294f125f18354e669effce097871e91.

I've observed the same result for both CircuitPython (v2.2.4) on the CircuitPlayground, however i'm less sure how micropython works on CircuitPython. The CircuitPython script is below:

import board
import digitalio

a1 = digitalio.DigitalInOut(board.A1)
a1.direction = digitalio.Direction.OUTPUT

while True:
    a1.value = 1
    for i in range(0,100000):
        i=i
    a1.value = 0
    for i in range(0,100000):
        i=i

CC @mmoskal @carlosperate @microbit-carlos @ladyada @tannewt

[ZanderBrown]

Ping @ntoll while we're at it

[carlosperate]

I've tested this code as well with MicroPython ee6ddc8 (and older v1.0-beta) inside a function:

from microbit import *
import time

def timed_function(f, *args, **kwargs):
    def new_func(*args, **kwargs):
        t = time.ticks_us()
        result = f(*args, **kwargs)
        delta = time.ticks_diff(time.ticks_us(), t)
        print('Function Time = {:6.3f}ms'.format(delta/1000))
        return result
    return new_func

@timed_function
def test_me():
    pin1.write_digital(0)
    for i in range(0,100000):
        i = i
    pin1.write_digital(1)
    for i in range(0,100000):
        i = i

test_me()

A single call to the function on the script or within the REPL takes about 10s as well (verified with a scope):

>>> test_me()
Function Time = 10078.202ms

However, if I test the same code in the REPL in a while loop:

>>> while True:
...    pin1.write_digital(0)
...    for i in range(0,100000):
...        i = i
...    pin1.write_digital(1)
...    for i in range(0,100000):
...        i = i
...

I see the slightly worst results, around 40 seconds per period (between 38 and 40 seconds, hard to tell on my USB DSO).

Interestingly, if the code runs inside a function called within a while loop, it goes back to around 10 seconds (this is still true if a new function is created within the REPL and used that one instead of test_me):

>>> while True:
...    test_me()
...
Function Time = 10078.210ms
Function Time = 10078.265ms
Function Time = 10078.207ms
Function Time = 10078.265ms
Function Time = 10078.217ms
Function Time = 10078.269ms

[dpgeorge]

REPL execution is different to script execution because the former attempts to print the result. If the result is None then it won't print anything but it takes time to work this out, so that's why the same code takes longer at the REPL.

Try this at the REPL:

>>> for i in range(5):
...    i
...
0
1
2
3
4

Things to generally keep in mind if you're benchmarking:

• all statements executed at the REPL (even if within a for/if/etc) are always printed (if not None) and stored into the special variable _
• code excuted in the global context (of a module or at the REPL) stores to global variables, which take longer than accessing local variables
• code executed in a function uses local variables which are fast

It's always good practice to run benchmarking code from within a function because it doesn't print out statements and uses fast local variables.

[carlosperate]

That makes perfect sense, thank you @dpgeorge!

[jamesadevine]

@dpgeorge Cool, thanks for the info!