Wasmtime: lldb cannot symbolise the last retq of functions

[ggreif]

First off, this might be an lldb bug. But since that SW is a bit more mature, let's start here.
I have a debugging session recorded:

$ cd tests/all/debug/testsuite
/Users/ggreif/motoko/wasmtime/tests/all/debug/testsuite

$ lldb-10.0.1/bin/lldb -- ../../../../target/debug/wasmtime --disable-cache -g fib-wasm-dwarf5.wasm --invoke fib 2

(lldb) target create "../../../../target/debug/wasmtime"
Current executable set to '/Users/ggreif/motoko/wasmtime/target/debug/wasmtime' (x86_64).
(lldb) settings set -- target.run-args  "--disable-cache" "-g" "fib-wasm-dwarf5.wasm" "--invoke" "fib" "2"
(lldb) 
(lldb) b fib
Breakpoint 1: no locations (pending).
WARNING:  Unable to resolve breakpoint to any actual locations.
(lldb) r
Process 42125 launched: '/Users/ggreif/motoko/wasmtime/target/debug/wasmtime' (x86_64)
map: PrimaryMap { elems: [FunctionMap { offset: 0, len: 142, wasm_start: 3, wasm_end: 206, addresses: [AddressMap { generated: 7, wasm: 4 }, AddressMap { generated: 13, wasm: 6 }, AddressMap { generated: 17, wasm: 22 }, AddressMap { generated: 20, wasm: 29 }, AddressMap { generated: 26, wasm: 37 }, AddressMap { generated: 29, wasm: 37 }, AddressMap { generated: 33, wasm: 37 }, AddressMap { generated: 38, wasm: 44 }, AddressMap { generated: 43, wasm: 51 }, AddressMap { generated: 48, wasm: 58 }, AddressMap { generated: 53, wasm: 63 }, AddressMap { generated: 53, wasm: 67 }, AddressMap { generated: 58, wasm: 74 }, AddressMap { generated: 63, wasm: 91 }, AddressMap { generated: 68, wasm: 91 }, AddressMap { generated: 72, wasm: 102 }, AddressMap { generated: 75, wasm: 108 }, AddressMap { generated: 80, wasm: 108 }, AddressMap { generated: 80, wasm: 112 }, AddressMap { generated: 85, wasm: 121 }, AddressMap { generated: 90, wasm: 126 }, AddressMap { generated: 95, wasm: 135 }, AddressMap { generated: 100, wasm: 140 }, AddressMap { generated: 105, wasm: 147 }, AddressMap { generated: 110, wasm: 156 }, AddressMap { generated: 112, wasm: 163 }, AddressMap { generated: 117, wasm: 168 }, AddressMap { generated: 122, wasm: 181 }, AddressMap { generated: 125, wasm: 188 }, AddressMap { generated: 130, wasm: 191 }, AddressMap { generated: 132, wasm: 197 }, AddressMap { generated: 141, wasm: 204 }] }], unused: PhantomData }

The above is just a dump of the translation map, I use origin/main f1a5e55b981f141780912dfb40881cb3891d0466 wasmtime, with this slight patch. Eyeballing doesn't seem to detect anything strange in it.

