Duet 3 mini 5+ random "pause" while printing

Krohm Koala

Hi, I have faced an issue recently, since i run SBC (PI 3B) on my duet 3 mini with the last unstable release (3.4.0beta5), my printer stops for less than a second randomly during printing and continues normally.
It cause a lot of "blobs" around the perimeters of the prints...

An idea for what's the cause of that ?
Here's the M122 in case it can help.

M122
=== Diagnostics ===
RepRapFirmware for Duet 3 Mini 5+ version 3.4.0beta5 (2021-10-12 13:53:24) running on Duet 3 Mini5plus WiFi (SBC mode)
Board ID: RBLWU-5096U-D65J0-40KMQ-K513Z-HRUJH
Used output buffers: 8 of 40 (18 max)
=== RTOS ===
Static ram: 103844
Dynamic ram: 98436 of which 0 recycled
Never used RAM 36576, free system stack 206 words
Tasks: SBC(ready,1.5%,507) HEAT(notifyWait,0.0%,359) Move(notifyWait,0.0%,362) CanReceiv(notifyWait,0.0%,941) CanSender(notifyWait,0.0%,371) CanClock(delaying,0.0%,340) TMC(notifyWait,0.0%,123) MAIN(running,93.0%,522) IDLE(ready,4.7%,30) AIN(delaying,0.8%,273), total 100.0%
Owned mutexes: HTTP(MAIN)
=== Platform ===
Last reset 00:00:51 ago, cause: power up
Last software reset at 2021-10-30 19:50, reason: User, GCodes spinning, available RAM 36792, slot 0
Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00000000 BFAR 0xe000ed38 SP 0x00000000 Task SBC Freestk 0 n/a
Error status: 0x00
Aux0 errors 0,0,0
MCU revision 3, ADC conversions started 51188, completed 51187, timed out 0, errs 0
Step timer max interval 1490
MCU temperature: min 27.5, current 30.6, max 30.6
Supply voltage: min 2.2, current 2.3, max 2.3, under voltage events: 0, over voltage events: 0, power good: no
Heap OK, handles allocated/used 99/4, heap memory allocated/used/recyclable 2048/320/286, gc cycles 0
Driver 0: pos 0,ok, SG min/max n/a, read errors 0, write errors 0, ifcnt 0, reads 0, writes 0, timeouts 0, DMA errors 0
Driver 1: pos 0,ok, SG min/max n/a, read errors 0, write errors 0, ifcnt 0, reads 0, writes 0, timeouts 0, DMA errors 0
Driver 2: pos 0,ok, SG min/max n/a, read errors 0, write errors 0, ifcnt 0, reads 0, writes 0, timeouts 0, DMA errors 0
Driver 3: pos 0,ok, SG min/max n/a, read errors 0, write errors 0, ifcnt 0, reads 0, writes 0, timeouts 0, DMA errors 0
Driver 4: pos 0,ok, SG min/max n/a, read errors 0, write errors 0, ifcnt 0, reads 0, writes 0, timeouts 0, DMA errors 0
Driver 5: pos 0,ok, SG min/max n/a, read errors 0, write errors 0, ifcnt 0, reads 0, writes 0, timeouts 0, DMA errors 0
Driver 6: pos 0,ok, SG min/max n/a, read errors 0, write errors 0, ifcnt 0, reads 0, writes 0, timeouts 0, DMA errors 0
Date/time: 2021-10-31 08:01:12
Cache data hit count 111269772
Slowest loop: 14.46ms; fastest: 0.07ms
=== Storage ===
Free file entries: 10
SD card 0 not detected, interface speed: 0.0MBytes/sec
SD card longest read time 0.0ms, write time 0.0ms, max retries 0
=== Move ===
DMs created 83, segments created 0, maxWait 0ms, bed compensation in use: none, comp offset 0.000
=== MainDDARing ===
Scheduled moves 0, completed 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], 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, chamberHeaters = -1 -1
Heater 1 is on, I-accum = 0.0
=== GCodes ===
Segments left: 0
Movement lock held by null
HTTP* is doing "M122" 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
=== Filament sensors ===
Extruder 0 sensor: ok
=== CAN ===
Messages queued 358, received 0, lost 0, longest wait 0ms for reply type 0, peak Tx sync delay 0, free buffers 17 (min 17), ts 256/0/0
Tx timeouts 0,0,255,0,0,101 last cancelled message type 30 dest 127
=== SBC interface ===
State: 4, failed transfers: 1, checksum errors: 0
Last transfer: 5ms ago
RX/TX seq numbers: 2585/2585
SPI underruns 0, overruns 0
Disconnects: 0, timeouts: 0, IAP RAM available 0x0f210
Buffer RX/TX: 0/0-0
=== Duet Control Server ===
Duet Control Server v3.4-b5
Daemon:
Executing macro daemon.g, started by system
> Next stack level
Code buffer space: 4096
Configured SPI speed: 8000000Hz
Full transfers per second: 1.95, max wait times: 36.0ms/11.0ms
Codes per second: 0.06
Maximum length of RX/TX data transfers: 3428/844

