Question: Array Assignment

DonStauffer

@DonStauffer Ran these macros a couple times without error, then ran again and got this log. You can see the effect is unpredictable and not reproducable:

Log:

LED Num= 4
Pend= {0,0,0}
PendingOld= 0 Clr= 0 Pend= {0,0,0} iters= 0
Almost Bot Pend= {0,0,0}
Bot Pend = {0,null,null}
Pend= {0,null,null}
PendingOld= null Clr= 0 Pend= {0,null,null} iters= 1
Error: in file macro line 58 column 54: meta command: expected numeric operands

dc42

@DonStauffer please provide the declarations of the missing variables so that we can try to reproduce this. For example: var.Count, var.PEND, global.NeoPixColor.

It would also be worth running M122 to check whether it still reports "Heap OK", or reports a heap error.

DonStauffer

@dc42

;-------------------------------------------------------------------------------
;	AddNeoPix
;-------------------------------------------------------------------------------
;	Adds color values to pending NeoPixel LED color values.
;   Does no I2C communication. Call SendNeoPix to update via I2C, and
;   ShowNeoPix to display changes.
;
;	Parameters
;		C	Color Array {R, G, B}
;		S	Starting LED Number
;		N	Number of LEDs to Set
;-------------------------------------------------------------------------------
;	Don Stauffer							April, 2024
;-------------------------------------------------------------------------------
echo "AddNeoPix C",param.C," S", param.S, " N", param.N

;   Constants

var PEND = 1

;   Parameters

var Color = {0, 0, 0}
var Start = 0
var Count = global.NeoPixLEDCount

if exists(param.C)
    set var.Color = param.C

if exists(param.S)
    set var.Start = param.S

if exists(param.N)
    set var.Count = param.N

;   Add to pending color values, to be sent later

var LEDNum = 0
var Pending = vector(3, 0)
var PendingOld = vector(3, 0)
var Clr = vector(3, 0)
var PendingNew = vector(3, 0)

while iterations < var.Count

    set var.LEDNum = var.Start + iterations

    set var.Pending = global.NeoPixColor[var.PEND][var.LEDNum]
    if var.Pending == null
        set var.Pending = {0, 0, 0}
    
    echo "LED Num=",var.LEDNum
    while iterations < #var.Color
        echo "Pend=",var.Pending
        set var.PendingOld = var.Pending[iterations]
        set var.Clr = var.Color[iterations]
        echo "PendingOld=",var.PendingOld,"Clr=",var.Clr,"Pend=",var.Pending,"iters=",iterations
        set var.PendingNew = var.PendingOld + var.Clr
        echo "Almost Bot Pend=",var.Pending
        set var.Pending[iterations] = var.PendingNew
        echo "Bot Pend =",var.Pending
        ;echo "PendingNew=",var.PendingNew

    set global.NeoPixColor[var.PEND][var.LEDNum] = var.Pending
    echo "Pending=",var.Pending

echo "Exiting AddNeoPix"

DonStauffer

@DonStauffer All this macro does is take the RGB color array in param.C, and for each of param.N LEDNum value starting from param.S, updates global.NeoPixColor[1][LEDNum]. The update simply adds the 3 elements from param.C to the corresponding elements of each of those global.NeoPixColor elements; if a global.NeoPixColor element is null, the value in param.C replaces that element.

So, M98 P"...AddNeoPix" C{1, 2, 3} S5 N3 should effectively do this:

if global.NeoPixColor[1][5] == null
    set global.NeoPixColor[1][5] = param.C
else
    set global.NeoPixColor[1][5][0] = global.NeoPixColor[1][5][0]+param.C[0] ; add 1
    set global.NeoPixColor[1][5][1] = global.NeoPixColor[1][5][1]+param.C[1] ; add 2
    set global.NeoPixColor[1][5][2] = global.NeoPixColor[1][5][2]+param.C[2] ; add 3

if global.NeoPixColor[1][6] == null
    set global.NeoPixColor[1][6] = param.C
