print slows down mid print

TimTom

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

Phaedrux

The board you got may have been produced much earlier than when you bought it.

The solution was just to change the amount of space allocated to the pi partition and the standalone partition so that the standalone isn't limited to such a small space.

TimTom

@phaedrux
Ahh ok, so you already adjusted the partition scheme, great to hear

According to serial my board was 2021-06.
Nevertheless I'd add a note to Setup/install guide, I'd written something but can't find my docu credentials at the moment.