Timer too close - only in Copy/Mirror-Mode - Idex

General Discussion
1

Basic Information:

Printer Model: custome idex printer
MCU / Printerboard: BTT Octopus, 2xEBB36
Host / SBC: RPI4
klippy-short.log (3.6 MB)

Describe your issue:

I’m getting a “Timer too close” error with my EBB36 CAN bus boards when printing in copy or mirror mode on my IDEX printer. I can print the same models without using copy or mirror mode without any issues. The error always occurs at the same point in the print (I tested two models, twice each).

I’ve already disabled the camera. When checking the system load tab, I didn’t notice anything unusual — the host system load was consistently in the single-digit percentage range.

I’ve read through this guide, but I’m still unsure how to proceed:

Has anyone experienced something similar or have any ideas on what else I could try?

Thanks in advance!

(I’ve manually trimmed the log file (it was way too long — I hadn’t cleaned it before). If anything seems missing or incorrect, please let me know and I’ll do another round and provide a clean, complete version.)

2

Hi @Stefan5454 ,

Please do not trim the log file. If it is too long, compress it as a .zip.

To make the log smaller (and easier to diagnose), it would be much appreciated if you could perform a log rollover.

  1. Restart the Klipper service from the power menu in Mainsail/Fluidd (not the RESTART command)
  2. Reproduce the error
  3. Upload the log (compress if necessary)
1 Like
3 
Stats 2295.9:
  gcodein=0
  mcu: mcu_awake=0.007 mcu_task_avg=0.000010 mcu_task_stddev=0.000008 bytes_write=10054821 bytes_read=1691217 bytes_retransmit=9 bytes_invalid=0 send_seq=186345 receive_seq=186345 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180001998
  EBBCan0: mcu_awake=0.015 mcu_task_avg=0.000018 mcu_task_stddev=0.000024 bytes_write=2921469 bytes_read=500863 bytes_retransmit=0 bytes_invalid=0 send_seq=52255 receive_seq=52255 retransmit_seq=0 srtt=0.009 rttvar=0.006 rto=0.033 ready_bytes=7 upcoming_bytes=50 freq=63999593 adj=63998683 
  EBBCan1: mcu_awake=0.020 mcu_task_avg=0.000017 mcu_task_stddev=0.000023 bytes_write=2912512 bytes_read=543761 bytes_retransmit=708148 bytes_invalid=0 send_seq=51320 receive_seq=51320 retransmit_seq=51316 srtt=0.005 rttvar=0.004 rto=0.025 ready_bytes=7 upcoming_bytes=50 freq=63999720 adj=63999007 sd_pos=1645003
  beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=34864 bytes_read=952471 bytes_retransmit=0 bytes_invalid=0 send_seq=4105 receive_seq=4105 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999503 adj=31999241 coil_temp=48.6 refs=0 mcu_temp=48.41 supply_voltage=3.052
  heater_bed: target=75 temp=74.8 pwm=0.156 sysload=0.16 cputime=282.963 memavail=522016 print_time=2476.702 buffer_time=2.158 print_stall=0
  extruder: target=230 temp=230.0 pwm=0.381
  extruder1: target=235 temp=234.7 pwm=0.529
Stats 2296.9:
  gcodein=0
  mcu: mcu_awake=0.007 mcu_task_avg=0.000010 mcu_task_stddev=0.000008 bytes_write=10058572 bytes_read=1691900 bytes_retransmit=9 bytes_invalid=0 send_seq=186417 receive_seq=186417 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=28 upcoming_bytes=5458 freq=180001994
  EBBCan0: mcu_awake=0.015 mcu_task_avg=0.000018 mcu_task_stddev=0.000024 bytes_write=2924612 bytes_read=501203 bytes_retransmit=0 bytes_invalid=0 send_seq=52307 receive_seq=52304 retransmit_seq=0 srtt=0.009 rttvar=0.005 rto=0.029 ready_bytes=533 upcoming_bytes=40 freq=63999593 adj=63998646
  EBBCan1: mcu_awake=0.019 mcu_task_avg=0.000017 mcu_task_stddev=0.000022 bytes_write=2914611 bytes_read=544061 bytes_retransmit=708885 bytes_invalid=0 send_seq=51355 receive_seq=51352 retransmit_seq=51355 srtt=0.006 rttvar=0.001 rto=0.100 ready_bytes=1121 upcoming_bytes=432 freq=63999715 adj=63998911 sd_pos=1645758
  beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=34870 bytes_read=952827 bytes_retransmit=0 bytes_invalid=0 send_seq=4106 receive_seq=4106 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999504 adj=31999223 coil_temp=48.6 refs=0 mcu_temp=48.37 supply_voltage=3.052
  heater_bed: target=75 temp=74.7 pwm=0.156 sysload=0.15 cputime=283.111 memavail=522016 print_time=2478.079 buffer_time=2.535 print_stall=0
  extruder: target=230 temp=229.9 pwm=0.381
  extruder1: target=235 temp=234.8 pwm=0.529
