High M98 call latency
-
I'm running RRF 3.3 with SBC on a Duet2Wifi.
I am using M98 to call a short macro file on every layer change during my prints.
Even with a completely empty macro file, the whole M98 call takes 300-500ms (gut estimate) to complete - which is causing blobs/zits/nasty print artifacts because the extruder stays in one spot and oozes a bit while the pressure drops. It feels like the whole execution pipeline (buffer) is flushed or stalled on every M98.Here a snippet of what my slicer generates:
... G1 X128.262 Y126.26 E.03379 G1 X127.224 Y125.223 E.07089 ; stop printing object handle v1 id:0 copy 0 ;LAYER_CHANGE ;Z:0.5 ;HEIGHT:0.2 G1 Z.5 F7800 M98 P"0:sys/print_layer_change_script.g" ; printing object handle v1 id:0 copy 0 G1 X129.874 Y119.338 ;TYPE:Perimeter ;WIDTH:0.45 G1 F900 G1 X130.127 Y119.109 E.01155 G1 X130.422 Y118.89 E.01242 ...Is M98 supposed to take that long to call and complete?
Even if there is not a single command inside the macro file? -
On closer inspection, I think I'm chasing the wrong thing here.
I set my slicer to "align seams", so the zits should all be aligned because thats where the layer change is happening.But this is not what I am seeing. My prints have zits all over the place (all around in my circular/tower-like objects). I ran a test print, exactly the same gcode file but with all M98 lines commented out. Still the same ugly print result.
So, M98 is not to blame here. Sorry for the false alert.
I'd be happy to hear any ideas what my root cause could be...
My Raspberry Pi 3B seems to be doing fine: average "load" of 1.6, DCS with at most 35% CPU, plenty of free RAM.Here a few M122 outputs during a print:
30/12/2021, 16:27:23 M122 === Diagnostics === RepRapFirmware for Duet 2 SBC version 3.3 (2021-06-15 21:45:20) running on Duet 2 1.02 or later + SBC (SBC mode) Board ID: 08DDM-9FAMU-JWNSW-6J9F2-3S46N-KLJRT Used output buffers: 1 of 24 (22 max) === RTOS === Static ram: 17420 Dynamic ram: 62828 of which 0 recycled Never used RAM 31312, free system stack 100 words Tasks: SENSORS(delaying,0.0%,80) SBC(ready,5.0%,327) HEAT(delaying,0.0%,331) Move(notifyWait,1.3%,290) MAIN(running,93.6%,385) IDLE(ready,0.0%,30), total 100.0% Owned mutexes: HTTP(MAIN) === Platform === Last reset 00:26:50 ago, cause: power up Last software reset at 2021-11-14 14:36, reason: User, GCodes spinning, available RAM 34376, slot 2 Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00417000 BFAR 0xe000ed38 SP 0x00000000 Task MAIN Freestk 0 n/a Error status: 0x00 Aux0 errors 0,0,0 Step timer max interval 0 MCU temperature: min 38.9, current 39.4, max 39.7 Supply voltage: min 23.9, current 24.1, max 24.2, under voltage events: 0, over voltage events: 0, power good: yes Heap OK, handles allocated/used 99/1, heap memory allocated/used/recyclable 2048/40/0, gc cycles 0 Driver 0: position 39363, ok, SG min/max 0/1023 Driver 1: position 3570, ok, SG min/max 0/206 Driver 2: position 60480, standstill, SG min/max 0/1023 Driver 3: position 0, ok, SG min/max 0/1023 Driver 4: position 0, standstill, SG min/max 0/1023 Driver 5: position 0 Driver 6: position 0 Driver 7: position 0 Driver 8: position 0 Driver 9: position 0 Driver 10: position 0 Driver 11: position 0 Date/time: 2021-12-30 16:27:21 Cache data hit count 4294967295 Slowest loop: 12.34ms; fastest: 0.15ms I2C nak errors 0, send timeouts 0, receive timeouts 0, finishTimeouts 0, resets 0 === Move === DMs created 83, maxWait 685ms, bed compensation in use: none, comp offset 0.000 === MainDDARing === Scheduled moves 52307, completed moves 52268, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 23], CDDA state 3 === AuxDDARing === Scheduled moves 0, completed moves 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1 === Heat === Bed heaters = 0 -1 -1 -1, chamberHeaters = -1 -1 -1 -1 Heater 0 is on, I-accum = 0.1 Heater 1 is on, I-accum = 0.6 === 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 X125.657997 Y129.677002 E0.033040" 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 === SBC interface === State: 4, failed transfers: 1, checksum errors: 0 Last transfer: 4ms ago RX/TX seq numbers: 6465/6465 SPI underruns 0, overruns 0 Disconnects: 0, timeouts: 0, IAP RAM available 0x0d284 Buffer RX/TX: 1248/2552-0 === Duet Control Server === Duet Control Server v3.3.0 File: Buffered code: G1 X125.323 Y129.364 E.0155 Buffered code: G1 X124.652 Y128.644 E.03335 Buffered code: G1 X124.076 Y127.897 E.03191 Buffered code: G1 X123.555 Y127.071 E.03304 Buffered code: G1 X123.12 Y126.212 E.03263 Buffered code: G1 X122.766 Y125.315 E.03263 Buffered code: G1 X122.499 Y124.389 E.03263 Buffered code: G1 X122.319 Y123.442 E.03263 Buffered code: G1 X122.229 Y122.482 E.03263 Buffered code: G1 X122.229 Y121.518 E.03263 Buffered code: G1 X122.319 Y120.558 E.03263 Buffered code: G1 X122.499 Y119.611 E.03263 Buffered code: G1 X122.77 Y118.674 E.03304 Buffered code: G1 X122.928 Y118.244 E.0155 Buffered code: G1 X123.231 Y117.569 E.02505 Buffered code: G1 X122.714 Y117.725 F7800 Buffered code: G1 F5400 Buffered code: G1 X122.965 Y117.165 E.02077 Buffered code: G1 X123.454 Y116.304 E.03353 Buffered code: G1 X124.032 Y115.476 E.03417 Buffered code: G1 X124.68 Y114.712 E.03392 Buffered code: G1 X125.397 Y114.011 E.03392 Buffered code: G1 X126.176 Y113.381 E.03392 Buffered code: G1 X127.011 Y112.827 E.03392 Buffered code: G1 X127.894 Y112.353 E.03392 Buffered code: G1 X128.818 Y111.964 E.03392 Buffered code: G1 X129.774 Y111.664 E.03392 Buffered code: G1 X130.753 Y111.454 E.03392 Buffered code: G1 X131.756 Y111.336 E.03417 Buffered code: G1 X132.242 Y111.313 E.01646 Buffered code: G1 X133.255 Y111.336 E.03431 ==> 1472 bytes Code buffer space: 1352 Configured SPI speed: 8000000Hz Full transfers per second: 51.87, max wait times: 21.7ms/0.0ms Codes per second: 50.58 Maximum length of RX/TX data transfers: 4552/1664 File /opt/dsf/sd/gcodes/handle v1 no-layer-change-macro.gcode is selected, processing 30/12/2021, 16:25:01 M122 === Diagnostics === RepRapFirmware for Duet 2 SBC version 3.3 (2021-06-15 21:45:20) running on Duet 2 1.02 or later + SBC (SBC mode) Board ID: 08DDM-9FAMU-JWNSW-6J9F2-3S46N-KLJRT Used output buffers: 7 of 24 (20 max) === RTOS === Static ram: 17420 Dynamic ram: 62828 of which 0 recycled Never used RAM 31312, free system stack 100 words Tasks: SENSORS(delaying,0.0%,80) SBC(ready,5.0%,327) HEAT(delaying,0.0%,331) Move(notifyWait,1.3%,300) MAIN(running,93.6%,387) IDLE(ready,0.0%,30), total 100.0% Owned mutexes: HTTP(MAIN) === Platform === Last reset 00:24:29 ago, cause: power up Last software reset at 2021-11-14 14:36, reason: User, GCodes spinning, available RAM 34376, slot 2 Software reset code 0x0003 HFSR 0x00000000 CFSR 0x00000000 ICSR 0x00417000 BFAR 0xe000ed38 SP 0x00000000 Task MAIN Freestk 0 n/a Error status: 0x00 Aux0 errors 0,0,0 Step timer max interval 0 MCU temperature: min 38.6, current 39.2, max 40.0 Supply voltage: min 23.8, current 24.1, max 24.3, under voltage events: 0, over voltage events: 0, power good: yes Heap OK, handles allocated/used 99/1, heap memory allocated/used/recyclable 2048/40/0, gc cycles 0 Driver 0: position 42492, ok, SG min/max 0/1023 Driver 1: position 412, ok, SG min/max 0/992 Driver 2: position 52160, standstill, SG min/max 0/1023 Driver 3: position 0, ok, SG min/max 0/1023 Driver 4: position 0, standstill, SG min/max 0/1023 Driver 5: position 0 Driver 6: position 0 Driver 7: position 0 Driver 8: position 0 Driver 9: position 0 Driver 10: position 0 Driver 11: position 0 Date/time: 2021-12-30 16:25:00 Cache data hit count 4294967295 Slowest loop: 12.69ms; fastest: 0.16ms I2C nak errors 0, send timeouts 0, receive timeouts 0, finishTimeouts 0, resets 0 === Move === DMs created 83, maxWait 774ms, bed compensation in use: none, comp offset 0.000 === MainDDARing === Scheduled moves 45318, completed moves 45279, hiccups 0, stepErrors 0, LaErrors 0, Underruns [1, 0, 42], CDDA state 3 === AuxDDARing === Scheduled moves 0, completed moves 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1 === Heat === Bed heaters = 0 -1 -1 -1, chamberHeaters = -1 -1 -1 -1 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 doing "M122" in state(s) 0 Telnet is idle in state(s) 0 File* is doing "G1 X142.119003 Y121.704002 E0.015880" 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 === SBC interface === State: 4, failed transfers: 1, checksum errors: 0 Last transfer: 16ms ago RX/TX seq numbers: 64681/64681 SPI underruns 0, overruns 0 Disconnects: 0, timeouts: 0, IAP RAM available 0x0d284 Buffer RX/TX: 2256/3596-0 === Duet Control Server === Duet Control Server v3.3.0 File: Buffered code: G1 X142.033 Y123.366 E.03109 Buffered code: G1 X141.885 Y124.128 E.02626 Buffered code: ; stop printing object handle v1 id:0 copy 0 Buffered code: ;LAYER_CHANGE Buffered code: ;HEIGHT:0.200001 Buffered code: G1 Z16.5 F7800 Buffered code: ; M98 P"0:sys/print_layer_change_script.g" Buffered code: ; printing object handle v1 id:0 copy 0 Buffered code: G10 ; retract Buffered code: G1 X129.874 Y119.338 Buffered code: G11 ; unretract Buffered code: G1 F900 Buffered code: G1 X130.127 Y119.109 E.01155 Buffered code: G1 X130.422 Y118.89 E.01242 Buffered code: G1 X130.737 Y118.701 E.01243 Buffered code: G1 X131.069 Y118.544 E.01242 Buffered code: G1 X131.414 Y118.421 E.01243 Buffered code: G1 X131.793 Y118.326 E.01323 Buffered code: G1 X132.434 Y118.26 E.02181 Buffered code: G1 X132.861 Y118.277 E.01445 Buffered code: G1 X133.23 Y118.331 E.01262 Buffered code: G1 X133.586 Y118.421 E.01242 Buffered code: G1 X133.931 Y118.544 E.01243 Buffered code: G1 X134.263 Y118.701 E.01242 Buffered code: G1 X134.578 Y118.89 E.01242 Buffered code: G1 X134.873 Y119.109 E.01242 Buffered code: G1 X135.145 Y119.355 E.01243 ==> 1316 bytes Code buffer space: 2304 Configured SPI speed: 8000000Hz Full transfers per second: 52.41, max wait times: 21.7ms/0.0ms Codes per second: 51.64 Maximum length of RX/TX data transfers: 4552/1664 File /opt/dsf/sd/gcodes/handle v1 no-layer-change-macro.gcode is selected, processing -
I've found https://github.com/Duet3D/DuetSoftwareFramework/issues/137, which I believe covers my problem pretty well.
I managed to play with various values in DCS config and achieved an improvement, although at very high speeds I still get the occasional "thinking pause".
My new values in
/opt/dsf/conf/config.jsonare:"SpiBufferSize": 16384, # was 8192 "SpiFrequency": 16000000, # was 8000000 "SpiPollDelay": 15, # was 25 "BufferedPrintCodes": 128, # was 32 "BufferedMacroCodes": 64, # was 16 "MaxBufferSpacePerChannel": 3000, # was 1536 "MaxCodeBufferSize": 512, # was 256 "MaxMessageLength": 8192, # was 4096@chrishamm how "safe" are these new values? My RPi seems to have plenty of RAM, so I'm not too worried on that side. Any chance of running into actual memory limits on the Duet2?
-
@resam your might wish to try switching to the unstable feed on the package server so that you can install RRF 3.4.0beta7. The protocol between the Pi and the Duet has been improved since RRF 3.3. @chrishamm may be able to provide more details.
-
@resam Please try 3.4-b7 and check if the problem persists - there have been significant timing changes since 3.3 in order to address this and a few other problems.
