[3.3RC3] Missed stepps or overdue moves
-
@o_lampe said in [3.3-rc3] Missed stepps:
@typqxq
Right, that's like Pest or CholeraI think it is a bug if it is worse than in RC1.
I read about CAN issues and 3HC-controllers not being updated.
Can you confirm your boards are running on the same FW?I confirm and I included it in the above Debug info.
-
Update, here is debug after successfull print of the file on RC2:
2021-05-29 19:11:21 [warn] Finished printing file 0:/gcodes/ScrewMount.gcode, print time was 1h 30m 2021-05-29 19:19:14 [debug] Diagnostics for board 2: 2021-05-29 19:19:14 [debug] Duet EXP3HC firmware version 3.3RC2 (2021-05-11 14:59:18) Bootloader ID: not available 2021-05-29 19:19:14 [debug] Never used RAM 158184, free system stack 0 words Tasks: Move(notifyWait<null>,0.1%,92) HEAT(delaying<null>,0.0%,63) CanAsync(notifyWait<null>,0.0%,72) CanRecv(notifyWait<null>,0.1%,81) CanClock(notifyWait<null>,0.0%,74) TMC(notifyWait<null>,24.7%,29) MAIN(running<null>,73.6%,301) IDLE(ready<null>,0.0%,40) AIN(delaying<null>,1.4%,263), total 100.0% Last reset 01:54:43 ago, cause: software 2021-05-29 19:19:14 [debug] Last software reset at 2021-05-25 23:19, reason: AssertionFailed, available RAM 158184, slot 2 Software reset code 0x0120 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00000000 BFAR 0xe000ed38 SP 0x20004764 Task HEAT Freestk 146 ok 2021-05-29 19:19:14 [debug] Stack: 00000544 0002eb10 000260ff 42000400 0002232f 00000000 00000020 2002f020 2000159c 00000003 0001d25b 00000000 2002f020 00000020 000157b1 00000000 000d205a 000d205a 41c13260 a5a5a5a5 a5a5a5a5 a5a5a5a5 00024f45 a5a5a5a5 00000058 00000000 2002ee70 2021-05-29 19:19:14 [debug] Driver 0: position 4611121, 830.0 steps/mm, standstill, reads 14526, writes 0 timeouts 0, SG min/max 0/1023, steps req 4586389 done 4586534 Driver 1: position 0, 830.0 steps/mm, standstill, reads 14527, writes 0 timeouts 0, SG min/max not available, steps req 0 done 0 Driver 2: position 0, 830.0 steps/mm, standstill, reads 14526, writes 0 timeouts 0, SG min/max not available, steps req 0 done 0 2021-05-29 19:19:14 [debug] Moves scheduled 204025, completed 204025, in progress 0, hiccups 0, step errors 2, maxPrep 54, maxOverdue 11457, maxInc 7958, mcErrs 0, gcmErrs 0 Peak sync jitter 13, peak Rx sync delay 183, resyncs 2, no step interrupt scheduled VIN: 24.1V, V12: 12.2V MCU temperature: min 39.1C, current 39.8C, max 41.0C Ticks since heat task active 202, ADC conversions started 6883308, completed 6883306, timed out 0, errs 0 2021-05-29 19:19:14 [debug] Last sensors broadcast 0x0000000e found 3 208 ticks ago, loop time 0 CAN messages queued 64786, send timeouts 0, received 243311, lost 0, free buffers 36, min 36, error reg 0 dup 0, oos 0, bm 0, wbm 0 2021-05-29 19:19:39 [debug] Diagnostics for board 1: 2021-05-29 19:19:39 [debug] Duet EXP3HC firmware version 3.3RC2 (2021-05-11 14:59:18) Bootloader ID: SAME5x bootloader version 2.2 (2021-01-16b1) 2021-05-29 19:19:39 [debug] Never used RAM 159136, free system stack 0 words Tasks: Move(notifyWait<null>,12.8%,100) HEAT(delaying<null>,0.7%,63) CanAsync(notifyWait<null>,0.0%,72) CanRecv(notifyWait<null>,6.3%,81) CanClock(notifyWait<null>,0.5%,74) TMC(notifyWait<null>,1516.8%,29) MAIN(running<null>,4164.4%,347) IDLE(ready<null>,0.0%,40) AIN(delaying<null>,86.8%,263), total 5788.3% Last reset 01:55:07 ago, cause: software 2021-05-29 19:19:39 [debug] Last software reset time unknown, reason: AssertionFailed, available RAM 159320, slot 1 Software reset code 0x0120 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00000000 BFAR 0xe000ed38 SP 0x20004754 Task HEAT Freestk 142 bad marker 2021-05-29 19:19:39 [debug] Stack: 00000544 0002eb94 000261af 42000400 000223e3 2002f020 00000000 2002f038 2000151c 00000000 0001d681 0002dd80 0002de38 0002d43c 000b0000 2000159c 00000000 2002f020 00015609 00000000 000009c4 000009c4 a5a5a5a5 a5a5a5a5 a5a5a5a5 a5a5a5a5 00024ff5 2021-05-29 19:19:39 [debug] Driver 0: position -96320, 320.0 steps/mm, standstill, reads 57006, writes 0 timeouts 0, SG min/max 0/1023, steps req 60331474 done 60331474 Driver 1: position -960, 320.0 steps/mm, standstill, reads 57006, writes 0 timeouts 0, SG min/max 0/1023, steps req 54769612 done 54769612 Driver 2: position 0, 80.0 steps/mm, standstill, reads 57006, writes 0 timeouts 0, SG min/max not available, steps req 0 done 0 2021-05-29 19:19:39 [debug] Moves scheduled 210369, completed 210369, in progress 0, hiccups 0, step errors 0, maxPrep 199, maxOverdue 11864, maxInc 7956, mcErrs 0, gcmErrs 0 Peak sync jitter 11, peak Rx sync delay 219, resyncs 5, no step interrupt scheduled VIN: 32.1V, V12: 12.1V MCU temperature: min 37.8C, current 39.2C, max 40.2C Ticks since heat task active 6, ADC conversions started 6907864, completed 6907864, timed out 0, errs 0 2021-05-29 19:19:39 [debug] Last sensors broadcast 0x00000000 found 0 12 ticks ago, loop time 0 CAN messages queued 23351, send timeouts 0, received 286095, lost 0, free buffers 36, min 36, error reg 0 dup 0, oos 0, bm 0, wbm 0 2021-05-29 19:19:50 [debug] === Diagnostics === 2021-05-29 19:19:50 [debug] RepRapFirmware for Duet 3 MB6HC version 3.3RC2 (2021-05-11 14:55:28) running on Duet 3 MB6HC v0.6 or 1.0 (standalone mode) 2021-05-29 19:19:50 [debug] Board ID: 08DJM-956L2-G43S4-6JKDD-3SJ6L-TB62G 2021-05-29 19:19:50 [debug] Used output buffers: 1 of 40 (40 max) 2021-05-29 19:19:50 [debug] === RTOS === 2021-05-29 19:19:50 [debug] Static ram: 150680 2021-05-29 19:19:50 [debug] Dynamic ram: 94992 of which 0 recycled 2021-05-29 19:19:50 [debug] Never used RAM 105664, free system stack 98 words 2021-05-29 19:19:50 [debug] Tasks: 2021-05-29 19:19:50 [debug] NETWORK(ready,1313.9%,194) 2021-05-29 19:19:50 [debug] ETHERNET(notifyWait,7.9%,117) 2021-05-29 19:19:50 [debug] HEAT(delaying,0.9%,295) 2021-05-29 19:19:50 [debug] Move(notifyWait,24.7%,176) 2021-05-29 19:19:50 [debug] CanReceiv(notifyWait,1.5%,773) 2021-05-29 19:19:50 [debug] CanSender(notifyWait,1.9%,359) 2021-05-29 19:19:50 [debug] CanClock(delaying,0.3%,341) 2021-05-29 19:19:50 [debug] TMC(notifyWait,460.5%,59) 2021-05-29 19:19:50 [debug] MAIN(running,3444.9%,486) 2021-05-29 19:19:50 [debug] IDLE(ready,0.0%,29) 2021-05-29 19:19:50 [debug] , total 5256.4% Owned mutexes: 2021-05-29 19:19:50 [debug] HTTP(MAIN) 2021-05-29 19:19:50 [debug] === Platform === 2021-05-29 19:19:50 [debug] Last reset 01:55:17 ago, cause: software 2021-05-29 19:19:50 [debug] Last software reset at 2021-05-29 17:24, reason: User, GCodes spinning, available RAM 108872, slot 2 2021-05-29 19:19:50 [debug] Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x0044a000 BFAR 0x00000000 SP 0x00000000 Task MAIN Freestk 0 n/a 2021-05-29 19:19:50 [debug] Error status: 0x04 2021-05-29 19:19:50 [debug] Aux0 errors 0,0,0 2021-05-29 19:19:50 [debug] Aux1 errors 0,0,0 2021-05-29 19:19:50 [debug] Step timer max interval 305 2021-05-29 19:19:50 [debug] MCU temperature: min 41.5, current 42.0, max 43.2 2021-05-29 19:19:50 [debug] Supply voltage: min 31.8, current 31.9, max 31.9, under voltage events: 0, over voltage events: 0, power good: yes 2021-05-29 19:19:50 [debug] 12V rail voltage: min 12.0, current 12.0, max 12.1, under voltage events: 0 2021-05-29 19:19:50 [debug] Heap OK, handles allocated/used 99/0, heap memory allocated/used/recyclable 2048/164/164, gc cycles 0 2021-05-29 19:19:50 [debug] Driver 0: position 320000, standstill, reads 10807, writes 0 timeouts 0, SG min/max 0/1023 2021-05-29 19:19:50 [debug] Driver 1: position 0, standstill, reads 10807, writes 0 timeouts 0, SG min/max 0/1023 2021-05-29 19:19:50 [debug] Driver 2: position 134880, standstill, reads 10803, writes 4 timeouts 0, SG min/max 0/155 2021-05-29 19:19:50 [debug] Driver 3: position 0, standstill, reads 10807, writes 0 timeouts 0, SG min/max 0/149 2021-05-29 19:19:50 [debug] Driver 4: position 0, standstill, reads 10803, writes 0 timeouts 0, SG min/max 0/165 2021-05-29 19:19:50 [debug] Driver 5: position 0, standstill, reads 10807, writes 0 timeouts 0, SG min/max 0/107 2021-05-29 19:19:50 [debug] Date/time: 2021-05-29 19:19:50 [debug] 2021-05-29 19:19:50 2021-05-29 19:19:50 [debug] Slowest loop: 67.54ms; fastest: 0.06ms 2021-05-29 19:19:50 [debug] === Storage === Free file entries: 9 2021-05-29 19:19:50 [debug] SD card 0 detected, interface speed: 25.0MBytes/sec 2021-05-29 19:19:50 [debug] SD card longest read time 3.6ms, write time 3.8ms, max retries 0 2021-05-29 19:19:50 [debug] === Move === DMs created 125, maxWait 11770ms, bed compensation in use: none, comp offset 0.000 2021-05-29 19:19:50 [debug] === MainDDARing === Scheduled moves 211676, completed moves 211676, hiccups 0, stepErrors 0, LaErrors 0, Underruns [65, 0, 0], CDDA state -1 2021-05-29 19:19:50 [debug] === AuxDDARing === Scheduled moves 0, completed moves 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1 2021-05-29 19:19:50 [debug] === Heat === Bed heaters = 2021-05-29 19:19:50 [debug] 0 2021-05-29 19:19:50 [debug] -1 2021-05-29 19:19:50 [debug] -1 2021-05-29 19:19:50 [debug] -1 2021-05-29 19:19:50 [debug] -1 2021-05-29 19:19:50 [debug] -1 2021-05-29 19:19:50 [debug] -1 2021-05-29 19:19:50 [debug] -1 2021-05-29 19:19:50 [debug] -1 2021-05-29 19:19:50 [debug] -1 2021-05-29 19:19:50 [debug] -1 2021-05-29 19:19:50 [debug] -1 2021-05-29 19:19:50 [debug] , chamberHeaters = 2021-05-29 19:19:50 [debug] -1 2021-05-29 19:19:50 [debug] -1 2021-05-29 19:19:50 [debug] -1 2021-05-29 19:19:50 [debug] -1 2021-05-29 19:19:50 [debug] Heater 0 is on, I-accum = 0.1 2021-05-29 19:19:50 [debug] === GCodes === 2021-05-29 19:19:50 [debug] Segments left: 0 2021-05-29 19:19:50 [debug] Movement lock held by null 2021-05-29 19:19:50 [debug] HTTP is ready with "m122 b0" in state(s) 0 2021-05-29 19:19:50 [debug] Telnet is idle in state(s) 0 2021-05-29 19:19:50 [debug] File is idle in state(s) 0 2021-05-29 19:19:50 [debug] USB is idle in state(s) 0 2021-05-29 19:19:50 [debug] Aux is idle in state(s) 0 2021-05-29 19:19:50 [debug] Trigger is idle in state(s) 0 2021-05-29 19:19:50 [debug] Queue is idle in state(s) 0 2021-05-29 19:19:50 [debug] LCD is idle in state(s) 0 2021-05-29 19:19:50 [debug] SBC is idle in state(s) 0 2021-05-29 19:19:50 [debug] Daemon is idle in state(s) 0 2021-05-29 19:19:50 [debug] Aux2 is idle in state(s) 0 2021-05-29 19:19:50 [debug] Autopause is idle in state(s) 0 2021-05-29 19:19:50 [debug] Code queue is empty. 2021-05-29 19:19:50 [debug] === CAN === Messages queued 467291, send timeouts 213, received 93979, lost 0, longest wait 21ms for reply type 6024, peak Tx sync delay 506, free buffers 49 (min 18) 2021-05-29 19:19:50 [debug] Last cancelled message type 51 dest 1 2021-05-29 19:19:50 [debug] === Network === 2021-05-29 19:19:50 [debug] Slowest loop: 17.81ms; fastest: 0.02ms 2021-05-29 19:19:50 [debug] Responder states: 2021-05-29 19:19:50 [debug] HTTP(0) 2021-05-29 19:19:50 [debug] HTTP(0) 2021-05-29 19:19:50 [debug] HTTP(0) 2021-05-29 19:19:50 [debug] HTTP(0) 2021-05-29 19:19:50 [debug] HTTP(0) 2021-05-29 19:19:50 [debug] HTTP(0) 2021-05-29 19:19:50 [debug] FTP(0) 2021-05-29 19:19:50 [debug] Telnet(0), 0 sessions 2021-05-29 19:19:50 [debug] Telnet(0), 0 sessions 2021-05-29 19:19:50 [debug] HTTP sessions: 2 of 8 2021-05-29 19:19:50 [debug] - Ethernet - State: active 2021-05-29 19:19:50 [debug] Error counts: 0 0 1 1 0 Socket states: 2021-05-29 19:19:50 [debug] 5 2021-05-29 19:19:50 [debug] 2 2021-05-29 19:19:50 [debug] 2 2021-05-29 19:19:50 [debug] 2 2021-05-29 19:19:50 [debug] 2 2021-05-29 19:19:50 [debug] 0 2021-05-29 19:19:50 [debug] 0 2021-05-29 19:19:50 [debug] 0
-
Update, I followed a print on RC1. Pulled diagnostics while printing and the maxOverdue was 0 until I heard the steppers getting the jitters at about 35%. Pulled the diagnostics and there the high maxOverdue value was:
2021-05-29 14:49:05 [debug] Moves scheduled 78776, completed 78773, in progress 1, hiccups 0, step errors 0, maxPrep 53, maxOverdue 11483, maxInc 7925, mcErrs 0, gcmErrs 0 Peak sync jitter 13, peak Rx sync delay 182, resyncs 0, next step interrupt due in 547 ticks, enabled
It then stayed at 0 throughout the print so I assume that some moves are worse than others?
Here are the complete logs while printing the file: event_rc1.txt
The print turned out fine without layer shifts.
-
Update: Printing the same file in 3.3b2 gave almost no errors:
2021-05-30 10:51:33 [debug] Moves scheduled 210365, completed 210365, in progress 0, hiccups 0, step errors 0, maxPrep 231, maxOverdue 4, maxInc 1, mcErrs 0, gcmErrs 0 Peak sync jitter 11, peak Rx sync delay 215, resyncs 10, no step interrupt scheduled
Here is the complete eventlog troughout the print: event_b2.txt
-
Update: Running at 400% speed factor from layer 2 on 3.3b2 with this file: https://we.tl/t-37EugjkZzi worked well, same 4 maxOverdue:
2021-05-30 11:55:59 [debug] Moves scheduled 420730, completed 420730, in progress 0, hiccups 0, step errors 0, maxPrep 253, maxOverdue 4, maxInc 1, mcErrs 0, gcmErrs 0 Peak sync jitter 10, peak Rx sync delay 207, resyncs 8, no step interrupt scheduled
Here are the full logs: event_b2x400.txt
-
Update: Something changed between Beta2 and Beta3 that got much worse in RC3.
I can run the fast x400 file https://we.tl/t-37EugjkZz without problems in Beta2 but later builds give me stuttering steppers and high maxOverdue counter, if that matters at all.
Beta3:
Event log for the standard file: event_b3.txt
Event log for the x400 file: event_b3x400.txt
I tried changing the Grace period for the movement queue length from 10 to 0, as in Beta 2 but nothing changed as seen in this event_b3x400_GP0.txt logs.All logs include a M122 for each card after homing and after successful or paused print.
-
@o_lampe said in [3.3RC3] Missed stepps or overdue moves:
@typqxq said in [3.3-rc3] Missed stepps:
M584 X0.0:1.0 Y0.1:1.1
I don't know if it's helpful, but I'd put both X-motors on one controller and both Y-motor on the other.
I can confirm that this actually works much better and is usable now that the EndStop fixes are in place.
-
@typqxq
It's good to hear, but also put's the whole idea of toolboards in question. They were designed to reduce wiring, but practice tells a different story (for now). -
@typqxq said in [3.3RC3] Missed stepps or overdue moves:
Last reset 00:07:24 ago, cause: software 2021-05-29 12:03:19 [debug] Last software reset time unknown, reason: AssertionFailed, available RAM 159320, slot 1
I am more concerned by that line. Please try installing the firmware binaries from https://www.dropbox.com/sh/nmpsl9a3jfsumm5/AAA6adSjEcd1AM_j5_tVberGa?dl=0 and try again.
-
@dc42 I haven't experienced any issues with the board reseting.
I use 3 ways of reseting the board:- Emergency Stop button in Web interface.
- Emergency Stop button on mains power.
- Emergency reset button and endstops mapped to Trigger file:
M25 M122 B0 M122 B1 M112
-
@typqxq those lines in the M122 B1 report indicate that the expansion board reset at some point. We need to establish whether that happened during the print, or a long time ago. If it did occur during the print, that would account for the maxOverdue value being so high.
Please do the following:
- Upgrade the main board and expansion board firmwares to the versions at https://www.dropbox.com/sh/nmpsl9a3jfsumm5/AAA6adSjEcd1AM_j5_tVberGa?dl=0. Ignore the .map files.
- Send M122 B1 P1004.
- Run M122 B1 and check that the M122 report shows the software reset reason as "deliberate HardFault zeroDiv".
- Reset the main board.
- Try a print.
-
@dc42 Made the above steps and I can't see any change. Here is the new logs event_rc3+1.txt . It's too long for the post limit.
-
@typqxq thanks, I will try to replicate your setup today.
-
@typqxq said in [3.3RC3] Missed stepps or overdue moves:
Here is a link to the configuration and a test gcode file https://we.tl/t-DQueVGrH61
Unfortunately that .link has expired. Please provide a new link to your files.
-
@dc42 Here is a new link: https://www.dropbox.com/sh/yfjwidhzvlxk8k2/AAAQd95XneD8zUVNV8VnNO3ya?dl=0
-
@typqxq thanks.
I have spotted an error in your configuration, in file custom/tool_1.g:
; Create Heater M308 S2 P"2.temp1" Y"thermistor" T100000 B4725 C0.0000000706 A"T1 Heater" ; configure sensor 2 as thermistor on pin temp1 M950 H2 C"2.out1" T2 ; create nozzle heater output on out1 and map it to sensor 2 M143 H2 S300 ; set temperature limit for heater 1 to 300C (e3d v6 all metal) M307 H2 B0 S1.00 ; disable bang-bang mode for heater and set PWM limit ; Create Part Fan M950 F3 C"2.out4" ; Define Part Cooling fan on out4 (4pin) M106 P3 C"Part Cooling T1" ; Setup Part Cooling Fan as Part Cooling T1 ; Create Hotend Fan M950 F4 C"1.out7" ; Define Hotend Fan on out7 (2pin) M106 P4 S255 T45 H2 ; Setup Hotend Fan for thermal control, full on when H2 reaches 45C
You create the sensor and heater on board 2, but the fan on board 1. RRF has the following documented limitation:
A thermostatically-controlled fan on an expansion board can only be controlled by a temperature sensor on the same expansion board.
Did you perhaps mean to use port 2.out7 for the fan?
I don't know whether this is relevant to the problem of maxOverdue being much too large and the associated print issues. I will change the config to use port 2.out7 and try running your print.
-
@typqxq I have reproduced the problem on my bench system so I am now able to investigate it.
For future reference, it would be easier for me to use your configuration files if instead of using M98 P"/sys/custom/xxx" in many places, you used M98 P"custom/xxx". This is because I have your configuration in a subfolder of /sys.
-
@dc42 Thank you, I found and fixed it last week. It had no effect from what I can see.
This are the configuration files as of when I reported the problem. -
@typqxq please try the new firmware binaries at https://www.dropbox.com/sh/xfsvscbaab0dtzl/AACCcSeiTNINZL-xbs6IhC4Ja?dl=0. Ignore the .map files.
-
@TypQxQ have you had a chance to try the new firmware? We're waiting to release 3.3 stable but I would like to know whether this issue is resolved first.