T3P3Tony

@krohm-koala thanks for the M122. there are few failed transfers on the SBC interface but not loads.

Did this happen before upgrading to 3.4b5?
How frequently are the stops?

@chrishamm any ideas on what else to check?

Krohm Koala

@t3p3tony I've just setup SBC, i was already on 3.4b5 before SBC and didn't have any problem, since the posting I've done some "simpler" prints with basically just straight lines (and also many reboots between the posting and printing) and i didn't seem to have problems on these. The problems occurs quite frequently, so i think it's on complex print that the problem occurs, I'll retry some complex print to see if this confirms.

chrishamm

@krohm-koala I don't see anything obvious in your diagnostics. There is a single failed transfer but that cannot be responsible for short pauses during prints. What do you have in your daemon.g file?

Krohm Koala

@chrishamm Here's my daemon.g, i've use a global variable to "stop" it while printing. I'll remove network lines as it's not needed anymore.

while global.daemon == 0
    G4 S1
    while boards[0].vIn.current < 23
        if {heat.heaters[1].active >= 60 && heat.heaters[1].state == "active"} || {heat.heaters[0].active >= 30 && heat.heaters[0].state == "active"}
            M80
            break
        else
            break
    if boards[0].vIn.current > 5 && fans[3].actualValue < 0.04
        M106 P3 S255
    if network.interfaces[0].actualIP == "255.255.255.255"
        M552 S-1
        G4 S5
        M552 S1
        G4 S5

Krohm Koala

I'm printing one of the files that cause the problem, here is an M122 of during the print and a video of what's happening.
https://drive.google.com/file/d/1sf2hwCVugUFkOxACFBU_eWUYYlFWunLD/view?usp=sharing

