[3.2-beta-3.2] Strange pauses during print

BoA

Duet3 standalone. I am experiencing strange pauses during print. Also they are random, as printing same file has pause in different places each time. Also pause duration is not constant.

https://drive.google.com/file/d/19WUGwQewotbk_SURjygI4EKqiXi7COx4/view?usp=sharing (pause at 0:55)

Pauses for a short moment, and then continues without any action required.
M122 after pause:

M122
=== Diagnostics ===
RepRapFirmware for Duet 3 MB6HC version 3.2-beta3.2 running on Duet 3 MB6HC v1.01 or later (standalone mode)
Board ID: 08DJM-956L2-G43S8-6J1D6-3SJ6R-KA0YG
Used output buffers: 10 of 40 (31 max)
=== RTOS ===
Static ram: 122236
Dynamic ram: 170404 of which 60 recycled
Never used RAM 99492, free system stack 116 words
Tasks: NETWORK(ready,155) ETHERNET(blocked,106) HEAT(blocked,271) CanReceiv(blocked,948) CanSender(blocked,344) CanClock(blocked,349) TMC(blocked,18) MAIN(running,675) IDLE(ready,19)
Owned mutexes:
=== Platform ===
Last reset 00:28:52 ago, cause: software
Last software reset at 2020-11-17 17:49, reason: User, GCodes spinning, available RAM 99492, slot 0
Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x0044a000 BFAR 0x00000000 SP 0xffffffff Task MAIN
Error status: 0x00
MCU temperature: min 38.8, current 39.0, max 39.3
Supply voltage: min 24.6, current 24.8, max 24.9, under voltage events: 0, over voltage events: 0, power good: yes
12V rail voltage: min 12.1, current 12.2, max 12.3, under voltage events: 0
Driver 0: position 27870, standstill, reads 21523, writes 0 timeouts 0, SG min/max 0/1023
Driver 1: position 19411, ok, reads 21523, writes 0 timeouts 0, SG min/max 0/951
Driver 2: position 2030, ok, reads 21523, writes 0 timeouts 0, SG min/max 0/1023
Driver 3: position 0, standstill, reads 21523, writes 0 timeouts 0, SG min/max 0/125
Driver 4: position 0, standstill, reads 21523, writes 0 timeouts 0, SG min/max 0/119
Driver 5: position 0, standstill, reads 21524, writes 0 timeouts 0, SG min/max not available
Date/time: 2020-11-17 18:17:57
Slowest loop: 329.89ms; fastest: 0.15ms
=== Storage ===
Free file entries: 9
SD card 0 detected, interface speed: 25.0MBytes/sec
SD card longest read time 4.3ms, write time 0.0ms, max retries 0
=== Move ===
Hiccups: 32307(0), FreeDm: 372, MinFreeDm: 324, MaxWait: 0ms
Bed compensation in use: mesh, comp offset 0.000
=== MainDDARing ===
Scheduled moves 28431, completed moves 28382, StepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state 3
=== AuxDDARing ===
Scheduled moves 0, completed moves 0, StepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== Heat ===
Bed heaters = 0 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1 -1, chamberHeaters = 3 -1 -1 -1
Heater 0 is on, I-accum = 0.6
Heater 1 is on, I-accum = 0.5
=== GCodes ===
Segments left: 1
Movement lock held by null
HTTP is idle in state(s) 0
Telnet is idle in state(s) 0
File is doing "G1 X110.083 Y95.674 E0.00883" in state(s) 0
USB is assembling a command in state(s) 0
Aux is idle in state(s) 0
Trigger is idle in state(s) 0
Queue is idle in state(s) 0
LCD is idle in state(s) 0
SBC is idle in state(s) 0
Daemon is idle in state(s) 0
Aux2 is idle in state(s) 0
Autopause is idle in state(s) 0
Code queue is empty.
=== Network ===
Slowest loop: 350.03ms; fastest: 0.03ms
Responder states: HTTP(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0), 0 sessions Telnet(0), 0 sessions
HTTP sessions: 1 of 8
- Ethernet -
State: active
Error counts: 0 0 0 0 0
Socket states: 5 2 2 2 2 2 0 0
=== Filament sensors ===
Extruder 0: pos 315.00, errs: frame 0 parity 0 ovrun 0 pol 0 ovdue 0
Extruder 1: pos 0.00, errs: frame 0 parity 0 ovrun 0 pol 0 ovdue 0
=== CAN ===
Messages sent 645, send timeouts 645, longest wait 0ms for type 0, free CAN buffers 47

