print slows down mid print

TimTom

Hi,

I'm runnin 3.4.0-B7 on a Duet3 Mini within a Voron 2.4.
Yesterday evening I starteted a print (Slicer estimated ~3,5 hours), this morning the printer was showing some erratic movement (but still somehow printing) and telling me that the print still needs "5-6 hours being 75% in the print".

As some filament built up on the nozzle, I paused the print and when I continued it, the print speed was normal again, just to return to the weired behavior after some seconds.

It seems reproducible as I restartet the print yesterday evening and on the second print the same thing happens. I can also provide the G-code if necessary (25 MB).

Edit: Other Prints work fine so far - MCU Temperature is ~39°C calibrated.

I recorded it and uploaded it to youtube.
https://youtu.be/J5aKBldvis0

Used SuperSlicer 2.3.57 with Voron default profile.

Config.g:

; Configuration file for Duet 3 (firmware version 3)
; executed by the firmware on start-up
;
; General preferences
G21                     							; Work in millimetres
G90                                            	    ; send absolute coordinates...
M83                                                 ; ...but relative extruder moves
M550 P"Voron"                                   	; set printer name
M669 K1                                            	; select CoreXY mode

; Network
M552 S1                                   	; enable network and acquire dynamic address via DHCP
M586 P0 S1                                          ; enable HTTP
M586 P1 S1                                         	; enable FTP
M586 P2 T1 S1                                      	; disable Telnet


;===========================================================================================================
; Drive Configuration
; 0 = B, 1 = A, 2,3,4,5 = Z, 6 = Extruder

; Drives for XY 
M569 P0 S2                                       	; A motor = X in Reprap/Duet
M569 P1 S2                                       	; B motor = Y in Reprap/Duet

; Drives for Z - as the Z-drives are opposing, two of them therefore need to inverted (go backward) 
; - Carefull with this, you need to test/configure with baby steps if config is correct)
M569 P2 S1                                       	; Front left Z0 - S1 = go backward
M569 P3 S0                                       	; Back left Z1 - S0 = go forward
M569 P4 S1                                       	; Back right Z2 - S1 = go backward
M569 P5 S0                                       	; Front right Z3 - S0 = go forward
; Drive for extruder 
M569 P6 S0                                       	; physical drive 1.0 goes forwards