1 location added to breakpoint 1
warning: using `--invoke` with a function that takes arguments is experimental and may break in the future
Process 42125 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = breakpoint 1.1
    frame #0: 0x00000001040e7026 JIT(0x10580d600)`fib(n=2) at fib-wasm.c:9:10
   6    //     -Wl,--no-entry,--export=fib -nostdlib -fdebug-prefix-map=$PWD=.
   7    
   8    int fib(int n) {
-> 9      int t, a = 0, b = 1;
   10     for (int i = 0; i < n; i++) {
   11       t = a;
   12       a = b;
(lldb) disass
JIT(0x10580d600)`fib:
    0x1040e7000 <+0>:   pushq  %rbp
    0x1040e7002 <+2>:   movq   %rsp, %rbp
    0x1040e7005 <+5>:   pushq  %rbx
    0x1040e7007 <+7>:   movl   $0x0, %eax
    0x1040e700d <+13>:  movl   0x40(%rdi), %ecx
    0x1040e7011 <+17>:  addl   $-0x20, %ecx
    0x1040e7014 <+20>:  movl   $0x1, %ebx
    0x1040e701a <+26>:  movl   %ecx, %ecx
    0x1040e701d <+29>:  movq   0x2c(%rdi), %rsi
    0x1040e7021 <+33>:  movl   %edx, 0x1c(%rsi,%rcx)
->  0x1040e7026 <+38>:  movl   %eax, 0x14(%rsi,%rcx)
    0x1040e702b <+43>:  movl   %ebx, 0x10(%rsi,%rcx)
    0x1040e7030 <+48>:  movl   %eax, 0xc(%rsi,%rcx)
    0x1040e7035 <+53>:  movl   0xc(%rsi,%rcx), %eax
    0x1040e703a <+58>:  movl   0x1c(%rsi,%rcx), %edx
    0x1040e703f <+63>:  cmpl   %edx, %eax
    0x1040e7041 <+65>:  setl   %al
    0x1040e7044 <+68>:  movzbl %al, %eax
    0x1040e7048 <+72>:  andl   $0x1, %eax
    0x1040e704b <+75>:  testl  %eax, %eax
    0x1040e704e <+78>:  je     0x1040e7084               ; <+132> at fib-wasm.c:15:10
    0x1040e7050 <+80>:  movl   0x14(%rsi,%rcx), %eax
    0x1040e7055 <+85>:  movl   %eax, 0x18(%rsi,%rcx)
    0x1040e705a <+90>:  movl   0x10(%rsi,%rcx), %eax
    0x1040e705f <+95>:  movl   %eax, 0x14(%rsi,%rcx)
    0x1040e7064 <+100>: movl   0x18(%rsi,%rcx), %eax
    0x1040e7069 <+105>: movl   0x10(%rsi,%rcx), %edx
    0x1040e706e <+110>: addl   %eax, %edx
    0x1040e7070 <+112>: movl   %edx, 0x10(%rsi,%rcx)
    0x1040e7075 <+117>: movl   0xc(%rsi,%rcx), %eax
    0x1040e707a <+122>: addl   $0x1, %eax
    0x1040e707d <+125>: movl   %eax, 0xc(%rsi,%rcx)
    0x1040e7082 <+130>: jmp    0x1040e7035               ; <+53> at fib-wasm.c:10:19
    0x1040e7084 <+132>: movl   0x10(%rsi,%rcx), %eax
    0x1040e7089 <+137>: popq   %rbx
    0x1040e708b <+139>: popq   %rbp
    0x1040e708d <+141>: retq   
(lldb) b 0x1040e708b
Breakpoint 2: where = JIT(0x10580d600)`fib + 139 at fib-wasm.c:15:10, address = 0x00000001040e708b
(lldb) c
Process 42125 resuming
Process 42125 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = breakpoint 2.1
    frame #0: 0x00000001040e708b JIT(0x10580d600)`fib(n=2) at fib-wasm.c:15:10
   12       a = b;
   13       b += t;
   14     }
-> 15     return b;
   16   }
(lldb) reg rea rip
     rip = 0x00000001040e708b  JIT(0x10580d600)`fib + 139 at fib-wasm.c:15:10

at this point all is fine, reverse mapping from rip to source works fine.

(lldb) ni
Process 42125 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = instruction step over
    frame #0: 0x00000001040e708d JIT(0x10580d600)`fib(n=2) + 141
JIT(0x10580d600)`fib:
->  0x1040e708d <+141>: retq   
    0x1040e708e:        pushq  %rbp
    0x1040e7090:        movq   %rsp, %rbp
    0x1040e7093:        pushq  %r15
(lldb) 

Now suddenly we find ourselves in assembly land. No mapping to source shown:

(lldb) reg rea rip
     rip = 0x00000001040e708d  JIT(0x10580d600)`fib + 141

How can this be debugged? Thankfully all ingredients are in the repo itself, so it should be easy to take a first step and reproduce.

@yurydelendik any tips?

For completeness, here is the wasmtime patch I mentioned:

$ git diff
diff --git a/crates/debug/src/transform/address_transform.rs b/crates/debug/src/transform/address_transform.rs
index 43bfc0b63..da7ae36f0 100644
--- a/crates/debug/src/transform/address_transform.rs
+++ b/crates/debug/src/transform/address_transform.rs
@@ -219,6 +219,7 @@ fn build_function_addr_map(
             addresses: fn_map.into_boxed_slice(),
         });
     }
