Calibration glitch with long run times

[mungewell]

Testing with Rev2.0, and seen a glitch where the calibration appears to change during a long session. Ie. after multiple hours...

It looks like the process which toggles between two divider values is getting stuck. Normally Timer-2 would run for 10s, with Timer-1 running for a fraction of this - depending on the fractional part of the calibration value. The when Timer-2 terminates it re-setups Timer-1 and Timer-2.

However it seems that Timer-1 never restarts for some reason.

$ cut -d ' ' -f 8 2024-10-25_09\:13\:51 | uniq -c
...
      6 Timer(mode=ONE_SHOT,
      4 None
      6 Timer(mode=ONE_SHOT,
      4 None
      6 Timer(mode=ONE_SHOT,
      4 None
      6 Timer(mode=ONE_SHOT,
  28093 None

[1968.983111 0.955910] 12:37:31:00 0.003426666 0.0010681 -0.39968 26.58251 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1969.981384 0.998273] 12:37:32:01 0.0005766665 0.0010728 -0.39968 26.58251 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1971.004731 1.023347] 12:37:33:02 0.0006066663 0.0010922 -0.39968 26.58251 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1972.028565 1.023834] 12:37:34:03 0.001326666 0.001107 -0.39968 26.58251 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1973.026493 0.997927] 12:37:35:02 0.004506667 0.0011272 -0.39968 26.58251 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1974.047708 1.021215] 12:37:36:03 0.0001566662 0.0011253 -0.39968 26.58251 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1974.961448 0.913740] 12:37:37:00 0.002166667 0.0011375 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1975.976106 1.014658] 12:37:38:01 0.001056666 0.0011459 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1977.015479 1.039373] 12:37:39:02 0.001086666 0.0011313 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1977.953503 0.938024] 12:37:40:00 0.0005466668 0.0011416 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1978.969227 1.015724] 12:37:41:00 0.001116667 0.0011444 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1979.964200 0.994973] 12:37:42:00 0.000636667 0.0011242 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1980.988200 1.024000] 12:37:43:01 6.666407e-06 0.0011095 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1982.004757 1.016557] 12:37:44:02 -5.333312e-05 0.0010961 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1983.018508 1.013751] 12:37:45:02 6.666687e-05 0.0011007 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1984.015306 0.996798] 12:37:46:02 0.001386667 0.0010837 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1984.988131 0.972824] 12:37:47:00 0.0008166665 0.0010591 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1985.987488 0.999357] 12:37:48:01 0.0005766665 0.0010443 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1987.003771 1.016283] 12:37:49:02 0.0003966661 0.0010258 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1988.022267 1.018497] 12:37:50:02 0.0002766661 0.0010003 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)
[1989.015780 0.993512] 12:37:51:02 0.0002766661 0.0009593994 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10000000)

[mungewell]

Another example, were I modulate timer2 slightly when it is setup...

[1198.127973 0.969679] 22:51:55:00 0.2615867 0.2633127 -0.39968 26.58251 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(m
ode=ONE_SHOT, tick_hz=1000000, period=10014000)
[1199.183278 1.055305] 22:51:56:02 0.2632267 0.2633016 -0.39968 26.58251 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(m
ode=ONE_SHOT, tick_hz=1000000, period=10014000)
[1200.154580 0.971302] 22:51:57:01 0.2631766 0.2633023 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10014000)
[1201.124361 0.969780] 22:51:58:00 0.2634166 0.2632997 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10014000)
[1202.202419 1.078058] 22:51:59:02 0.2631967 0.263303 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10014000)
[1203.171627 0.969208] 22:52:00:00 0.2625667 0.2632962 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10014000)
[1204.228971 1.057344] 22:52:01:03 0.2623567 0.2632727 -0.39968 26.58251 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10025000)
[1205.198417 0.969447] 22:52:02:02 0.2634667 0.2632707 -0.39968 26.58251 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10025000)
[1206.166555 0.968138] 22:52:03:01 0.2628667 0.2632589 -0.39968 26.58251 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10025000)
[1207.142656 0.976101] 22:52:04:00 0.2637067 0.2632538 -0.39968 26.58251 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10025000)
[1208.221319 1.078663] 22:52:05:02 0.2638567 0.2632487 -0.39968 26.67614 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10025000)
[1209.191378 0.970059] 22:52:06:01 0.2632267 0.2632587 -0.39968 26.67614 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10025000)
[1210.157711 0.966333] 22:52:07:00 0.2632867 0.263242 -0.39968 26.67614 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10025000)
[1211.206338 1.048627] 22:52:08:02 0.2634767 0.2632387 -0.39968 26.67614 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10025000)
[1212.171052 0.964714] 22:52:09:01 0.2628967 0.2632426 -0.39968 26.67614 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10025000)
[1213.134869 0.963817] 22:52:10:00 0.2640367 0.2632369 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10025000)
[1214.183943 1.049074] 22:52:11:02 0.2640067 0.2632406 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10025000)
[1215.147570 0.963627] 22:52:12:00 0.2628367 0.2632442 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10025000)
[1216.219328 1.071758] 22:52:13:03 0.2621167 0.263226 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10025000)
[1217.198675 0.979347] 22:52:14:01 0.2641267 0.2632142 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10025000)
[1218.163179 0.964504] 22:52:15:01 0.2631367 0.2631911 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10025000)
[1219.127188 0.964009] 22:52:16:00 0.2625467 0.2631835 -0.39968 26.58251 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10025000)

