RV32 native emitter fails compiling some of the tests

Port, board and/or hardware

Any RISC-V 32 architecture

MicroPython version

Current master version (commit 6007f3e)

Reproduction

Using an ESP32C3 board, run the test suite using the following:

$ cd tests
$ ./run-tests.py --target esp32 --device /dev/ttyUSB0 --via-mpy --emit native --mpy-cross-flags="-march=rv32imc" -d basics

The output is:

518 tests performed (16146 individual testcases)
488 tests passed
18 tests skipped: annotate_var builtin_next_arg2 builtin_range_binop del_deref del_local exception_chain gen_yield_from_close memoryview_itemsize namedtuple_asdict nanbox_smallint scope_implicit subclass_native_call sys_path sys_tracebacklimit try_finally_return2 try_reraise try_reraise2 unboundlocal
30 tests failed: array1 array_construct array_construct_endian array_intbig builtin_property class_ordereddict class_super dict1 dict_fixed errno1 frozenset_binop fun_calldblstar3 gc1 ifcond int1 logic_constfolding memoryview_intbig namedtuple1 set_binop stopiteration string_format_modulo string_format_modulo_int struct1 struct1_intbig struct2 struct_micropython sys_getsizeof true_value try_finally_return unpack1

The test failures are due to mpy-cross crashing:

mpy-cross: ../py/asmbase.c:94: mp_asm_base_label_assign: Assertion `as->label_offsets[label] == as->code_offset' failed.

Alternatively, a much simpler way to see the problem:

$ ./mpy-cross/build/mpy-cross -march=rv32imc -X emit=native tests/basics/array1.py 
mpy-cross: ../py/asmbase.c:94: mp_asm_base_label_assign: Assertion `as->label_offsets[label] == as->code_offset' failed.

Expected behaviour

mpy-cross should be able to compile all the tests with the rv32imc emitter selected.

Observed behaviour

mpy-cross crashes with an assertion failure.

Additional Information

No response

Code of Conduct

Yes, I agree

@agatti

@agatti you may be interested to look into this issue.

Thanks for bringing this to my attention, I'll look into this right away.

I guess there are more spots where having code sequences of variable length (as in, using RVC opcodes or performing some simple optimisations) is an issue. If there's a way for the emitter to detect it's running under mpy-cross at compile time I can attempt to have longer sequences only in that case, otherwise I'll have less efficient code also when generating code at runtime.

There are actually two issues here. The first one is mpy-cross not handling variable length sequences in asm_rv32_emit_call_ind, asm_rv32_emit_jump_if_reg_eq, asm_rv32_emit_jump_if_reg_nonzero, and asm_rv32_emit_jump. I thought that was not a problem?

Once that's sorted out, then the generated code for those tests crashes mid-way on device, and I'm analysing what's been produced by the emitter. The code looks OK but I need to spend more time with that to bisect where things go wrong. However, I'm looking at the output of basics/array1.py and I notice there are a lot of dead loads to REG_ARG2, both from registers and locals (see attached image). Since I don't recall that happening when I was debugging the emitter the last time before commit, is that normal? (because if it's not then I messed something along the way, which makes it easier for me to check I guess :)) Edit: no, it was my Ghidra analysis script that didn't pick that argument up - sorry.

If there's a way for the emitter to detect it's running under mpy-cross at compile time I can attempt to have longer sequences only in that case

In principle there should be no difference when mpy-cross generates code compared to generating it on-device. So I suspect this code generation issue would also occur on-device, but I didn't test that yet.

The problem is because the RV32 assembler is emitting short jumps when it shouldn't be. It can only emit short jumps (jumps encoded in fewer bytes than would be by an arbitrarily large jump) when it's a backwards jump, because then the offset is known on the first pass and the code size doesn't change.

See eg py/asmthumb.c, eg:

    mp_uint_t dest = get_label_dest(as, label);
    mp_int_t rel = dest - as->base.code_offset;
    rel -= 4; // account for instruction prefetch, PC is 4 bytes ahead of this instruction

    if (dest != (mp_uint_t)-1 && rel <= -4) {
        // is a backwards jump, so we know the size of the jump on the first pass
        // calculate rel assuming 9 bit relative jump
        if (SIGNED_FIT9(rel)) {
            asm_thumb_op16(as, OP_BCC_N(cond, rel));
            return;
        }
    }

    ... otherwise encode a large jump