; Drive mappings (assign previously configured drive to axis mapping
M584 X0 Y1 Z2:3:4:5 E6               	; set drive mapping 

;===========================================================================================================
; General drive config like speeds, accel, jerk, etc

M350 X16 Y16 Z16 E16 I1                                                 ; configure microstepping with interpolation
M92 X160.00 Y160.00 Z400.00 E429.00              	; set steps per mm (how many steps are required for 1 mm)
;M566 X900.00 Y900.00 Z900.00 E120              		; set maximum instantaneous speed changes (mm/min)
;M203 X60000.00 Y60000.00 Z60000.00 E120.00  		; set maximum speeds (mm/min)
;M201 X6000.00 Y6000.00 Z4000.00 E250.00     		; set accelerations (mm/s^2)
; Motor currents, LDO motors for x,y,z are rated for 2A, Duet 3 Mini 5 has Trinamic 2209 stepper 
; drivers rated for 1,4A RMS (constant) and 2A peak, 1,4 seems a reasonable value.
M906 X1400 Y1400 Z1400 E1000 I30                      ; set motor currents (mA) and motor idle factor in per cent, I is idle power in percent
M98 P"/macros/print_scripts/setup_printing.g"
M84 S120											;Idle Timeout 120 seconds, after this time the current is reduced


; Axis Limits https://duet3d.dozuki.com/Wiki/M208
M208 X0 Y0 Z0 S1                                   	; set axis minima
M208 X350 Y350 Z350 S0                             	; set axis maxima (change to 300, 250 according to printer size)

;===========================================================================================================
; Endstop configuration and Z-Probe
; io1 = x, io2 = y, io3 = Z-Probe, io5 = Nozzle click

; Endstops https://duet3d.dozuki.com/Wiki/M574
M574 X2 S1 P"io1.in"                               ; X Endstop Switch
M574 Y2 S1 P"io2.in"                               ; Y Endstop switch
M574 Z0 P"nil"                               ; configure Z-probe endstop for low end on Z


; Z probes
M558 K0 P8 C"io3.in" T18000 F120 H5 A5 S0.01 R0.2 ; Assign K0 to inductive Probe
G31 K0 P500 X0 Y25 Z1.59            
M558 K1 P8 C"io5.in" T18000 F240:60 H2 A10 S0.005 R0.2 ;Assign K1 to nozzle switch
G31 K1 P500 X0 Y0 Z1.3; Z switch offset (if positive, greater value = lower nozzle. if negative, more negative = higher nozzle)
;Identiy and configure Z Offset see https://docs.duet3d.com/User_manual/Connecting_hardware/Z_probe_testing

;===========================================================================================================
; Configure Leveling (Mesh and Quad-Gantry self levelling)

; TODO CHECK
; Bed leveling (quad level gantry compensation)
M671 X-65:-65:415:415 Y-20:430:430:-20 S20      ; Define Z belts locations (Front_Left, Back_Left, Back_Right, Front_Right)
M557 X25:325 Y25:325 S25                        ; Define bed mesh grid (inductive probe, positions include the Z offset!)

;===========================================================================================================
; Heater and thermistor (for Bed and Extruder configuration) 
; Out_0 = Heated Bed, Out_1 = Hotend Heater, Temp0 = Bed, Temp1 = Hotend, Temp2 = Chamber

; Heated Bed
M308 S0 P"temp0" Y"thermistor" T100000 B4138 A"Bed"   ; configure sensor 0 as thermistor on pin bedtemp
M950 H0 C"out0" T0                            ; create bed heater output on bedheat and map it to sensor 0
;M307 H0 R0.397 K0.265:0.000 D5.44 E1.35 S1.00 B0
;M307 H0 B0 R0.637 C222.4 D0.95 S1.00 V24.0
M307 H0 B1 S1.00                                 ; enable bang-bang mode for the bed heater and set PWM limit
M140 H0                                          ; map heated bed to heater 0
M143 H0 S120                                     ; set temperature limit for heater 0 to 120C

; Hotend
; I have a Mosquite Hotend, which is rated for over 280°C and the Thermistor as well
M308 S1 P"temp1" Y"thermistor" T100000 B4138 A"Hotend"   ; configure sensor 1 as thermistor on pin e0temp
M950 H1 C"out1" T1                             ; create nozzle heater output on e0heat and map it to sensor 1
M307 H1 A614.3 C180.2 D5.3 S1.00 V24.4 B0        ; Mosquito + PT100 PID, 50W heater
;M307 H1 R3.490 K0.656:0.192 D5.50 E1.35 S1.00 B0 ; after PID tune
M307 H1 B0 S1.00                                 ; disable bang-bang mode for heater  and set PWM limit
M143 H1 S300                                     ; set temperature limit for heater 1 to 300C

;===========================================================================================================
; Sensors
M308 S2 Y"drivers" A"DRIVERS"  					; configure sensor 2 as temperature warning and overheat flags on the TMC2660 on Duet
M308 S3 Y"mcu-temp" A"Board Temp" 				; configure sensor 3 for board temperature
M308 S4 P"temp2" Y"thermistor" A"Chamber Temp"  ; configure sensor 4 as chamber thermistor
;===========================================================================================================
; Fans
; Part cooling fan
M950 F0 C"out6"                                 ; create fan 0 on pin 121.out1 and set its frequency
M106 P0 S0 H-1 C"Part Cooling Fan"              ; set fan 0 value. Thermostatic control is turned off

; Hotend fan
M950 F1 C"out5"                              	; create fan 1 on pin 121.out2 and set its frequency
M106 P1 S255 C"Hotend Fan" H1 T50                ; set fan 1 value. Thermostatic control is turned on for hotend (hotend above 45°C it's turned on)

;Electronics Bay Fans
M950 F2 C"out4" Q10                				; create fan 2 on pin out4 and set its frequency
M106 P2 H2:3 L0.15 X1 B0.3 T10:42 C"Electronics Bay" B0.5 ; set fan 2 value

;Chamber Fan
M950 F3 C"out3" Q10              ; create fan 2 on pin out4 and set its frequency
M106 P3 S0 H-1 C"Chamber Fan" B0.5                                 ; set fan 0 value. Thermostatic control is turned off

;===========================================================================================================
; Tools
M563 P0 D0 H1 F0 S"Slice Mosquito"                                 ; define tool 0
G10 P0 X0 Y0 Z0                                                     ; set tool 0 axis offsets
G10 P0 R0 S0                                                        ; set initial tool 0 active and standby temperatures to 0C
;===========================================================================================================
; Enable 12864 display
M918 P2 E4 F2000000
M150 X2 R100 U80 B255 P250 S3   ; Set LED colours
M501 											; load changed parameters
T0												; select Tool0

dc42

@timtom I'll need to see the GCode file to investigate this.

Are you running the Duet in standalone or SBC mode?

TimTom

@dc42

Hi, pleasure to hear from you.

The Duet runs in standalone mode.

You can download the G-Code here:
https://timthinks-my.sharepoint.com/:u:/g/personal/tim_koehler_3dobjektmanufaktur_de/EfwqUmPQDvBOgsCSBPOuj3wBqgHARafrCgjZrYVwrrp9dA?e=9fEd34

I'll try another version now. I could also up/downgrade the firmware if you want me to.

TimTom

@dc42

Ok with a shorter (similar file) it also happens. To me it seems, that the board is getting just really slow, movements are "paused" on every direction change.
Also an initial load of the webinterface takes much longer than normal.

I see, that the MAIN task is running at 423.7% - when pausing it drops to 70/80%.

I paused for a couple of minutes (to see if some kind of "garbage control" kicks in, but after short period of time it's back to slow.

M122
=== Diagnostics ===
RepRapFirmware for Duet 3 Mini 5+ version 3.4.0beta7 (2021-12-16 12:22:56) running on Duet 3 Mini5plus WiFi (standalone mode)
Board ID: UMKSF-J096U-D65J0-40KML-2D03Z-HXVSM
Used output buffers: 1 of 40 (26 max)
=== RTOS ===
Static ram: 103460
Dynamic ram: 116376 of which 16 recycled
Never used RAM 18260, free system stack 112 words
Tasks: NETWORK(ready,267.8%,216) HEAT(notifyWait,0.3%,340) Move(notifyWait,22.6%,273) CanReceiv(notifyWait,0.0%,942) CanSender(notifyWait,0.0%,358) CanClock(delaying,0.1%,331) TMC(notifyWait,10.0%,105) MAIN(running,423.7%,406) IDLE(ready,38.4%,29) AIN(delaying,7.0%,264), total 770.0%
Owned mutexes:
=== Platform ===
Last reset 01:49:41 ago, cause: software
Last software reset at 2022-01-31 11:01, reason: User, GCodes spinning, available RAM 17768, slot 0
Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00000000 BFAR 0xe000ed38 SP 0x00000000 Task MAIN Freestk 0 n/a
Error status: 0x00
MCU revision 3, ADC conversions started 6582928, completed 6582928, timed out 0, errs 0
Step timer max interval 1462
MCU temperature: min 30.3, current 38.8, max 39.9
Supply voltage: min 23.7, current 24.0, max 24.1, under voltage events: 0, over voltage events: 0, power good: yes
Heap OK, handles allocated/used 99/6, heap memory allocated/used/recyclable 2048/514/130, gc cycles 0
Events: 0 queued, 0 completed
Driver 0: pos 52272, ok, SG min 0, read errors 0, write errors 1, ifcnt 82, reads 8055, writes 19, timeouts 0, DMA errors 0, CC errors 0
Driver 1: pos -4968, ok, SG min 0, read errors 0, write errors 1, ifcnt 83, reads 8054, writes 20, timeouts 0, DMA errors 0, CC errors 0
Driver 2: pos 8800, standstill, SG min 0, read errors 0, write errors 1, ifcnt 82, reads 8053, writes 21, timeouts 0, DMA errors 0, CC errors 0
Driver 3: pos 0, standstill, SG min 0, read errors 0, write errors 1, ifcnt 85, reads 8052, writes 21, timeouts 0, DMA errors 0, CC errors 0
Driver 4: pos 0, standstill, SG min 0, read errors 0, write errors 1, ifcnt 84, reads 8055, writes 19, timeouts 0, DMA errors 0, CC errors 0
Driver 5: pos 0, standstill, SG min 0, read errors 0, write errors 1, ifcnt 84, reads 8054, writes 20, timeouts 0, DMA errors 0, CC errors 0
Driver 6: pos 0, ok, SG min 0, read errors 0, write errors 1, ifcnt 31, reads 8062, writes 11, timeouts 0, DMA errors 0, CC errors 0
Date/time: 2022-01-31 12:51:30
Cache data hit count 4294967295
Slowest loop: 257.84ms; fastest: 0.09ms
=== Storage ===
Free file entries: 8
SD card 0 detected, interface speed: 22.5MBytes/sec
SD card longest read time 4.5ms, write time 2.9ms, max retries 0
=== Move ===
DMs created 83, segments created 31, maxWait 224914ms, bed compensation in use: none, comp offset 0.000
=== MainDDARing ===
Scheduled moves 349773, completed 349773, hiccups 0, stepErrors 0, LaErrors 0, Underruns [6961, 13, 6362], CDDA state -1
=== AuxDDARing ===
Scheduled moves 0, completed 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== Heat ===
Bed heaters 0 -1, chamber heaters -1 -1, ordering errs 0
Heater 0 is on, I-accum = 0.1
Heater 1 is on, I-accum = 0.6
=== GCodes ===
Segments left: 0
Movement lock held by null
HTTP is idle in state(s) 0
Telnet is idle in state(s) 0
File is idle in state(s) 0
USB is idle 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 0, running macro
Aux2 is idle in state(s) 0
Autopause is idle in state(s) 0
Code queue is empty
=== CAN ===
Messages queued 59274, received 0, lost 0, boc 0
Longest wait 0ms for reply type 0, peak Tx sync delay 0, free buffers 17 (min 17), ts 32907/0/0
Tx timeouts 0,42,32906,0,0,26323 last cancelled message type 30 dest 127
=== Network ===
Slowest loop: 406.11ms; fastest: 0.00ms
Responder states: HTTP(0) HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0), 0 sessions
HTTP sessions: 1 of 8
- WiFi -
Network state is active
WiFi module is connected to access point 
Failed messages: pending 0, notready 0, noresp 0
WiFi firmware version 1.26
WiFi MAC address f0:08:d1:03:81:4f
WiFi Vcc 3.36, reset reason Power up
WiFi flash size 2097152, free heap 22760
WiFi IP address 10.10.0.128
WiFi signal strength -57dBm, mode 802.11n, reconnections 0, sleep mode modem
Clock register 00002002
Socket states: 0 0 0 0 0 0 0 0

TimTom

@dc42

Sorry for "spaming", just adding input. It seems the printer gets slower and slower.

As the layers are all exactly the same, it's pretty weired.

I'd exclude temperature issues, as I started the new print with electronics fans at full speed (keeping the board at ~32°C).

Next I'm going to try a downgrade to older stable firmware.

TimTom

@dc42
Ok I did a downgrade to 3.3 Firmware, same behavior.

The print massively slows down at layer ~30.

Very weired, will test with other prints next days.

Phaedrux

Can you also test with this updated beta 7?

https://www.dropbox.com/sh/i5vox3xmkd55gaz/AAC19mI0WEC5GmEjLOBRbKs-a?dl=0

TimTom

@phaedrux
Just installed the provided build.

It seems to be still there. Layertime seems to double (from 1 min 12 secs to 2 min 25 secs). - but the new version shows the behavior a couple of layers later (not sure if it's only white noise)

This is the STL I'm using, just put 12 of these on the print bed, for an estimated print time of less than 3 hours it's a comparably large G-Code file
https://www.thingiverse.com/thing:2110134

I'm a technical product manager in tech industry, so let me know if I could further support with troubleshooting.
I could connect via Telnet to read out additional values but as it's only console top won't work? Is there additional logging/debugging options?

TimTom

@phaedrux

Just to annotate, the files are comparably large (one file is 12x the clip, the other 9x clip - both are affected):

So affected file ~10 MB/h ~ 166 kb/min
Other printjobs ~2-5 MB/h
(Print times match pretty good if full speed is maintained)

Could that be an "overload" of some kind (memory/CPU)?
Slicing the files with PrusaSlicer for an MK3s results in 5-8hours print time (in dependance of infill) - just as a comparison, file size is similar).

gloomyandy

@timtom said in print slows down mid print:

Scheduled moves 349773, completed 349773, hiccups 0, stepErrors 0, LaErrors 0, Underruns [6961, 13, 6362], CDDA state -1

The high number of underruns may be part of the problem, the question then though is what is causing the underruns? The read times from the SD card look to be fine, but it may be worth trying a different card if you have one, just to be sure.

TimTom

@gloomyandy

Thanks for the reply, still learning Duet troubleshooting.
Very weired, 10 MB

For everyone else running in this issue, @gloomyandy s report is documented here:
https://docs.duet3d.com/en/User_manual/RepRapFirmware/SD_card
Following documentation, I ran an SD card speed test in Duet:

Wow thats slow! It's the stock card, will replace these days (need to find such a small capacity card) . . .

jay_s_uk

@timtom why do you want a small SD card? I tend to use 16gb and 32gb cards

TimTom

@jay_s_uk

THAT IS SMALL!
I usually buy 128 or 256 GB in special offers, also mostly sandisk Ultra or extreme, so I can use them in Cameras, etc. as well. Small cards are comparably expensive (in price per GB).

jay_s_uk

@timtom ah, fair enough. FAT32 doesn't like large cards so not much bigger is supported

Phaedrux

@timtom said in print slows down mid print:

Free file entries: 8
SD card 0 detected, interface speed: 22.5MBytes/sec
SD card longest read time 4.5ms, write time 2.9ms, max retries 0

that looks about right for a Duet3.

Trying a new card is worth a try.

TimTom

@jay_s_uk
Sorry didn't want to be rude, I tend to pay a Euro more per card to avoid such kind of issues, currently the Sandisk 32 GB cards are only 2 Euros more than the "cheaper noname" cards. Filament cost and the time invest is worth much more than these 2 Euros so far.

@Phaedrux
Let's hope this solves the issue, cards should arrive today. Nevertheless, the card currently in use, is the stock card coming with the Duet board.

Will keep you updated.

TimTom

@phaedrux @dc42 @gloomyandy
I believe I found the Issue - small volume size lead to massive fragementation resulting in horrible SD-card performance.

In preparation for the "new cards" I took out the stock card and found out that the 8 GB card only has a 256 MB partition (so only 256 MB were usable).

Being curious I reformatted the card to it's full capacity and ran the Speed tests M122 P104 again, surprise, surprise speed tests dramatically improved:

with 256 MB partition (mostlikely massivly fragmented):

with 8GB partition:

Read speed nearly trippled!

Trying it again and BAM issue solved! - With the very same SD-Card!!!!

My assumptions and maybe what might cause this:

with 256 MB the "volume" is pretty full as my gcode+firmware files already occupied ~200 MB so not a lot of "free space"
doing a several firmware updates and lots of configuration changes, deleting and uploading always performs writes to the SD-card
FAT32 tends to fragment much more than other more modern filesystems
SD-card interface of Duet is not comparable with a high-tech PCIe SSD.

Bottom line the small volume got highly fragmented (explanation see below), resulting in super bad performance.
Unfortunatly I did not check the SD-card for fragmentation prior deleting, so I have no "proof".

Suggestion for Duet
I assume the small volume size of 256 GB is a result of historic artifact, because that allows to use any size of SD-card (down to 256 MB) in the production process. My humble suggestion would be

to change the manufacturing process to either start with lager volumes (e.g. 4 GB or 8 GB) or to make this a dynamic process, automatically sizing the partition/volume to the maximum available space (maybe add a cap at 32 GB to take FAT32 limit into account).
for existing customers and new customers receiving such cards, I'd put a clear Note about this topic in the documentation (something like "Consider reformating your SD-card to maximum capacity).

*Fragmentation explained by Roland (music instruments) -
When an SD card recorder stores new files, it squeezes them into any bits of space it can find. As a result, the data winds up scattered all over the hard drive. When the data from one song file, for example, is stored in many locations within the card memory, the card is said to be fragmented. When the recorder plays back a file from a fragmented card, it has to grab a little piece from here, another piece from there and so on. This is much harder than playing one continuous chunk of data from a single card location. This can slow things down unacceptably and lead to errors during playback, recording and/or any other function in the recorder.

Fragmentation is a naturally occurring process for a card used with any computer or recording device. SD cards that record audio are especially prone to fragmentation due to the start-and-stop nature of recording.

We recommend backing up all of your data and then initializing the SD card to clear out this normal fragmentation. To avoid receiving errors and/or problems, initialize the card a couple of times a year.. The following steps will guide you through the Card Backup, Card Initialize and Card Recover procedures:*

gloomyandy

@timtom The card supplied with the Duet3 has two partitions on the SD card. The first is a 256Mb FAT volume the second a Linux volume. The Linux volume contains the Duet RPI SBC image. This allows the SD card to be used either with a standalone system (using the FAT partition) or an SBC based system (with the SD card in the RPi). So the small size of the FAT partition is deliberate. As to if this is a good idea, I'll let others decide.

Phaedrux

After some investigation we've solved the issue of the too small partitions going forward. There were likely only a very small number of early Duet 3 boards that have the problem.

TimTom

@phaedrux
Well the board I had was not too old (I received it 1-2 months ago), it already had the current stable version on the SD-card.

As I'm a product manager myself (also for snom phones in the past = embedded devices), I'm very curious on what the solution is. Having invested some time and money (filament and new SD-cards), I'd love to hear what your conclusions are. Feel free to reach out on separate channel