How to interpret Timer too close error message dump

Developers
1

Hi all,
I’m developing a functionality that gets very deep into the weeds of toolhead moves, and timing/scheduling in general.
I eventually stumbled into the classic “Timer too close” error and shutdown and I’d like to better understand the information attached to debug with more awareness.
Could anyone indicate what the different parts of the message refer to (in particular the clocksync one), and what problems they might underline?

INFO:root:MCU 'mcu' shutdown: Timer too close
clocksync state: mcu_freq=72000000 last_clock=1805348344 clock_est=(77558.904 742031425 72004145.108) min_half_rtt=0.000980 min_rtt_time=77566.773 time_avg=77558.903(56.673) clock_avg=742031425.993(4080690100.707) pred_variance=2148463118.258
Dumping serial stats: bytes_write=5865 bytes_read=7286 bytes_retransmit=0 bytes_invalid=0 send_seq=259 receive_seq=259 retransmit_seq=0 srtt=0.013 rttvar=0.002 rto=0.025 ready_bytes=0 stalled_bytes=66

looking forward to your help

cheers
stef

1 Like
2

Hello @cooked !

Could you please share the klippy.log to see what causes this.

3

Hi @EddyMI3D,
I’ve attached the log. Just for the sake of context the error is thrown upon an homing attempt, when I’m testing a modified _drip_move
klippy-dev.log (33.5 KB)

4

A “timer too close” message typically occurs when the host sends a message to the micro-controller scheduling an event at a time that is in the past. When developing code, this is generally an indication that a generated schedule isn’t accurate or that buffer flushing wasn’t done properly.

When I get errors like the above, I start by using the ./scripts/logextract.py tool as described at Debugging - Klipper documentation . That tool tries to reorder the log messages in a “chronological” order. It also tries to convert the various timestamps into unified timestamps. The dump itself contains lots of low-level fields of various modules - there isn’t good documentation on these low-level values.

-Kevin

5

Hi @koconnor ,
thanks for the pointer. I see that the script in fact rearranges the log entries (attached) from the earliest to the latest, which helps a little… but I still miss some foundational knowledge to be able to find a lead through the log. Here my questions:

  • does each line corresponds to a command processed by the MCU? or the host?
  • I see 3 types of entries, sent, receive, stats… who is the reporter there? in other words who is the sender of a “sent”? who is the receiver of a “receive”?
  • each command seems to have 2 time tags? is it print time? why 2?
  • are sent/receive matched by looking at the seq: number?

finally and most importantly, how close is Too close? or if you will, which 2 timetags should I compare and how much the time difference should be?

thanks for your valuable help

cheers,
stef

klippy-dev.gcode00146.log (134 Bytes)
klippy-dev.shutdown00146.log (42.6 KB)

6

Hi @koconnor ,
maybe I can also try to understand better the code at higher level. Taking the drip_move() as an example here, could you just help me understand which one of the lines makes the time tag right for the move sent in the end?

image

7

Hi,
I eventually managed to solve the issue. I changed my old code

curtime = self.toolhead.reactor.monotonic()
print_time = self.toolhead.mcu.estimated_print_time(curtime)

for the new

self.toolhead._calc_print_time()
print_time = self.toolhead.print_time

Step by step I’m slowly learning my way down into the Klipper core timing features.