samd21: time.monotonic() slows down under pressure #876
Comments
|
What do you think the problem is? I don't think its a matter of Monotonic is driven by an internal interrupt based on the SysTick timer. The only way I'd expect it to lose time is if interrupts are disabled for more than a millisecond. |
|
The thing is, monotonic should always have elapsed one second or more, never (much) less. I'm using monotonic to measure the time it takes for one second to elapse on the RTC. I have now run the same test on a Metro M4 Express, and it doesn't show the same problem. I can upload a test so people can try and reproduce when I've done with tools/cpboard.py, which the test depends upon. |
|
I don't think that's what your code above is doing. I think its measuring the time until the first seconds change from script start up. I don't see where it waits to ensure the first monotonic is captured on a seconds change. Do you have an updated version of the code? |
|
The script might be a bit convoluted since it has evolved over time without getting a cleanup.
There is some dump code in here that I've used when only checking the diff once a minute to see if the amount of printing over USB could have anything to do with my discrepancies. import sys
sys.path.append('.')
import time
import cpboard
def wait_for_tick_tm(board, field):
c = """
import time
lt1 = time.localtime()
lt2 = lt1
i = 0
while lt1.%s == lt2.%s:
lt2 = time.localtime()
i += 1
#time.sleep(0.01)
m = time.monotonic()
print("%%s:%%.6f:%%d" %% ( str(tuple(lt2)), m, i ))
""" % (field, field)
retry = 10
while True:
s = None
try:
s = board.exec(c.strip(), timeout=70)
if s:
break
except CPboardError as e:
if retry == 0:
raise e
retry -= 1
if retry < 8:
print('retry(%d): %s' % (retry, s))
try:
vals = s.split(b':')
t = eval(vals[0])
lt2 = time.struct_time(t)
m = eval(vals[1])
i = eval(vals[2])
except Exception as e:
print("s=%s" % s)
raise e
return lt2, m, i
def wait_for_tick(board):
return wait_for_tick_tm(board, 'tm_sec')
def wait_for_tick_minute(board):
return wait_for_tick_tm(board, 'tm_min')
def sync_time(board, verbose=False):
# Start in 2 seconds
t = time.localtime(time.time() + 2)
w = time.mktime(t) - time.time()
if verbose:
print("wait: %f secs" % w)
time.sleep(w)
cmd = 'import rtc; rtc.RTC().datetime = %s' % str(tuple(t))
if verbose:
print(cmd)
board.exec(cmd)
return t
def measure_ppm(board, localtime_base):
dbg = True
#dbg = False
time_base = time.mktime(localtime_base)
tstr = time.strftime("%d %b %Y %H:%M:%S", localtime_base)
print("Base time: %s" % tstr)
first_time_diff = None
monotonic_prev = 0
time_diff_prev = None
dump_lines = [''] * 70
dump = None
while True:
localtime_remote, monotonic, i = wait_for_tick(board)
time_local = time.time()
time_remote = time.mktime(localtime_remote)
time_diff = time_remote - time_local
# Strip off the fact that the clocks don't run in sync
if first_time_diff is None:
first_time_diff = time_diff
print("\n\nFirst diff: % .6f secs\n\n" % first_time_diff)
time_diff -= first_time_diff
if time_diff_prev is None:
time_diff_prev = time_diff
if dump is None and abs(time_diff) > abs(time_diff_prev) + 2:
dump = True
time_diff_prev = time_diff
db = time_local - time_base
days = db / (24 * 60 * 60)
if days:
dv = time_diff / days
else:
dv = 0
s = "%+.6f secs / %.6f days = %+.6f secs/day (%+.2f ppm) : %s (%.3f - %.3f = %.3f) : %d" % \
(time_diff, days, dv, (dv / (24 * 60 * 60) ) * 10**6,
time.strftime("%d %b %Y %H:%M:%S", localtime_remote),
monotonic, monotonic_prev, monotonic - monotonic_prev,
i)
if dbg or not (int(time_local) % 60):
if dump:
dump = False
print("\ndump 70--->")
for line in dump_lines:
print(line)
print("<---dump\n")
#
print(s)
break
print(s)
monotonic_prev = monotonic
dump_lines.pop(0)
dump_lines.append(s)
print('Board:', sys.argv[1])
board = cpboard.CPboard(sys.argv[1])
board.open()
localtime_base = sync_time(board, True)
measure_ppm(board, localtime_base) |
|
Ah, its possible that the USB code is starving the SysTick interrupt. Try a similar test that doesn't use USB actively while measuring monotonic vs the RTC. |
We now track the last time the background task ran and bail on the PulseIn if it starves the background work. In practice, this happens after the numbers from pulsein are no longer accurate. This also adjusts interrupt priorities so most are the lowest level except for the tick and USB interrupts. Fixes #516 and #876
|
I'm still getting the same result. Here's a stripped down version of my example: code.py: import time
lt1 = time.localtime()
lt2 = lt1
m1 = time.monotonic()
while True:
i = 0
while lt1.tm_sec == lt2.tm_sec:
lt2 = time.localtime()
i += 1
#time.sleep(0.1)
m2 = time.monotonic()
print("time: %s monotonic:%.6f iterations:%d" % ( str(tuple(lt2)[:6]), m2 - m1, i ))
lt1 = lt2
m1 = m2Result with no sleep: Result with 100ms sleep: |
|
I just tried the test case in the previous post on an M4 (without sleep) and the number of iteration varies quite a lot: |
|
Perhaps stating the obvious... I am new to ARM, CP implementation, and even github... I am today seeing this same behavior. |
|
I tinkered with the test script and it seems that time.localtime() or time.time() takes about 4.46 ms and during its execution 3 tick interrupts seem to be lost. |
|
Oh, the 4.5 ms for time.time() and the 3 lost SYSTICKs are from testing on Feather M0 Express. |
|
I'm going to assume this is fixed by the switch to using the RTC for timing. Please comment if it's not fixed. |
I don't know if this is by (unfortunate) design or not, but time.monotonic() slows down under pressure.
I run a script to measure RTC accuracy and it slows down the monotonic clock.
This snippet is run on the board through the REPL to give me the moment that the second ticks over:
This is the resulting test script output:
The important part is the last two numbers: monotonic has elapsed ~0.5 seconds and the loop has run 127/124 times.
If I add a 100ms delay in the loop:
Then I get that monotonic has elapsed ~1 second and the loop has run 7/8 times:
This is with a 10ms sleep:
Does anyone have an explanation for this?
The text was updated successfully, but these errors were encountered: