esp32: crash when calling dynamically loaded native module function

[tve]

I started writing a dynamically loadable native module and before I got to add any real code the "stub testing" I did caused a hard crash (Guru meditation error, etc). A backtrace shows:

PC: 0x400df854: mp_call_function_n_kw at /home/src/esp32/mpy-1.13/micropython/ports/esp32/../../py/r
untime.c:649
BT-0: 0x400df851: mp_call_function_n_kw at /home/src/esp32/mpy-1.13/micropython/ports/esp32/../../py
/runtime.c:646
BT-1: 0x400df98e: mp_call_method_n_kw at /home/src/esp32/mpy-1.13/micropython/ports/esp32/../../py/r
untime.c:666
BT-2: 0x400ed47d: mp_execute_bytecode at /home/src/esp32/mpy-1.13/micropython/ports/esp32/../../py/v
m.c:1085

it crashes on the type->call:

    // do the call
    if (type->call != NULL) {
        return type->call(fun_in, n_args, n_kw, args);
    }

Sometimes as I modify unrelated code, instead of a crash I get a non-sensical "tuple cannot be called" or "bytearray cannot be called" exception (I forget the exact exception text). I suspect that something that gets loaded as part of the module gets garbage collected or perhaps not properly sized... Notice the explicit GC calls in the test code, which I added to replace a gc.threshold I had in my original code.

I spent time to reduce to a small reproducible test case, which is in the attached zip file. For me this fails with both the released generic v1.12 and v1.13 firmwares (esp32-idf4-20191220-v1.12.bin, esp32-idf4-20200902-v1.13.bin). To reproduce:

• expand the zip archive mpy-zzz.tar.gz
• perform an erase_all on your esp32
• flash either v1.12 or v1.13
• pyboard.py -f cp *.py modu8g2.mpy :/
• start minicom, reset the board, and watch it crash

The crash looks like this:

MicroPython 1.12.0 v1.12 on 2019-12-20
initialising module self=3ffe5310
done with 3ffe5310
*** modinfo initial
access(): [0, 0, 0, 0]
access(1): 0
draw_glyph_GS4: start
draw_glyph_GS4(...): (nil)
modu8g2: initial ['__class__', '__name__', '__file__', 'access', 'draw_glyph_GS4']
  access <class 'function'> ['__class__']
  draw_glyph_GS4 <class 'function'> ['__class__']
Loading mqtt
*** modinfo pre-loading
access(): [0, 0, 0, 0]
access(1): 0
draw_glyph_GS4: start
draw_glyph_GS4(...): (nil)
modu8g2: pre-loading ['__class__', '__name__', '__file__', 'access', 'draw_glyph_GS4']
  access <class 'function'> ['__class__']
  draw_glyph_GS4 <class 'function'> ['__class__']
*** modinfo post-loading
Guru Meditation Error: Core  1 panic'ed (LoadProhibited). Exception was unhandled.
Core 1 register dump:
PC      : 0x400df4c0  PS      : 0x00060f30  A0      : 0x800df554  A1      : 0x3ffd0290
A2      : 0x3ffe5434  A3      : 0x00000000  A4      : 0x00000000  A5      : 0x3ffe5384
A6      : 0x00000001  A7      : 0x000011fa  A8      : 0x800df4c0  A9      : 0x3ffd0270
A10     : 0xffffffff  A11     : 0x00000482  A12     : 0x3ffe537c  A13     : 0x0000be3b
A14     : 0x3f4002d4  A15     : 0x00000002  SAR     : 0x0000001e  EXCCAUSE: 0x0000001c
EXCVADDR: 0x0000000f  LBEG    : 0x4000c46c  LEND    : 0x4000c477  LCOUNT  : 0x00000000

I've tried to trace the native module loading but it's pretty obscure sparsely documented code...

NB: I looked at https://github.com/micropython/micropython/commit/9883d8e818feba112935676eb5aa4ce211d7779c and it doesn't apply to esp32.

[jonnor]

A comment over here seems to support that it is possible for modules to get GC'ed https://github.com/micropython/micropython/issues/6592#issuecomment-722335722 - so that could indeed be what is going on here?

[jonnor]