else
    set global.NeoPixColor[1][6][0] = global.NeoPixColor[1][6][0]+param.C[0] ; add 1
    set global.NeoPixColor[1][6][1] = global.NeoPixColor[1][6][1]+param.C[1] ; add 2
    set global.NeoPixColor[1][6][2] = global.NeoPixColor[1][6][2]+param.C[2] ; add 3

if global.NeoPixColor[1][7] == null
    set global.NeoPixColor[1][7] = param.C
else
    set global.NeoPixColor[1][7][0] = global.NeoPixColor[1][7][0]+param.C[0] ; add 1
    set global.NeoPixColor[1][7][1] = global.NeoPixColor[1][7][1]+param.C[1] ; add 2
    set global.NeoPixColor[1][7][2] = global.NeoPixColor[1][7][2]+param.C[2] ; add 3

DonStauffer

@dc42 It seems like the Duet rebooted after the error, so I don't know if this is useful. Trying to get an M122 after the error but without a reboot between. Will post if successful.

5/15/2024, 11:59:10 AM M122
=== Diagnostics ===
RepRapFirmware for Duet 2 WiFi/Ethernet version 3.5.1 (2024-04-19 14:40:46) running on Duet WiFi 1.02 or later + DueX5
Board ID: 08DGM-9T6BU-FG3SN-6JKD0-3S06Q-9AY7D
Used output buffers: 3 of 26 (23 max)
=== RTOS ===
Static ram: 23256
Dynamic ram: 75600 of which 0 recycled
Never used RAM 11432, free system stack 182 words
Tasks: NETWORK(1,ready,13.5%,215) HEAT(3,nWait 5,0.1%,328) Move(4,nWait 5,0.0%,359) DUEX(5,nWait 5,0.0%,19) MAIN(1,running,86.4%,703) IDLE(0,ready,0.0%,29), total 100.0%
Owned mutexes:
=== Platform ===
Last reset 00:44:07 ago, cause: software
Last software reset at 2024-05-15 11:15, reason: HardFault bfarValid precise, Gcodes spinning, available RAM 824, slot 0
Software reset code 0x4063 HFSR 0x40000000 CFSR 0x00008200 ICSR 0x00417803 BFAR 0x6d754e40 SP 0x20002568 Task MAIN Freestk 1151 ok
Stack: 6d754e44 6d754e40 200027a3 00000017 ffffffff 0045d6a7 004663aa 210e0000 00410f21 20002784 00000017 20002684 20002784 00000002 00000000 00000001 00411491 00000000 20002680 20002688 00000001 00000000 00000001 a5a5a5a5 00000000 454c000c 6d754e44
Error status: 0x00
Aux0 errors 0,0,0
MCU temperature: min 42.9, current 43.3, max 46.9
Supply voltage: min 24.0, current 24.1, max 24.4, under voltage events: 0, over voltage events: 0, power good: yes
Heap OK, handles allocated/used 99/35, heap memory allocated/used/recyclable 2048/1188/56, gc cycles 1
Events: 0 queued, 0 completed
Driver 0: standstill, SG min n/a
Driver 1: standstill, SG min n/a
Driver 2: standstill, SG min n/a
Driver 3: standstill, SG min n/a
Driver 4: standstill, SG min n/a
Driver 5: standstill, SG min n/a
Driver 6: standstill, SG min n/a
Driver 7: standstill, SG min n/a
Driver 8: standstill, SG min n/a
Driver 9: standstill, SG min n/a
Driver 10:
Driver 11:
Date/time: 2024-05-15 11:59:09
Cache data hit count 4294967295
Slowest loop: 8.79ms; fastest: 0.19ms
I2C nak errors 0, send timeouts 0, receive timeouts 0, finishTimeouts 0, resets 0
=== Storage ===
Free file entries: 10
SD card 0 detected, interface speed: 20.0MBytes/sec
SD card longest read time 2.1ms, write time 0.0ms, max retries 0
=== Move ===
DMs created 83, segments created 0, maxWait 0ms, bed compensation in use: none, height map offset 0.000, max steps late 0, min interval 0, bad calcs 0, ebfmin 0.00, ebfmax 0.00
no step interrupt scheduled
Moves shaped first try 0, on retry 0, too short 0, wrong shape 0, maybepossible 0
=== DDARing 0 ===
Scheduled moves 0, completed 0, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 0], CDDA state -1
=== Heat ===
Bed heaters 0 -1 -1 -1, chamber heaters -1 -1 -1 -1, ordering errs 0
Heater 1 is on, I-accum = 0.0
=== GCodes ===
Movement locks 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
Daemon is idle in state(s) 0
Autopause is idle in state(s) 0
Q0 segments left 0
Code queue 0 is empty
=== Filament sensors ===
check 0 clear 21909205
Extruder 0 sensor: no data received
Extruder 1 sensor: no data received
=== DueX ===
Read count 1, 0.02 reads/min
=== Network ===
Slowest loop: 8.52ms; fastest: 0.00ms
Responder states: HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0)
HTTP sessions: 1 of 8
=== WiFi ===
Interface state: active
Module is connected to access point
Failed messages: pending 0, notrdy 0, noresp 0
Firmware version 2.1.0
MAC address 84:f3:eb:83:47:be
Module reset reason: Power up, Vcc 3.36, flash size 4194304, free heap 42792
WiFi IP address 192.168.1.130
Signal strength -45dBm, channel 11, mode 802.11n, reconnections 0
Clock register 00002002
Socket states: 0 0 0 0 0 0 0 0