+    println!("map: {:?}", map);
     map
 }

[bjorn3]

Maybe a duplicate of https://github.com/bytecodealliance/wasmtime/issues/1145?

[ggreif]

@bjorn3 possibly. At least it is not related to the DWARF epilogue_begin indication, since the function doesn't carry one:

$ llvm-dwarfdump ./fib-wasm-dwarf5.o -debug-line
./fib-wasm-dwarf5.o:    file format ELF64-x86-64

.debug_line contents:
debug_line[0x00000000]
Line table prologue:
    total_length: 0x0000007c
         version: 4
 prologue_length: 0x00000024
 min_inst_length: 1
max_ops_per_inst: 1
 default_is_stmt: 1
       line_base: -5
      line_range: 14
     opcode_base: 13
standard_opcode_lengths[DW_LNS_copy] = 0
standard_opcode_lengths[DW_LNS_advance_pc] = 1
standard_opcode_lengths[DW_LNS_advance_line] = 1
standard_opcode_lengths[DW_LNS_set_file] = 1
standard_opcode_lengths[DW_LNS_set_column] = 1
standard_opcode_lengths[DW_LNS_negate_stmt] = 0
standard_opcode_lengths[DW_LNS_set_basic_block] = 0
standard_opcode_lengths[DW_LNS_const_add_pc] = 0
standard_opcode_lengths[DW_LNS_fixed_advance_pc] = 1
standard_opcode_lengths[DW_LNS_set_prologue_end] = 0
standard_opcode_lengths[DW_LNS_set_epilogue_begin] = 0
standard_opcode_lengths[DW_LNS_set_isa] = 1
include_directories[  1] = "."
file_names[  1]:
           name: "fib-wasm.c"
      dir_index: 1
       mod_time: 0x00000000
         length: 0x00000000

Address            Line   Column File   ISA Discriminator Flags
------------------ ------ ------ ------ --- ------------- -------------
0x0000000000000000      8      0      1   0             0  is_stmt
0x0000000000000026      9     10      1   0             0  is_stmt prologue_end
0x000000000000002b      9     17      1   0             0 
0x0000000000000030     10     12      1   0             0  is_stmt
0x0000000000000035     10     19      1   0             0 
0x000000000000003a     10     23      1   0             0 
0x000000000000003f     10     21      1   0             0 
0x0000000000000048     10      3      1   0             0 
0x0000000000000050     11      9      1   0             0  is_stmt
0x0000000000000055     11      7      1   0             0 
0x000000000000005a     12      9      1   0             0  is_stmt
0x000000000000005f     12      7      1   0             0 
0x0000000000000064     13     10      1   0             0  is_stmt
0x0000000000000069     13      7      1   0             0 
0x0000000000000075     10     27      1   0             0  is_stmt
0x0000000000000082     10      3      1   0             0 
0x0000000000000084     15     10      1   0             0  is_stmt
0x000000000000008d     15      3      1   0             0 
0x000000000000008d     15      3      1   0             0  end_sequence

Addendum

As @bjorn3 notes below, the last two lines should be

0x000000000000008d     15      3      1   0             0 
0x000000000000008e     15      3      1   0             0  end_sequence

