Clock Desync? - Crash Midway Through Print

General Discussion
1

I was instructed to move this here, from Clock Desync? - Crash Midway Through Print · Issue #5526 · Klipper3d/klipper · GitHub

I have been having prints freeze mid print, after using Klipper for 6 months. I have not introduced new hardware, and I have removed all variables which might be causing the problem. The only thing that I have changed is I changed ZV input shaper to MZV, but if I flip things back the issue still happens.

I am seeing this in logs:

Resetting prediction variance 48331.481: freq=49996692 diff=2502311 stddev=3050.493
Stats 48331.7: gcodein=0 mcu: mcu_awake=0.011 mcu_task_avg=0.000012 mcu_task_stddev=0.000010 bytes_write=41489249 bytes_read=12102994 bytes_retransmit=9 bytes_invalid=0 send_seq=866994 receive_seq=866994 retransmit_seq=2 srtt=0.001 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=167994493 rpi: mcu_awake=0.000 mcu_task_avg=0.000009 mcu_task_stddev=0.000014 bytes_write=158298 bytes_read=489037 bytes_retransmit=0 bytes_invalid=0 send_seq=26358 receive_seq=26358 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=50000360 adj=49998355 sd_pos=2435086 heater_bed: target=70 temp=70.0 pwm=0.363 raspberry_pi: temp=39.7 mcu_temp: temp=31.6 sysload=0.23 cputime=2094.753 memavail=595576 print_time=25864.784 buffer_time=2.402 print_stall=0 extruder: target=220 temp=220.1 pwm=0.506
Resetting prediction variance 48332.470: freq=50000360 diff=2400876 stddev=50000.000
Stats 48332.7: gcodein=0 mcu: mcu_awake=0.007 mcu_task_avg=0.000010 mcu_task_stddev=0.000009 bytes_write=41490253 bytes_read=12103488 bytes_retransmit=9 bytes_invalid=0 send_seq=867020 receive_seq=867020 retransmit_seq=2 srtt=0.001 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=167994487 rpi: mcu_awake=0.000 mcu_task_avg=0.000009 mcu_task_stddev=0.000014 bytes_write=158304 bytes_read=489053 bytes_retransmit=0 bytes_invalid=0 send_seq=26359 receive_seq=26359 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=50003770 adj=50040535 sd_pos=2435306 heater_bed: target=70 temp=70.0 pwm=0.393 raspberry_pi: temp=39.7 mcu_temp: temp=31.5 sysload=0.30 cputime=2094.846 memavail=595864 print_time=25865.557 buffer_time=2.175 print_stall=0 extruder: target=220 temp=220.0 pwm=0.533
Resetting prediction variance 48333.454: freq=50003770 diff=2296227 stddev=50000.000

And:

mcu 'mcu': got {'#receive_time': 819.066948802, u'next_clock': 744358144, u'oid': 24, u'value': 7539, '#name': u'analog_in_state', '#sent_time': 819.01618052}
mcu 'mcu': got {'#receive_time': 819.117116302, u'next_clock': 752758144, u'oid': 29, u'value': 31413, '#name': u'analog_in_state', '#sent_time': 819.01618052}

Klipper and Moonraker logs, my configurations, project files:
Klipper Error Log Config and Print.zip (376.2 KB)

I am not getting undervoltage warnings, and the only USB I have plugged in are: 1. the USB cable to the MCU, which is a nice thick shielded one provided by BTT with the SKR 2, and my Endoscope camera, which has been plugged in forever.

One additional weird point is that once I fully rebooted the Pi, and I issued a firmware restart- upon connecting it thinks the print is still in progress, it did not enter a status failed state.

2

The “Resetting prediction variance” error is a severe error - it indicates the host software was unable to make accurate predictions of the micro-controller clock. Oddly, it was the “linux mcu” running on the host that was having the synchronization problem. I suspect this might occur if the system clock has an incorrect time and the system ntp process is struggling to correct the time.

I’d try commenting out the “mcu rpi” and “adxl345” config sections to see if that resolves the immediate problem. Also, you might want to check if the rpi system time is accurate.

-Kevin

3

I have commented those sections out.

The time was incorrect, by about 5 hours. When I set the time zone through raspi-config it updated to the correct time, so not sure how it got out of sync.

pi@fluiddpi:~ $ timedatectl status
               Local time: Tue 2022-05-24 13:16:24 EDT
           Universal time: Tue 2022-05-24 17:16:24 UTC
                 RTC time: n/a
                Time zone: America/New_York (EDT, -0400)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no

pi@fluiddpi:~ $ ping 0.us.pool.ntp.org
PING 0.us.pool.ntp.org (173.0.48.220) 56(84) bytes of data.
64 bytes from smtp.us.naz.com (173.0.48.220): icmp_seq=1 ttl=37 time=84.9 ms
64 bytes from smtp.us.naz.com (173.0.48.220): icmp_seq=2 ttl=37 time=82.9 ms
64 bytes from smtp.us.naz.com (173.0.48.220): icmp_seq=3 ttl=37 time=78.7 ms
64 bytes from smtp.us.naz.com (173.0.48.220): icmp_seq=4 ttl=37 time=84.5 ms
64 bytes from smtp.us.naz.com (173.0.48.220): icmp_seq=5 ttl=37 time=84.8 ms
4

Just had another halt (before a lot of the above changes went into affect with a firmware restart). In these lines of code, is this significant?

Receive: 99 33851.886658 33851.886218 12: seq: 13, shutdown clock=3745843657 static_string_id=Command request

What is shutdown clock?

Receive: 74 33831.818190 33831.817932 11: seq: 1e, clock clock=2742450677

Receive: 75 33832.802871 33832.802532 11: seq: 1f, clock clock=2791683239

Receive: 76 33833.787952 33833.787703 11: seq: 10, clock clock=2840938579

Receive: 77 33834.773003 33834.772782 11: seq: 11, clock clock=2890189727

Receive: 78 33835.417971 33834.772782 13: seq: 11, stats count=56 sum=24111 sumsq=152075

Receive: 79 33835.757694 33835.757444 11: seq: 12, clock clock=2939421495

Receive: 80 33836.742785 33836.742459 11: seq: 13, clock clock=2988672859

Receive: 81 33837.727622 33837.727408 11: seq: 14, clock clock=3037916587

Receive: 82 33838.712230 33838.711763 11: seq: 15, clock clock=3087138340

Receive: 83 33839.696704 33839.696445 11: seq: 16, clock clock=3136367408

Receive: 84 33840.418120 33839.696445 13: seq: 16, stats count=55 sum=26052 sumsq=172963

Receive: 85 33840.681679 33840.681438 11: seq: 17, clock clock=3185614493

Receive: 86 33841.666120 33841.665802 11: seq: 18, clock clock=3234833199

Receive: 87 33842.650145 33842.649953 11: seq: 19, clock clock=3284035559

Receive: 88 33843.635147 33843.634902 11: seq: 1a, clock clock=3333283551

Receive: 89 33844.619607 33844.619268 11: seq: 1b, clock clock=3382503012

Receive: 90 33845.418305 33844.619268 13: seq: 1b, stats count=55 sum=24224 sumsq=150678

Receive: 91 33845.604873 33845.604496 11: seq: 1c, clock clock=3431760753

Receive: 92 33846.589618 33846.589457 11: seq: 1d, clock clock=3481004539

Receive: 93 33847.574169 33847.573867 11: seq: 1e, clock clock=3530227477

Receive: 94 33848.558815 33848.558540 11: seq: 1f, clock clock=3579458862

Receive: 95 33849.543467 33849.543316 11: seq: 10, clock clock=3628692666

Receive: 96 33850.518386 33849.543316 13: seq: 10, stats count=56 sum=23707 sumsq=159361

Receive: 97 33850.527747 33850.527506 11: seq: 11, clock clock=3677902750

Receive: 98 33851.512656 33851.512414 11: seq: 12, clock clock=3727147695

Receive: 99 33851.886658 33851.886218 12: seq: 13, shutdown clock=3745843657 static_string_id=Command request

Stats 33851.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=15882 freq=167994374 rpi: mcu_awake=0.000 mcu_task_avg=0.000008 mcu_task_stddev=0.000015 bytes_write=193785 bytes_read=598427 bytes_retransmit=0 bytes_invalid=0 send_seq=32274 receive_seq=32274 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998523 adj=50000125 sd_pos=24663017 heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=41.3 mcu_temp: temp=33.0 sysload=0.33 cputime=2705.003 memavail=594380 print_time=31690.873 buffer_time=2.244 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Exiting SD card print (position 24663045)