...
MCU 'EBBCan1' shutdown: Timer too close
...
Sent 98 2296.930462 2296.927054 60: seq: 1b, get_clock, queue_digital_out oid=9 clock=3900533207 on_ticks=537098, queue_digital_out oid=9 clock=3906933115 on_ticks=574745, queue_step oid=7 interval=55086 count=1 add=0, set_next_step_dir oid=7 dir=1, queue_step oid=7 interval=275274 count=1 add=0, queue_step oid=7 interval=65723 count=2 add=-9889, queue_step oid=7 interval=47872 count=4 add=-644
Sent 99 2296.933554 2296.927537 56: seq: 1c, queue_step oid=7 interval=45739 count=4 add=4820, queue_step oid=7 interval=66510 count=2 add=13833, queue_step oid=7 interval=101747 count=1 add=0, queue_step oid=7 interval=192343 count=1 add=0, set_next_step_dir oid=7 dir=0, queue_step oid=7 interval=131199 count=1 add=0, set_next_step_dir oid=7 dir=1, queue_step oid=7 interval=366480 count=1 add=0
...
Receive: 98 2296.942103 2296.930462 11: seq: 1c, clock clock=3903203695
Receive: 99 2296.942522 2296.930462 12: seq: 1c, shutdown clock=3903204868 static_string_id=Timer too close

I think in your specific case, it is a communication issue with EBBCan1.
Just too many retransmissions, just high latency.

4

Hello, thanks for the quick replies.

Here’s a new log, cleaned just before the print: klippy (42).log (3.6 MB)

I reduced the microsteps for the extruders from 16 to 8, but it had no effect — the error still occurs at the same point.

What does “bytes_retransmit” tell me? Can0 has 0 and Can1 has a very high number.

What are my options now?
Can I reduce the CAN bus rate to fix the problem? What would be the consequences of doing so?
Or would I need to rewire the CAN1 board?

If you need any further information, feel free to ask. Thanks in advance!

5

Please do so!

1 Like
6

Sorry, my bad. Here it is: klippy (43).log (3.6 MB)

7

That means that the toolhead is not acknowledge the reception of the transmission in time.

You can look around for different topics. But AFAIK, there is no known good solution or a simple root cause.
You can reflash your MCUs, which will add some CAN hardware counters.
They will help a little to see what happens, but probably will do nothing, from the point of fixing the real issue underneath.

Also, it is seems that you have a 4th device that is working as a CAN bridge.
So, it is the one, that can provide information about communication between eveything.

You can try to check the bus wiring, terminal resistors & etc.

You are already running at low CAN speed, as I can see from the logs: CANBUS_FREQUENCY=250000

So, I don’t think there is something, you can do from the software side to workaround that.

8

FWIW, I think this is duct tape, but I’m curious if it will work.

It is slightly tested, I hope it won’t break anything.

This patch on top will add a log output with a limit of commands per message block.

... upcoming_bytes=0 max_msg_cmd=64 freq=...

64 - Everything is good, any amount of commands, up to the size limit, low overhead.
1 - is the minimum possible value. 1 cmd per message, highest possible transmission overhead for one command.

You can test that patch if you wish.
The basic idea is simple: If the line is unreliable, small packages have higher chances of being delivered.
So, it will auto-limit the count of commands for a new message on retry.
Which will make the following message shorter, occupy fewer CAN packets to transmit, and probably have higher chances of doing so.
That is it, basically soft limit the size of transmission, if there are retries on the line.

Some sort of feedback to the send queue.

Hope that helps.