DonStauffer

@DonStauffer

This was after a run which had multiple losses of WiFi connectivity, which has been happening a lot lately, but afterward it still showed as Homed, so it must not have rebooted.

5/15/2024, 12:08:43 PM M122
=== Diagnostics ===
RepRapFirmware for Duet 2 WiFi/Ethernet version 3.5.1 (2024-04-19 14:40:46) running on Duet WiFi 1.02 or later + DueX5
Board ID: 08DGM-9T6BU-FG3SN-6JKD0-3S06Q-9AY7D
Used output buffers: 12 of 26 (26 max)
=== RTOS ===
Static ram: 23256
Dynamic ram: 80072 of which 224 recycled
Never used RAM 952, free system stack 116 words
Tasks: NETWORK(1,ready,15.1%,215) HEAT(3,nWait 5,0.1%,328) Move(4,nWait 5,0.0%,298) DUEX(5,nWait 5,0.0%,19) MAIN(1,running,84.0%,703) IDLE(0,ready,0.8%,29), total 100.0%
Owned mutexes:
=== Platform ===
Last reset 00:53:40 ago, cause: software
Last software reset at 2024-05-15 11:15, reason: HardFault bfarValid precise, Gcodes spinning, available RAM 824, slot 0
Software reset code 0x4063 HFSR 0x40000000 CFSR 0x00008200 ICSR 0x00417803 BFAR 0x6d754e40 SP 0x20002568 Task MAIN Freestk 1151 ok
Stack: 6d754e44 6d754e40 200027a3 00000017 ffffffff 0045d6a7 004663aa 210e0000 00410f21 20002784 00000017 20002684 20002784 00000002 00000000 00000001 00411491 00000000 20002680 20002688 00000001 00000000 00000001 a5a5a5a5 00000000 454c000c 6d754e44
Error status: 0x0c
Aux0 errors 0,0,0
MCU temperature: min 43.0, current 46.3, max 46.4
Supply voltage: min 24.0, current 24.2, max 24.4, under voltage events: 0, over voltage events: 0, power good: yes
Heap OK, handles allocated/used 297/68, heap memory allocated/used/recyclable 6144/2808/840, gc cycles 264
Events: 0 queued, 0 completed
Driver 0: standstill, SG min 0
Driver 1: standstill, SG min 0
Driver 2: standstill, SG min n/a
Driver 3: standstill, SG min n/a
Driver 4: standstill, SG min n/a
Driver 5: standstill, SG min 0
Driver 6: standstill, SG min 0
Driver 7: standstill, SG min 0
Driver 8: standstill, SG min n/a
Driver 9: standstill, SG min n/a
Driver 10:
Driver 11:
Date/time: 2024-05-15 12:08:42
Cache data hit count 4294967295
Slowest loop: 20.69ms; fastest: 0.10ms
I2C nak errors 0, send timeouts 0, receive timeouts 0, finishTimeouts 0, resets 0
=== Storage ===
Free file entries: 9
SD card 0 detected, interface speed: 20.0MBytes/sec
SD card longest read time 15.4ms, write time 0.0ms, max retries 0
=== Move ===
DMs created 83, segments created 3, maxWait 2785753ms, bed compensation in use: none, height map offset 0.000, max steps late 0, min interval 0, bad calcs 0, ebfmin 0.00, ebfmax 0.00
no step interrupt scheduled
Moves shaped first try 0, on retry 0, too short 0, wrong shape 0, maybepossible 0
=== DDARing 0 ===
Scheduled moves 109, completed 109, hiccups 0, stepErrors 0, LaErrors 0, Underruns [0, 0, 4], CDDA state -1
=== Heat ===
Bed heaters 0 -1 -1 -1, chamber heaters -1 -1 -1 -1, ordering errs 0
Heater 1 is on, I-accum = 0.0
=== GCodes ===
Movement locks 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
Daemon is doing "G4 P{global.DaemonPeriod}" in state(s) 0 0, running macro
Autopause is idle in state(s) 0
Q0 segments left 0
Code queue 0 is empty
=== Filament sensors ===
check 0 clear 25655011
Extruder 0 sensor: no data received
Extruder 1 sensor: no data received
=== DueX ===
Read count 0, 0.00 reads/min
=== Network ===
Slowest loop: 21.15ms; fastest: 0.07ms
Responder states: HTTP(0) HTTP(0) HTTP(0) FTP(0) Telnet(0)
HTTP sessions: 1 of 8
=== WiFi ===
Interface state: active
Module is connected to access point
Failed messages: pending 0, notrdy 0, noresp 0
Firmware version 2.1.0
MAC address 84:f3:eb:83:47:be
Module reset reason: Power up, Vcc 3.36, flash size 4194304, free heap 42792
WiFi IP address 192.168.1.130
Signal strength -41dBm, channel 11, mode 802.11n, reconnections 0
Clock register 00002002
Socket states: 0 0 0 0 0 0 0 0

