[3.3RC3] Missed stepps or overdue moves

[TypQxQ]

I use a 6HC+EXP3HC+EXP3HC in standalone (for accelerator support).
Using CoreXY with dual X and dual Y:

M584 X0.0:1.0 Y0.1:1.1 Z0.4:0.3:0.5 E2.0:2.1:2.2 U0.2

When printing and the speeds go up over 40-50mm/s the steppers stall.
I went back to RC1 and could print at 240mm/s without visible problems. Will soon try again.
Went back to RC2 and RC2+3 and I did get stalls but after several layers of printing at max speed.

021-05-29 12:03:16 [debug] === Diagnostics ===
2021-05-29 12:03:16 [debug] RepRapFirmware for Duet 3 MB6HC version 3.3RC3 (2021-05-26 12:29:42) running on Duet 3 MB6HC v0.6 or 1.0 (standalone mode)
2021-05-29 12:03:16 [debug] Board ID: 08DJM-956L2-G43S4-6JKDD-3SJ6L-TB62G
2021-05-29 12:03:16 [debug] Used output buffers: 1 of 40 (40 max)
2021-05-29 12:03:16 [debug] === RTOS ===
2021-05-29 12:03:16 [debug] Static ram: 150784
2021-05-29 12:03:16 [debug] Dynamic ram: 94984 of which 0 recycled
2021-05-29 12:03:16 [debug] Never used RAM 105568, free system stack 124 words
2021-05-29 12:03:16 [debug] Tasks:
2021-05-29 12:03:16 [debug]  NETWORK(ready,27.2%,224)
2021-05-29 12:03:16 [debug]  ETHERNET(notifyWait,0.4%,117)
2021-05-29 12:03:16 [debug]  HEAT(delaying,0.0%,295)
2021-05-29 12:03:16 [debug]  Move(notifyWait,0.2%,262)
2021-05-29 12:03:16 [debug]  CanReceiv(notifyWait,0.0%,773)
2021-05-29 12:03:16 [debug]  CanSender(notifyWait,0.0%,360)
2021-05-29 12:03:16 [debug]  CanClock(delaying,0.0%,339)
2021-05-29 12:03:16 [debug]  TMC(notifyWait,9.1%,59)
2021-05-29 12:03:16 [debug]  MAIN(running,63.0%,858)
2021-05-29 12:03:16 [debug]  IDLE(ready,0.0%,29)
2021-05-29 12:03:16 [debug] , total 100.0%
Owned mutexes:
2021-05-29 12:03:16 [debug]  HTTP(MAIN)
2021-05-29 12:03:16 [debug] === Platform ===
2021-05-29 12:03:16 [debug] Last reset 00:07:20 ago, cause: software
2021-05-29 12:03:16 [debug] Last software reset at 2021-05-29 11:55, reason: User, GCodes spinning, available RAM 108816, slot 1
2021-05-29 12:03:16 [debug] Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x0044a000 BFAR 0x00000000 SP 0x00000000 Task MAIN Freestk 0 n/a
2021-05-29 12:03:16 [debug] Error status: 0x04
2021-05-29 12:03:16 [debug] Aux0 errors 0,0,0
2021-05-29 12:03:16 [debug] Aux1 errors 0,0,0
2021-05-29 12:03:16 [debug] Step timer max interval 131
2021-05-29 12:03:16 [debug] MCU temperature: min 40.0, current 40.7, max 40.8
2021-05-29 12:03:16 [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 12:03:16 [debug] 12V rail voltage: min 12.0, current 12.0, max 12.1, under voltage events: 0
2021-05-29 12:03:16 [debug] Heap OK, handles allocated/used 99/0, heap memory allocated/used/recyclable 2048/140/140, gc cycles 0
2021-05-29 12:03:16 [debug] Driver 0: position 147222, standstill, reads 52856, writes 0 timeouts 0, SG min/max 0/873
2021-05-29 12:03:16 [debug] Driver 1: position -2545, standstill, reads 52856, writes 0 timeouts 0, SG min/max 0/1023
2021-05-29 12:03:16 [debug] Driver 2: position 19104, standstill, reads 52852, writes 4 timeouts 0, SG min/max 0/131
2021-05-29 12:03:16 [debug] Driver 3: position 288, standstill, reads 52857, writes 0 timeouts 0, SG min/max 0/813
2021-05-29 12:03:16 [debug] Driver 4: position 0, standstill, reads 52856, writes 0 timeouts 0, SG min/max 0/158
2021-05-29 12:03:16 [debug] Driver 5: position 0, standstill, reads 52856, writes 0 timeouts 0, SG min/max 0/100
2021-05-29 12:03:16 [debug] Date/time: 
2021-05-29 12:03:16 [debug] 2021-05-29 12:03:16
2021-05-29 12:03:16 [debug] Slowest loop: 56.01ms; fastest: 0.03ms
2021-05-29 12:03:16 [debug] === Storage ===
Free file entries: 8
2021-05-29 12:03:16 [debug] SD card 0 detected, interface speed: 25.0MBytes/sec
2021-05-29 12:03:16 [debug] SD card longest read time 3.6ms, write time 37.2ms, max retries 0
2021-05-29 12:03:16 [debug] === Move ===
DMs created 125, maxWait 11555ms, bed compensation in use: none, comp offset 0.000
2021-05-29 12:03:16 [debug] === MainDDARing ===
Scheduled moves 846, completed moves 846, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
2021-05-29 12:03:16 [debug] === AuxDDARing ===
Scheduled moves 0, completed moves 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
2021-05-29 12:03:16 [debug] === Heat ===
Bed heaters =
2021-05-29 12:03:16 [debug]  0
2021-05-29 12:03:16 [debug]  -1
2021-05-29 12:03:16 [debug]  -1
2021-05-29 12:03:16 [debug]  -1
2021-05-29 12:03:16 [debug]  -1
2021-05-29 12:03:16 [debug]  -1
2021-05-29 12:03:16 [debug]  -1
2021-05-29 12:03:16 [debug]  -1
2021-05-29 12:03:16 [debug]  -1
2021-05-29 12:03:16 [debug]  -1
2021-05-29 12:03:16 [debug]  -1
2021-05-29 12:03:16 [debug]  -1
2021-05-29 12:03:16 [debug] , chamberHeaters =
2021-05-29 12:03:16 [debug]  -1
2021-05-29 12:03:16 [debug]  -1
2021-05-29 12:03:16 [debug]  -1
2021-05-29 12:03:16 [debug]  -1
2021-05-29 12:03:16 [debug] Heater 0 is on, I-accum = 0.2
2021-05-29 12:03:16 [debug] Heater 1 is on, I-accum = 0.0
2021-05-29 12:03:16 [debug] === GCodes ===
2021-05-29 12:03:16 [debug] Segments left: 0
2021-05-29 12:03:16 [debug] Movement lock held by null
2021-05-29 12:03:16 [debug] HTTP is ready with "m122 b0" in state(s) 0
2021-05-29 12:03:16 [debug] Telnet is idle in state(s) 0
2021-05-29 12:03:16 [debug] File is idle in state(s) 0
2021-05-29 12:03:16 [debug] USB is idle in state(s) 0
2021-05-29 12:03:16 [debug] Aux is idle in state(s) 0
2021-05-29 12:03:16 [debug] Trigger is idle in state(s) 0
2021-05-29 12:03:16 [debug] Queue is idle in state(s) 0
2021-05-29 12:03:16 [debug] LCD is idle in state(s) 0
2021-05-29 12:03:16 [debug] SBC is idle in state(s) 0
2021-05-29 12:03:16 [debug] Daemon is idle in state(s) 0
2021-05-29 12:03:16 [debug] Aux2 is idle in state(s) 0
2021-05-29 12:03:16 [debug] Autopause is idle in state(s) 0
2021-05-29 12:03:16 [debug] Code queue is empty.
2021-05-29 12:03:16 [debug] === CAN ===
Messages queued 2342, send timeouts 0, received 1570, lost 0, longest wait 3ms for reply type 6024, peak Tx sync delay 108, free buffers 49 (min 18), ts 465/465/0
2021-05-29 12:03:16 [debug] === Network ===
2021-05-29 12:03:16 [debug] Slowest loop: 19.57ms; fastest: 0.02ms
2021-05-29 12:03:16 [debug] Responder states:
2021-05-29 12:03:16 [debug]  HTTP(0)
2021-05-29 12:03:16 [debug]  HTTP(0)
2021-05-29 12:03:16 [debug]  HTTP(0)
2021-05-29 12:03:16 [debug]  HTTP(0)
2021-05-29 12:03:16 [debug]  HTTP(0)
2021-05-29 12:03:16 [debug]  HTTP(0)
2021-05-29 12:03:16 [debug]  FTP(0)
2021-05-29 12:03:16 [debug]  Telnet(0), 0 sessions
2021-05-29 12:03:16 [debug]  Telnet(0), 0 sessions
2021-05-29 12:03:16 [debug] HTTP sessions: 3 of 8
2021-05-29 12:03:16 [debug] - Ethernet -
State: active
2021-05-29 12:03:16 [debug] Error counts: 0 0 1 0 0
Socket states:
2021-05-29 12:03:16 [debug]  5
2021-05-29 12:03:16 [debug]  2
2021-05-29 12:03:16 [debug]  2
2021-05-29 12:03:16 [debug]  2
2021-05-29 12:03:16 [debug]  2
2021-05-29 12:03:16 [debug]  0
2021-05-29 12:03:16 [debug]  0
2021-05-29 12:03:16 [debug]  0
2021-05-29 12:03:19 [debug] Diagnostics for board 1:
2021-05-29 12:03:19 [debug] Duet EXP3HC firmware version 3.3RC3 (2021-05-26 13:46:00)
Bootloader ID: SAME5x bootloader version 2.2 (2021-01-16b1)
2021-05-29 12:03:19 [debug] Never used RAM 158920, free system stack 4371 words
Tasks: Move(notifyWait<null>,0.1%,100) HEAT(delaying<null>,0.0%,99) CanAsync(notifyWait<null>,0.0%,65) CanRecv(notifyWait<null>,0.0%,79) CanClock(notifyWait<null>,0.0%,74) TMC(notifyWait<null>,24.0%,63) MAIN(running<null>,74.4%,375) IDLE(ready<null>,0.0%,40) AIN(delaying<null>,1.5%,263), total 100.0%
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
Software reset code 0x0120 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00000000 BFAR 0xe000ed38 SP 0x20004754 Task HEAT Freestk 142 bad marker
2021-05-29 12:03:19 [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 12:03:19 [debug] Driver 0: position -269098, 320.0 steps/mm,  standstill, reads 14702, writes 0 timeouts 0, SG min/max 0/1023, steps req 876746 done 876746
Driver 1: position -3505, 320.0 steps/mm,  standstill, reads 14702, writes 0 timeouts 0, SG min/max 0/279, steps req 851953 done 851953
Driver 2: position 0, 80.0 steps/mm,  standstill, reads 14701, writes 0 timeouts 0, SG min/max not available, steps req 0 done 0
2021-05-29 12:03:19 [debug] Moves scheduled 799, completed 799, in progress 0, hiccups 0, step errors 0, maxPrep 79, maxOverdue 45579, maxInc 44749, mcErrs 0, gcmErrs 0
Peak sync jitter -2/10, peak Rx sync delay 242, resyncs 0/0, no step interrupt scheduled
VIN: 32.1V, V12: 12.1V
MCU temperature: min 36.2C, current 37.8C, max 37.8C
Ticks since heat task active 158, ADC conversions started 444944, completed 444944, timed out 0, errs 0
2021-05-29 12:03:19 [debug] Last sensors broadcast 0x00000000 found 0 163 ticks ago, loop time 0
CAN messages queued 426, send timeouts 0, received 2027, lost 0, free buffers 37, min 37, error reg 0
dup 0, oos 0/0/0/0, bm 0, wbm 0
2021-05-29 12:03:22 [debug] Diagnostics for board 2:
2021-05-29 12:03:22 [debug] Duet EXP3HC firmware version 3.3RC3 (2021-05-26 13:46:00)
Bootloader ID: not available
2021-05-29 12:03:22 [debug] Never used RAM 157968, free system stack 4375 words
Tasks: Move(notifyWait<null>,0.0%,92) HEAT(delaying<null>,0.0%,107) CanAsync(notifyWait<null>,0.0%,69) CanRecv(notifyWait<null>,0.0%,79) CanClock(notifyWait<null>,0.0%,74) TMC(notifyWait<null>,23.4%,29) MAIN(running<null>,75.1%,303) IDLE(ready<null>,0.0%,40) AIN(delaying<null>,1.4%,263), total 100.0%
Last reset 00:07:27 ago, cause: software
2021-05-29 12:03:22 [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 12:03:22 [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 12:03:22 [debug] Driver 0: position 54647, 830.0 steps/mm,  standstill, reads 4780, writes 1 timeouts 0, SG min/max 0/1001, steps req 58155 done 58155
Driver 1: position 0, 830.0 steps/mm,  standstill, reads 4782, writes 0 timeouts 0, SG min/max not available, steps req 0 done 0
Driver 2: position 0, 830.0 steps/mm,  standstill, reads 4781, writes 0 timeouts 0, SG min/max not available, steps req 0 done 0
2021-05-29 12:03:22 [debug] Moves scheduled 723, completed 723, in progress 0, hiccups 0, step errors 0, maxPrep 49, maxOverdue 45180, maxInc 44672, mcErrs 0, gcmErrs 0
Peak sync jitter 0/11, peak Rx sync delay 179, resyncs 0/0, no step interrupt scheduled
VIN: 24.2V, V12: 12.2V
MCU temperature: min 37.7C, current 38.3C, max 38.3C
Ticks since heat task active 16, ADC conversions started 447798, completed 447798, timed out 0, errs 0
2021-05-29 12:03:22 [debug] Last sensors broadcast 0x0000000e found 3 22 ticks ago, loop time 0
CAN messages queued 1237, send timeouts 0, received 1631, lost 0, free buffers 37, min 37, error reg 0
dup 0, oos 0/0/0/0, bm 0, wbm 0

Could this line be the most important?

2021-05-29 12:03:19 [debug] Moves scheduled 799, completed 799, in progress 0, hiccups 0, step errors 0, maxPrep 79, maxOverdue 45579, maxInc 44749, mcErrs 0, gcmErrs 0
Peak sync jitter -2/10, peak Rx sync delay 242, resyncs 0/0, no step interrupt scheduled

Here is a link to the configuration and a test gcode file https://we.tl/t-DQueVGrH61

[o_lampe]

@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.

[TypQxQ]

@o_lampe That would make the stepper cables over 1m long... My printer is 500x500x600 and it worked fine in RC1.
This, as far as I know would greatly increase the EMI.

[o_lampe]

@typqxq
Right, that's like Pest or Cholera
I read about CAN issues and 3HC-controllers not being updated.
Can you confirm your boards are running on the same FW?

[TypQxQ]

@o_lampe said in [3.3-rc3] Missed stepps:

@typqxq
Right, that's like Pest or Cholera

I 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.

[TypQxQ]

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
 

[TypQxQ]

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.

[TypQxQ]

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

[TypQxQ]

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

[TypQxQ]

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.

[TypQxQ]

@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.

[o_lampe]

@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).

[dc42]

@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.

[TypQxQ]

@dc42 I haven't experienced any issues with the board reseting.
I use 3 ways of reseting the board:

1. Emergency Stop button in Web interface.
2. Emergency Stop button on mains power.
3. Emergency reset button and endstops mapped to Trigger file:

M25
M122 B0
M122 B1
M112

[dc42]

@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:

1. 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.
2. Send M122 B1 P1004.
3. Run M122 B1 and check that the M122 report shows the software reset reason as "deliberate HardFault zeroDiv".
4. Reset the main board.
5. Try a print.

[TypQxQ]

@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.

[dc42]

@typqxq thanks, I will try to replicate your setup today.

[dc42]

@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.

[TypQxQ]

@dc42 Here is a new link: https://www.dropbox.com/sh/yfjwidhzvlxk8k2/AAAQd95XneD8zUVNV8VnNO3ya?dl=0

[dc42]

@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.