M122
=== Diagnostics ===
RepRapFirmware for Duet 3 Mini 5+ version 3.4.0beta5 (2021-10-12 13:53:24) running on Duet 3 Mini5plus WiFi (SBC mode)
Board ID: RBLWU-5096U-D65J0-40KMQ-K513Z-HRUJH
Used output buffers: 8 of 40 (40 max)
=== RTOS ===
Static ram: 103844
Dynamic ram: 98900 of which 0 recycled
Never used RAM 35080, free system stack 118 words
Tasks: SBC(ready,13.2%,509) HEAT(notifyWait,0.1%,339) Move(notifyWait,4.1%,272) CanReceiv(notifyWait,0.0%,941) CanSender(notifyWait,0.0%,357) CanClock(delaying,0.1%,340) TMC(notifyWait,2.0%,71) MAIN(running,75.6%,443) IDLE(ready,0.2%,30) AIN(delaying,4.6%,264), total 100.0%
Owned mutexes: HTTP(MAIN)
=== Platform ===
Last reset 05:50:22 ago, cause: software
Last software reset at 2021-11-01 08:16, reason: User, Platform spinning, available RAM 35368, slot 2
Software reset code 0x0000 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00000000 BFAR 0xe000ed38 SP 0x00000000 Task SBC Freestk 0 n/a
Error status: 0x04
Aux0 errors 0,5,0
MCU revision 3, ADC conversions started 21022424, completed 21022424, timed out 0, errs 0
Step timer max interval 1491
MCU temperature: min 25.9, current 57.4, max 59.4
Supply voltage: min 1.9, current 24.4, max 24.6, under voltage events: 2, over voltage events: 0, power good: yes
Heap OK, handles allocated/used 99/5, heap memory allocated/used/recyclable 2048/994/924, gc cycles 73
Driver 0: pos 30459,ok, SG min/max 0/16, read errors 0, write errors 2, ifcnt 14, reads 21350, writes 47, timeouts 0, DMA errors 0
Driver 1: pos 20232,ok, SG min/max 0/506, read errors 0, write errors 2, ifcnt 19, reads 21291, writes 106, timeouts 0, DMA errors 0
Driver 2: pos 887, standstill, SG min/max 0/16, read errors 0, write errors 2, ifcnt 14, reads 21348, writes 47, timeouts 0, DMA errors 0
Driver 3: pos 0,ok, SG min/max 0/510, read errors 0, write errors 2, ifcnt 19, reads 21331, writes 63, timeouts 0, DMA errors 0
Driver 4: pos 0,ok, SG min/max 0/16, read errors 0, write errors 2, ifcnt 12, reads 21365, writes 32, timeouts 0, DMA errors 0
Driver 5: pos 0, assumed not present
Driver 6: pos 0, assumed not present
Date/time: 2021-11-01 14:06:25
Cache data hit count 4294967295
Slowest loop: 1524.16ms; fastest: 0.09ms
=== Storage ===
Free file entries: 10
SD card 0 not detected, interface speed: 0.0MBytes/sec
SD card longest read time 0.0ms, write time 0.0ms, max retries 0
=== Move ===
DMs created 83, segments created 43, maxWait 8839785ms, bed compensation in use: mesh, comp offset 0.000
=== MainDDARing ===
Scheduled moves 23580, completed 23540, hiccups 0, stepErrors 0, LaErrors 0, Underruns [6, 0, 100], CDDA state 3
=== AuxDDARing ===
Scheduled moves 0, completed 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== Heat ===
Bed heaters = 0 -1, chamberHeaters = -1 -1
Heater 0 is on, I-accum = 0.4
Heater 1 is on, I-accum = 0.7
=== GCodes ===
Segments left: 1
Movement lock held by null
HTTP* is doing "M122" in state(s) 0
Telnet is idle in state(s) 0
File* is doing "G1 X158.873993 Y116.336998 E25.112080" 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
Aux2 is idle in state(s) 0
Autopause is idle in state(s) 0
Code queue is empty
=== Filament sensors ===
Extruder 0 sensor: ok
=== CAN ===
Messages queued 189290, received 0, lost 0, longest wait 0ms for reply type 0, peak Tx sync delay 0, free buffers 17 (min 16), ts 105111/0/0
Tx timeouts 0,109,105110,1,0,84066 last cancelled message type 30 dest 127
=== SBC interface ===
State: 4, failed transfers: 0, checksum errors: 0
Last transfer: 6ms ago
RX/TX seq numbers: 7067/7067
SPI underruns 0, overruns 0
Disconnects: 0, timeouts: 0, IAP RAM available 0x0f210
Buffer RX/TX: 2064/3480-0
=== Duet Control Server ===
Duet Control Server v3.4-b5
File:
Buffered code: G1 X158.935 Y116.607 E25.12145
Buffered code: G1 X158.981 Y116.958 E25.13344
Buffered code: G1 X158.984 Y117.332 E25.14611
Buffered code: G1 X158.958 Y117.669 E25.15754
Buffered code: G1 X158.899 Y118.027 E25.16982
Buffered code: G1 X158.809 Y118.385 E25.18231
Buffered code: G1 X158.689 Y118.736 E25.19487
Buffered code: G1 X158.533 Y119.087 E25.20787
Buffered code: G1 X158.361 Y119.402 E25.22002
Buffered code: G1 X158.159 Y119.708 E25.23244
Buffered code: G1 X157.935 Y119.993 E25.24471
Buffered code: G1 X157.691 Y120.254 E25.25682
Buffered code: G1 X157.421 Y120.495 E25.26905
Buffered code: G1 X156.958 Y120.821 E25.28823
Buffered code: G1 X157.176 Y121.582 E25.31502
Buffered code: G1 X157.327 Y122.209 E25.33686
Buffered code: G1 X157.452 Y122.858 E25.35923
Buffered code: G1 X157.547 Y123.504 E25.38133
Buffered code: G1 X157.618 Y124.179 E25.40430
Buffered code: G1 X157.662 Y124.857 E25.42732
Buffered code: G1 X157.678 Y125.599 E25.45245
Buffered code: G1 X157.631 Y126.958 E25.49847
Buffered code: G1 X157.562 Y127.705 E25.52386
Buffered code: G1 X157.478 Y128.367 E25.54644
Buffered code: G1 X157.356 Y129.106 E25.57180
Buffered code: G1 X157.048 Y130.514 E25.62058
Buffered code: G1 X156.840 Y131.267 E25.64702
Buffered code: G1 X156.620 Y131.966 E25.67184
Buffered code: G1 X156.111 Y133.341 E25.72146
Buffered code: G1 X155.813 Y134.036 E25.74706
Buffered code: G1 X155.496 Y134.712 E25.77232
==> 1488 bytes
Pending code: G1 X155.149 Y135.389 E25.79807
Code buffer space: 2112
Configured SPI speed: 8000000Hz
Full transfers per second: 37.75, max wait times: 81.7ms/15.9ms
Codes per second: 5.56
Maximum length of RX/TX data transfers: 3284/1696
File /opt/dsf/sd/gcodes/PLA_0.2_porte cure dents.gcode is selected, processing

