1
0
mirror of https://github.com/trezor/trezor-firmware.git synced 2025-04-19 16:49:02 +00:00

wip: log GC roots from regs & stack

 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 <trezor_lib::ui::layout::obj::LayoutObj::obj_type::TYPE>`
This commit is contained in:
Roman Zeyde 2025-04-01 16:50:59 +03:00
parent 101d584aa4
commit 2d7b4b8a39
8 changed files with 22 additions and 55 deletions

View File

@ -46,6 +46,7 @@ impl<T> Gc<T> {
// 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);
}

View File

@ -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();
}

View File

@ -40,6 +40,7 @@ where
unsafe {
IMAGE_BUFFER_LOCKED = false;
}
dbg_println!("ImageBuffer::drop");
}
}

View File

@ -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:

View File

@ -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:

8
deps.py Normal file
View File

@ -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]

View File

@ -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:

2
vendor/micropython vendored

@ -1 +1 @@
Subproject commit 6bdefd147256d6a72827ac6225fc5e36bd92a801
Subproject commit f58f9b74e5f8b01da9208b855602b85364e29679