Stats 33852.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=15884 freq=167994374 rpi: mcu_awake=0.000 mcu_task_avg=0.000008 mcu_task_stddev=0.000015 bytes_write=193797 bytes_read=598455 bytes_retransmit=0 bytes_invalid=0 send_seq=32276 receive_seq=32276 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998524 adj=50000142  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=41.3 mcu_temp: temp=33.0 sysload=0.33 cputime=2705.080 memavail=593148 print_time=31690.873 buffer_time=1.240 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33853.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16158 freq=167994374 rpi: mcu_awake=0.000 mcu_task_avg=0.000008 mcu_task_stddev=0.000015 bytes_write=193803 bytes_read=598471 bytes_retransmit=0 bytes_invalid=0 send_seq=32277 receive_seq=32277 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998525 adj=50000149  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=41.9 mcu_temp: temp=33.0 sysload=0.30 cputime=2705.112 memavail=593148 print_time=31690.893 buffer_time=0.258 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33854.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16159 freq=167994374 rpi: mcu_awake=0.000 mcu_task_avg=0.000008 mcu_task_stddev=0.000015 bytes_write=193809 bytes_read=598487 bytes_retransmit=0 bytes_invalid=0 send_seq=32278 receive_seq=32278 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998526 adj=50000169  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=40.8 mcu_temp: temp=33.0 sysload=0.30 cputime=2705.143 memavail=593148 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33855.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16160 freq=167994374 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000020 bytes_write=193815 bytes_read=598516 bytes_retransmit=0 bytes_invalid=0 send_seq=32279 receive_seq=32279 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998527 adj=50000184  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=41.3 mcu_temp: temp=33.0 sysload=0.30 cputime=2705.173 memavail=593148 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33856.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16161 freq=167994374 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000020 bytes_write=193821 bytes_read=598532 bytes_retransmit=0 bytes_invalid=0 send_seq=32280 receive_seq=32280 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998528 adj=50000198  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=40.8 mcu_temp: temp=33.0 sysload=0.30 cputime=2705.203 memavail=593148 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33857.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16162 freq=167994374 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000020 bytes_write=193827 bytes_read=598548 bytes_retransmit=0 bytes_invalid=0 send_seq=32281 receive_seq=32281 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998529 adj=50000217  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=40.8 mcu_temp: temp=33.0 sysload=0.27 cputime=2705.231 memavail=593152 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33858.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16163 freq=167994374 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000020 bytes_write=193833 bytes_read=598564 bytes_retransmit=0 bytes_invalid=0 send_seq=32282 receive_seq=32282 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998530 adj=50000231  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=41.3 mcu_temp: temp=33.0 sysload=0.27 cputime=2705.254 memavail=593480 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33859.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16164 freq=167994374 rpi: mcu_awake=0.001 mcu_task_avg=0.000011 mcu_task_stddev=0.000020 bytes_write=193839 bytes_read=598580 bytes_retransmit=0 bytes_invalid=0 send_seq=32283 receive_seq=32283 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998551 adj=50000237  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=41.9 mcu_temp: temp=33.0 sysload=0.27 cputime=2705.279 memavail=593480 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33860.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16165 freq=167994374 rpi: mcu_awake=0.000 mcu_task_avg=0.000009 mcu_task_stddev=0.000016 bytes_write=193845 bytes_read=598609 bytes_retransmit=0 bytes_invalid=0 send_seq=32284 receive_seq=32284 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998551 adj=50000556  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=41.9 mcu_temp: temp=33.0 sysload=0.27 cputime=2705.304 memavail=598436 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33861.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16166 freq=167994374 rpi: mcu_awake=0.000 mcu_task_avg=0.000009 mcu_task_stddev=0.000016 bytes_write=193851 bytes_read=598625 bytes_retransmit=0 bytes_invalid=0 send_seq=32285 receive_seq=32285 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998551 adj=50000474  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=41.9 mcu_temp: temp=33.0 sysload=0.27 cputime=2705.334 memavail=597592 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33862.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16167 freq=167994374 rpi: mcu_awake=0.000 mcu_task_avg=0.000009 mcu_task_stddev=0.000016 bytes_write=193857 bytes_read=598640 bytes_retransmit=0 bytes_invalid=0 send_seq=32286 receive_seq=32286 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998551 adj=50000412  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=42.4 mcu_temp: temp=33.0 sysload=0.25 cputime=2705.353 memavail=597592 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33863.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16168 freq=167994374 rpi: mcu_awake=0.000 mcu_task_avg=0.000009 mcu_task_stddev=0.000016 bytes_write=193863 bytes_read=598655 bytes_retransmit=0 bytes_invalid=0 send_seq=32287 receive_seq=32287 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998551 adj=50000365  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=41.9 mcu_temp: temp=33.0 sysload=0.25 cputime=2705.375 memavail=597616 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33864.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16169 freq=167994374 rpi: mcu_awake=0.000 mcu_task_avg=0.000009 mcu_task_stddev=0.000016 bytes_write=193869 bytes_read=598670 bytes_retransmit=0 bytes_invalid=0 send_seq=32288 receive_seq=32288 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998551 adj=50000330  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=42.4 mcu_temp: temp=33.0 sysload=0.25 cputime=2705.407 memavail=597368 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33865.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16170 freq=167994374 rpi: mcu_awake=0.000 mcu_task_avg=0.000009 mcu_task_stddev=0.000016 bytes_write=193875 bytes_read=598698 bytes_retransmit=0 bytes_invalid=0 send_seq=32289 receive_seq=32289 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998551 adj=50000304  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=41.9 mcu_temp: temp=33.0 sysload=0.25 cputime=2705.439 memavail=597368 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33866.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16171 freq=167994374 rpi: mcu_awake=0.000 mcu_task_avg=0.000009 mcu_task_stddev=0.000016 bytes_write=193881 bytes_read=598713 bytes_retransmit=0 bytes_invalid=0 send_seq=32290 receive_seq=32290 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998551 adj=50000285  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=41.9 mcu_temp: temp=33.0 sysload=0.25 cputime=2705.471 memavail=596864 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33867.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16172 freq=167994374 rpi: mcu_awake=0.000 mcu_task_avg=0.000009 mcu_task_stddev=0.000016 bytes_write=193887 bytes_read=598729 bytes_retransmit=0 bytes_invalid=0 send_seq=32291 receive_seq=32291 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998551 adj=50000270  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=41.9 mcu_temp: temp=33.0 sysload=0.23 cputime=2705.501 memavail=595604 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33868.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16173 freq=167994374 rpi: mcu_awake=0.000 mcu_task_avg=0.000009 mcu_task_stddev=0.000016 bytes_write=193893 bytes_read=598745 bytes_retransmit=0 bytes_invalid=0 send_seq=32292 receive_seq=32292 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998551 adj=50000259  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=41.3 mcu_temp: temp=33.0 sysload=0.23 cputime=2705.531 memavail=595604 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Stats 33869.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16174 freq=167994374 rpi: mcu_awake=0.000 mcu_task_avg=0.000009 mcu_task_stddev=0.000016 bytes_write=193899 bytes_read=598761 bytes_retransmit=0 bytes_invalid=0 send_seq=32293 receive_seq=32293 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49998551 adj=50000251  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=40.8 mcu_temp: temp=33.0 sysload=0.23 cputime=2705.559 memavail=595616 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Resetting prediction variance 33870.220: freq=49998551 diff=865828 stddev=4318.980