It does not fix your line, but it will probably allow you to survive errors longer

The right solution should probably split and repack messages, and it is a much higher amount of work. I hope that should be enough for now.

1 Like
9

Thanks for the suggestion. Before I try this, I’m going to inspect my wiring first and see if I can get better results by switching out the wire to the EBB CAN1 board. If this doesn’t work, I will try your solution.

2 Likes
10

I put a new cable between the U2C and the second CAN board—still the same result.
Then I tried your solution—sadly, it didn’t work. Here’s the new log:
klippy.log.txt (3.7 MB)

I’m thinking of switching to USB-C, at least for the second CAN board. But if anyone has a better idea, I’m open to it.

1 Like
11 
Stats 2162.1:
  gcodein=0
  mcu: mcu_awake=0.009 mcu_task_avg=0.000010 mcu_task_stddev=0.000009 bytes_write=9996528 bytes_read=1609683 bytes_retransmit=9 bytes_invalid=0 send_seq=182597 receive_seq=182597 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=180001991
  EBBCan0: mcu_awake=0.014 mcu_task_avg=0.000018 mcu_task_stddev=0.000023 bytes_write=2643427 bytes_read=456886 bytes_retransmit=0 bytes_invalid=0 send_seq=47058 receive_seq=47058 retransmit_seq=0 srtt=0.007 rttvar=0.006 rto=0.032 ready_bytes=0 upcoming_bytes=50 freq=63999584 adj=63999021
  EBBCan1: mcu_awake=0.015 mcu_task_avg=0.000017 mcu_task_stddev=0.000023 bytes_write=2644203 bytes_read=509052 bytes_retransmit=654059 bytes_invalid=0 send_seq=46916 receive_seq=46916 retransmit_seq=46904 srtt=0.005 rttvar=0.003 rto=0.025 ready_bytes=50 upcoming_bytes=50 freq=63999689 adj=63998833 sd_pos=1644821
  beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=33277 bytes_read=880109 bytes_retransmit=0 bytes_invalid=0 send_seq=3902 receive_seq=3902 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999469 adj=31999155 coil_temp=52.1 refs=0 mcu_temp=51.51 supply_voltage=3.052
  heater_bed: target=75 temp=75.2 pwm=0.100 sysload=0.24 cputime=270.928 memavail=519468 print_time=2198.591 buffer_time=2.219 print_stall=0
  extruder: target=230 temp=230.0 pwm=0.374
  extruder1: target=235 temp=235.0 pwm=0.409
Stats 2163.1:
  gcodein=0
  mcu: mcu_awake=0.009 mcu_task_avg=0.000010 mcu_task_stddev=0.000009 bytes_write=10000698 bytes_read=1610396 bytes_retransmit=9 bytes_invalid=0 send_seq=182675 receive_seq=182675 retransmit_seq=2 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=1772 freq=180001992
  EBBCan0: mcu_awake=0.014 mcu_task_avg=0.000018 mcu_task_stddev=0.000023 bytes_write=2645597 bytes_read=457161 bytes_retransmit=0 bytes_invalid=0 send_seq=47094 receive_seq=47094 retransmit_seq=0 srtt=0.008 rttvar=0.005 rto=0.028 ready_bytes=0 upcoming_bytes=50 freq=63999591 adj=63998984
  EBBCan1: mcu_awake=0.018 mcu_task_avg=0.000017 mcu_task_stddev=0.000022 bytes_write=2646378 bytes_read=509392 bytes_retransmit=654609 bytes_invalid=0 send_seq=46953 receive_seq=46953 retransmit_seq=46928 srtt=0.006 rttvar=0.003 rto=0.025 ready_bytes=57 upcoming_bytes=50 freq=63999696 adj=63998819 sd_pos=1645377
  beacon: mcu_awake=0.000 mcu_task_avg=0.000000 mcu_task_stddev=0.000000 bytes_write=33283 bytes_read=880465 bytes_retransmit=0 bytes_invalid=0 send_seq=3903 receive_seq=3903 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 upcoming_bytes=0 freq=31999470 adj=31999192 coil_temp=52.1 refs=0 mcu_temp=51.52 supply_voltage=3.052 
  heater_bed: target=75 temp=75.1 pwm=0.125 sysload=0.24 cputime=271.061 memavail=519468 print_time=2199.652 buffer_time=2.279 print_stall=0
  extruder: target=230 temp=230.0 pwm=0.374
  extruder1: target=235 temp=235.1 pwm=0.409