chrishamm

@krohm-koala Thanks, can you provide your G-code/STL as well? I'll try to reproduce it on my setup then. Your latest diagnostics report shows a very high time for the slowest loop, which should not be there, and a couple of underruns.

Is there any chance you have high CPU/IO load on the SBC or persistent logging with log level debug for DuetControlServer?

Krohm Koala

@chrishamm Sure, here's both
STL : porte cure dents.stl
GCODE : https://drive.google.com/file/d/15_oE3-WkcI9CXi_3WlEfSSdbUpI9Or7g/view?usp=sharing

I don't think i can have high load on sbc as it's just running duet, but if there's a way to check, i'll do it.
For persistent logging, how do you check it ?

chrishamm

@krohm-koala Thanks, I'll give it a try tomorrow. You can run this in a Linux console or via SSH to check the configured log level, it should be set to info:

cat /opt/dsf/conf/config.json | grep LogLevel

I'll let you know if I manage to reproduce your problem.

Krohm Koala

@chrishamm Here's what it gives me


{
  "PluginSupport": true,
  "RootPluginSupport": false,
  "PluginsFilename": "/opt/dsf/conf/plugins.txt",
  "LogLevel": "info",
  "SocketDirectory": "/var/run/dsf",
  "SocketFile": "dcs.sock",
  "Backlog": 4,
  "SocketPollInterval": 2000,
  "BaseDirectory": "/opt/dsf/sd",
  "PluginDirectory": "/opt/dsf/plugins",
  "NoTerminateOnReset": false,
  "HostUpdateInterval": 4000,
  "MaxMessageAge": 60,
  "SpiDevice": "/dev/spidev0.0",
  "SpiBufferSize": 8192,
  "SpiTransferMode": 0,
  "SpiFrequency": 8000000,
  "SpiConnectTimeout": 500,
  "SpiTransferTimeout": 500,
  "SpiConnectionTimeout": 4000,
  "MaxSpiRetries": 3,
  "GpioChipDevice": "/dev/gpiochip0",
  "TransferReadyPin": 25,
  "BufferedPrintCodes": 32,
  "BufferedMacroCodes": 16,
  "MaxBufferSpacePerChannel": 1536,
  "MaxCodeBufferSize": 256,
  "MaxMessageLength": 4096,
  "FirmwareComments": [
    "printing object",
    "MESH",
    "process",
    "stop printing object",
    "layer",
    "LAYER",
    "BEGIN_LAYER_OBJECT z=",
    "HEIGHT",
    "PRINTING",
    "REMAINING_TIME"
  ],
  "ModelUpdateInterval": 250,
  "MaxMachineModelLockTime": -1,
  "FileBufferSize": 8192,
  "FileInfoReadLimitHeader": 12288,
  "FileInfoReadLimitFooter": 262144,
  "MaxLayerHeight": 0.9,
  "LayerHeightFilters": [
    {
      "Pattern": "^\\s*layer_height\\D+(?<mm>(\\d+\\.?\\d*))",
      "Options": 17
    },
    {
      "Pattern": "Layer height\\D+(?<mm>(\\d+\\.?\\d*))",
      "Options": 17
    },
    {
      "Pattern": "layerHeight\\D+(?<mm>(\\d+\\.?\\d*))",
      "Options": 17
    },
    {
      "Pattern": "layer_thickness_mm\\D+(?<mm>(\\d+\\.?\\d*))",
      "Options": 17
    },
    {
      "Pattern": "layerThickness\\D+(?<mm>(\\d+\\.?\\d*))",
      "Options": 17
    },
    {
      "Pattern": "sliceHeight\\D+(?<mm>(\\d+\\.?\\d*))",
      "Options": 17
    }
  ],
  "FilamentFilters": [
    {
      "Pattern": "filament used\\D+(((?<mm>\\d+\\.?\\d*)\\s*mm)(\\D+)?)+",
      "Options": 17
    },
    {
      "Pattern": "filament used\\D+(((?<m>\\d+\\.?\\d*)m([^m]|$))(\\D+)?)+",
      "Options": 17
    },
    {
      "Pattern": "filament length\\D+(((?<mm>\\d+\\.?\\d*)\\s*mm)(\\D+)?)+",
      "Options": 17
    },
    {
      "Pattern": "filament used \\[mm\\]\\D+((?<mm>\\d+\\.?\\d*)(\\D+)?)+",
      "Options": 17
    },
    {
      "Pattern": "material\\#(?<index>\\d+)\\D+(?<mm>\\d+\\.?\\d*)",
      "Options": 17
    },
    {
      "Pattern": "Ext\\s*\\#\\d+\\D+(?<mm>\\d+\\.?\\d*)",
      "Options": 17
    },
    {
      "Pattern": "Filament used per extruder:\\r\\n;\\s*(?<name>.+)\\s+=\\s*(?<mm>[0-9.]+)",
      "Options": 17
    },
    {
      "Pattern": "filament used extruder (?<index>\\d+) \\(mm\\) = (?<mm>\\d+\\.?\\d*)",
      "Options": 17
    }
  ],
  "GeneratedByFilters": [
    {
      "Pattern": "generated by\\s+(.+)",
      "Options": 17
    },
    {
      "Pattern": "Sliced by\\s+(.+)",
      "Options": 17
    },
    {
      "Pattern": "(KISSlicer.*)",
      "Options": 17
    },
    {
      "Pattern": "Sliced at:\\s*(.+)",
      "Options": 17
    },
    {
      "Pattern": "Generated with\\s*(.+)",
      "Options": 17
    }
  ],
  "PrintTimeFilters": [
    {
      "Pattern": "estimated printing time .*= ((?<h>(\\d+))h\\s*)?((?<m>(\\d+))m\\s*)?((?<s>(\\d+))s)?",
      "Options": 17
    },
    {
      "Pattern": "TIME:(?<s>(\\d+\\.?\\d*))",
      "Options": 17
    },
    {
      "Pattern": "Build Time:\\s+((?<h>(\\d+\\.?\\d*)) hour(s)?\\s*)?((?<m>(\\d+\\.?\\d*)) minute(s)?\\s*)?((?<s>(\\d+\\.?\\d*)) second(s)?)?",
      "Options": 17
    },
    {
      "Pattern": "print time:\\s+(?<s>(\\d+\\.?\\d*))(s)?",
      "Options": 17
    },
    {
      "Pattern": "Total estimated \\(pre-cool\\) minutes: ((?<m>\\d+\\.?\\d*))",
      "Options": 17
    },
    {
      "Pattern": "total print time \\(s\\) = (?<s>(\\d+\\.?\\d*))",
      "Options": 17
    }
  ],
  "SimulatedTimeFilters": [
    {
      "Pattern": "Simulated print time\\D+(?<s>(\\d+\\.?\\d*))",
      "Options": 17
    }
  ]

chrishamm

@krohm-koala Thanks. I suspect there is something wrong with your SD card, please exchange it and check if the problem persists. In the past damaged SD cards could lead to the same symptoms you are seeing.

I've been printing your G-code and I haven't been able to spot any sudden pauses yet:

=== MainDDARing ===
Scheduled moves 24765, completed 24725, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 1], CDDA state 3