Stats 33870.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16175 freq=167994374 rpi: mcu_awake=0.001 mcu_task_avg=0.000009 mcu_task_stddev=0.000017 bytes_write=193905 bytes_read=598790 bytes_retransmit=0 bytes_invalid=0 send_seq=32294 receive_seq=32294 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=49999795 adj=50000245  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=41.3 mcu_temp: temp=33.0 sysload=0.23 cputime=2705.585 memavail=595616 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Resetting prediction variance 33871.205: freq=49999795 diff=847607 stddev=50000.000

Stats 33871.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16176 freq=167994374 rpi: mcu_awake=0.001 mcu_task_avg=0.000009 mcu_task_stddev=0.000017 bytes_write=193911 bytes_read=598806 bytes_retransmit=0 bytes_invalid=0 send_seq=32295 receive_seq=32295 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=50000976 adj=50020797  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=41.3 mcu_temp: temp=33.0 sysload=0.23 cputime=2705.615 memavail=595616 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Resetting prediction variance 33872.190: freq=50000976 diff=823865 stddev=50000.000

Stats 33872.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16178 freq=167994374 rpi: mcu_awake=0.001 mcu_task_avg=0.000009 mcu_task_stddev=0.000017 bytes_write=193917 bytes_read=598822 bytes_retransmit=0 bytes_invalid=0 send_seq=32296 receive_seq=32296 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=50002092 adj=50035600  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=41.9 mcu_temp: temp=33.0 sysload=0.37 cputime=2705.646 memavail=588236 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Resetting prediction variance 33873.175: freq=50002092 diff=800240 stddev=50000.000