Phaedrux

@BoA said in [3.2-beta-3.2] Strange pauses during print:

Hiccups: 32307(0),

That's a lot of hiccups. Post your config.g

BoA

My config: config.g

Phaedrux

Thanks.

M350 X16 Y16 Z16 E16:16 I1                               ; configure microstepping with interpolation
M92 X200.00 Y200.00 Z400.00 E830.00:830.00               ; set steps per mm

I had expected to see a high microstepping value, but that doesn't seem to be the case, unless it's being changed elsewhere? Perhaps in M98 P"dynamics_normal.g"? I assume your other speed settings are in there?

How fast are you printing in that video? Curious to work out the step rate.

BoA

@Phaedrux in dynamics_normal.g I have setting for speed/acceleration:

M913 X100 Y100 Z100 E100                        ; set XY motors current to 100%
M566 X1200.00 Y1200.00 Z12.00                   ; set maximum instantaneous speed changes (mm/min)
M203 X18000.00 Y18000.00 Z1800.00               ; set maximum speeds (mm/min)
M201 X3500.00 Y3500.00 Z120.00                  ; set accelerations (mm/s^2)
M593 F36.5

Actual speed is limited there by acceleration below 100mm/s-ish. But I printed much faster that this one without any problems

Also I did not have this pauses with the same config on RRF 3.1.1

And... printed part does not look particularly bad as I would expect in case of some steps skipping etc.

Phaedrux

Reason I ask about print speed is because if we have the requested max speed we could work out the step rate based on your steps per mm.

BoA

@Phaedrux Max speed I use, is 300mm/s for idle moves, and I have never had any problems with this. 200steps/mm @ 300mm/s (as configured), should result with around 60k steps/s. Nothing very fast. Not sure what this counter actually counts as hiccups.

Phaedrux

@BoA said in [3.2-beta-3.2] Strange pauses during print:

Not sure what this counter actually counts as hiccups.

Usually when it can't sustain the step rate. It inserts a brief pause to allow catch up. 32000 isn't extreme, but it would be noticeable as you saw.

Can you give this a try?

https://forum.duet3d.com/topic/16291/reprapfirmware-3-2-planned-improvements/57?_=1605641146748

Work out a long move that you can use on your machine to test the step rate. It needs to be long enough that most of the move will be at the requested speed, not doing acceleration or deceleration
Select x256 microstepping
Send M122 to clear the hiccup count
Execute that move
Send M122 to read the hiccup count
Repeat the last 3 steps at different speeds, to find the speed at which the hiccup count increases dramatically. For a 300mm move at x256 microstepping, I reckon that 50 to 100 hiccups is acceptable, more is not.
Use the steps/mm and the speed you measured to work out the step pulse rate.

Would be interesting to see the results in 3.2 compared to 3.1.1

BoA

@Phaedrux I changed speed limits to 24000mm/min in config and created a simple gcode for a test:

G90 ; use absolute coordinates
M83 ; extruder relative mode
T0
G28 ; home all without mesh bed level
G32 ; gantry leveling
M404 N1.75 D0.4
T0
G92 E0.0
G1 X0.0 Y100.0 Z20.0 F12000.0
G1 F24000.0
G1 X0.0
G1 X250.0
G1 X0.0
G1 X250.0
G1 X0.0
G1 X250.0
G1 X0.0
G1 X250.0
G1 X0.0
G1 X250.0
G1 X0.0
T-1

after executing it few times M122 gives hiccups counter 0

Phaedrux

Did you see the test procedure in my last post for inducing hiccups?

BoA

@Phaedrux OK, so with 256 microstepping, 3200steps/mm I reached 65mm/s with 0 hiccups. Which is 208k steps/s

With 66.6mm/s I had 2 hiccups (at over 210k steps/s).

Far higher than required during printing.

Phaedrux

With a single axis active anyway. Will be interesting to see what @DC42 thinks.

BoA

@Phaedrux Same results with XY active - moving head diagonally 0,0 to 200,200 and back to 0,0

at 4000mm/min 0 hiccups

And for completness: gcode file I am printing: gravitrax_dual_0.2mm_PETG_MK3S_52m.gcode

BoA

There is something in this gcode that makes rrf3 struggle to process. I am printing similar hexagonal elements filling the whole bed at ~100mm/s, 300mm/s idle moves and... 0 pauses, 0 hiccups counted. Same slicer, same slicer settings.

Phaedrux

@BoA said in [3.2-beta-3.2] Strange pauses during print:

M566 X1200.00 Y1200.00 Z12.00

Can you try increasing your Z jerk to 60 and reprinting the gcode that was pausing before?

There is an interaction between mesh compensation and low z jerk that can cause pauses in XY movement to allow the slower z axis time to adjust since it's part of the coordinated move. this can be exacerbated by high print speeds.

https://duet3d.dozuki.com/Wiki/Using_mesh_bed_compensation#Section_Troubleshooting

BoA

@Phaedrux Just started. But... I do not think this is it. Bed compensation works on all prints same way, as it compensates for the same bed. Also I just printed a square element 140x140mm at 180mm/s + 300mm/s idle without any issues.

Neverthless I just changes Z jerk to 60 and started print that causes pauses... Will let You know in an hour

BoA

@Phaedrux As expected, that did not help. A executed M122 during print, and just after the single pause hiccups counter went from 0 to over 16000.

https://drive.google.com/file/d/19Zhcq5f3gCc43F2qHmSnbkO4UZDmZIAL/view?usp=sharing

Pause at 0:52

And more pauses following, but not recorded.
Before this pause, 0 hiccups:

=== Platform ===
Last reset 03:09:09 ago, cause: software
Last software reset at 2020-11-18 17:42, reason: User, GCodes spinning, available RAM 99700, slot 0
Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x0044a000 BFAR 0x00000000 SP 0xffffffff Task MAIN
Error status: 0x04
MCU temperature: min 38.2, current 38.3, max 38.5
Supply voltage: min 24.6, current 24.7, max 24.9, under voltage events: 0, over voltage events: 0, power good: yes
12V rail voltage: min 12.1, current 12.2, max 12.3, under voltage events: 0
Driver 0: position 16847, ok, reads 21772, writes 0 timeouts 0, SG min/max 0/1023
Driver 1: position 17242, ok, reads 21771, writes 0 timeouts 0, SG min/max 0/423
Driver 2: position 2596, ok, reads 21771, writes 0 timeouts 0, SG min/max 0/225
Driver 3: position 0, ok, reads 21771, writes 0 timeouts 0, SG min/max 0/386
Driver 4: position 0, ok, reads 21772, writes 0 timeouts 0, SG min/max 0/320
Driver 5: position 0, standstill, reads 21772, writes 0 timeouts 0, SG min/max not available
Date/time: 2020-11-18 20:51:44
Slowest loop: 8.57ms; fastest: 0.14ms

After over 16000 hiccups counted and:

=== Platform ===
Last reset 00:28:52 ago, cause: software
Last software reset at 2020-11-17 17:49, reason: User, GCodes spinning, available RAM 99492, slot 0
Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x0044a000 BFAR 0x00000000 SP 0xffffffff Task MAIN
Error status: 0x00
MCU temperature: min 38.8, current 39.0, max 39.3
Supply voltage: min 24.6, current 24.8, max 24.9, under voltage events: 0, over voltage events: 0, power good: yes
12V rail voltage: min 12.1, current 12.2, max 12.3, under voltage events: 0
Driver 0: position 27870, standstill, reads 21523, writes 0 timeouts 0, SG min/max 0/1023
Driver 1: position 19411, ok, reads 21523, writes 0 timeouts 0, SG min/max 0/951
Driver 2: position 2030, ok, reads 21523, writes 0 timeouts 0, SG min/max 0/1023
Driver 3: position 0, standstill, reads 21523, writes 0 timeouts 0, SG min/max 0/125
Driver 4: position 0, standstill, reads 21523, writes 0 timeouts 0, SG min/max 0/119
Driver 5: position 0, standstill, reads 21524, writes 0 timeouts 0, SG min/max not available
Date/time: 2020-11-17 18:17:57
Slowest loop: 329.89ms; fastest: 0.15ms

Take a look on Slowest loop time. Seems to be much higher after this strange pause.

Phaedrux

Thanks for testing. Definitely an exaggerated pause there.

Phaedrux

Each time you run M122 it clears the hiccup counter.

BoA

@Phaedrux I am aware of that. Just in the middle of print, each m122 reported 0 hiccups, and just after pause over 16000, after another pause (longer one) almost 50000. And other thing is this platform slowest loop significantly higher than normally.