...
MCU 'EBBCan1' shutdown: Timer too close
clocksync state: mcu_freq=64000000 last_clock=140743713389 clock_est=(2134.409 138879407701 63999711.043) min_half_rtt=0.000206 min_rtt_time=1086.181 time_avg=2134.409(868.486) clock_avg=138879407701.093(55582828399.125) pred_variance=46255007.053 clock_adj=(-1.347 63998930.770)
Dumping serial stats: bytes_write=2646827 bytes_read=509538 bytes_retransmit=654975 bytes_invalid=0 send_seq=46961 receive_seq=46959 retransmit_seq=46958 srtt=0.006 rttvar=0.005 rto=0.028 ready_bytes=1158 upcoming_bytes=30
...
Sent 97 2163.538388 2163.534916 62: seq: 1e, get_clock, queue_digital_out oid=9 clock=3302668650 on_ticks=537098, queue_digital_out oid=9 clock=3309068538 on_ticks=574745, queue_step oid=7 interval=90907 count=2 add=10935, queue_step oid=7 interval=120289 count=1 add=0, queue_step oid=7 interval=161071 count=1 add=0, queue_step oid=7 interval=792937 count=1 add=0, queue_step oid=7 interval=108709 count=1 add=0
Sent 98 2163.544163 2163.540691 62: seq: 1f, queue_step oid=7 interval=67392 count=2 add=-12447, queue_step oid=7 interval=44773 count=5 add=-3018, queue_step oid=7 interval=30743 count=10 add=-808, queue_step oid=7 interval=23104 count=16 add=-192, queue_step oid=7 interval=20378 count=15 add=163, queue_step oid=7 interval=23117 count=11 add=761, queue_step oid=7 interval=31696 count=6 add=2269
...
Receive: 97 2163.551085 0.000000 16: seq: 1e, thermocouple_result oid=6 next_clock=3322878320 value=28756 fault=0
Receive: 98 2163.552194 2163.538388 11: seq: 1f, clock clock=3304759917
Receive: 99 2163.552635 2163.538388 12: seq: 1f, shutdown clock=3304761090 static_string_id=Timer too close

So, the 1e is late.
3302668650 - 3304761090 = -2092440
-2092440 / 64_000_000 = -0.0326

Late by 33ms.

Hmmm..

Generally, it looks better, and RTO is lower.
There is no debugging output, so I’m not sure how much it affects the result.
From the commands per line count, it looks like not at all (there is still more than 1 or 2 cmds per line, maybe my patch is not well made).

I think in this specific case, it is a low bandwidth and line congestion.
From my rough estimation, you are using half of the CAN bandwidth, and maybe, maybe it with the retransmissions, in the end, it makes that.

But the source of retransmissions is still unknown.

FWIW, of course USB should be simpler and stable in general.

2 Likes
12

If you don’t mind, can I ask you to test this one?

Now, it includes the output for me, and it should also restrict the TX window side.
I hope as you have a large number of retransmission bytes, it will lower it, because now we allow sending fewer bytes at a time → less to retransmit.

Thanks.

13

Thanks for the fast replies! I wanted to test it, but with this patch, I couldn’t connect to Klipper anymore.

Moonraker can’t connect to Klipper!

Please check if the Klipper service is running and klippy_uds_address is correctly configured in the moonraker.conf.

As soon as I switched back to the standard version, the issue was resolved.

1 Like
14

FYI, if you choose to stay with CANbus, I suggest you go back to the recommended 1Mbit/s canbus data rate. Reducing the canbus speeds has an adverse impact on latency, timing, and total available bandwidth which can show up as hard to diagnose issues.

I also recommend you update to the latest code and reflash your micro-controllers as there is now better diagnostic information available.

-Kevin

1 Like
15

Thank you so much!

After a lot of trouble with reflashing, I finally got everything working at 500 kbit/s. The Print is now finishing. Now that I understand the flashing process, I’ll bump it up to 1 Mbit/s.
Originally, I was running at 250 kbit/s because the EBB36 documentation stated that as the default.

Huge thanks to everyone who helped out and to the creator of this flashing guide.

2 Likes