Repository navigation
RV32 native emitter fails compiling some of the tests #15551
Description
Activity
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, andasm_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 ofEdit: no, it was my Ghidra analysis script that didn't pick that argument up - sorry.basics/array1.pyand 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 :))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 toarray.arrayis 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 toarray_make_newseems 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 toarray_make_new. The comparison withmp_obj_str_binary_opfails andbad_implicit_conversiongets 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_RETis different toREG_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.
Thanks! With #15573 applied now the
basicstest suite passes when ran through mpy-cross except forfrozenset_binop,set_binop, andstring_splitlines.mpy-crossdidn'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.Jopcode had an off-by-one error in its address range check, now fixed. Now failures areextmod/vfs_fat_ilistdir_del,float/string_format2,unicode/file1,unicode/file2,unicode/file_invalid, and anything pastthread/disable_irqin thethreadsuite.unicode/file1fails withTraceback (most recent call last): File "<stdin>", line 28, in <module> AttributeError: '__File' object has no attribute 'readline'unicode/file2andunicode/file_invalidfail withTraceback (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_delfails only ifextmod/socket_tcp_basicorextmod/socket_udp_nonblockandextmod/vfs_fat_finalisertests 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 afterThe test crashes when setting up the code state (theOKis being sent to the serial port and things are cleaned up the board crashes:OKstring 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.pyFor
float/string_format2things are even more interesting. In the code block invoked through the second call tofun_native_call, the pointer tomp_setup_code_stateends up pointing to some random area with invalid opcodes.Regarding
float/string_format2- either I got theC.LWopcode wrong or something else is fishy.fun_native_callgets 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 ; DoneThe 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_callgoes 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_delfails 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
threadtests 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_delcrashes because mp_setup_code_state_helper receives a code_state parameter with NULLmp_code_state_t->ip.thread/mutate_{byteordering,dict,instance,list,set}deadlock.thread/stress_aescompletes but does not emit thedonestring.thread/stress_{recurse,schedule}deadlock.thread/thread_{coop,exc1}deadlock.thread/thread_exc2completes 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 tomp_load_method.
@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 = 0x3f7505c0Can 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.pyI 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.pythat 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_pointersneeds to be a linked list (not using GC heap) and then this link list freed aftergc_sweep_all()has been called.- soft reset frees all
Right. I'll focus on the deadlocks then and leave that failure alone as it's not specific to the code generator, thanks!
@projectgus Do you have a list of the tests that failed due to #15423?
I'm seeing similar issues when running most
threadtests 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
threadtest 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 threadand the firmware built from the master branch forESP32_GENERIC...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 skippedSo this issue can be closed.
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:
The output is:
The test failures are due to
mpy-crosscrashing:Alternatively, a much simpler way to see the problem:
Expected behaviour
mpy-crossshould be able to compile all the tests with the rv32imc emitter selected.Observed behaviour
mpy-crosscrashes with an assertion failure.Additional Information
No response
Code of Conduct
Yes, I agree