Timer too close if extruder runs for more than 0.5s

[stestagg]

Basic Information:

Printer Model: Voron 2.4 build
MCU: rpi5, btt octopus (usb serial), both ebb 36 & sb 0000 can board using fysetc ucan.
klippy.log (101.5 KB)

Description

I’m doing a modified Voron build, using can to the toolhead and a sherpa-mini.

Everything is working fine so far, but if I run the extruder for more than exactly 0.5s, I get a shutdown with ‘Timer too close’ error.

My connections are:

rpi5 > btt octopus direct usb serial
rpi5 > fysetc ucan board > btt ebb36 can board.

Things I’ve tried:

1. Varying can speed from 250,000, 500,000 and 1,000,000
2. Changing out ebb36 for an rp2040 sb0000
3. Changing stepper motor
4. dialing down the stepper settings (turning down microsteps, stealthchop etc…)
5. Changing the can cable (tried 2 different btt ones, and one shielded can cable)

None of these seem to change the behaviour.

I can sit there spamming the [extrude] button in the UI, keeping the stepper running as long as the extrusion time is 0.49s.
The moment it’s 0.51 s, I get immediate timer too close error (0.5 seconds is flaky, sometimes it works).

Here’s from the klippy logs with me manually triggering:

Received 647.950365: b'{"id": 140734109642128, "method": "gcode/script", "params": {"script": "M83"}}'
Received 652.473364: b'{"id": 140734109642000, "method": "gcode/script", "params": {"script": "G1 E0.40 F54"}}'
Received 656.078122: b'{"id": 140734109637904, "method": "gcode/script", "params": {"script": "G1 E0.40 F120"}}'
Received 667.708930: b'{"id": 140734109633680, "method": "gcode/script", "params": {"script": "G1 E0.42 F60"}}'
Received 670.156653: b'{"id": 140734109639312, "method": "gcode/script", "params": {"script": "G1 E0.44 F60"}}'
Received 672.326313: b'{"id": 140734109477840, "method": "gcode/script", "params": {"script": "G1 E0.46 F60"}}'
Received 674.673540: b'{"id": 140734109635984, "method": "gcode/script", "params": {"script": "G1 E0.48 F60"}}'
Received 678.755363: b'{"id": 140734109631056, "method": "gcode/script", "params": {"script": "G1 E0.50 F60"}}'
Received 682.511831: b'{"id": 140734109631760, "method": "gcode/script", "params": {"script": "G1 E0.52 F60"}}'
< Timer too close shutdown >

Given the exact 0.5s time issue, it feels like there’s either a bug, or something I’m missing, but I can’t see how’s it’s an actual can bus connection issue.

Any ideas?

Thanks

[gaolst]

I did expirience same story but on different hardware
issue was that i did enable “Verbose logging” “-v” option for klipper

So if you did enable some DEBUG or Verbose logging - they can create additional load on system.

Your log file shows following:
“MCU ‘toolhead’ shutdown: Timer too close”
it means: Host can’t handle it.

Next in log you have latest dump of steps for toolhead:
Dumping stepper ‘extruder’ (toolhead) 5 queue_step:
queue_step 0: t=4320971286 p=657 i=96767 c=202 a=0
queue_step 1: t=4340517465 p=859 i=96012 c=8 a=277
queue_step 2: t=4341299237 p=867 i=101932 c=3 a=6400
queue_step 3: t=4341652896 p=870 i=130595 c=2 a=30416
queue_step 4: t=4342066528 p=872 i=252621 c=1 a=0

where t- time, p-start_position, i-interval, c-step_count, a-added time

My assumptions:
When you extruder start moving - there is a quick jump in steps because of somethin (presure Adv, autoRetract, etc) and your toolhead/Host can’t keep up with that speed. Try to reduce speed/accel of extruder, reduce microsteping, offload “toolhead” mcu, etc …

Problem can be at your Host - it can be overloaded, like something is running in background, your storage can’t keep-up with IO, your canbus is overloaded, etc …
Try to analyze real time system load on your host when you are playing with extruder.

[stestagg]

For the record, this was me making a silly mistake.

The octopus board had the wrong frequency selected, which caused issues because klippy was trying to sync the clocks, but was giving funky values because it could’t work out the octopus clock properly.

Flashing octopus with the correct clock setting fixed the problem.