DonStauffer

@dc42 More information:

(EDIT: I SPOKE TOO SOON. Still getting array corruption, or at least the "expected numeric operand" even without nan param)

(EDIT: Confirmed that array corruption is still happening.)

I've been doing some troubleshooting and discovered the macro is sometimes receiving "nan" for the S and/or N parameter(s). This shouldn't happen and was due to an uninitialized global value used to calculate those parameters by the calling macro. So far, it seems like correcting that error prevented nan in the parameters and eliminated the array corruption.

It's possible this should have resulted in RRF reporting an error somewhere, but it seems like it should have done that before corrupting array contents, though I haven't analyzed how nan would affect this macro. It also seems like it should probably either have caused an error or (if there was nothing syntactically or semantically illegal) not, rather than only causing one occasionally, although again, it's possible there's a logical reason for this. Maybe the use of nan in certain contexts should just generate an error that you can't do that, if it's letting you do it now.

I'm also still interested in whether my assumptions about array initialization and assignment are correct, and how the nuts and bolts work.

dc42

@DonStauffer how should I initialise global.NeiPixColor ?

DonStauffer

@dc42

var SENT = 0
var PEND = 1
global NeoPixLEDCount = 28

global NeoPixColor = vector(2, vector(global.NeoPixLEDCount, vector(3, 0)))
set global.NeoPixColor[var.PEND] = vector(global.NeoPixLEDCount, null)

NeoPixColor[0] holds the color already transmitted to each LED, to avoid resending data unnecessarily. NeoPixColor[1] collects updated colors for each LED, to send them all at once for efficiency. The elements are initialized to null, meaning "there is nothing to send".