Timer2 is stuck for the rest of the log, meaning that the timer interrupt did not trigger at what should have been the end of the 10s period (~1214.183943).

[mungewell]

Have evidence to confirm that there is (was) an issue with the timers NOT triggering, or the interrupt being missed,

I added some protection and some "!!!!!" alerting/messaging
https://github.com/mungewell/pico-timecode/blob/main/pico_timecode.py#L277

    if timer == eng.timer3:
        # This should NEVER occur, it means previous timers were missed.
        print("!!!!!")
        if eng.timer1:
            eng.timer1.deinit()
        if eng.timer2:
            eng.timer2.deinit()

Unit 2: Occurs 11.5s after "7350s" which shows that the timers are reset shortly before this.... so why didn't Timer2 trigger?

[7347.038466 1.040454] 14:59:40:00 -0.01643333 -0.01713873 -0.39968 31.45111 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10027000)
[7348.071103 1.032637] 14:59:41:02 -0.01727333 -0.01712903 -0.39968 31.45111 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10027000)
[7349.040902 0.969799] 14:59:42:01 -0.01667333 -0.01712653 -0.39968 31.54474 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10027000)
[7350.078080 1.037178] 14:59:43:02 -0.01748334 -0.01715382 -0.39968 31.54474 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10016000)
[7351.003724 0.925644] 14:59:44:00 -0.01778333 -0.01714962 -0.39968 31.63837 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10016000)
[7352.039870 1.036146] 14:59:45:01 -0.01664333 -0.01715882 -0.39968 31.54474 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10016000)
[7352.972244 0.932374] 14:59:46:00 -0.01682333 -0.01715142 -0.39968 31.45111 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10016000)
[7354.027520 1.055276] 14:59:47:00 -0.01787333 -0.01715722 -0.39968 31.35748 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10016000)
[7355.043512 1.015992] 14:59:48:01 -0.01682333 -0.01716623 -0.39968 31.35748 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10016000)
[7356.083560 1.040047] 14:59:49:03 -0.01658334 -0.01716032 -0.39968 31.26385 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10016000)
[7357.037072 0.953513] 14:59:50:01 -0.01676333 -0.01716092 -0.39968 31.35748 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10016000)
[7357.973365 0.936292] 14:59:51:00 -0.01691333 -0.01715542 -0.39968 31.35748 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10016000)
[7359.001207 1.027843] 14:59:52:00 -0.01808333 -0.01716052 -0.39968 31.35748 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10016000)
[7360.042491 1.041284] 14:59:53:01 -0.01670333 -0.01716212 -0.39968 31.35748 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10016000)
[7361.104639 1.062148] 14:59:54:03 -0.01895333 -0.01718282 -0.39968 31.35748 None Timer(mode=ONE_SHOT, tick_hz=1000000, period=10016000)
[7361.414385 0.309746] !!!!!
[7362.031253 0.616868] 14:59:55:01 -0.01736333 -0.01717952 -0.39968 31.26385 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10013000)
[7363.067486 1.036232] 14:59:56:02 -0.01715333 -0.01718302 -0.39968 31.35748 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10013000)
[7363.990536 0.923050] 14:59:57:00 -0.01622333 -0.01718292 -0.39968 31.45111 Timer(mode=ONE_SHOT, tick_hz=1000000, period=6003000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10013000)

Unit 3 has Timer1 fail instead.

[4590.039782 1.032039] 14:13:47:02 -0.01439333 -0.01446434 -0.2110583 22.18203 Timer(mode=ONE_SHOT, tick_hz=1000000, period=7889000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10049000)
[4590.752297 0.712515] !!!
[4590.963127 0.210830] 14:13:48:00 -0.01463333 -0.01446674 -0.2110583 22.18203 Timer(mode=ONE_SHOT, tick_hz=1000000, period=7889000) Timer(mode=ONE_SHOT, tick_hz=1000000, period=10021000)