modutime.c sleep_ms() occasionally affects ticks_ms()

[peterhinch]

Issuing sleep_ms(t) can cause ticks to be missed. The number of ms lost is min(10, t). The following script demonstrates this with timer callbacks apparently occurring early. Note that they never occur correspondingly late so this is not a manifestation of latency. Examination of the lastrun output around an early callback seems to show this happening. The script runs for 15s which is long enough for at least one instance to occur.

Behaviour with Timer(1) and Timer(-1) is identical. It is specific to the ESP32 port: this does not occur on ESP8266 or Pyboard.

from machine import Timer
from utime import ticks_ms, ticks_diff, sleep_ms
from micropython import schedule

timer = Timer(-1)
lastrun = None
maxtime = 0
mintime = 1000

def timer_cb(timer):
    global lastrun, maxtime, mintime
    if lastrun is not None:
        delta = ticks_diff(ticks_ms(), lastrun)
        maxtime = max(maxtime, delta)
        mintime = min(mintime, delta)
        schedule(print_me, delta)
    lastrun = ticks_ms()

def print_me(delta):
    print("timer_cb", delta, lastrun)

def start(duration, sleeptime):
    timer.init(period=100, mode=Timer.PERIODIC, callback=timer_cb)
    count = 0
    while count <= duration // sleeptime:
        sleep_ms(sleeptime)
        count += 1
    timer.deinit()
    print('{}ms max    {}ms min'.format(maxtime, mintime))

start(15000, 50)  # Run for 15s sleeping for 50ms

[robert-hh]

I can support that observation. I added a small GPIO pulse in the callback and checked the times with an oscilloscope. Results:
a) The times taken with tick_diff match those seen on the GPIO Pin. so using ticks_diff is a suitable method.
b) The timing pulse variation pattern seen depends on the sleep time. For a sleep time of 1ms it disappears, at other sleep times you's see different variations of patterns, with pulse time differences between 90 ms and 110 ms.

[peterhinch]

Interesting. In my code the minimum conformed with your measurements but it never produced maximums greater than ~102ms. I had assumed that the short interval was an artefact caused by an inaccuracy in the ticks_ms() response but your measurements demonstrate that it really does occur early. That has me foxed. Further, the fact that you see 110ms indicates that my measurement in code is somehow wrong. So perhaps ticks_ms() is going wrong. Puzzling.

[robert-hh]

The 110ms are also shown by your code. Just vary the sleep times to values like 17 or 201.