I seem to be hitting this issue - or something very similar - on recent MicroPython versions. Have tested 1.22.0, 1.22.2, 1.23.0, as well as v1.24.0-preview.92.gf61fac0ba - all ESP32_GENERIC_S3 downloads from the official website.

Here is some simple code that reproduces this issue.

import gc
import array
from distance import euclidean_argmin

# Test using the function
print(euclidean_argmin)

vv = array.array('B', [0, 0, 0, 1, 1, 1, 2, 2, 2])
p = array.array('B', [1, 1, 1])

idx, dist = euclidean_argmin(vv, p)
print(idx, dist)
# Works as expected, prints "1 0"

# Do some unrelated things that allocate/free memory
unrelated = array.array('B', (1337 for _ in range(100)))
gc.collect()

PALETTE_EGA16_HEX = [
    '#ffffff',
    '#aa0000',
    '#ff55ff',
    '#ffff55',
]

def hex_to_rgb8(s : str) -> tuple:
    assert s[0] == '#'

    r = int(s[1:3], 16)
    g = int(s[2:4], 16)
    b = int(s[4:6], 16)
    return r, g, b

data = []
for h in PALETTE_EGA16_HEX:
    data.append(hex_to_rgb8(h))

# Try using the function in the same way
# Get errors like: 'slice' object isn't callable
# or it just crashes the interpreter
print(euclidean_argmin)
idx, dist = euclidean_argmin(vv, p)
print(idx, dist)

// distance.c
#include "py/dynruntime.h"

#include <string.h>
#include <stdint.h>

#if 0
#define debug_printf(...) mp_printf(&mp_plat_print, "distance-" __VA_ARGS__)
#else
#define debug_printf(...) //(0)
#endif

// Find which vector in @vectors that @v is closes to
uint16_t
compute_euclidean3_argmin_uint8(const uint8_t *vectors, int vectors_length,
            const uint8_t *vv, int channels, uint32_t *out_dist)
{

    uint16_t min_idx = 0;
    uint32_t min_value = UINT32_MAX-10;
    for (int i=0; i<vectors_length; i++) {
        uint32_t dist = 0;

        for (int j=0; j<channels; j++) {
            uint8_t c = vectors[(i*channels)+j];
            uint8_t v = vv[j];
            dist += (v - c) * (v - c);
        }
        if (dist < min_value) {
            min_value = dist;
            min_idx = i;
        }
    }
    if (out_dist) {
        *out_dist = min_value;
    }

    return min_idx;
}

// MicroPython API
static mp_obj_t
euclidean_argmin(mp_obj_t vectors_obj, mp_obj_t point_obj) {

    // First arg
    mp_buffer_info_t bufinfo;
    mp_get_buffer_raise(vectors_obj, &bufinfo, MP_BUFFER_RW);
    if (bufinfo.typecode != 'B') {
        mp_raise_ValueError(MP_ERROR_TEXT("expecting B array (uint8)"));
    }
    const uint8_t *values = bufinfo.buf;
    const int values_length = bufinfo.len / sizeof(*values);

    // Second arg
    mp_get_buffer_raise(point_obj, &bufinfo, MP_BUFFER_RW);
    if (bufinfo.typecode != 'B') {
        mp_raise_ValueError(MP_ERROR_TEXT("expecting B array (uint8)"));
    }
    const uint8_t *point = bufinfo.buf;
    const int n_channels = bufinfo.len / sizeof(*values);

    if ((values_length % n_channels) != 0) {
        mp_raise_ValueError(MP_ERROR_TEXT("vectors length must be divisible by @point dimensions"));
    }

    const int vector_length = values_length / n_channels;

    debug_printf("in in=%d vectors=%d channels=%d \n", \
        values_length, vector_length, n_channels
    );

    uint32_t min_dist = 0;
    const uint16_t min_index = \
        compute_euclidean3_argmin_uint8(values, vector_length, point, n_channels, &min_dist);

    debug_printf("out idx=%d dist=%d \n", \
        (int)min_index, (int)min_dist
    );

    return mp_obj_new_tuple(2, ((mp_obj_t []) {
        mp_obj_new_int(min_index),
        mp_obj_new_int(min_dist),
    }));
 }
static MP_DEFINE_CONST_FUN_OBJ_2(euclidian_argmin_obj, euclidean_argmin);

