Very strange behaviour on RP2040 (RPICO)

beyonlo commented 2 years ago

Hi all.

I found a strange behaviour on the RPICO. I did a simple test creating a PWM, and I did a loop just changing the duty cycle (pwm.duty_u16()) and calculate how much microseconds the PICO execute the line pwm.duty_u16(32000).

    start = time.ticks_us()
    pwm.duty_u16(32000)
    end = time.ticks_us()
    x[c] = time.ticks_diff(end, start)

The intention is to measure the speed and the accuracy.

MicroPython version: 1.18

There are two strange behaviours:

1. In the every print on the tests below, you can check that the first 2 - 3 numbers on the printed array are always with number bigger than others of array. Why that?

array('i', [14, 8, 7, 6, 7, 5, 6, 6, 5, 5, 6, 6, 7, 6, 6, 6, 6, 6, 6, 7, 6, 6, 5, 6, 5, 6, 6, 6, 6, 6])
array('i', [13, 11, 10, 9, 9, 10, 10, 7, 8, 9, 9, 10, 8, 9, 8, 9, 8, 10, 9, 9, 8, 10, 9, 8, 8, 9, 8, 10, 8, 9])

Look at the first two position of array at line 1 (numbers 14 and 8). That two numbers are very different than others. All others are with time very close (stable).
The same for the second line.

2. Look that my first test (import pwm) just after I transferred the pwm.py to the RPICO flash, the all numbers of array are lower than next tests - without copy again the pwm.py file. I repeated the tests just doing a soft reset (CTRL+D) and results are still all bigger. And look that (below in the Tests executed) even I get out from picocom and connect again, the result still happen with all numbers bigger. And, finally, if I power off and power on (usb cable disconnect and connect) the RPICO, and execute again the tests, numbers are still bigger. But, always when I transfer the pwm.py file to RPICO, and execute a new test, values back to be lower numbers (like as the first line below). Why that?

array('i', [14, 8, 7, 6, 7, 5, 6, 6, 5, 5, 6, 6, 7, 6, 6, 6, 6, 6, 6, 7, 6, 6, 5, 6, 5, 6, 6, 6, 6, 6])
array('i', [13, 11, 10, 9, 9, 10, 10, 7, 8, 9, 9, 10, 8, 9, 8, 9, 8, 10, 9, 9, 8, 10, 9, 8, 8, 9, 8, 10, 8, 9])

Look that first line numbers are lower than second line. First line is when the test was execute just after I trasnferred the pwm.py file to the RPICO flash. Second line is a test when IS NOT the first test after pwm.py is transferred.

The code:

from machine import Pin, PWM, Timer, freq
import time
import array
import micropython
import gc

freq(270_000_000)

global start, end, c

p22 = Pin(22, Pin.IN, Pin.PULL_UP) # External interruption

p21 = Pin(21, Pin.OUT) # Pin that will generate the external interruption on pin 22
p21.off()

#PWM
pwm = PWM(Pin(25))
pwm.freq(60)
pwm.duty_u16(65535)

cycles = 30 # 30 count for test

#create array for tests
x = array.array('i', (0 for _ in range(cycles)))

@micropython.native
def change_pwm_duty_cycle():
    global pwm, c
    start = time.ticks_us()
    pwm.duty_u16(32000)
    end = time.ticks_us()
    x[c] = time.ticks_diff(end, start)

change_pwm_duty_cycle_ref = change_pwm_duty_cycle

p22.irq(lambda p:change_pwm_duty_cycle(), Pin.IRQ_RISING)
gc.collect()

c = 0
while c < cycles:
    p21.on()
    time.sleep_ms(3)
    gc.collect()
    p21.off()
    c += 1

print(x)

Tests executed:

Ps: the tests was executed exactly as pasted below:

Here the RPICO is connect do USB (to power on and access via USB):

pi@pi:~$ sudo ampy -p /dev/ttyACM0 put pwm.py 
pi@pi:~$ 
pi@pi:~$ sudo picocom /dev/ttyACM0 -b115200
picocom v3.1

port is        : /dev/ttyACM0
flowcontrol    : none
baudrate is    : 115200
parity is      : none
databits are   : 8
stopbits are   : 1
escape is      : C-a
local echo is  : no
noinit is      : no
noreset is     : no
hangup is      : no
nolock is      : no
send_cmd is    : sz -vv
receive_cmd is : rz -vv -E
imap is        : 
omap is        : 
emap is        : crcrlf,delbs,
logfile is     : none
initstring     : none
exit_after is  : not set
exit is        : no

Type [C-a] [C-h] to see available commands
Terminal ready

>>> 
>>> import os
>>> os.uname()
(sysname='rp2', nodename='rp2', release='1.18.0', version='v1.18 on 2022-01-17 (GNU 11.2.0 MinSizeRel)', machine='Raspberry Pi Pico with RP2040')
>>> 
>>> import pwm
array('i', [14, 8, 7, 6, 7, 5, 6, 6, 5, 5, 6, 6, 7, 6, 6, 6, 6, 6, 6, 7, 6, 6, 5, 6, 5, 6, 6, 6, 6, 6])
>>> 
>>> 
>>> 
MPY: soft reboot
MicroPython v1.18 on 2022-01-17; Raspberry Pi Pico with RP2040
Type "help()" for more information.
>>> import pwm
array('i', [13, 11, 10, 9, 9, 10, 10, 7, 8, 9, 9, 10, 8, 9, 8, 9, 8, 10, 9, 9, 8, 10, 9, 8, 8, 9, 8, 10, 8, 9])
>>> 
Terminating...
Thanks for using picocom
pi@pi:~$
pi@pi:~$
pi@pi:~$ sudo ampy -p /dev/ttyACM0 put pwm.py 
pi@pi:~$ 
pi@pi:~$ sudo picocom /dev/ttyACM0 -b115200
picocom v3.1

port is        : /dev/ttyACM0
flowcontrol    : none
baudrate is    : 115200
parity is      : none
databits are   : 8
stopbits are   : 1
escape is      : C-a
local echo is  : no
noinit is      : no
noreset is     : no
hangup is      : no
nolock is      : no
send_cmd is    : sz -vv
receive_cmd is : rz -vv -E
imap is        : 
omap is        : 
emap is        : crcrlf,delbs,
logfile is     : none
initstring     : none
exit_after is  : not set
exit is        : no

Type [C-a] [C-h] to see available commands
Terminal ready

>>> 
>>> import os
>>> os.uname()
(sysname='rp2', nodename='rp2', release='1.18.0', version='v1.18 on 2022-01-17 (GNU 11.2.0 MinSizeRel)', machine='Raspberry Pi Pico with RP2040')
>>> import pwm
array('i', [13, 8, 7, 6, 6, 6, 6, 6, 7, 5, 6, 6, 7, 6, 5, 6, 6, 6, 7, 6, 6, 5, 6, 6, 6, 7, 6, 7, 5, 6])
>>> 
MPY: soft reboot
MicroPython v1.18 on 2022-01-17; Raspberry Pi Pico with RP2040
Type "help()" for more information.
>>> import pwm
array('i', [11, 12, 9, 9, 9, 8, 9, 10, 9, 9, 9, 9, 8, 9, 9, 8, 8, 8, 9, 8, 8, 9, 9, 9, 9, 10, 8, 10, 9, 9])
>>> 
>>> 
MPY: soft reboot
MicroPython v1.18 on 2022-01-17; Raspberry Pi Pico with RP2040
Type "help()" for more information.
>>> import pwm
array('i', [12, 10, 8, 9, 8, 9, 8, 8, 8, 9, 10, 8, 8, 10, 8, 8, 8, 8, 8, 8, 9, 9, 8, 10, 10, 9, 9, 8, 9, 9])
>>> 
>>> 
Terminating...
Thanks for using picocom
pi@pi:~$
pi@pi:~$ 
pi@pi:~$ sudo picocom /dev/ttyACM0 -b115200
picocom v3.1

port is        : /dev/ttyACM0
flowcontrol    : none
baudrate is    : 115200
parity is      : none
databits are   : 8
stopbits are   : 1
escape is      : C-a
local echo is  : no
noinit is      : no
noreset is     : no
hangup is      : no
nolock is      : no
send_cmd is    : sz -vv
receive_cmd is : rz -vv -E
imap is        : 
omap is        : 
emap is        : crcrlf,delbs,
logfile is     : none
initstring     : none
exit_after is  : not set
exit is        : no

Type [C-a] [C-h] to see available commands
Terminal ready

>>> 
>>> import pwm
array('i', [13, 10, 10, 10, 8, 10, 9, 10, 8, 8, 9, 10, 9, 9, 9, 7, 10, 9, 10, 8, 8, 8, 9, 8, 8, 9, 8, 9, 10, 9])
>>> 
MPY: soft reboot
MicroPython v1.18 on 2022-01-17; Raspberry Pi Pico with RP2040
Type "help()" for more information.
>>> 
>>> import pwm
array('i', [12, 11, 10, 8, 9, 9, 8, 9, 8, 10, 8, 8, 9, 8, 9, 8, 8, 8, 9, 8, 9, 8, 9, 8, 8, 9, 8, 8, 9, 9])
>>> 
>>> 
>>> 
Terminating...
Thanks for using picocom
pi@pi:~$
pi@pi:~$
pi@pi:~$ sudo picocom /dev/ttyACM0 -b115200
picocom v3.1

port is        : /dev/ttyACM0
flowcontrol    : none
baudrate is    : 115200
parity is      : none
databits are   : 8
stopbits are   : 1
escape is      : C-a
local echo is  : no
noinit is      : no
noreset is     : no
hangup is      : no
nolock is      : no
send_cmd is    : sz -vv
receive_cmd is : rz -vv -E
imap is        : 
omap is        : 
emap is        : crcrlf,delbs,
logfile is     : none
initstring     : none
exit_after is  : not set
exit is        : no

Type [C-a] [C-h] to see available commands
Terminal ready

>>> import pwm
array('i', [13, 10, 9, 9, 9, 9, 9, 9, 8, 10, 9, 9, 9, 9, 10, 9, 8, 8, 8, 10, 8, 9, 8, 8, 10, 9, 9, 8, 9, 9])
>>> 
Terminating...
Thanks for using picocom
pi@pi:~$
pi@pi:~$
pi@pi:~$ sudo ampy -p /dev/ttyACM0 put pwm.py 
pi@pi:~$ 
pi@pi:~$ sudo picocom /dev/ttyACM0 -b115200
picocom v3.1

port is        : /dev/ttyACM0
flowcontrol    : none
baudrate is    : 115200
parity is      : none
databits are   : 8
stopbits are   : 1
escape is      : C-a
local echo is  : no
noinit is      : no
noreset is     : no
hangup is      : no
nolock is      : no
send_cmd is    : sz -vv
receive_cmd is : rz -vv -E
imap is        : 
omap is        : 
emap is        : crcrlf,delbs,
logfile is     : none
initstring     : none
exit_after is  : not set
exit is        : no

Type [C-a] [C-h] to see available commands
Terminal ready

>>> 
>>> import pwm
array('i', [12, 7, 6, 6, 6, 6, 6, 5, 6, 7, 5, 7, 6, 6, 6, 6, 6, 6, 6, 5, 6, 6, 7, 7, 6, 6, 7, 6, 5, 7])
>>>

Any idea what are happening?

Thank you.

dpgeorge commented 2 years ago

The fact that the first 2 runs are slower than the rest, is most likely due to caching effects: code is stored in external SPI flash and must be transferred into the RP2040 before it can be executed. This takes time. After it's transferred in it will sit in an internal cache so it's faster next time around.

beyonlo commented 2 years ago

The fact that the first 2 runs are slower than the rest, is most likely due to caching effects: code is stored in external SPI flash and must be transferred into the RP2040 before it can be executed. This takes time. After it's transferred in it will sit in an internal cache so it's faster next time around.

@dpgeorge all right, understood! That explain about the strange behavior 1. And about the strange behavior 2?

Thank you!

dpgeorge commented 2 years ago

And about the strange behavior 2?

I don't know, that is strange.

First thing I would try is to not change machine.freq() and just leave it as a default, and run the test again.

beyonlo commented 2 years ago

@dpgeorge Hello

I don't know, that is strange.

First thing I would try is to not change machine.freq() and just leave it as a default, and run the test again.

I commented the line machine.freq() and run again:

#freq(270_000_000)

But the results was the same, with other values of course, because clock is lower now.

Here the simple test:

pi@pi:~/rp2-pico/tests$ sudo ampy -p /dev/ttyACM0 put pwm.py 
pi@pi:~/rp2-pico/tests$ 
>>> import pwm
array('i', [25, 14, 14, 14, 13, 10, 12, 14, 12, 12, 11, 13, 14, 11, 12, 13, 11, 12, 14, 14, 14, 14, 13, 14, 13, 14, 13, 12, 15, 15])
>>> 
MPY: soft reboot
MicroPython v1.18 on 2022-01-17; Raspberry Pi Pico with RP2040
Type "help()" for more information.
>>> 
>>> import pwm
array('i', [27, 26, 19, 23, 19, 20, 18, 17, 18, 20, 20, 19, 16, 17, 20, 16, 19, 18, 19, 19, 19, 19, 19, 19, 16, 21, 19, 18, 19, 20])
>>>

I need to know the estimated time as near as possible to do a better (near of real) offset in my application. Could you please give some more ideas to me to do tests to find the problem?

Ps: I remembered now that this same behaviour has happened in other tests that I did with different code with adc, etc, where the time was better in the first test after the python code is copied to the flash.

Thank you in advance!

micropython / micropython

Very strange behaviour on RP2040 (RPICO) #8424