and thus in sync with FunctionMap { offset: 0, len: 142, ...
So this line table comes from wasm2obj and it is already buggy.

I am checking these next:

$ git grep end_sequence
crates/debug/src/transform/line_program.rs:                if row.end_sequence() {
crates/debug/src/transform/line_program.rs:            let saved_row = if row.end_sequence() {
crates/debug/src/transform/line_program.rs:            out_program.end_sequence(end_addr);
crates/debug/src/transform/simulate.rs:        out_program.end_sequence(end_addr);

[bjorn3]

    0x1040e708d <+141>: retq

that is offset 0x8d, which is exactly the end of the line program. I think it needs to continue until the end of the last instruction, not the start.

[ggreif]

Ha, this is a good point, indeed, I wanted to post the wasm's DWARF line program, but I slipped, and above I posted the wasmtime wasm2obj's line table. end_sequence should belong to the offset 0x8e, thanks for spotting! So can we assume that the line table is wrongly emitted by wasmtime? Or is that gimli's job?

Below is the untranslated one:

$ llvm-dwarfdump ./fib-wasm-dwarf5.wasm -debug-line
./fib-wasm-dwarf5.wasm: file format WASM

.debug_line contents:
debug_line[0x00000000]
Line table prologue:
    total_length: 0x00000094
         version: 5
    address_size: 4
 seg_select_size: 0
 prologue_length: 0x00000037
 min_inst_length: 1
max_ops_per_inst: 1
 default_is_stmt: 1
       line_base: -5
      line_range: 14
     opcode_base: 13
standard_opcode_lengths[DW_LNS_copy] = 0
standard_opcode_lengths[DW_LNS_advance_pc] = 1
standard_opcode_lengths[DW_LNS_advance_line] = 1
standard_opcode_lengths[DW_LNS_set_file] = 1
standard_opcode_lengths[DW_LNS_set_column] = 1
standard_opcode_lengths[DW_LNS_negate_stmt] = 0
standard_opcode_lengths[DW_LNS_set_basic_block] = 0
standard_opcode_lengths[DW_LNS_const_add_pc] = 0
standard_opcode_lengths[DW_LNS_fixed_advance_pc] = 1
standard_opcode_lengths[DW_LNS_set_prologue_end] = 0
standard_opcode_lengths[DW_LNS_set_epilogue_begin] = 0
standard_opcode_lengths[DW_LNS_set_isa] = 1
include_directories[  0] = "."
file_names[  0]:
           name: "fib-wasm.c"
      dir_index: 0
   md5_checksum: 3444f0aa42db6d50ac2e4e57ac752c75

Address            Line   Column File   ISA Discriminator Flags
------------------ ------ ------ ------ --- ------------- -------------
0x0000000000000003      8      0      0   0             0  is_stmt
0x0000000000000028      9     10      0   0             0  is_stmt prologue_end
0x000000000000002f      9     17      0   0             0 
0x0000000000000036     10     12      0   0             0  is_stmt
0x000000000000003d     10     19      0   0             0 
0x0000000000000048     10     23      0   0             0 
0x000000000000004f     10     21      0   0             0 
0x000000000000005e     10      3      0   0             0 
0x000000000000006e     11      9      0   0             0  is_stmt
0x0000000000000075     11      7      0   0             0 
0x000000000000007c     12      9      0   0             0  is_stmt
0x0000000000000083     12      7      0   0             0 
0x000000000000008a     13     10      0   0             0  is_stmt
0x0000000000000091     13      7      0   0             0 
0x00000000000000a6     10     27      0   0             0  is_stmt
0x00000000000000bf     10      3      0   0             0 
0x00000000000000c1     10      3      0   0             0 
0x00000000000000c3     15     10      0   0             0  is_stmt
0x00000000000000ca     15      3      0   0             0 
0x00000000000000ce     15      3      0   0             0  end_sequence

The disassembly follows

$ llvm-objdump ./fib-wasm-dwarf5.wasm --disassemble

./fib-wasm-dwarf5.wasm: file format WASM


Disassembly of section CODE:

00000000 CODE:
        # 1 functions in section.
       1: cb                            <unknown>
       2: 01                            nop
       3: 01                            nop
       4: 15                            <unknown>
       5: 7f                            i64.div_s
       6: 23 80 80 80 80 00             global.get  0
       c: 21 01                         local.set   1
       e: 41 20                         i32.const   32
      10: 21 02                         local.set   2
<snip>
      bc: 36 02 0c                      i32.store   12
      bf: 0c 00                         br          0
      c1: 0b                            end
      c2: 0b                            end
      c3: 20 03                         local.get   3
      c5: 28 02 10                      i32.load    16
      c8: 21 15                         local.set   21
      ca: 20 15                         local.get   21
      cc: 0f                            return
      cd: 0b                            end

[bjorn3]

Wasmtime determines the content of the line program, gimli then encodes it in the DWARF format. I think removing the - 1 from the following line will fix the problem: https://github.com/bytecodealliance/wasmtime/blob/79f054f77f2edf84ff9b46b1e0ad57a423e6727b/crates/debug/src/transform/line_program.rs#L274

[ggreif]

@bjorn3 Indeed, now I get

0x000000000000008d     15      3      1   0             0 
0x000000000000008e     15      3      1   0             0  end_sequence

Thanks for the fix. Do you care to file a PR?

[bjorn3]

Opened #2174.