// This is the entry point and is called when the module is imported
mp_obj_t mpy_init(mp_obj_fun_bc_t *self, size_t n_args, size_t n_kw, mp_obj_t *args) {
    // This must be first, it sets up the globals dict and other things
    MP_DYNRUNTIME_INIT_ENTRY

    mp_store_global(MP_QSTR_euclidean_argmin, MP_OBJ_FROM_PTR(&euclidian_argmin_obj));

    // This must be last, it restores the globals dict
    MP_DYNRUNTIME_INIT_EXIT
}

# Makefile
# Location of top-level MicroPython directory
MPY_DIR = ../../micropython

# Architecture to build for (x86, x64, armv6m, armv7m, xtensa, xtensawin)
ARCH = x64

# The ABI version for .mpy files
MPY_ABI_VERSION := 6.2

DIST_DIR := ./dist/$(ARCH)_$(MPY_ABI_VERSION)

# Name of module
MOD = distance

# Source files (.c or .py)
SRC = distance.c

# Releases
DIST_FILE = $(DIST_DIR)/$(MOD).mpy
$(DIST_DIR):
    mkdir -p $@

$(DIST_FILE): $(MOD).mpy $(DIST_DIR)
    cp $< $@

include $(MPY_DIR)/py/dynruntime.mk

dist: $(DIST_FILE)

[jonnor]

Did some investigation, and managed to minimize what is needed to reproduce this. In the code below, if one uses #if 0 then the issue does not reproduce. With #if 1 it does reproduce - in form of a crash on ESP32 when trying to access the module function (after GC has been ran). To the best of my understanding, there is nothing wrong with the code inside the #if define code per se - it follows the same conventions used in several other natmod examples. So I have really no idea why this happens. Anyone got ideas on what to check next?

I have integrated it into the test that existed around this stuff, in https://github.com/jonnor/micropython/tree/18d15fcf1538d945fa3fcb2a366ceab62614cc9a (based on master as of today)

So one can then reproduce by running this against a connected ESP32 device

python tests/run-tests.py --target esp32 tests/micropython/import_mpy_native_gc.py; python tests/run-tests.py --target esp32 tests/micropython/import_mpy_native_gc.py --print-failures

To update the mpy code which is inlined in the test, use this command, and copy the buffer into the test for xtensawin.

make clean && make ARCH=xtensawin && cat distance.mpy | python -c 'import sys; print(sys.stdin.buffer.read())'

Module code

#include "py/dynruntime.h"
#include <stdint.h>

static mp_obj_t
euclidean_argmin(mp_obj_t vectors_obj, mp_obj_t point_obj) {

    // Checking first arg
    mp_buffer_info_t bufinfo;
    mp_get_buffer_raise(vectors_obj, &bufinfo, MP_BUFFER_RW);

// XXX: switching this to 0 makes issue not reproduce. Unsure why...
#if 1
    if (bufinfo.typecode != 'B') {
        mp_raise_ValueError(MP_ERROR_TEXT("expecting B array (uint8)"));
    }
#endif
    // hardcoded return values
    uint32_t min_dist = 0;
    const uint16_t min_index = 1;

    return mp_obj_new_tuple(2, ((mp_obj_t []) {
        mp_obj_new_int(min_index),
        mp_obj_new_int(min_dist),
    }));
 }
static MP_DEFINE_CONST_FUN_OBJ_2(euclidian_argmin_obj, euclidean_argmin);

// This is the entry point and is called when the module is imported
mp_obj_t mpy_init(mp_obj_fun_bc_t *self, size_t n_args, size_t n_kw, mp_obj_t *args) {
    // This must be first, it sets up the globals dict and other things
    MP_DYNRUNTIME_INIT_ENTRY

    mp_store_global(MP_QSTR_euclidean_argmin, MP_OBJ_FROM_PTR(&euclidian_argmin_obj));

    // This must be last, it restores the globals dict
    MP_DYNRUNTIME_INIT_EXIT
}

[jonnor]

In case it can be useful, here is the output of the module build with and without triggering the issue.

Triggers crash