Stats 33873.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16179 freq=167994374 rpi: mcu_awake=0.001 mcu_task_avg=0.000009 mcu_task_stddev=0.000017 bytes_write=193923 bytes_read=598838 bytes_retransmit=0 bytes_invalid=0 send_seq=32297 receive_seq=32297 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=50003147 adj=50046021  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=44.0 mcu_temp: temp=33.0 sysload=0.37 cputime=2705.669 memavail=590964 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Resetting prediction variance 33874.159: freq=50003147 diff=777239 stddev=50000.000

Stats 33874.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16180 freq=167994374 rpi: mcu_awake=0.001 mcu_task_avg=0.000009 mcu_task_stddev=0.000017 bytes_write=193929 bytes_read=598854 bytes_retransmit=0 bytes_invalid=0 send_seq=32298 receive_seq=32298 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=50004148 adj=50053207  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=45.1 mcu_temp: temp=33.0 sysload=0.37 cputime=2705.691 memavail=602700 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Resetting prediction variance 33875.143: freq=50004148 diff=753325 stddev=50000.000

Stats 33875.9: gcodein=0 mcu: mcu_awake=0.010 mcu_task_avg=0.000011 mcu_task_stddev=0.000010 bytes_write=80694825 bytes_read=17950285 bytes_retransmit=24 bytes_invalid=0 send_seq=1563971 receive_seq=1563970 retransmit_seq=1563971 srtt=0.001 rttvar=0.000 rto=0.050 ready_bytes=0 stalled_bytes=16181 freq=167994374 rpi: mcu_awake=0.000 mcu_task_avg=0.000008 mcu_task_stddev=0.000014 bytes_write=193935 bytes_read=598883 bytes_retransmit=0 bytes_invalid=0 send_seq=32299 receive_seq=32299 retransmit_seq=0 srtt=0.000 rttvar=0.000 rto=0.025 ready_bytes=0 stalled_bytes=0 freq=50005096 adj=50058023  heater_bed: target=70 temp=70.0 pwm=0.352 raspberry_pi: temp=43.5 mcu_temp: temp=33.0 sysload=0.37 cputime=2705.715 memavail=601712 print_time=31690.893 buffer_time=0.000 print_stall=0 extruder: target=220 temp=219.8 pwm=0.564

Resetting prediction variance 33876.128: freq=50005096 diff=732016 stddev=50000.000
5

Also of note, I checked the time as soon as it failed, and the clock is behind again, over a span of an hour or two.

pi@fluiddpi:~ $ timedatectl status
               Local time: Tue 2022-05-24 17:18:00 EDT
           Universal time: Tue 2022-05-24 21:18:00 UTC
                 RTC time: n/a
                Time zone: America/New_York (EDT, -0400)
System clock synchronized: yes
              NTP service: active
          RTC in local TZ: no
6

Humm. Not sure it is fixed. I made the changes you mentioned, and also reduced vref on my extruder, and slowed down my Z accel, and same thing. once again- and this time it was on layer 1 or 2.
klippyV2.zip (3.0 MB)

Any other insight @koconnor ?

I changed my NTP server to my pfSense and the clock seems to be syncing correctly.

[49095.604234] WARN::dwc_otg_hcd_handle_hc_fsm:2462: Unexpected IRQ state on FSM transaction:dev_addr=20 ep=2 fsm=6, hcint=0x00000002


[49095.604258] WARN::dwc_otg_hcd_handle_hc_fsm:2462: Unexpected IRQ state on FSM transaction:dev_addr=20 ep=2 fsm=6, hcint=0x00000002


[49095.604282] WARN::dwc_otg_hcd_handle_hc_fsm:2462: Unexpected IRQ state on FSM transaction:dev_addr=20 ep=2 fsm=6, hcint=0x00000002

[49095.604283] usb 1-1.5: USB disconnect, device number 20

[49095.604305] WARN::dwc_otg_hcd_handle_hc_fsm:2462: Unexpected IRQ state on FSM transaction:dev_addr=20 ep=2 fsm=6, hcint=0x00000002