I2C is a slow way to update NeoPixels. This is an attempt to eliminate some communication overhead. So AddNeoPix sums the colors sent to it for each LED, then there's a SendNeoPix macro which sends the LED colors from the "pending" part of the array, if they exist (are not null) and are not the same as the "sent" part of the array (NeoPixColor[0]). The colors get added to the pending part of the array rather than replacing existing values there, to aid in color blending, for displaying overlapping ranges of LEDs in different colors, with the middle a blend of the 2 colors.

The problem probably happens less than 1% of calls to AddNeoPix. Running bed leveling probably calls it a couple hundred times, and about half of bed levelings will produce the error. Most recent (cleaned up) code & log; it appears as though the assignment of one element of the RGB array corrupts another element (happens randomly; not always element 0 corrupting 1, or even an earlier element corrupting a later one). Not "line 56" in the error refers to what is line 21 in the snippet.

;   Add to pending color values, to be sent later

var LEDNum = null
var Pend = null

while iterations < var.Count

    set var.LEDNum = var.Start + iterations
    set var.Pend = global.NeoPixColor[var.PEND][var.LEDNum]

    ;   Check for null pending RGB array

    if var.Pend == null
        set var.Pend = {0, 0, 0}

    ;   Add new color value to pending
    echo "LED#",var.LEDNum,": Pend1=",var.Pend, "Color=",var.Color

    while iterations < #var.Color
        echo "Pend[i]=",var.Pend[iterations], "Color[i]=",var.Color[iterations]
        set var.Pend[iterations] = var.Pend[iterations] + var.Color[iterations]
    echo "Pend2=",var.Pend
    set global.NeoPixColor[var.PEND][var.LEDNum] = var.Pend

Log

LED 22 : Pend1= {0,0,0} Color= {0,32,16}
Pend[i]= 0 Color[i]= 0
Pend[i]= 0 Color[i]= 32
Pend[i]= 0 Color[i]= 16
Pend2= {0,32,16}
Exiting AddNeoPix
AddNeoPix C {0,0,0} S 23 N 5
LED# 23 : Pend1= {0,0,0} Color= {0,0,0}
Pend[i]= 0 Color[i]= 0
Pend[i]= null Color[i]= 0
Error: in file macro line 56 column 80: meta command: expected numeric operands

DonStauffer

@dc42 Workaround, tested a dozen runs with no errors; avoids subscripted assignment of RGB array elements by using 3 discrete variables to build an array to assign in its entirety:

;   Add to pending color values, to be sent later

var LEDNum = null
var Pend = null
var r = null
var g = null
var b = null

while iterations < var.Count

    set var.LEDNum = var.Start + iterations
    set var.Pend = global.NeoPixColor[var.PEND][var.LEDNum]

    ;   Check for null pending RGB array

    if var.Pend == null
        set var.Pend = {0, 0, 0}

    ;   Add new color value to pending

    set var.r = var.Pend[0] + var.Color[0]
    set var.g = var.Pend[1] + var.Color[1]
    set var.b = var.Pend[2] + var.Color[2]
    set var.Pend = {{var.r},{var.g},{var.b}}
    set global.NeoPixColor[var.PEND][var.LEDNum] = var.Pend

dc42

@DonStauffer I believe I have identified an issue when using 'set' to assign an element in an array of arrays, where the nested array whose element is being assigned is a copy of another array. I have created this issue https://github.com/Duet3D/RepRapFirmware/issues/1008.

Using 'set' with only a single array index should always be safe. For example, I think the following may be unsafe if global.myarray[1] is a copy of another array:

set global.myarray[1][2] = 1

whereas the following would be safe:

var tempArray = global.myArray[1]
set var.tempArray[2] = 1
set global.myArray[1] = var.tempArray

dc42 created this issue in Duet3D/RepRapFirmware

closed Bug: setting elements of nested arrays sometimes goes wrong #1008

DonStauffer

@dc42 Off the top of my head, that sounds like exactly the workaround I tried which didn't work. What ended up working as a workaround was avoiding subscripted assignment to the subarray, but instead constructing the array from discrete variables like
set global.myArrayrray[1] = {var.A, var.B, var.C}
I'll look back through my notes and see if I'm remembering right.