arch:         EM_XTENSA
text size:    141
rodata size:  36
bss size:     0
GOT entries:  4
GEN distance.mpy
b'M\x06+\x1f\x02\x002build/distance.native.mpy\x00 euclidean_argmin\x00\x88j\x06\x18\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x1c\x00\x00\x006\x81\x001\xfb\xff\xad\x02\x82#A\x0c|\xbd\x01\xe0\x08\x00\x88!L"\'\x18\x10"#72#\x07<z\xe0\x03\x00\xb1\xf5\xff\xe0\x02\x00"#\x138C\x0c+\x0c\x1a\xe0\x03\x00\xa91\x0c+\xa2\xa0\x00\xe0\x03\x00\xa9A\xcb\xb1\x0c*\xe0\x02\x00-\n\x1d\xf0\x00\x00\x006A\x001\xe7\xff(\x12HS\xa2"\x01\xe0\x04\x00\x91\xe5\xff\x88\xd3\xb1\xe5\xff-\n\xa2\x19\x01\xe0\x08\x00\xad\x02\xe0\x04\x00(\x03\x1d\xf00$expecting B array (uint8)\x00\x00\x00\x00\x00\x00\x00\x14\x00\x00\x00\x11\x02\r\x04\x07\x06\x02\xb1\x0f\x01\x11\xff'

Does not trigger

arch:         EM_XTENSA
text size:    113
rodata size:  8
bss size:     0
GOT entries:  3
GEN distance.mpy
b'M\x06+\x1f\x02\x002build/distance.native.mpy\x00 euclidean_argmin\x00\x87\n\x06\x11\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x006\x81\x001\xfc\xff\x0c|\x82#A\x10\xb1  \xa2 \xe0\x08\x00"#\x138C\x0c+\x0c\x1a\xe0\x03\x00\xa91\x0c+\x0c\n\xe0\x03\x00\xa9A\xcb\xb1\x0c*\xe0\x02\x00-\n\x1d\xf0\x00\x006A\x001\xee\xff(\x12HS\xa2"\x01\xe0\x04\x00\x91\xec\xff\x88\xd3\xb1\xeb\xff-\n\xa2\x19\x01\xe0\x08\x00\xad\x02\xe0\x04\x00(\x03\x1d\xf00\x08\x00\x00\x00\x00\x10\x00\x00\x00\x11\x02\r\x04\x05\x06\xb1\x01\x01\x03\xff'

[jonnor]

Have been investigating how this is implemented. It seems that py/persistentcode.c and load_raw_code is used to load in the native code. In the case of ESP32 the MP_PLAT_COMMIT_EXEC macro is set. That means the function esp_native_code_commit in ports/esp32/main.c is called to store the code. This function uses heap_caps_malloc(len, MALLOC_CAP_EXEC) to allocate space. And the puts an object on a MicroPython root pointer native_code_pointers to track it. During soft reset, all objects on that root pointer are explicitly freed. Apart from that, I do not see any code that frees code from this - so my naive thinking is that this should have lifetime until soft reset?

In this bug, we are seeing that the native code function is being can get replaced by standard Python objects, such as a string, tuple, list etc. Is it expected that the same memory can be used for Python objects and native code - ie from the same heap (on ESP32)?

[jonnor]

I got an JTAG debugger set up to look at this properly. And I believe I have found the issue - the allocations done by the MicroPython GC are overwriting the allocations done by heap_caps_malloc(len, MALLOC_CAP_EXEC). Below the steps I did in MicroPython repl + GDB.

But I do not know how to fix this. And I do not understand, what mechanism is supposed to prevent gc_alloc() from overwriting what was allocated by heap_caps_malloc()? It seems like they are sharing the same memory areas, and I do not see how one is aware of the other...

Import native module

>>> import micropython
>>> import distance
>>> hex(id(distance.euclidean_argmin))
'0x3fcab96c'

Setup watchpoint for the memory of the native module

(gdb) watch *0x3fcab96c
Hardware watchpoint 8: *0x3fcab96c

Do some things that allocate memory, with GC in between

Not really important what it is

>>> import micropython
>>> micropython.mem_info(True)
stack: 720 out of 15360
GC: total: 64000, used: 3120, free: 60880, max new split: 188416
 No. of 1-blocks: 57, 2-blocks: 12, max blk sz: 18, max free sz: 3793