[49095.604326] WARN::dwc_otg_hcd_handle_hc_fsm:2462: Unexpected IRQ state on FSM transaction:dev_addr=20 ep=2 fsm=6, hcint=0x00000002


[49095.604349] WARN::dwc_otg_hcd_handle_hc_fsm:2462: Unexpected IRQ state on FSM transaction:dev_addr=20 ep=2 fsm=6, hcint=0x00000002


[49095.604370] WARN::dwc_otg_hcd_handle_hc_fsm:2462: Unexpected IRQ state on FSM transaction:dev_addr=20 ep=2 fsm=6, hcint=0x00000002


[49095.604392] WARN::dwc_otg_hcd_handle_hc_fsm:2462: Unexpected IRQ state on FSM transaction:dev_addr=20 ep=2 fsm=6, hcint=0x00000002


[49095.604419] WARN::dwc_otg_hcd_handle_hc_fsm:2462: Unexpected IRQ state on FSM transaction:dev_addr=20 ep=2 fsm=6, hcint=0x00000002


[49095.604446] WARN::dwc_otg_hcd_handle_hc_fsm:2462: Unexpected IRQ state on FSM transaction:dev_addr=20 ep=2 fsm=6, hcint=0x00000002

[49095.899374] Indeed it is in host mode hprt0 = 00001501
[49096.109293] usb 1-1: new high-speed USB device number 21 using dwc_otg
[49096.109398] Indeed it is in host mode hprt0 = 00001101
[49096.349488] usb 1-1: New USB device found, idVendor=0424, idProduct=9514, bcdDevice= 2.00
[49096.349514] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[49096.350031] hub 1-1:1.0: USB hub found
[49096.350103] hub 1-1:1.0: 5 ports detected
[49096.669362] usb 1-1.1: new high-speed USB device number 22 using dwc_otg
[49096.799719] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00, bcdDevice= 2.00
[49096.799757] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[49096.802858] smsc95xx v2.0.0
[49096.962156] SMSC LAN8700 usb-001:022:01: attached PHY driver (mii_bus:phy_addr=usb-001:022:01, irq=POLL)
[49096.963255] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb-3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:5f:b0:fa
[49097.259380] usb 1-1.2: new high-speed USB device number 23 using dwc_otg
[49097.393565] usb 1-1.2: New USB device found, idVendor=090c, idProduct=f37d, bcdDevice= 0.04
[49097.393602] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[49097.393624] usb 1-1.2: Product: HD Endoscope Camera
[49097.393642] usb 1-1.2: Manufacturer: Endoscope
[49097.395477] usb 1-1.2: Found UVC 1.00 device HD Endoscope Camera (090c:f37d)
[49097.435027] input: HD Endoscope Camera: Endoscope as /devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2:1.0/input/input9
[49097.529433] usb 1-1.5: new full-speed USB device number 24 using dwc_otg
[49097.676330] usb 1-1.5: New USB device found, idVendor=1d50, idProduct=614e, bcdDevice= 1.00
[49097.676356] usb 1-1.5: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[49097.676367] usb 1-1.5: Product: stm32f429xx
[49097.676376] usb 1-1.5: Manufacturer: Klipper
[49097.676384] usb 1-1.5: SerialNumber: 370019000250315637383220
[49097.683776] cdc_acm 1-1.5:1.0: ttyACM0: USB ACM device
[49097.871146] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup
[49098.024377] smsc95xx 1-1.1:1.0 eth0: Link is Down
[49100.210600] smsc95xx 1-1.1:1.0 eth0: Link is Up - 100Mbps/Full - flow control off
[49100.210680] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[51847.035111] usb 1-1.5: USB disconnect, device number 24
[51848.610445] usb 1-1.5: new full-speed USB device number 25 using dwc_otg
[51848.757620] usb 1-1.5: New USB device found, idVendor=1d50, idProduct=614e, bcdDevice= 1.00
[51848.757649] usb 1-1.5: New USB device strings: Mfr=1, Product=2, SerialNumber=3
[51848.757660] usb 1-1.5: Product: stm32f429xx
[51848.757669] usb 1-1.5: Manufacturer: Klipper
[51848.757678] usb 1-1.5: SerialNumber: 370019000250315637383220
[51848.763912] cdc_acm 1-1.5:1.0: ttyACM0: USB ACM device
[51881.597171] usb 1-1.2: USB disconnect, device number 23