EDIT: Ah, I sort of "half" did it. I was using an array with an array element with an array element, so the original workaround attempt did start with two subscripts. Maybe that was why it didn't work. Anyhow, my workaround reconstructing the subarray "manually" without subscripts did work, so I'm not stuck any more.

Intermittent problems are tough to trouble shoot. BTW, error messages often don't name the macro they're referring to even when they give line numbers. If it's a complicated tree of nested M98 calls, it only names the outermost one and I have to go searching through the branches. The name of the macro the offending line is actually in would really help.

droftarts

@DonStauffer said in Question: Array Assignment:

Intermittent problems are tough to trouble shoot. BTW, error messages often don't name the macro they're referring to even when they give line numbers. If it's a complicated tree of nested M98 calls, it only names the outermost one and I have to go searching through the branches. The name of the macro the offending line is actually in would really help.

It’s been requested before, but can be quite a memory intensive process. See https://github.com/Duet3D/RepRapFirmware/issues/771

Ian

T3P3 created this issue in Duet3D/RepRapFirmware

open Busy status to include the macro file that is running when busy #771

DonStauffer

@droftarts Option or command to dump call stack maybe?

gloomyandy

@DonStauffer said in Question: Array Assignment:

@droftarts Option or command to dump call stack maybe?

Reply

You can always create that yourself. Have a global array that you push and pop the name of the macro to and print it out if when you need to. Or just echo the name of the macro at the start may be enough.

DonStauffer

@gloomyandy Kind of what I'm doing now. I put something like "echo "MyMacroName" at the beginning of each macro, and "Leaving MyMacroName" as the last line. That clutters the log, but I'm thinking maybe something like:

In config.g:

global CallStack = vector(<nice large number>, "")
global CallStackDepth = 0

Then, presumably at the outermost level of whatever I'm running:

set global.CallStackDepth = 0

Then in my macro:

set global.CallStack[global.CallStackDepth] = "MyMacroName"
set global.CallStackDepth = global.CallStackDepth + 1
. . .
set global.CallStackDepth = global.CallStackDepth - 1

When I needed it, I could run a DumpCallStack macro:

while iterations < global.CallStackDepth
    echo global.CallStack[iterations]

Maintaining the global.CallStackDepth = 0 could be bothersome when running a macro separately from a stack of macros, but at least it's only one simple line. But a bigger problem would be that an error may abort only the macro it's in, and the calling macro then continues. So CallStackDepth will be left too high in that case. Besides that functional problem, the stack would get more added to it after the error, leaving me unable to tell where the error was - the whole point of the stack trace. If there were a way to know about the error and do something when it occurs, this could be solved, but I don't know of a way. I'm not sure when execution continues vs. the entire call stack aborts (in which case this scheme works). I just assumed it was whether execution could continue, based on the severity of the error.

I wonder how much processing overhead this would take as compared with a compiled-in RRF solution.

gloomyandy

@DonStauffer The thing is it takes zero amount of memory and adds zero overhead for the many folks who do not need it. That would not be the case for a firmware based solution. Plus you get to use it now rather than waiting for anyone else to implement it and you can tailor it to your needs.

I suspect just echoing the name of the function at the start of a macro is enough for most situations.

DonStauffer

@gloomyandy That's what I'm doing now, but it's got some problems. Iterative calls add sometimes thousands of lines to the console log, and I have to keep adding and removing these lines of code as I go back and edit macros. I've gotten so I just comment them out and leave them there for the future. But the log clutter is problematic.

DonStauffer

@gloomyandy I suspect the amount of overhead for a compiled-in version would be very minimal. I don't know what's under the hood in RRF, but if there's a correlation between macros and subroutines, the compiler may already have debugging info stored anyway, and it would just be a matter of having a command to dump that to the log. But I'm speculating.

gloomyandy

@DonStauffer None of the compiler generated debug information is in the final binary installed on the control board there is nowhere near enough flash space for it. The pressure on RAM and (especially) flash space is already very high on the Duet2 boards so adding anything new requires a lot of thought and consideration.