If you get a new one, please consider an A1- or A2-rated microSD card for the Pi - they're generally faster and have more IOPS than the standard cards.

Krohm Koala

@chrishamm Thank's i'll consider that, it would be weird if the SD card is already damaged as it's the original SD card from the duet 3 mini (2/3 months old and not that much use), i'll check if i find good sd card

jay_s_uk

@chrishamm I am also seeing random pauses on 3.4b5 in SBC mode with a mini5+.
Lots of random blobs all over prints.
Wasn't an issue with 3.4b4.
Anything I can provide?

Krohm Koala

@jay_s_uk Thanks, i hope both of us can have everything to help resolve that problem
@chrishamm so i've just change the SD card for an A2 U3 V30, i still have the problem with that SD, i've clone the other SD, maybe the problem ? i think i'll try a clean install if i manage to backup all the config files of the SBC, i haven't found where they are

chrishamm

@krohm-koala That's pretty strange, I haven't been able to reproduce it on my machines yet with your G-code file:

Apparently the print settings don't match my machine but there are no blobs or indications for random pauses visible AFAICS. I'll be happy to address this problem as soon as I figure out what exactly is going on.

Krohm Koala

@chrishamm Clean install done, with the good sd card, problem still here, so i give you my config files, maybe it could be usefull @jay_s_uk can you upload yours too so we can compare if there's "weird" similarities that can cause the bug ?
https://drive.google.com/file/d/1AaEKxDz_qTaEhUuqW9kx5FhKrRhhtVNA/view?usp=sharing

Krohm Koala

@chrishamm this is a weird problem, i have a small print that i've done recently where there's 3 circular tower of small diameter and with this the problem is quite frequent. at least, we have eliminate the fact that it can be a sd problem. If you need me to run some other tests, don't hesitate

dc42

@krohm-koala we have just released software 3.4.0beta6. I know that @chrishamm has improved the SBC to Duet interface in this release, so I suggest you upgrade to see if the problem has been resolved.

Krohm Koala

@dc42 thanks, upgrade is done, i launch a print right now

Krohm Koala

@dc42 Problem still here