[3.2-beta-3.2] Strange pauses during print

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.

BoA

This post is deleted!

BoA

@Phaedrux I just tested this particular print with 3.2beta4, and there ar even more pauses and for longer time, than with 3.2beta3.2

After each pause I gou a hiccups counter from 0 to around 30000. Between pauses hiccups counter is 0 all the time.

As I can not see anything from @dc42 I am guessing he just missed that.

dc42

@BoA, please post the file you are printing and your config.g file.

This may be related to https://forum.duet3d.com/post/195269.

BoA

@dc42 I posted before, but:
config.g
gravitrax_dual_support_0.2mm_PETG_52m.gcode

dc42

Thanks. I confirmed and fixed this issue. I have put new RRF 3.2beta4+3 binaries at https://www.dropbox.com/sh/tehhdvunh0pgr7q/AADgJ4Qj7W18MYaRRNNDdhpwa?dl=0.

BoA

@dc42 Confirmed: No more pauses during print. Zero hiccups, and some 3 underruns?

=== MainDDARing ===
hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 3]

Anyway - prints with no issues now.

dc42

Thanks for confirming. I will mark this as solved.