Wasmtime GitHub notifications bot (Oct 30 2024 at 23:38): Wasmtime GitHub notifications bot (Oct 30 2024 at 23:38):SingleAccretion opened PR #9526 from SingleAccretion:DI-Log-Up to bytecodealliance:main:
The DI transform is a kind of compiler and logging is a very good way to gain insight into compilers.
This has already helped me narrow down the cause of #9512:
2024-10-30T23:26:56.408332Z TRACE debug-info-transform: === Begin DIE at 0x0000007a (depth = 2): DW_TAG_subprogram DW_AT_linkage_name ("_ZN9SomeClass16SeparateFunctionEv") DW_AT_name ("SeparateFunction") DW_AT_decl_file (0x00000002) DW_AT_decl_line (20) DW_AT_type (0x0000008b) DW_AT_declaration (true) DW_AT_external (true) DW_AT_accessibility (DW_ACCESS_public) 2024-10-30T23:26:56.408361Z TRACE debug-info-transform: === End DIE at 0x0000007a (depth = 2): Skipped as unreachableI also took the liberty of renaming a few variables for clarity.
<details>
<summary>Sample output</summary>2024-10-30T23:26:56.398154Z TRACE debug-info-transform: Commencing DWARF transform for [#0: main.wasm, #1: wit-component:adapter:wasi_snapshot_preview1, #2: wit-component:shim, #3: wit-component:fixups] 2024-10-30T23:26:56.405243Z TRACE debug-info-transform: [== Transforming CUs for module #0 ==] 2024-10-30T23:26:56.405357Z TRACE debug-info-transform: Cloning CU 0x00000000 ["C:\wasi-sdk\sysroot\wasi-libc-wasm32-wasip2", "libc-bottom-half/crt\crt1-command.c"] 2024-10-30T23:26:56.405562Z TRACE debug-info-transform: === Begin DIE at 0x0000000b (depth = 0): DW_TAG_compile_unit DW_AT_producer ("clang version 18.1.2 (https://github.com/llvm/llvm-project 26a1d6601d727a96f4301d0d8647b5a42760ae0c)") DW_AT_language (DW_LANG_C11) DW_AT_name ("libc-bottom-half/crt\crt1-command.c") DW_AT_stmt_list (0x00000000) DW_AT_comp_dir ("C:\wasi-sdk\sysroot\wasi-libc-wasm32-wasip2") DW_AT_low_pc (00000005) DW_AT_high_pc (82) 2024-10-30T23:26:56.405789Z TRACE debug-info-transform: === End DIE at 0x0000000b (depth = 0): DW_TAG_compile_unit DW_AT_ranges (<TODO: out rnglist dump>) DW_AT_producer ("clang version 18.1.2 (https://github.com/llvm/llvm-project 26a1d6601d727a96f4301d0d8647b5a42760ae0c)") DW_AT_language (DW_LANG_C11) DW_AT_name ("libc-bottom-half/crt\crt1-command.c") DW_AT_stmt_list (LineProgramRef) DW_AT_comp_dir ("C:\wasi-sdk\sysroot\wasi-libc-wasm32-wasip2") 2024-10-30T23:26:56.405832Z TRACE debug-info-transform: === Begin DIE at 0x00000026 (depth = 1): DW_TAG_subprogram DW_AT_low_pc (00000005) DW_AT_high_pc (82) DW_AT_frame_base (<TODO: exprloc dump>) DW_AT_GNU_all_call_sites (true) DW_AT_name ("_start") DW_AT_decl_file (0x00000001) DW_AT_decl_line (11) DW_AT_prototyped (true) DW_AT_external (true) 2024-10-30T23:26:56.406070Z TRACE debug-info-transform: === End DIE at 0x00000026 (depth = 1): DW_TAG_subprogram DW_AT_low_pc (symbol #1+0) DW_AT_high_pc (182) DW_AT_frame_base (<TODO: out exprloc dump>) DW_AT_GNU_all_call_sites (true) DW_AT_name ("_start") DW_AT_decl_file (FileId(1)>) DW_AT_decl_line (11) DW_AT_prototyped (true) DW_AT_external (true) 2024-10-30T23:26:56.406119Z TRACE debug-info-transform: === Begin DIE at 0x0000003d (depth = 2): DW_TAG_variable DW_AT_name ("started") DW_AT_type (0x00000089) DW_AT_decl_file (0x00000001) DW_AT_decl_line (26) DW_AT_location (<TODO: exprloc dump>) 2024-10-30T23:26:56.406174Z TRACE debug-info-transform: === End DIE at 0x0000003d (depth = 2): DW_TAG_variable DW_AT_name ("started") DW_AT_decl_file (FileId(1)>) DW_AT_decl_line (26) 2024-10-30T23:26:56.406204Z TRACE debug-info-transform: === Begin DIE at 0x00000055 (depth = 2): DW_TAG_variable DW_AT_location (<TODO: loclist dump>) DW_AT_name ("r") DW_AT_decl_file (0x00000001) DW_AT_decl_line (43) DW_AT_type (0x0000008e) 2024-10-30T23:26:56.406359Z TRACE debug-info-transform: === End DIE at 0x00000055 (depth = 2): DW_TAG_variable DW_AT_location (<TODO: out loclist dump>) DW_AT_name ("r") DW_AT_decl_file (FileId(1)>) DW_AT_decl_line (43) 2024-10-30T23:26:56.406392Z TRACE debug-info-transform: === Begin DIE at 0x00000064 (depth = 2): DW_TAG_GNU_call_site DW_AT_abstract_origin (0x00000095) DW_AT_low_pc (00000036) 2024-10-30T23:26:56.406428Z TRACE debug-info-transform: === End DIE at 0x00000064 (depth = 2): Skipped as unreachable 2024-10-30T23:26:56.406456Z TRACE debug-info-transform: === Begin DIE at 0x0000006d (depth = 2): DW_TAG_GNU_call_site DW_AT_abstract_origin (0x0000009c) DW_AT_low_pc (0000003c) 2024-10-30T23:26:56.406505Z TRACE debug-info-transform: === End DIE at 0x0000006d (depth = 2): Skipped as unreachable 2024-10-30T23:26:56.406541Z TRACE debug-info-transform: === Begin DIE at 0x00000076 (depth = 2): DW_TAG_GNU_call_site DW_AT_abstract_origin (0x000000a7) DW_AT_low_pc (00000044) 2024-10-30T23:26:56.406588Z TRACE debug-info-transform: === End DIE at 0x00000076 (depth = 2): Skipped as unreachable 2024-10-30T23:26:56.406610Z TRACE debug-info-transform: === Begin DIE at 0x0000007f (depth = 2): DW_TAG_GNU_call_site DW_AT_abstract_origin (0x000000ae) DW_AT_low_pc (00000055) 2024-10-30T23:26:56.406633Z TRACE debug-info-transform: === End DIE at 0x0000007f (depth = 2): Skipped as unreachable 2024-10-30T23:26:56.406650Z TRACE debug-info-transform: === Begin DIE at 0x00000089 (depth = 1): DW_TAG_volatile_type DW_AT_type (0x0000008e) 2024-10-30T23:26:56.406696Z TRACE debug-info-transform: === End DIE at 0x00000089 (depth = 1): DW_TAG_volatile_type 2024-10-30T23:26:56.406740Z TRACE debug-info-transform: === Begin DIE at 0x0000008e (depth = 1): DW_TAG_base_type DW_AT_name ("int") DW_AT_encoding (DW_ATE_signed) DW_AT_byte_size (4) 2024-10-30T23:26:56.406805Z TRACE debug-info-transform: === End DIE at 0x0000008e (depth = 1): DW_TAG_base_type DW_AT_name ("int") DW_AT_encoding (DW_ATE_signed) DW_AT_byte_size (4) 2024-10-30T23:26:56.406835Z TRACE debug-info-transform: === Begin DIE at 0x00000095 (depth = 1): DW_TAG_subprogram DW_AT_name ("__wasm_call_ctors") DW_AT_decl_file (0x00000001) DW_AT_decl_line (6) DW_AT_prototyped (true) DW_AT_declaration (true) DW_AT_external (true) 2024-10-30T23:26:56.406865Z TRACE debug-info-transform: === End DIE at 0x00000095 (depth = 1): Skipped as unreachable</details>
Wasmtime GitHub notifications bot (Oct 30 2024 at 23:40):SingleAccretion submitted PR review.
Wasmtime GitHub notifications bot (Oct 30 2024 at 23:40):SingleAccretion created PR review comment:
This a placeholder for what should ideally be
if #cfg(feature = "trace-log"), same as Cranelift'strace!, however, I do not know how to properly encode this into the build files.
Wasmtime GitHub notifications bot (Oct 30 2024 at 23:50):SingleAccretion updated PR #9526.
Wasmtime GitHub notifications bot (Oct 30 2024 at 23:56):SingleAccretion updated PR #9526.
Wasmtime GitHub notifications bot (Oct 31 2024 at 00:05):SingleAccretion updated PR #9526.
Wasmtime GitHub notifications bot (Oct 31 2024 at 00:54):SingleAccretion has marked PR #9526 as ready for review.
Wasmtime GitHub notifications bot (Oct 31 2024 at 00:54):SingleAccretion requested elliottt for a review on PR #9526.
Wasmtime GitHub notifications bot (Oct 31 2024 at 00:54):SingleAccretion requested wasmtime-core-reviewers for a review on PR #9526.
Wasmtime GitHub notifications bot (Oct 31 2024 at 01:07):SingleAccretion edited PR #9526:
The DI transform is a kind of compiler and logging is a very good way to gain insight into compilers, hence this change.
This has already helped me narrow down the cause of #9512:
2024-10-30T23:26:56.408332Z TRACE debug-info-transform: === Begin DIE at 0x0000007a (depth = 2): DW_TAG_subprogram DW_AT_linkage_name ("_ZN9SomeClass16SeparateFunctionEv") DW_AT_name ("SeparateFunction") DW_AT_decl_file (0x00000002) DW_AT_decl_line (20) DW_AT_type (0x0000008b) DW_AT_declaration (true) DW_AT_external (true) DW_AT_accessibility (DW_ACCESS_public) 2024-10-30T23:26:56.408361Z TRACE debug-info-transform: === End DIE at 0x0000007a (depth = 2): Skipped as unreachableI also took the liberty of renaming a few variables for clarity.
<details>
<summary>Sample output</summary>2024-10-30T23:26:56.398154Z TRACE debug-info-transform: Commencing DWARF transform for [#0: main.wasm, #1: wit-component:adapter:wasi_snapshot_preview1, #2: wit-component:shim, #3: wit-component:fixups] 2024-10-30T23:26:56.405243Z TRACE debug-info-transform: [== Transforming CUs for module #0 ==] 2024-10-30T23:26:56.405357Z TRACE debug-info-transform: Cloning CU 0x00000000 ["C:\wasi-sdk\sysroot\wasi-libc-wasm32-wasip2", "libc-bottom-half/crt\crt1-command.c"] 2024-10-30T23:26:56.405562Z TRACE debug-info-transform: === Begin DIE at 0x0000000b (depth = 0): DW_TAG_compile_unit DW_AT_producer ("clang version 18.1.2 (https://github.com/llvm/llvm-project 26a1d6601d727a96f4301d0d8647b5a42760ae0c)") DW_AT_language (DW_LANG_C11) DW_AT_name ("libc-bottom-half/crt\crt1-command.c") DW_AT_stmt_list (0x00000000) DW_AT_comp_dir ("C:\wasi-sdk\sysroot\wasi-libc-wasm32-wasip2") DW_AT_low_pc (00000005) DW_AT_high_pc (82) 2024-10-30T23:26:56.405789Z TRACE debug-info-transform: === End DIE at 0x0000000b (depth = 0): DW_TAG_compile_unit DW_AT_ranges (<TODO: out rnglist dump>) DW_AT_producer ("clang version 18.1.2 (https://github.com/llvm/llvm-project 26a1d6601d727a96f4301d0d8647b5a42760ae0c)") DW_AT_language (DW_LANG_C11) DW_AT_name ("libc-bottom-half/crt\crt1-command.c") DW_AT_stmt_list (LineProgramRef) DW_AT_comp_dir ("C:\wasi-sdk\sysroot\wasi-libc-wasm32-wasip2") 2024-10-30T23:26:56.405832Z TRACE debug-info-transform: === Begin DIE at 0x00000026 (depth = 1): DW_TAG_subprogram DW_AT_low_pc (00000005) DW_AT_high_pc (82) DW_AT_frame_base (<TODO: exprloc dump>) DW_AT_GNU_all_call_sites (true) DW_AT_name ("_start") DW_AT_decl_file (0x00000001) DW_AT_decl_line (11) DW_AT_prototyped (true) DW_AT_external (true) 2024-10-30T23:26:56.406070Z TRACE debug-info-transform: === End DIE at 0x00000026 (depth = 1): DW_TAG_subprogram DW_AT_low_pc (symbol #1+0) DW_AT_high_pc (182) DW_AT_frame_base (<TODO: out exprloc dump>) DW_AT_GNU_all_call_sites (true) DW_AT_name ("_start") DW_AT_decl_file (FileId(1)>) DW_AT_decl_line (11) DW_AT_prototyped (true) DW_AT_external (true) 2024-10-30T23:26:56.406119Z TRACE debug-info-transform: === Begin DIE at 0x0000003d (depth = 2): DW_TAG_variable DW_AT_name ("started") DW_AT_type (0x00000089) DW_AT_decl_file (0x00000001) DW_AT_decl_line (26) DW_AT_location (<TODO: exprloc dump>) 2024-10-30T23:26:56.406174Z TRACE debug-info-transform: === End DIE at 0x0000003d (depth = 2): DW_TAG_variable DW_AT_name ("started") DW_AT_decl_file (FileId(1)>) DW_AT_decl_line (26) 2024-10-30T23:26:56.406204Z TRACE debug-info-transform: === Begin DIE at 0x00000055 (depth = 2): DW_TAG_variable DW_AT_location (<TODO: loclist dump>) DW_AT_name ("r") DW_AT_decl_file (0x00000001) DW_AT_decl_line (43) DW_AT_type (0x0000008e) 2024-10-30T23:26:56.406359Z TRACE debug-info-transform: === End DIE at 0x00000055 (depth = 2): DW_TAG_variable DW_AT_location (<TODO: out loclist dump>) DW_AT_name ("r") DW_AT_decl_file (FileId(1)>) DW_AT_decl_line (43) 2024-10-30T23:26:56.406392Z TRACE debug-info-transform: === Begin DIE at 0x00000064 (depth = 2): DW_TAG_GNU_call_site DW_AT_abstract_origin (0x00000095) DW_AT_low_pc (00000036) 2024-10-30T23:26:56.406428Z TRACE debug-info-transform: === End DIE at 0x00000064 (depth = 2): Skipped as unreachable 2024-10-30T23:26:56.406456Z TRACE debug-info-transform: === Begin DIE at 0x0000006d (depth = 2): DW_TAG_GNU_call_site DW_AT_abstract_origin (0x0000009c) DW_AT_low_pc (0000003c) 2024-10-30T23:26:56.406505Z TRACE debug-info-transform: === End DIE at 0x0000006d (depth = 2): Skipped as unreachable 2024-10-30T23:26:56.406541Z TRACE debug-info-transform: === Begin DIE at 0x00000076 (depth = 2): DW_TAG_GNU_call_site DW_AT_abstract_origin (0x000000a7) DW_AT_low_pc (00000044) 2024-10-30T23:26:56.406588Z TRACE debug-info-transform: === End DIE at 0x00000076 (depth = 2): Skipped as unreachable 2024-10-30T23:26:56.406610Z TRACE debug-info-transform: === Begin DIE at 0x0000007f (depth = 2): DW_TAG_GNU_call_site DW_AT_abstract_origin (0x000000ae) DW_AT_low_pc (00000055) 2024-10-30T23:26:56.406633Z TRACE debug-info-transform: === End DIE at 0x0000007f (depth = 2): Skipped as unreachable 2024-10-30T23:26:56.406650Z TRACE debug-info-transform: === Begin DIE at 0x00000089 (depth = 1): DW_TAG_volatile_type DW_AT_type (0x0000008e) 2024-10-30T23:26:56.406696Z TRACE debug-info-transform: === End DIE at 0x00000089 (depth = 1): DW_TAG_volatile_type 2024-10-30T23:26:56.406740Z TRACE debug-info-transform: === Begin DIE at 0x0000008e (depth = 1): DW_TAG_base_type DW_AT_name ("int") DW_AT_encoding (DW_ATE_signed) DW_AT_byte_size (4) 2024-10-30T23:26:56.406805Z TRACE debug-info-transform: === End DIE at 0x0000008e (depth = 1): DW_TAG_base_type DW_AT_name ("int") DW_AT_encoding (DW_ATE_signed) DW_AT_byte_size (4) 2024-10-30T23:26:56.406835Z TRACE debug-info-transform: === Begin DIE at 0x00000095 (depth = 1): DW_TAG_subprogram DW_AT_name ("__wasm_call_ctors") DW_AT_decl_file (0x00000001) DW_AT_decl_line (6) DW_AT_prototyped (true) DW_AT_declaration (true) DW_AT_external (true) 2024-10-30T23:26:56.406865Z TRACE debug-info-transform: === End DIE at 0x00000095 (depth = 1): Skipped as unreachable</details>
Wasmtime GitHub notifications bot (Oct 31 2024 at 01:07):SingleAccretion edited PR #9526:
The DI transform is a kind of compiler and logging is a very good way to gain insight into compilers - hence this change.
This has already helped me narrow down the cause of #9512:
2024-10-30T23:26:56.408332Z TRACE debug-info-transform: === Begin DIE at 0x0000007a (depth = 2): DW_TAG_subprogram DW_AT_linkage_name ("_ZN9SomeClass16SeparateFunctionEv") DW_AT_name ("SeparateFunction") DW_AT_decl_file (0x00000002) DW_AT_decl_line (20) DW_AT_type (0x0000008b) DW_AT_declaration (true) DW_AT_external (true) DW_AT_accessibility (DW_ACCESS_public) 2024-10-30T23:26:56.408361Z TRACE debug-info-transform: === End DIE at 0x0000007a (depth = 2): Skipped as unreachableI also took the liberty of renaming a few variables for clarity.
<details>
<summary>Sample output</summary>2024-10-30T23:26:56.398154Z TRACE debug-info-transform: Commencing DWARF transform for [#0: main.wasm, #1: wit-component:adapter:wasi_snapshot_preview1, #2: wit-component:shim, #3: wit-component:fixups] 2024-10-30T23:26:56.405243Z TRACE debug-info-transform: [== Transforming CUs for module #0 ==] 2024-10-30T23:26:56.405357Z TRACE debug-info-transform: Cloning CU 0x00000000 ["C:\wasi-sdk\sysroot\wasi-libc-wasm32-wasip2", "libc-bottom-half/crt\crt1-command.c"] 2024-10-30T23:26:56.405562Z TRACE debug-info-transform: === Begin DIE at 0x0000000b (depth = 0): DW_TAG_compile_unit DW_AT_producer ("clang version 18.1.2 (https://github.com/llvm/llvm-project 26a1d6601d727a96f4301d0d8647b5a42760ae0c)") DW_AT_language (DW_LANG_C11) DW_AT_name ("libc-bottom-half/crt\crt1-command.c") DW_AT_stmt_list (0x00000000) DW_AT_comp_dir ("C:\wasi-sdk\sysroot\wasi-libc-wasm32-wasip2") DW_AT_low_pc (00000005) DW_AT_high_pc (82) 2024-10-30T23:26:56.405789Z TRACE debug-info-transform: === End DIE at 0x0000000b (depth = 0): DW_TAG_compile_unit DW_AT_ranges (<TODO: out rnglist dump>) DW_AT_producer ("clang version 18.1.2 (https://github.com/llvm/llvm-project 26a1d6601d727a96f4301d0d8647b5a42760ae0c)") DW_AT_language (DW_LANG_C11) DW_AT_name ("libc-bottom-half/crt\crt1-command.c") DW_AT_stmt_list (LineProgramRef) DW_AT_comp_dir ("C:\wasi-sdk\sysroot\wasi-libc-wasm32-wasip2") 2024-10-30T23:26:56.405832Z TRACE debug-info-transform: === Begin DIE at 0x00000026 (depth = 1): DW_TAG_subprogram DW_AT_low_pc (00000005) DW_AT_high_pc (82) DW_AT_frame_base (<TODO: exprloc dump>) DW_AT_GNU_all_call_sites (true) DW_AT_name ("_start") DW_AT_decl_file (0x00000001) DW_AT_decl_line (11) DW_AT_prototyped (true) DW_AT_external (true) 2024-10-30T23:26:56.406070Z TRACE debug-info-transform: === End DIE at 0x00000026 (depth = 1): DW_TAG_subprogram DW_AT_low_pc (symbol #1+0) DW_AT_high_pc (182) DW_AT_frame_base (<TODO: out exprloc dump>) DW_AT_GNU_all_call_sites (true) DW_AT_name ("_start") DW_AT_decl_file (FileId(1)>) DW_AT_decl_line (11) DW_AT_prototyped (true) DW_AT_external (true) 2024-10-30T23:26:56.406119Z TRACE debug-info-transform: === Begin DIE at 0x0000003d (depth = 2): DW_TAG_variable DW_AT_name ("started") DW_AT_type (0x00000089) DW_AT_decl_file (0x00000001) DW_AT_decl_line (26) DW_AT_location (<TODO: exprloc dump>) 2024-10-30T23:26:56.406174Z TRACE debug-info-transform: === End DIE at 0x0000003d (depth = 2): DW_TAG_variable DW_AT_name ("started") DW_AT_decl_file (FileId(1)>) DW_AT_decl_line (26) 2024-10-30T23:26:56.406204Z TRACE debug-info-transform: === Begin DIE at 0x00000055 (depth = 2): DW_TAG_variable DW_AT_location (<TODO: loclist dump>) DW_AT_name ("r") DW_AT_decl_file (0x00000001) DW_AT_decl_line (43) DW_AT_type (0x0000008e) 2024-10-30T23:26:56.406359Z TRACE debug-info-transform: === End DIE at 0x00000055 (depth = 2): DW_TAG_variable DW_AT_location (<TODO: out loclist dump>) DW_AT_name ("r") DW_AT_decl_file (FileId(1)>) DW_AT_decl_line (43) 2024-10-30T23:26:56.406392Z TRACE debug-info-transform: === Begin DIE at 0x00000064 (depth = 2): DW_TAG_GNU_call_site DW_AT_abstract_origin (0x00000095) DW_AT_low_pc (00000036) 2024-10-30T23:26:56.406428Z TRACE debug-info-transform: === End DIE at 0x00000064 (depth = 2): Skipped as unreachable 2024-10-30T23:26:56.406456Z TRACE debug-info-transform: === Begin DIE at 0x0000006d (depth = 2): DW_TAG_GNU_call_site DW_AT_abstract_origin (0x0000009c) DW_AT_low_pc (0000003c) 2024-10-30T23:26:56.406505Z TRACE debug-info-transform: === End DIE at 0x0000006d (depth = 2): Skipped as unreachable 2024-10-30T23:26:56.406541Z TRACE debug-info-transform: === Begin DIE at 0x00000076 (depth = 2): DW_TAG_GNU_call_site DW_AT_abstract_origin (0x000000a7) DW_AT_low_pc (00000044) 2024-10-30T23:26:56.406588Z TRACE debug-info-transform: === End DIE at 0x00000076 (depth = 2): Skipped as unreachable 2024-10-30T23:26:56.406610Z TRACE debug-info-transform: === Begin DIE at 0x0000007f (depth = 2): DW_TAG_GNU_call_site DW_AT_abstract_origin (0x000000ae) DW_AT_low_pc (00000055) 2024-10-30T23:26:56.406633Z TRACE debug-info-transform: === End DIE at 0x0000007f (depth = 2): Skipped as unreachable 2024-10-30T23:26:56.406650Z TRACE debug-info-transform: === Begin DIE at 0x00000089 (depth = 1): DW_TAG_volatile_type DW_AT_type (0x0000008e) 2024-10-30T23:26:56.406696Z TRACE debug-info-transform: === End DIE at 0x00000089 (depth = 1): DW_TAG_volatile_type 2024-10-30T23:26:56.406740Z TRACE debug-info-transform: === Begin DIE at 0x0000008e (depth = 1): DW_TAG_base_type DW_AT_name ("int") DW_AT_encoding (DW_ATE_signed) DW_AT_byte_size (4) 2024-10-30T23:26:56.406805Z TRACE debug-info-transform: === End DIE at 0x0000008e (depth = 1): DW_TAG_base_type DW_AT_name ("int") DW_AT_encoding (DW_ATE_signed) DW_AT_byte_size (4) 2024-10-30T23:26:56.406835Z TRACE debug-info-transform: === Begin DIE at 0x00000095 (depth = 1): DW_TAG_subprogram DW_AT_name ("__wasm_call_ctors") DW_AT_decl_file (0x00000001) DW_AT_decl_line (6) DW_AT_prototyped (true) DW_AT_declaration (true) DW_AT_external (true) 2024-10-30T23:26:56.406865Z TRACE debug-info-transform: === End DIE at 0x00000095 (depth = 1): Skipped as unreachable</details>
Wasmtime GitHub notifications bot (Oct 31 2024 at 01:08):SingleAccretion edited PR #9526:
The DI transform is a kind of compiler and logging is a very good way to gain insight into compilers - hence this change.
For example, this has already helped me narrow down the cause of #9512:
2024-10-30T23:26:56.408332Z TRACE debug-info-transform: === Begin DIE at 0x0000007a (depth = 2): DW_TAG_subprogram DW_AT_linkage_name ("_ZN9SomeClass16SeparateFunctionEv") DW_AT_name ("SeparateFunction") DW_AT_decl_file (0x00000002) DW_AT_decl_line (20) DW_AT_type (0x0000008b) DW_AT_declaration (true) DW_AT_external (true) DW_AT_accessibility (DW_ACCESS_public) 2024-10-30T23:26:56.408361Z TRACE debug-info-transform: === End DIE at 0x0000007a (depth = 2): Skipped as unreachableI also took the liberty of renaming a few variables for clarity.
<details>
<summary>Sample output</summary>2024-10-30T23:26:56.398154Z TRACE debug-info-transform: Commencing DWARF transform for [#0: main.wasm, #1: wit-component:adapter:wasi_snapshot_preview1, #2: wit-component:shim, #3: wit-component:fixups] 2024-10-30T23:26:56.405243Z TRACE debug-info-transform: [== Transforming CUs for module #0 ==] 2024-10-30T23:26:56.405357Z TRACE debug-info-transform: Cloning CU 0x00000000 ["C:\wasi-sdk\sysroot\wasi-libc-wasm32-wasip2", "libc-bottom-half/crt\crt1-command.c"] 2024-10-30T23:26:56.405562Z TRACE debug-info-transform: === Begin DIE at 0x0000000b (depth = 0): DW_TAG_compile_unit DW_AT_producer ("clang version 18.1.2 (https://github.com/llvm/llvm-project 26a1d6601d727a96f4301d0d8647b5a42760ae0c)") DW_AT_language (DW_LANG_C11) DW_AT_name ("libc-bottom-half/crt\crt1-command.c") DW_AT_stmt_list (0x00000000) DW_AT_comp_dir ("C:\wasi-sdk\sysroot\wasi-libc-wasm32-wasip2") DW_AT_low_pc (00000005) DW_AT_high_pc (82) 2024-10-30T23:26:56.405789Z TRACE debug-info-transform: === End DIE at 0x0000000b (depth = 0): DW_TAG_compile_unit DW_AT_ranges (<TODO: out rnglist dump>) DW_AT_producer ("clang version 18.1.2 (https://github.com/llvm/llvm-project 26a1d6601d727a96f4301d0d8647b5a42760ae0c)") DW_AT_language (DW_LANG_C11) DW_AT_name ("libc-bottom-half/crt\crt1-command.c") DW_AT_stmt_list (LineProgramRef) DW_AT_comp_dir ("C:\wasi-sdk\sysroot\wasi-libc-wasm32-wasip2") 2024-10-30T23:26:56.405832Z TRACE debug-info-transform: === Begin DIE at 0x00000026 (depth = 1): DW_TAG_subprogram DW_AT_low_pc (00000005) DW_AT_high_pc (82) DW_AT_frame_base (<TODO: exprloc dump>) DW_AT_GNU_all_call_sites (true) DW_AT_name ("_start") DW_AT_decl_file (0x00000001) DW_AT_decl_line (11) DW_AT_prototyped (true) DW_AT_external (true) 2024-10-30T23:26:56.406070Z TRACE debug-info-transform: === End DIE at 0x00000026 (depth = 1): DW_TAG_subprogram DW_AT_low_pc (symbol #1+0) DW_AT_high_pc (182) DW_AT_frame_base (<TODO: out exprloc dump>) DW_AT_GNU_all_call_sites (true) DW_AT_name ("_start") DW_AT_decl_file (FileId(1)>) DW_AT_decl_line (11) DW_AT_prototyped (true) DW_AT_external (true) 2024-10-30T23:26:56.406119Z TRACE debug-info-transform: === Begin DIE at 0x0000003d (depth = 2): DW_TAG_variable DW_AT_name ("started") DW_AT_type (0x00000089) DW_AT_decl_file (0x00000001) DW_AT_decl_line (26) DW_AT_location (<TODO: exprloc dump>) 2024-10-30T23:26:56.406174Z TRACE debug-info-transform: === End DIE at 0x0000003d (depth = 2): DW_TAG_variable DW_AT_name ("started") DW_AT_decl_file (FileId(1)>) DW_AT_decl_line (26) 2024-10-30T23:26:56.406204Z TRACE debug-info-transform: === Begin DIE at 0x00000055 (depth = 2): DW_TAG_variable DW_AT_location (<TODO: loclist dump>) DW_AT_name ("r") DW_AT_decl_file (0x00000001) DW_AT_decl_line (43) DW_AT_type (0x0000008e) 2024-10-30T23:26:56.406359Z TRACE debug-info-transform: === End DIE at 0x00000055 (depth = 2): DW_TAG_variable DW_AT_location (<TODO: out loclist dump>) DW_AT_name ("r") DW_AT_decl_file (FileId(1)>) DW_AT_decl_line (43) 2024-10-30T23:26:56.406392Z TRACE debug-info-transform: === Begin DIE at 0x00000064 (depth = 2): DW_TAG_GNU_call_site DW_AT_abstract_origin (0x00000095) DW_AT_low_pc (00000036) 2024-10-30T23:26:56.406428Z TRACE debug-info-transform: === End DIE at 0x00000064 (depth = 2): Skipped as unreachable 2024-10-30T23:26:56.406456Z TRACE debug-info-transform: === Begin DIE at 0x0000006d (depth = 2): DW_TAG_GNU_call_site DW_AT_abstract_origin (0x0000009c) DW_AT_low_pc (0000003c) 2024-10-30T23:26:56.406505Z TRACE debug-info-transform: === End DIE at 0x0000006d (depth = 2): Skipped as unreachable 2024-10-30T23:26:56.406541Z TRACE debug-info-transform: === Begin DIE at 0x00000076 (depth = 2): DW_TAG_GNU_call_site DW_AT_abstract_origin (0x000000a7) DW_AT_low_pc (00000044) 2024-10-30T23:26:56.406588Z TRACE debug-info-transform: === End DIE at 0x00000076 (depth = 2): Skipped as unreachable 2024-10-30T23:26:56.406610Z TRACE debug-info-transform: === Begin DIE at 0x0000007f (depth = 2): DW_TAG_GNU_call_site DW_AT_abstract_origin (0x000000ae) DW_AT_low_pc (00000055) 2024-10-30T23:26:56.406633Z TRACE debug-info-transform: === End DIE at 0x0000007f (depth = 2): Skipped as unreachable 2024-10-30T23:26:56.406650Z TRACE debug-info-transform: === Begin DIE at 0x00000089 (depth = 1): DW_TAG_volatile_type DW_AT_type (0x0000008e) 2024-10-30T23:26:56.406696Z TRACE debug-info-transform: === End DIE at 0x00000089 (depth = 1): DW_TAG_volatile_type 2024-10-30T23:26:56.406740Z TRACE debug-info-transform: === Begin DIE at 0x0000008e (depth = 1): DW_TAG_base_type DW_AT_name ("int") DW_AT_encoding (DW_ATE_signed) DW_AT_byte_size (4) 2024-10-30T23:26:56.406805Z TRACE debug-info-transform: === End DIE at 0x0000008e (depth = 1): DW_TAG_base_type DW_AT_name ("int") DW_AT_encoding (DW_ATE_signed) DW_AT_byte_size (4) 2024-10-30T23:26:56.406835Z TRACE debug-info-transform: === Begin DIE at 0x00000095 (depth = 1): DW_TAG_subprogram DW_AT_name ("__wasm_call_ctors") DW_AT_decl_file (0x00000001) DW_AT_decl_line (6) DW_AT_prototyped (true) DW_AT_declaration (true) DW_AT_external (true) 2024-10-30T23:26:56.406865Z TRACE debug-info-transform: === End DIE at 0x00000095 (depth = 1): Skipped as unreachable</details>
Wasmtime GitHub notifications bot (Oct 31 2024 at 01:54):cfallin submitted PR review:
Looks generally fine, thanks! I personally agree that this sort of tracing, included in checked-in source rather than ad-hoc as one debugs, is really useful when working out issues. So thanks for building this out.
A few thoughts below but nothing major!
Wasmtime GitHub notifications bot (Oct 31 2024 at 01:54):cfallin created PR review comment:
Does this sample output correspond to the code below? I see
0x... [...]there, but not here, for example, and escaped doublequotes...
Wasmtime GitHub notifications bot (Oct 31 2024 at 01:54):cfallin created PR review comment:
Do you mean that you want to put it under the same feature but that feature isn't on this crate, or do you mean you want to use the
trace!macro fromcranelift-codegen?I think it wouldn't be the worst thing to define a
trace-logmacro on this crate (wasmtime-cranelift) too; in principle any part of the compiler pipeline might want to do very high-volume logging in a special build, as we have here. Then we can wire up that feature a top-level feature on thewasmtimecrate (and wire it to Cranelift's feature at the same time).
Wasmtime GitHub notifications bot (Oct 31 2024 at 15:40):SingleAccretion updated PR #9526.
Wasmtime GitHub notifications bot (Oct 31 2024 at 15:41):SingleAccretion submitted PR review.
Wasmtime GitHub notifications bot (Oct 31 2024 at 15:41):SingleAccretion created PR review comment:
Copy&paste issue. Fixed.
Wasmtime GitHub notifications bot (Oct 31 2024 at 16:01):SingleAccretion submitted PR review.
Wasmtime GitHub notifications bot (Oct 31 2024 at 16:01):SingleAccretion created PR review comment:
The end result in terms of user experience that I would like to see here is:
1) This logging is enabled by default for debug builds.
2) This logging _can_ be enabled for release builds.
3) There is a "one stop shop" feature for all verbose logging.Notably, AFAICT, Cranelift's
trace!does not work for1, for which presumably there is a good reason. It means that1and3are in conflict. Would you say1should win (implying adding a separate feature just to this crate)?
Wasmtime GitHub notifications bot (Oct 31 2024 at 20:06):cfallin created PR review comment:
I generally agree with these goals; and to fill in a bit of detail,
trace!is off by default (compiled out statically) when the option is disabled because in release settings it causes unacceptable overheads to even have the dynamic check/branch on the logging level in inner loops. This carries over to debug builds because we haven't done anything special to enable the option in debug builds.I think we can get all three (i.e. I don't see any conflicts) by:
- Putting this crate's logging macro, and
cranelift-codegen's, in code that is enabled with something like#![cfg(any(feature = "trace-log", debug_assertions))];- Adding a
trace-logfeature to thewasmtimeandwasmtime-clicrates (off by default) that in turn enablestrace-logonwasmtime-craneliftand oncranelift-codegen.Does this seem reasonable to you?
Wasmtime GitHub notifications bot (Oct 31 2024 at 20:06):cfallin submitted PR review.
Wasmtime GitHub notifications bot (Oct 31 2024 at 20:17):SingleAccretion submitted PR review.
Wasmtime GitHub notifications bot (Oct 31 2024 at 20:17):SingleAccretion created PR review comment:
Sounds good, I'll take a look at implementing it.
Wasmtime GitHub notifications bot (Oct 31 2024 at 21:03):SingleAccretion requested wasmtime-compiler-reviewers for a review on PR #9526.
Wasmtime GitHub notifications bot (Oct 31 2024 at 21:03):SingleAccretion updated PR #9526.
Wasmtime GitHub notifications bot (Oct 31 2024 at 21:03):SingleAccretion requested wasmtime-default-reviewers for a review on PR #9526.
Wasmtime GitHub notifications bot (Oct 31 2024 at 21:04):SingleAccretion updated PR #9526.
Wasmtime GitHub notifications bot (Oct 31 2024 at 22:07):SingleAccretion edited PR review comment.
Wasmtime GitHub notifications bot (Nov 04 2024 at 19:11):cfallin submitted PR review:
Looks good, thanks for the patience here!
Wasmtime GitHub notifications bot (Nov 04 2024 at 19:50):SingleAccretion commented on PR #9526:
removed this pull request from the merge queue due to failed status checks
Hmm, some quite odd breakage.
error: unused import: `EntityRef` --> cranelift/codegen/src/alias_analysis.rs:73:53 | 73 | use cranelift_entity::{packed_option::PackedOption, EntityRef}; | ^^^^^^^^^ | = note: `-D unused-imports` implied by `-D warnings` = help: to override `-D warnings` add `#[allow(unused_imports)]` error: unused variable: `data` --> cranelift/codegen/src/machinst/lower.rs:640:17 | 640 | let data = &self.f.dfg.insts[inst]; | ^^^^ help: if this is intentional, prefix it with an underscore: `_data` | = note: `-D unused-variables` implied by `-D warnings` = help: to override `-D warnings` add `#[allow(unused_variables)]` error: unused variable: `block` --> cranelift/codegen/src/machinst/lower.rs:877:9 | 877 | block: Block, | ^^^^^ help: if this is intentional, prefix it with an underscore: `_block` error: unused variable: `align` --> cranelift/codegen/src/machinst/buffer.rs:635:13 | 635 | align, | ^^^^^ help: try ignoring the field: `align: _` error: unused variable: `disasm` --> cranelift/codegen/src/isa/x64/mod.rs:82:21 | 82 | if let Some(disasm) = emit_result.disasm.as_ref() { | ^^^^^^ help: if this is intentional, prefix it with an underscore: `_disasm` error: unused variable: `old` --> cranelift/codegen/src/isa/pulley_shared/inst/emit.rs:56:13 | 56 | let old = self.virtual_sp_offset; | ^^^ help: if this is intentional, prefix it with an underscore: `_old` error: unused variable: `value` --> cranelift/codegen/src/egraph.rs:535:18 | 535 | for (value, def) in self.func.dfg.values_and_defs() { | ^^^^^ help: if this is intentional, prefix it with an underscore: `_value` error: unused variable: `i` --> cranelift/codegen/src/egraph.rs:538:38 | 538 | ValueDef::Result(i, 0) => { | ^ help: if this is intentional, prefix it with an underscore: `_i` The following warnings were emitted during compilation: warning: cranelift-codegen@0.114.0: Failed to run `rustfmt` on ISLE-generated code: Os { code: 32, kind: BrokenPipe, message: "Broken pipe" } warning: cranelift-codegen@0.114.0: Failed to run `rustfmt` on ISLE-generated code: Os { code: 32, kind: BrokenPipe, message: "Broken pipe" } warning: cranelift-codegen@0.114.0: Failed to run `rustfmt` on ISLE-generated code: Os { code: 32, kind: BrokenPipe, message: "Broken pipe" } warning: cranelift-codegen@0.114.0: Failed to run `rustfmt` on ISLE-generated code: Os { code: 32, kind: BrokenPipe, message: "Broken pipe" } warning: cranelift-codegen@0.114.0: Failed to run `rustfmt` on ISLE-generated code: Os { code: 32, kind: BrokenPipe, message: "Broken pipe" } warning: cranelift-codegen@0.114.0: Failed to run `rustfmt` on ISLE-generated code: Os { code: 32, kind: BrokenPipe, message: "Broken pipe" } error: could not compile `cranelift-codegen` (lib) due to 8 previous errors
Wasmtime GitHub notifications bot (Nov 04 2024 at 20:24):alexcrichton submitted PR review.
Wasmtime GitHub notifications bot (Nov 04 2024 at 20:24):alexcrichton created PR review comment:
Here you'll want to use
if cfg!(...) { ... }instead of#[cfg(...)]because that's what's causing the failure in CI. With#[cfg]then in--releasebuild mode these statements are compiled out meaning that if any variables or such are only used for the log statements then they're all of a sudden unused variables and get code warnings. By usingif cfg!(...)it keeps the same shape of the code in release/debug mode and the consequence is that the optimizer has to do a little more work to determine that it's the same as the#[cfg]mode
Wasmtime GitHub notifications bot (Nov 04 2024 at 21:05):SingleAccretion updated PR #9526.
Wasmtime GitHub notifications bot (Nov 04 2024 at 21:05):SingleAccretion submitted PR review.
Wasmtime GitHub notifications bot (Nov 04 2024 at 21:05):SingleAccretion created PR review comment:
Thank you!
Wasmtime GitHub notifications bot (Nov 04 2024 at 21:08):cfallin has enabled auto merge for PR #9526.
Wasmtime GitHub notifications bot (Nov 04 2024 at 21:35):cfallin merged PR #9526.
Last updated: Dec 23 2024 at 12:05 UTC