Intermittant Timer Too Close Fault during Eddy Home/Tap

General Discussion
21

Ah, I think I understand what is occurring.

Once a second the host sends a get_clock command to the micro-controller, and the host uses the clock response when converting the trsync_state timestamps. However, the host may choose to not process clock responses if the latency is unusually high (so as to not skew the clock synchronization). In this case, the host python code will still update its self.last_clock tracking, but it does not pass this information on to the low-level C code for the trsync_state handling.

In the above log, it seems the C code didn’t get a clock tracking update for about 5 seconds. This resulted in a 32-bit rollover issue as the main MCU is running at 520Mhz.

I’ll need to think about how to best handle this.
-Kevin

22

Interesting, glad the addition info helped identify a potential cause.

Is the heavy traffic and therefore latency part of the Eddy homing routine, or potentially my old Pi3b?

Wondering if my hw combo of an eddy current probe and 520Mhz MCU and Pi3b is why I’m seeing it and not many others?

Let me know if I can test anything else to help.

23

Hmm, I spent some time around this code.
I guess this can help:

diff --git a/klippy/clocksync.py b/klippy/clocksync.py
index 37dbec824..ce4d2a3a3 100644
--- a/klippy/clocksync.py
+++ b/klippy/clocksync.py
@@ -86,7 +86,7 @@ class ClockSync:
         clock_diff2 = (clock - exp_clock)**2
         if (clock_diff2 > 25. * self.prediction_variance
             and clock_diff2 > (.000500 * self.mcu_freq)**2):
-            if clock > exp_clock and sent_time < self.last_prediction_time+10.:
+            if clock > exp_clock and sent_time < self.last_prediction_time+7.:
                 logging.info("Ignoring clock sample %.3f:"
                               " freq=%d diff=%d stddev=%.3f",
                               sent_time, self.clock_est[2], clock - exp_clock,

Basically with an old 400Mhz, we had about: ((1 << 32) - 1) / 400_000_000 = 10.737s
So, there was a high chance that the sample would be accepted anyway.
I guess: (10.737 - 10) / 0.9839 = 0.749 ~ 75% that it would happen in time.

So, with the new MCU code:
((1 << 32) - 1) / 520_000_000 = 8.259s

It never triggers, and we get what we get.
So, I guess the reduction of the filter should work?

Another workaround that I can imagine is: ce->last_clock can be updated from clock sync in the same way as self.last_clock does. Regardless of the clock estimation, it should help with the overflow.
Basically, do: self.serial.set_clock_est( ..., self.last_clock) unconditionally.

Regards,
-Timofey

P.S.
Now I know why the time/clock estimate is lagging behind and does not represent the current time.
And that consistent lag of ~28.5s is expected =_=

24703.891 (24675.342433501748, 12836561249623.447, 520027199.4458751)
24704.876 (24676.326872126272, 12837073183569.299, 520027168.4603093)

I’ve noticed that there is 1-2ms lag to the main MCU during the shutdown, and MCU is the can bridge. So, I guess, that during homing there is a spike of traffic, which delays the main MCU responses because of the internal bridge priorities.
And because the initial lag was calculated with an idle state (less lag), it leads to this situation during homing.

24

FYI, there’s been a bunch of discussion on github about this. I have a PR up at Separate last_clock tracking from clock estimate tracking by KevinOConnor · Pull Request #7306 · Klipper3d/klipper · GitHub that hopefully fixes this issue.

Cheers,
-Kevin

25

FYI, I committed PR #7306. So, hopefully this issue is now fixed.

Cheers,
-Kevin

26

I’ve applied the update and turned off my methods for avoiding it. So far so good! Thanks for following through on this!