GC memory layout; from 3fcab310:
00000000: h=hLhhhBMhhDhhhh=hhh=================hh=======h=======h=hh======
00000400: =========Bhhh=hhhBhhhhh==BMDhhh=hhhhh==hh=h===============h=====
00000800: ===hLhh=h===h==Bh=======h==========hSDhh=hhhhh=Bh=hhh===hB..hhh=
00000c00: .......h=...h==.................................................
       (58 lines all free)
0000f800: ................................
>>> micropython.mem_info(True)
stack: 720 out of 15360
GC: total: 64000, used: 3280, free: 60720, max new split: 188416
 No. of 1-blocks: 62, 2-blocks: 13, max blk sz: 18, max free sz: 3783
GC memory layout; from 3fcab310:
00000000: h=hLhhhBMhhDhhhh=hhh=================hh=======h=======h=hh======
00000400: =========Bhhh=hhhBhhhhh==BMDhhh=hhhhh==hh=h===============h=====
00000800: ===hLhh=h===h==Bh=======h==========hSDhh=hhhhh=Bh=hhh===hBhhhhh=
00000c00: hB..h..h=h=.h==.......h==.......................................
       (58 lines all free)
0000f800: ................................
>>> gc.collect()
>>> micropython.mem_info(True)

gc_alloc overwrites the memory of the native module

Thread 2 "mp_task" hit Hardware watchpoint 8: *0x3fcab96c

Old value = 1007828420
New value = 0
0x400570f0 in ?? ()
(gdb) bt
#0  0x400570f0 in ?? ()
#1  0x4200bcb6 in gc_alloc (n_bytes=<optimized out>, alloc_flags=0) at /home/jon/projects/micropython/py/gc.c:853
#2  0x4200c1a0 in m_malloc (num_bytes=512) at /home/jon/projects/micropython/py/malloc.c:86
#3  0x42045ad6 in mp_parse (lex=0x3fcab6a0, input_kind=MP_PARSE_SINGLE_INPUT) at /home/jon/projects/micropython/py/parse.c:1036
#4  0x42024f0c in parse_compile_execute (source=0x3fcedca0, input_kind=MP_PARSE_SINGLE_INPUT, exec_flags=22) at /home/jon/projects/micropython/shared/runtime/pyexec.c:109
#5  0x4202526f in pyexec_friendly_repl () at /home/jon/projects/micropython/shared/runtime/pyexec.c:675
#6  0x420086cf in mp_task (pvParameter=<optimized out>) at /home/jon/projects/micropython/ports/esp32/main.c:162

Try access the native module function

>>> repr(distance.euclidean_argmin)

Crashes