Thanks for the clarification, I'll adapt the code accordingly after I fix the other issues.

Right now I've minimised `basics/array1.py' to:

import array

@micropython.native
def a():
        array.array('B', b'12')

a()

and that fails in the console with: TypeError: can't convert '' object to str implicitly - as in the first argument to array.array is invalid. I'm not able to reproduce this with the x64 emitter so I assume it's most probable due to some issue in my code to begin with.

I've removed all sorts of optimisations and variable code length generation to have something stable and to reduce the error surface, and I cannot easily see the issue at hand. The generated code seems fine on the surface, but now I'm deep into the method call infrastructure inside the runtime as args[0] passed to array_make_new seems to be of the wrong type and point to an invalid value:

   167         const char *typecode = mp_obj_str_get_str(args[0]);
      0x4200d068 <array_make_new+26>:  88 40   lw      a0,0(s1)
      0x4200d06a <array_make_new+28>:  ef 60 10 06     jal     ra,0x420138ca <mp_obj_str_get_str>

   mp_obj_str_get_str (self_in=0x3fca9ddc) at /home/agatti/src/micropython/py/objstr.c:2376
   2376        if (mp_obj_is_str_or_bytes(self_in)) {
      
   0x420138ce in mp_obj_is_qstr (o=<optimized out>)
       at /home/agatti/src/micropython/py/obj.h:93
   93          return (((mp_int_t)(o)) & 7) == 2;
      0x420138ce <mp_obj_str_get_str+4>:       13 77 75 00     andi    a4,a0,7
   (gdb) print/x $a0 
   $114 = 0x3fca9ddc 
   
   mp_obj_is_obj (o=<optimized out>) at /home/agatti/src/micropython/py/obj.h:126
   126         return (((mp_int_t)(o)) & 3) == 0;
      0x420138d8 <mp_obj_str_get_str+14>:      93 77 35 00     andi    a5,a0,3
   (gdb) print/x $a0
   $121 = 0x3fca9ddc
   
   0x420138f6        2376        if (mp_obj_is_str_or_bytes(self_in)) {
      0x420138dc <mp_obj_str_get_str+18>:      95 eb   bnez    a5,0x42013910 <mp_obj_str_get_str+70>
      0x420138de <mp_obj_str_get_str+20>:      18 41   lw      a4,0(a0)
      0x420138e0 <mp_obj_str_get_str+22>:      83 47 c7 00     lbu     a5,12(a4)
      0x420138e4 <mp_obj_str_get_str+26>:      95 c7   beqz    a5,0x42013910 <mp_obj_str_get_str+70>
      0x420138e6 <mp_obj_str_get_str+28>:      8d 07   addi    a5,a5,3
      0x420138e8 <mp_obj_str_get_str+30>:      8a 07   slli    a5,a5,0x2
      0x420138ea <mp_obj_str_get_str+32>:      3e 97   add     a4,a4,a5
      0x420138ec <mp_obj_str_get_str+34>:      58 43   lw      a4,4(a4)
      0x420138ee <mp_obj_str_get_str+36>:      b7 47 01 42     lui     a5,0x42014
      0x420138f2 <mp_obj_str_get_str+40>:      93 87 e7 a4     addi    a5,a5,-1458 # 0x42013a4e <mp_obj_str_binary_op>
      0x420138f6 <mp_obj_str_get_str+44>:      63 1d f7 00     bne     a4,a5,0x42013910 <mp_obj_str_get_str+70>
   (gdb) print/a $a4
   $129 = 0x31000001
   (gdb) print/a $a5
   $130 = 0x42013a4e <mp_obj_str_binary_op>

A4 gets filled in at 0x420138de by dereferencing the args[0] passed to array_make_new. The comparison with mp_obj_str_binary_op fails and bad_implicit_conversion gets invoked.

I'm still looking at that, apologies for delays in updates. I'm not yet familiar with this part of MicroPython's internals.

Right now I've minimised basics/array1.py' to: ... and that fails in the console with: TypeError: can't convert '' object to str implicitly- as in the first argument toarray.array` is invalid. I'm not able to reproduce this with the x64 emitter so I assume it's most probable due to some issue in my code to begin with.

I had a look at this and it's actually a bug in the native emitter.

But the bug only surfaces for emitters where REG_RET is different to REG_TEMP0. The RV32 emitter looks like it's the only emitter where that is the case, hence why we see it here.

I'll fix it.

See #15573 for a fix for the native emitter. The above array.array test should now work.

Thanks! With #15573 applied now the basics test suite passes when ran through mpy-cross except for frozenset_binop, set_binop, and string_splitlines.

mpy-cross didn't trigger any assertions so it could be something similar to #15573 or I might have messed up somewhere else. I'll let you know!

Edit: the C.J opcode had an off-by-one error in its address range check, now fixed. Now failures are extmod/vfs_fat_ilistdir_del, float/string_format2, unicode/file1, unicode/file2, unicode/file_invalid, and anything past thread/disable_irq in the thread suite.

unicode/file1 fails with

Traceback (most recent call last):
  File "<stdin>", line 28, in <module>
AttributeError: '__File' object has no attribute 'readline'

unicode/file2 and unicode/file_invalid fail with

Traceback (most recent call last):
  File "<stdin>", line 28, in <module>
AttributeError: '__File' object has no attribute 'read'

Could this be something similar to #15573?

extmod/vfs_fat_ilistdir_del fails only if extmod/socket_tcp_basic or extmod/socket_udp_nonblock and extmod/vfs_fat_finaliser tests were run before. To repro, ./run-tests.py --target esp32 --device /dev/ttyUSB0 --via-mpy --emit native --mpy-cross-flags="-march=rv32imc" -d extmod -i "socket_.*" -i "vfs_fat_finaliser.*" -i "vfs_fat_ilistdir.*" would be enough.

~~The test in question actually succeeds and after OK is being sent to the serial port and things are cleaned up the board crashes:~~ The test crashes when setting up the code state (the OK string comes from the previous test).

./run-tests.py --target esp32 --device /dev/ttyUSB0 --via-mpy --emit native --mpy-cross-flags="-march=rv32imc" -d extmod -i "socket_.*" -i "vfs_fat_finaliser.*" -i "vfs_fat_ilistdir.*"
pass  extmod/socket_tcp_basic.py
pass  extmod/socket_udp_nonblock.py
pass  extmod/vfs_fat_finaliser.py
b'OK\r\nESP-ROM:esp32c3-api1-20210207\r\nBuild:Feb  7 2021\r\nrst:0xc (RTC_SW_CPU_RST),boot:0xd (SPI_FAST_FLASH_BOOT)\r\nSaved PC:0x403807a8\r\nSPIWP:0xee\r\nmode:DIO, clock div:1\r\nload:0x3fcd5820,len:0xe8c\r\nload:0x403cc710,len:0x6ec\r\nload:0x403ce710,len:0x2b24\r\nentry 0x403cc710\r\nMicroPython v1.24.0-preview.153.g271339267.dirty on 2024-07-31; ESP32C3 module with ESP32C3\r\nType "help()" for more information.\r\n>>> '
FAIL  extmod/vfs_fat_ilistdir_del.py

For float/string_format2 things are even more interesting. In the code block invoked through the second call to fun_native_call, the pointer to mp_setup_code_state ends up pointing to some random area with invalid opcodes.

Regarding float/string_format2 - either I got the C.LW opcode wrong or something else is fishy.

fun_native_call gets invoked twice, the first time it merely sets up the code state and does nothing else:

=> 0x403ddf64:  addi    sp,sp,-48        ; Allocate stack space
   0x403ddf68:  sw      ra,0(sp)         ; Save changed registers
   0x403ddf6a:  sw      s0,4(sp)         ;
   0x403ddf6c:  sw      s1,8(sp)         ;
   0x403ddf6e:  sw      s3,12(sp)        ;
   0x403ddf70:  sw      s4,16(sp)        ;
   0x403ddf72:  sw      s5,20(sp)        ;
   0x403ddf74:  lw      s1,4(a0)         ; Lookup the address of the function table...
   0x403ddf76:  lw      s1,12(s1)        ; ...
   0x403ddf78:  lw      s1,0(s1)         ; S1 points to mp_fun_table
   0x403ddf7a:  sw      a0,24(sp)        ; Save the first argument into "local_a"
   0x403ddf7c:  li      a0,1             ;
   0x403ddf7e:  sw      a0,36(sp)        ; Store 1 into another local
   0x403ddf80:  addi    a0,sp,24         ; Load the address of "local_a" (code_state argument)
   0x403ddf82:  lw      s0,180(s1)       ; S0 points to mp_setup_code_state_native
   0x403ddf86:  jalr    s0               ; Call mp_setup_code_state_native
   0x403ddf88:  lw      a0,0(s1)         ; A0 points to const_none
   0x403ddf8a:  auipc   s0,0x0           ; Load PC
   0x403ddf8e:  jr      8(s0)            ; Jump to next instruction
   0x403ddf92:  lw      ra,0(sp)         ; Restore registers
   0x403ddf94:  lw      s0,4(sp)         ;
   0x403ddf96:  lw      s1,8(sp)         ;
   0x403ddf98:  lw      s3,12(sp)        ;
   0x403ddf9a:  lw      s4,16(sp)        ;
   0x403ddf9c:  lw      s5,20(sp)        ;
   0x403ddf9e:  addi    sp,sp,48         ; Reclaim stack space
   0x403ddfa2:  ret                      ; Done

The code sequence until the call to mp_setup_code_state_native is pretty much the same for every native call. Now, the second invocation of fun_native_call goes as follows:

=> 0x403a3734:  addi    sp,sp,-340       ; Allocate stack space
   0x403a3738:  sw      ra,0(sp)         ; Save changed registers
   0x403a373a:  sw      s0,4(sp)         ;
   0x403a373c:  sw      s1,8(sp)         ;
   0x403a373e:  sw      s3,12(sp)        ;
   0x403a3740:  sw      s4,16(sp)        ;
   0x403a3742:  sw      s5,20(sp)        ;
   0x403a3744:  lw      s1,4(a0)         ; Lookup the address of the function table
   0x403a3746:  lw      s5,8(s1)         ;
   0x403a374a:  lw      s1,12(s1)        ;
   0x403a374c:  lw      s1,80(s1)        ; S1 points somewhere else than mp_fun_table...
   0x403a374e:  sw      a0,96(sp)        ;
   0x403a3750:  li      a0,56            ;
   0x403a3754:  sw      a0,108(sp)       ;
   0x403a3756:  addi    a0,sp,96         ;
   0x403a3758:  lw      s0,180(s1)       ; ...that is still accessed as if it were mp_fun_table
   0x403a375c:  jalr    s0               ; and here be dragons
...

Edit: fixed in ba9d582

extmod/vfs_fat_ilistdir_del fails due to a NULL pointer when setting up the code state:

#0  0x4203bd38 in mp_setup_code_state_helper (code_state=0x3fca8db4, n_args=3, n_kw=0, args=0x3fcb6734) at /home/agatti/src/micropython/py/bc.c:139
139         MP_BC_PRELUDE_SIG_DECODE_INTO(code_state->ip, n_state_unused, n_exc_stack_unused, scope_flags, n_pos_args, n_kwonly_args, n_def_pos_args);
   0x4203bd32 <mp_setup_code_state_helper+30>:  13 87 17 00     addi    a4,a5,1
   0x4203bd36 <mp_setup_code_state_helper+34>:  58 c1   sw      a4,4(a0)
=> 0x4203bd38 <mp_setup_code_state_helper+36>:  03 ce 07 00     lbu     t3,0(a5)
(gdb) print $a5
$4 = 0
(gdb) print *code_state
$5 = {fun_bc = 0x3fcaf000, ip = 0x1 "", sp = 0x3fca8dc4, n_state = 10, exc_sp_idx = 0, old_globals = 0x42031706 <f_sync+100>, state = 0x3fca8dc8}

Getting up to that point looks fine:

   0x403de7f8:  addi    sp,sp,-156   ; Allocate stack space
   0x403de7fc:  sw      ra,0(sp)     ; Save registers
   0x403de7fe:  sw      s0,4(sp)
   0x403de800:  sw      s1,8(sp)
   0x403de802:  sw      s3,12(sp)
   0x403de804:  sw      s4,16(sp)
   0x403de806:  sw      s5,20(sp)
   0x403de808:  lw      s1,4(a0)     ; Get mp_fun_table address
   0x403de80a:  lw      s5,8(s1)
   0x403de80e:  lw      s1,12(s1)
   0x403de810:  lw      s1,0(s1)
   0x403de814:  sw      a0,96(sp)    ; Save code state
   0x403de816:  li      a0,10        
   0x403de818:  sw      a0,108(sp)
   0x403de81a:  addi    a0,sp,96     ; Get code state address
   0x403de81c:  lw      s0,180(s1)   ; Get mp_setup_code_state_helper address
   0x403de820:  jalr    s0           ; Call mp_setup_code_state_helper
   ...

The thread tests that fail (except for one) actually deadlock, so I suspect that memory ordering may play a role here.

Anyway, the state so far:

~~extmod/vfs_fat_ilistdir_del crashes because mp_setup_code_state_helper receives a code_state parameter with NULL mp_code_state_t->ip.~~ Fixed by esp32/main: Store native code as linked list instead of list on GC heap. #15589.
thread/mutate_{byteordering,dict,instance,list,set} deadlock.
thread/stress_aes completes but does not emit the done string.
thread/stress_{recurse,schedule} deadlock.
thread/thread_{coop,exc1} deadlock.
thread/thread_exc2 completes but does not print the traceback.
thread/thread_{gc1,ident1,lock3,shared1,shared2,sleep1,sleep2,stacksize1} deadlock.
unicode/{file1,file2,file_invalid} pass a non-method object to mp_load_method.

@dpgeorge

@dpgeorge Can this specific test failure be an issue with the native emitter infrastructure rather than with the RV32 code generator?

With ./run-tests.py --target esp32 --device /dev/ttyUSB0 --via-mpy --emit native --mpy-cross-flags="-march=rv32imc" -d extmod -i "socket_.*" -i "vfs_fat_finaliser.*" -i "vfs_fat_ilistdir.*" I see the bytecode buffer containing potentially incorrect data, as the code attempts to index a table pointer with a very large index (0x3FCDC724), and ultimately reading from unmapped memory (just a bit before 0x3FC80000, which is the beginning of the internal memory block).

Thread 2 "mp_task" hit Breakpoint 3, mp_obj_fun_native_get_prelude_ptr (fun_native=0x3fcaeeb0) at /home/agatti/src/micropython/py/objfun.h:74
74          uintptr_t prelude_ptr_index = ((uintptr_t *)fun_native->bytecode)[0];
=> 0x4203c252 <mp_setup_code_state_native+2>:   d8 47   lw      a4,12(a5)
(gdb) print *fun_native
$1 = {base = {type = 0x3c143274 <mp_type_fun_native>}, context = 0x3fca9ff0, child_table = 0x403de930, 
  bytecode = 0x403de7e8 "$\307\315?\023\001A\366\006\300\"\302&\304N\306R\310V\312DA\203\252\204", extra_args = 0x3fcaeec0}
(gdb) n
76          if (prelude_ptr_index == 0) {
=> 0x4203c258 <mp_setup_code_state_native+8>:   01 c7   beqz    a4,0x4203c260 <mp_setup_code_state_native+16>
(gdb) print/a prelude_ptr_index
$2 = 0x3fcdc724
(gdb) n
79              prelude_ptr = (const uint8_t *)fun_native->child_table[prelude_ptr_index];
=> 0x4203c25a <mp_setup_code_state_native+10>:  0a 07   slli    a4,a4,0x2
   0x4203c25c <mp_setup_code_state_native+12>:  ba 97   add     a5,a5,a4
   0x4203c25e <mp_setup_code_state_native+14>:  9c 43   lw      a5,0(a5)
(gdb) print/x fun_native->child_table + prelude_ptr_index
$3 = 0x3f7505c0

Can this specific test failure be an issue with the native emitter infrastructure rather than with the RV32 code generator?

Hmm, it looks like there's an issue with vfs_fat_finaliser.py, because running that multiple times in a row leads to issues. Eg:

./run-tests.py --target esp32 --device /dev/ttyUSB0 --via-mpy --emit native --mpy-cross-flags="-march=rv32imc" extmod/socket_udp_nonblock.py extmod/vfs_fat_finaliser.py extmod/vfs_fat_finaliser.py

I think it's because of:

soft reset frees all native_code_pointers
soft reset then call gc_sweep_all()
that triggers a FAT file finaliser to run, the file left over from vfs_fat_finaliser.py that wasn't explicitly closed
that triggers (via the FAT driver closing the file and flushing its data) native code to be run from RAMBlockDevice
native code memory is already freed (see first step), so it crashes

To fix that... probably native_code_pointers needs to be a linked list (not using GC heap) and then this link list freed after gc_sweep_all() has been called.

Right. I'll focus on the deadlocks then and leave that failure alone as it's not specific to the code generator, thanks!

To fix that... probably native_code_pointers needs to be a linked list (not using GC heap) and then this link list freed after gc_sweep_all() has been called.

I've done that in #15589.

@projectgus

@projectgus Do you have a list of the tests that failed due to #15423?

I'm seeing similar issues when running most thread tests through the native emitter and I was wondering if maybe that bug is still showing up somehow. I've looked at the generated code and there's nothing obviously wrong on my end.

I can reproduce the thread test issues also on a ESP32-D0WD-V3 using ./run-tests.py --target esp32 --device /dev/ttyUSB0 --via-mpy --emit native --mpy-cross-flags="-march=xtensawin" -d thread and the firmware built from the master branch for ESP32_GENERIC...

...same goes for the three unicode failing tests. I'll clean up #15575 and then I guess I can't do much more about this on the RV32 side.

@agatti

Thanks @agatti for working on this issue. Testing as of 7d8b2d8 on an RP2350-RISCV I get the following:

./run-tests.py --target rp2 --via-mpy --emit native --mpy-cross-flags="-march=rv32imc" -d basics extmod micropython misc float stress
...
796 tests performed (24386 individual testcases)
796 tests passed
86 tests skipped

So this issue can be closed.

Navigation Menu

Repository navigation

RV32 native emitter fails compiling some of the tests #15551

Port, board and/or hardware

MicroPython version

Reproduction

Expected behaviour

Observed behaviour

Additional Information

Code of Conduct

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

RV32 native emitter fails compiling some of the tests #15551

Description

Port, board and/or hardware

MicroPython version

Reproduction

Expected behaviour

Observed behaviour

Additional Information

Code of Conduct

Activity

dpgeorge commented on Jul 26, 2024

agatti commented on Jul 26, 2024

agatti commented on Jul 26, 2024

dpgeorge commented on Jul 28, 2024

dpgeorge commented on Jul 28, 2024

agatti commented on Jul 30, 2024

dpgeorge commented on Jul 30, 2024

dpgeorge commented on Jul 31, 2024

agatti commented on Jul 31, 2024

agatti commented on Jul 31, 2024

agatti commented on Jul 31, 2024

agatti commented on Jul 31, 2024

agatti commented on Aug 1, 2024

agatti commented on Aug 1, 2024

agatti commented on Aug 2, 2024

agatti commented on Aug 2, 2024

dpgeorge commented on Aug 2, 2024

agatti commented on Aug 2, 2024

dpgeorge commented on Aug 3, 2024

agatti commented on Aug 10, 2024

agatti commented on Aug 11, 2024

agatti commented on Aug 11, 2024

dpgeorge commented on Aug 19, 2024

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions