From 2d7b4b8a39f9d715803fab89c2370caec7400b28 Mon Sep 17 00:00:00 2001 From: Roman Zeyde Date: Tue, 1 Apr 2025 16:50:59 +0300 Subject: [PATCH] wip: log GC roots from regs & stack MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit  TREZOR_MODEL=T3T1 BITCOIN_ONLY=0 QUIET_MODE=1 PYOPT=0 make -C core build_unix_frozen  core/emu.py -ea --profiling -o /tmp/trezor.log -c pytest -xv tests/device_tests/test_msg_applysettings.py::test_apply_homescreen_jpeg ======================================================================================= short test summary info ======================================================================================== FAILED tests/device_tests/test_msg_applysettings.py::test_apply_homescreen_jpeg - trezorlib.exceptions.TrezorFailure: FirmwareError: !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! stopping after 1 failures !!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!!! ========================================================================================== 1 failed in 1.55s =========================================================================================== Terminating emulator... Emulator shut down after 0.064 seconds  grep -B2 '>Layout' /tmp/trezor.log alloc(424) = 0x71612f4723e0 flags: 0 alloc(176) = 0x71612f4725a0 flags: 1 >LayoutObj::new_root -- alloc(424) = 0x71612f4711c0 flags: 0 alloc(176) = 0x71612f471380 flags: 1 >LayoutObj::new_root  grep 0x71612f471380 /tmp/dump* /tmp/dump-002.json:6930 6900 6 0x71612f471380 #7 <0x637d78> /tmp/dump-002.json:7089 6900 6 0x71612f471380 #2 <0x637d78> /tmp/dump-003.json:6930 6900 6 0x71612f471380 #7 <0x637d78> /tmp/dump-003.json:7089 6900 6 0x71612f471380 #2 <0x637d78> ...  python deps.py 6900 < /tmp/dump-002.json | colrm 200 6930 6900 6 0x71612f471380 #7 <0x637d78> 6769 6930 6 0x71612f471740 #3 <0x5e92> 3508 6769 1 0x71612f470320 #69 <0x71612f46ba60> 3040 3508 24 0x71612f456b80 #3 <0x6eba> 3036 3040 1 0x71612f453100 #1 dict {'T': 0, 'utime': 0x61d3e0, 'const': 0x61ef80, 'backlight_fade': 0x63b210, 'Shutdown': 0x71612f453920, 'refresh': 0x71612f453740, 'HEIGHT': 240 3437 3036 1 0x71612f453080 #1 module {'T': 0, 'utime': 0x61d3e0, 'const': 0x61ef80, 'backlight_fade': 0x63b210, 'Shutdown': 0x71612f453920, 'refresh': 0x71612f453740, 'HEIGHT': 2 3457 3437 2 0x71612f4562a0 #1 gen_wrap 3116 3457 15 0x71612f456520 #3 <0x7d6a> 3447 3116 1 0x71612f453a80 #14 dict {'_handle_usb_iface': 0x71612f4562a0, 'stop': 0x71612f456060, 'create_tasks': 0x71612f456220, '__del__': 0x71612f4563a0, '_handle_input_iface': 6156 3447 4 0x71612f4563e0 #13 type Layout 6187 6156 4 0x71612f46b680 #13 type HomescreenBase 6333 6187 4 0x71612f46ba60 #1 type Homescreen 6095 6333 12 0x71612f46cca0 #3 <0x7eaa> 6012 6095 1 0x71612f46aee0 #1 dict {'Homescreen': 0x71612f46ba60, 'busy_expiry_ms': 0x71612f457820, '__file__': 'apps/homescreen/__init__.py', '__name__': 'apps.homescreen', 'Mes 6285 6012 1 0x71612f46a480 #1 module {'Homescreen': 0x71612f46ba60, 'busy_expiry_ms': 0x71612f457820, '__file__': 'apps/homescreen/__init__.py', '__name__': 'apps.homescreen', 'M 2050 6285 2 0x71612f46c6a0 #5 gen_wrap 1948 2050 15 0x71612f44b540 #3 <0x7742> 1936 1948 1 0x71612f44a880 #1 dict {'IdleTimer': 0x71612f44b420, 'spawn': 0x71612f44ae20, 'default_constructor': 0x71612f46c6a0, 'ALLOW_WHILE_LOCKED': 0x71612f44ad40, '__name__': 2823 1936 1 0x71612f44a700 #33 module {'IdleTimer': 0x71612f44b420, 'spawn': 0x71612f44ae20, 'default_constructor': 0x71612f46c6a0, 'ALLOW_WHILE_LOCKED': 0x71612f44ad40, '__name__ 1666 2823 15 0x71612f4515e0 #3 <0x84b2> 1663 1666 1 0x71612f448540 #1 dict {'UnexpectedMessageException': 0x71612f44d1c0, 'with_context': 0x71612f44d2c0, 'DataError': 0x71612f44f600, 'Message': 0x71612f44c0a0, '__name_ 2802 1663 1 0x71612f4484e0 #1 module {'UnexpectedMessageException': 0x71612f44d1c0, 'with_context': 0x71612f44d2c0, 'DataError': 0x71612f44f600, 'Message': 0x71612f44c0a0, '__nam 2936 2802 2 0x71612f451340 #3 fun_bc 785 2936 19 0x71612f452400 #3 <0x85ca> 784 785 1 0x71612f441720 #1 dict {'UnexpectedMessage': 0x71612f44de80, 'failure': 0x71612f451340, 'PinInvalid': 0x71612f44ffa0, 'setup': 0x71612f4528e0, 'protobuf': 0x71612f445 2977 784 1 0x71612f441700 #1 module {'UnexpectedMessage': 0x71612f44de80, 'failure': 0x71612f451340, 'PinInvalid': 0x71612f44ffa0, 'setup': 0x71612f4528e0, 'protobuf': 0x71612f4 6450 2977 2 0x71612f452920 #2 gen_wrap 1644 6450 9 0x71612f46db40 #3 gen_instance 364 1644 15 0x71612f448280 #3 <0x23a> 293 364 1 0x71612f43e280 #1 dict {'close': 0x71612f442640, 'this_task': 0x71612f46db40, 'io': 0x61c830, 'schedule': 0x71612f442120, '__name__': 'trezor.loop', '_TIMEOUT_ERROR': 3906 293 1 0x71612f43d9a0 #7 module {'close': 0x71612f442640, 'this_task': 0x71612f46db40, 'io': 0x61c830, 'schedule': 0x71612f442120, '__name__': 'trezor.loop', '_TIMEOUT_ERROR 210 3906 5 0x71612f459d40 #3 <(nil)> 199 210 1 0x71612f43cf40 #1 dict {'log': 0x71612f43d8a0, '__name__': 'session', 'loop': 0x71612f43d9a0, 'utils': 0x71612f43d3a0, 'apps': 0x71612f44a380, 'workflow': 0x71612f44a 315 199 1 0x71612f43cde0 #1 module {'log': 0x71612f43d8a0, '__name__': 'session', 'loop': 0x71612f43d9a0, 'utils': 0x71612f43d3a0, 'apps': 0x71612f44a380, 'workflow': 0x71612f4 0 315 2 0x71612f43dc60 #552 fun_bc  nm core/build/unix/trezor-emu-core | grep 637d78 0000000000637d78 d _ZN10trezor_lib2ui6layout3obj9LayoutObj8obj_type4TYPE17hb6ebd6797ed3a6e4E # from objdump => `637d78 ` --- core/embed/rust/src/micropython/gc.rs | 1 + .../rust/src/ui/api/firmware_micropython.rs | 2 + .../embed/rust/src/ui/shape/utils/imagebuf.rs | 1 + .../modtrezorutils/modtrezorutils-meminfo.h | 56 +------------------ core/src/trezor/utils.py | 5 ++ deps.py | 8 +++ docs/core/emulator/valgrind.md | 2 +- vendor/micropython | 2 +- 8 files changed, 22 insertions(+), 55 deletions(-) create mode 100644 deps.py diff --git a/core/embed/rust/src/micropython/gc.rs b/core/embed/rust/src/micropython/gc.rs index 62696e6afd..7a3b7f9175 100644 --- a/core/embed/rust/src/micropython/gc.rs +++ b/core/embed/rust/src/micropython/gc.rs @@ -46,6 +46,7 @@ impl Gc { // EXCEPTION: Returns null instead of raising. unsafe { let raw = ffi::gc_alloc(layout.size(), flags); + dbg_println!("alloc({}) = {:?} flags: {}", layout.size(), raw, flags); if raw.is_null() { return Err(Error::AllocationFailed); } diff --git a/core/embed/rust/src/ui/api/firmware_micropython.rs b/core/embed/rust/src/ui/api/firmware_micropython.rs index 0f1a3b901b..babffed8b1 100644 --- a/core/embed/rust/src/ui/api/firmware_micropython.rs +++ b/core/embed/rust/src/ui/api/firmware_micropython.rs @@ -789,7 +789,9 @@ extern "C" fn new_show_homescreen(n_args: usize, args: *const Obj, kwargs: *mut let skip_first_paint: bool = kwargs.get(Qstr::MP_QSTR_skip_first_paint)?.try_into()?; let layout = ModelUI::show_homescreen(label, hold, notification, notification_level)?; + dbg_println!("LayoutObj::new_root<"); let layout_obj = LayoutObj::new_root(layout)?; + dbg_println!(">LayoutObj::new_root"); if skip_first_paint { layout_obj.skip_first_paint(); } diff --git a/core/embed/rust/src/ui/shape/utils/imagebuf.rs b/core/embed/rust/src/ui/shape/utils/imagebuf.rs index 7565d7937a..4b2d4a667c 100644 --- a/core/embed/rust/src/ui/shape/utils/imagebuf.rs +++ b/core/embed/rust/src/ui/shape/utils/imagebuf.rs @@ -40,6 +40,7 @@ where unsafe { IMAGE_BUFFER_LOCKED = false; } + dbg_println!("ImageBuffer::drop"); } } diff --git a/core/embed/upymod/modtrezorutils/modtrezorutils-meminfo.h b/core/embed/upymod/modtrezorutils/modtrezorutils-meminfo.h index 98ad80d65e..a0524616d4 100644 --- a/core/embed/upymod/modtrezorutils/modtrezorutils-meminfo.h +++ b/core/embed/upymod/modtrezorutils/modtrezorutils-meminfo.h @@ -717,6 +717,8 @@ void dump_qstr_pool(FILE *out, const qstr_pool_t *pool) { } } +void log_roots_from_regs(FILE *out); + static void dump_meminfo_json(FILE *out) { bool should_close = true; if (out == NULL) { @@ -727,60 +729,9 @@ static void dump_meminfo_json(FILE *out) { out = &mp_plat_print; #endif } - fprintf(out, "\n[\n[" UINT_FMT ", " UINT_FMT ", " UINT_FMT "],\n", - (mp_uint_t)MP_STATE_MEM(gc_pool_start), - (mp_uint_t)MP_STATE_MEM(gc_pool_end), BYTES_PER_BLOCK); - // void **ptrs = (void **)(void *)&mp_state_ctx; - // size_t root_start = offsetof(mp_state_ctx_t, thread.dict_locals); - // size_t root_end = offsetof(mp_state_ctx_t, vm.qstr_last_chunk); + log_roots_from_regs(out); - // for (size_t i = root_start; i < root_end; i++) { - // void *ptr = ptrs[i]; - // if (i == 55) continue; // mp_loaded_modules_dict - // if (i == 62) continue; // dict_main - // if (i == 66) continue; // mp_sys_path_obj - // if (i == 70) continue; // mp_sys_argv_obj - // if (i == 123) continue; // qstr_last_chunk - // if (VERIFY_PTR(ptr)) { - // size_t block = BLOCK_FROM_PTR(ptr); - // if (ATB_GET_KIND(block) == AT_HEAD) { - // fprintf(out, "\"root_ofs: %ld\",\n", i); - // dump_value(out, ptr); - // // // An unmarked head: mark it, and mark all its children - // // TRACE_MARK(block, ptr); - // // ATB_HEAD_TO_MARK(block); - // // gc_mark_subtree(block); - // } - // } - // } - - fprintf(out, "\"dict_locals\",\n"); - dump_value(out, MP_STATE_THREAD(dict_locals)); - - fprintf(out, "\"mp_loaded_modules_dict\",\n"); - dump_value_opt(out, &MP_STATE_VM(mp_loaded_modules_dict), true); - - fprintf(out, "\"dict_main\",\n"); - dump_value_opt(out, &MP_STATE_VM(dict_main), true); - - fprintf(out, "\"mp_sys_path_obj\",\n"); - dump_value_opt(out, &MP_STATE_VM(mp_sys_path_obj), true); - - fprintf(out, "\"mp_sys_argv_obj\",\n"); - dump_value_opt(out, &MP_STATE_VM(mp_sys_argv_obj), true); - - fprintf(out, "\"ui_wait_callback\",\n"); - dump_value(out, MP_STATE_VM(trezorconfig_ui_wait_callback)); - - fprintf(out, "\"qstr_pools\",\n"); - const qstr_pool_t *pool = MP_STATE_VM(last_pool); - while (VERIFY_PTR((void *)pool)) { - dump_qstr_pool(out, pool); - pool = pool->prev; - } - - fprintf(out, "null\n]\n"); if (should_close) { fclose(out); } else { @@ -794,7 +745,6 @@ static void dump_meminfo_json(FILE *out) { } } - gc_dump_alloc_table(); } /// def meminfo(filename: str | None) -> None: diff --git a/core/src/trezor/utils.py b/core/src/trezor/utils.py index ebb0057560..ac507e52c8 100644 --- a/core/src/trezor/utils.py +++ b/core/src/trezor/utils.py @@ -96,6 +96,7 @@ def unimport_end(mods: set[str], collect: bool = True) -> None: class unimport: def __init__(self) -> None: self.mods: set[str] | None = None + self.i = 0 def __enter__(self) -> None: self.mods = unimport_begin() @@ -106,6 +107,10 @@ class unimport: self.mods.clear() self.mods = None gc.collect() + fname = f"/tmp/dump-{self.i:03}.json" + print(f"dumping to {fname}") + from trezorutils import meminfo; meminfo(fname) + self.i += 1 def presize_module(modname: str, size: int) -> None: diff --git a/deps.py b/deps.py new file mode 100644 index 0000000000..2ee5f95ae8 --- /dev/null +++ b/deps.py @@ -0,0 +1,8 @@ +import sys +block, = sys.argv[1:] +rows = list(l.strip().split('\t') for l in sys.stdin) + +while int(block) > 0: + row = next(r for r in rows if r[1] == block) + print(''.join(f'{c:<8} ' for c in row)) + block = row[0] diff --git a/docs/core/emulator/valgrind.md b/docs/core/emulator/valgrind.md index 05ad6b3a23..c3ab720863 100644 --- a/docs/core/emulator/valgrind.md +++ b/docs/core/emulator/valgrind.md @@ -29,7 +29,7 @@ With `PYOPT=0`, most of the execution time is spent formatting and writing logs, If you're using Nix, you can use Valgrind and KCachegrind packages from our `shell.nix`: ``` -nix-shell --args devTools true --run "poetry shell" +nix-shell --arg devTools true --run "poetry shell" ``` Record profiling data on some device tests: diff --git a/vendor/micropython b/vendor/micropython index 6bdefd1472..f58f9b74e5 160000 --- a/vendor/micropython +++ b/vendor/micropython @@ -1 +1 @@ -Subproject commit 6bdefd147256d6a72827ac6225fc5e36bd92a801 +Subproject commit f58f9b74e5f8b01da9208b855602b85364e29679