Thread 2 "mp_task" received signal SIGTRAP, Trace/breakpoint trap.
mp_obj_print_helper (print=0x3fceda70, o_in=0x3fcab96c, kind=PRINT_REPR) at /home/jon/projects/micropython/py/obj.c:128
128     if (MP_OBJ_TYPE_HAS_SLOT(type, print)) {

[jonnor]

Looks like the seemingly separate allocators were a red herring. On ESP32 the GC does get its underlying memory blocks from the esp-idf heap allocator. Notably the initial memory is allocated in main.c with MP_PLAT_ALLOC_HEAP (which calls malloc(), which calls heap_malloc_caps(...)), and then on growth gc_try_add_heap() also calls MP_PLAT_ALLOC_HEAP. I also checked the pointer returned for the native code - and that has an address far from the (initial) GC heap.

So it is not a case of colliding heaps, or that the native code gets overwritten. What is being overwritten by the GC is the function object, which wrap the native code. But the Python object that represents the module does not get overwritten. Neither does the name or file properties. Which I naively thought would be referenced / kept by the GC using the same mechanism?

Why would a (reachable) function of a module be garbage collected? And why do we seemingly only see this behavior on ESP32 ?

[jonnor]

I set the CLEAR_ON_SWEEP setting in py/gc.c. Now it is very easy with gdb to see that it gets garbage collected immediately, without influence by anything else. Minimal way to reproduce:

import distance
hex(id(distance.euclidean_argmin))

(gdb) watch *0x3fcab8cc

gc.collect()

Thread 4 "mp_task" hit Hardware watchpoint 3: *0x3fcab8cc

Old value = 1007828928
New value = 0
0x400570f0 in ?? ()
(gdb) bt
#0  0x400570f0 in ?? ()
#1  0x4200bace in gc_sweep () at /home/jon/projects/micropython/py/gc.c:538
#2  gc_collect_end () at /home/jon/projects/micropython/py/gc.c:638
#3  0x4202cd29 in gc_collect () at /home/jon/projects/micropython/ports/esp32/gccollect.c:61
#4  0x420411a6 in py_gc_collect () at /home/jon/projects/micropython/py/modgc.c:35
#5  0x4200fcb5 in fun_builtin_0_call (self_in=0x3c138c40 <gc_collect_obj>, n_args=0, n_kw=0, args=0x3fcedb90) at /home/jon/projects/micropython/py/objfun.c:56
....

[jonnor]

I verified that a pointer to the code buffer is added to the native_code_pointers list in esp_native_code_commit. And using a watchpoint I can see that gc_mark_subtree is called on native_code_pointers. That should allow the GC to see that the function objects are in use? If so, I have no idea why the function gets garbage collected.

[dpgeorge]

Thanks @jonnor for the detailed debugging. Based on your observations I'm pretty sure your issue (and probably the original issue posted here) is the same as #6592.

The point is that the function wrapper object for euclidean_argmin is stored in the native code bss/rodata:

static MP_DEFINE_CONST_FUN_OBJ_2(euclidian_argmin_obj, euclidean_argmin);

and that bss/rodata block is allocated on the MicroPython GC heap. It's this block that is being inadvertently reclaimed by the GC and reused for other Python objects (the actual native/machine code of the function is allocated using heap_malloc_caps).

When the #if 0 is used in your code above the issue goes away because in that case the function wrapper object is at the start of the bss/rodata and so as long as you have a pointer to the function the GC can see that the bss/rodata is being used. But when the #if 1 is used the function wrapper object is in the middle of the bss/rodata (the exception message appears before it) and then the GC does not see the bss/rodata as being used/pointed to.

In the case of your very simple native code with just an init function and the euclidean_argmin function, the latter is the only thing remaining after importing the module. The top-level mpy_init() code is no longer used, neither is anything it points to, including the bss/rodata (which is stored in the child_table pointer to try and maintain a reference to it, but this isn't working when the top-level module code is reclaimed by the GC).

One way to fix it would be to enable MICROPY_PERSISTENT_CODE_TRACK_RELOC_CODE on esp32 and apply this patch:

--- a/py/persistentcode.c
+++ b/py/persistentcode.c
@@ -299,11 +299,11 @@ static mp_raw_code_t *load_raw_code(mp_reader_t *reader, mp_module_context_t *co
                 read_bytes(reader, rodata, rodata_size);
             }

-            // Viper code with BSS/rodata should not have any children.
-            // Reuse the children pointer to reference the BSS/rodata
-            // memory so that it is not reclaimed by the GC.
-            assert(!has_children);
-            children = (void *)data;
+            // Retain a pointer to the BSS/rodata so that it is not reclaimed by the GC.
+            if (MP_STATE_PORT(track_reloc_code_list) == MP_OBJ_NULL) {
+                MP_STATE_PORT(track_reloc_code_list) = mp_obj_new_list(0, NULL);
+            }
+            mp_obj_list_append(MP_STATE_PORT(track_reloc_code_list), MP_OBJ_FROM_PTR(data));
         }
     }
     #endif

The other way to fix it might be to apply #6061 (which was not merged), which will retain a pointer to the mpy_init() function wrapper object, which in turn points to the bss/rodata section.

@jonnor are you able to try both of those fixes above, one at a time, to see if they work in your case?

---

One of your comments above is pertinent:

Why would a (reachable) function of a module be garbage collected? And why do we seemingly only see this behavior on ESP32 ?

The function object is not actually reachable by the GC because it's stored in the bss/rodata, and that is one big chunk of GC data. The head of this bss/rodata is reachable only from the top-level module init function, which can get reclaimed once the module has been imported.

The bug should be evident on all architectures, not just ESP32.

[darconeous]

I was running into this problem on 1.23 and applying #6061 fixed it. w00t!

[dpgeorge]

@jonnor any comment/ideas on my comment above https://github.com/micropython/micropython/issues/6769#issuecomment-2227676231 ?

[jonnor]

I have been struggling a bit to find concentration time lately. Will test on the weekend or early next week.