[3.2-beta-3.2] Strange pauses during print



  • 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
    

  • Moderator

    @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



  • My config: config.g


  • Moderator

    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.



  • @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.
    e13bbbb5-8fbe-4de3-adbf-21546c4d4a06-obraz.png


  • Moderator

    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.



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


  • Moderator

    @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



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


  • Moderator

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



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


  • Moderator

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



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



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

    20201118_113730.jpg


  • Moderator

    @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



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



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


  • Moderator

    Thanks for testing. Definitely an exaggerated pause there.


  • Moderator

    Each time you run M122 it clears the hiccup counter.



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



  • This post is deleted!


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


  • administrators

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

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




  • administrators

    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.


Log in to reply