rust-lang / rust

Empowering everyone to build reliable and efficient software.
https://www.rust-lang.org
Other
98.57k stars 12.74k forks source link

Incorrect line table generation for await points #123341

Closed Sandlot19 closed 2 months ago

Sandlot19 commented 7 months ago

I’m a developer for the Fuchsia Debugger (zxdb), and noticed an issue with setting a breakpoint on a line of rust code containing an await. In particular, this issue was filed: Breakpoint set on await line does not stop. There are additional details in that bug report with my investigation, and the workaround for zxdb will be similar to what LLDB does.

While debugging some async code, I noticed that a breakpoint I set on a particular line number wasn’t being hit. It turned out that the line table for the async function call site looked incorrect. Namely, the line table entry for a line containing an await generated an is_stmt on a ud2 instruction, which is never actually executed. The typical algorithm debuggers use for placing breakpoints uses the lowest address for the function that is marked is_stmt in the line table, which in this case is incorrect, since the first code either isn’t associated with the callsite, or shouldn’t be marked is_stmt.

This code is a minimal reproducer:

async fn process_int(i: u32) -> u32 {
    tokio::time::sleep(tokio::time::Duration::from_secs(2)).await;
    i+1
}

#[tokio::main(flavor = "current_thread")]
async fn main() -> Result<(), Box<dyn Error + Send + Sync>>{
    println!("Hello world!");

    let i = process_int(15).await; // Set a breakpoint on this line.

    println!("{}", i);
    Ok(())
}

Here is the relevant section of the line table, the above source is located in file index 3 in the fourth column, and the line indicated above is 18 in the second column (llvm-dwarfdump-15 --debug-line):

0x000000000001f219     18     29      3   0             0  is_stmt // <-- This address is a ud2 instruction, but is marked as valid
0x000000000001f21b      0     29      3   0             0 
0x000000000001f220     14      1      3   0             0  is_stmt
0x000000000001f228     16      5      3   0             0  is_stmt
0x000000000001f240     14      1      3   0             0  is_stmt
0x000000000001f256      0      1      3   0             0 
0x000000000001f25b     18     29      3   0             0  is_stmt // <-- This is the most reasonable address to choose for the breakpoint in the line table.
0x000000000001f268     14      1      3   0             0  is_stmt
0x000000000001f281      0      1      3   0             0 
0x000000000001f297     16      5      3   0             0  is_stmt
0x000000000001f2a7      0      5      3   0             0 
0x000000000001f2b4     18     13      3   0             0  is_stmt
0x000000000001f2bb      0     13      3   0             0 
0x000000000001f2cb     18     29      3   0             0 
0x000000000001f2d2     18     13      3   0             0 
0x000000000001f2e9     18     29      3   0             0

LLDB sets a breakpoint in several locations:

(lldb) b main.rs:18
Breakpoint 1: 3 locations.
(lldb) r
Hello world!
Process 1338689 stopped
* thread #1, name = 'tokio-test', stop reason = breakpoint 1.2
    frame #0: 0x00005555555732b4 tokio-test`tokio_test::main::_$u7b$$u7b$closure$u7d$$u7d$::hbcd05a4ce5f705a7((null)=0x00007fffffffcb60) at main.rs:18:13
   15   async fn main() -> Result<(), Box<dyn Error + Send + Sync>>{
   16      println!("Hello world!");
   17   
-> 18      let i = process_int(15).await;
   19   
   20      println!("{}", i);
   21      Ok(())
(lldb) breakpoint list
Current breakpoints:
1: file = 'main.rs', line = 18, exact_match = 0, locations = 3, resolved = 3, hit count = 1
  1.1: where = tokio-test`tokio_test::main::_$u7b$$u7b$closure$u7d$$u7d$::hbcd05a4ce5f705a7 + 73 at main.rs:18:29, address = 0x0000555555573219, resolved, hit count = 0   <-- Location on ud2, which is required by the debugger algorithm.
  1.2: where = tokio-test`tokio_test::main::_$u7b$$u7b$closure$u7d$$u7d$::hbcd05a4ce5f705a7 + 228 at main.rs:18:13, address = 0x00005555555732b4, resolved, hit count = 1   <-- Location that gets hit first.
  1.3: where = tokio-test`tokio_test::main::_$u7b$$u7b$closure$u7d$$u7d$::hbcd05a4ce5f705a7 + 487 at main.rs:18:13, address = 0x00005555555733b7, resolved, hit count = 0   <-- Location that gets hit when the future is resolved.

(lldb) dis 
tokio-test`tokio_test::main::_$u7b$$u7b$closure$u7d$$u7d$::hbcd05a4ce5f705a7:
    0x5555555731d0 <+0>:   subq   $0x238, %rsp              ; imm = 0x238 
    0x5555555731d7 <+7>:   movq   %rdx, 0x28(%rsp)
    0x5555555731dc <+12>:  movq   %rdi, 0x30(%rsp)
    0x5555555731e1 <+17>:  movq   %rdi, 0x38(%rsp)
    0x5555555731e6 <+22>:  movq   %rsi, 0x48(%rsp)
    0x5555555731eb <+27>:  movq   %rdx, 0x1e8(%rsp)
    0x5555555731f3 <+35>:  movq   0x48(%rsp), %rax
    0x5555555731f8 <+40>:  movzbl 0x80(%rax), %eax
    0x5555555731ff <+47>:  movq   %rax, 0x40(%rsp)
    0x555555573204 <+52>:  movq   0x40(%rsp), %rax
    0x555555573209 <+57>:  leaq   0x101308(%rip), %rcx
    0x555555573210 <+64>:  movslq (%rcx,%rax,4), %rax
    0x555555573214 <+68>:  addq   %rcx, %rax
    0x555555573217 <+71>:  jmpq   *%rax
    0x555555573219 <+73>:  ud2                          <-- Here's the first address, indicated by the lowest address in the line table.
    0x55555557321b <+75>:  movq   0x28(%rsp), %rax
    0x555555573220 <+80>:  movq   %rax, 0x1e0(%rsp)
    0x555555573228 <+88>:  leaq   0x146f49(%rip), %rsi
    0x55555557322f <+95>:  leaq   0x50(%rsp), %rdi
    0x555555573234 <+100>: movl   $0x1, %edx
    0x555555573239 <+105>: callq  0x555555571820            ; core::fmt::Arguments::new_const::h9d890b958e6b6cea at mod.rs:321
    0x55555557323e <+110>: jmp    0x555555573297            ; <+199> at main.rs:16:5
    0x555555573240 <+112>: xorl   %eax, %eax
    0x555555573242 <+114>: testb  $0x1, %al
    0x555555573244 <+116>: jne    0x555555573240            ; <+112> at main.rs:14:1
    0x555555573246 <+118>: jmp    0x55555557330d            ; <+317> at main.rs:14:1
    0x55555557324b <+123>: xorl   %eax, %eax
    0x55555557324d <+125>: testb  $0x1, %al
    0x55555557324f <+127>: jne    0x55555557324b            ; <+123> at main.rs:14:1
    0x555555573251 <+129>: jmp    0x555555573329            ; <+345> at main.rs:14:1
    0x555555573256 <+134>: movq   0x28(%rsp), %rax
    0x55555557325b <+139>: movq   %rax, 0x1e0(%rsp)
    0x555555573263 <+147>: jmp    0x5555555732e9            ; <+281> at main.rs:18:29
    0x555555573268 <+152>: movq   0x48(%rsp), %rax
    0x55555557326d <+157>: movb   $0x2, 0x80(%rax)
    0x555555573274 <+164>: movq   0x1f0(%rsp), %rdi
    0x55555557327c <+172>: callq  0x55555556c040            ; symbol stub for: _Unwind_Resume
    0x555555573281 <+177>: movq   %rax, %rcx
    0x555555573284 <+180>: movl   %edx, %eax
    0x555555573286 <+182>: movq   %rcx, 0x1f0(%rsp)
    0x55555557328e <+190>: movl   %eax, 0x1f8(%rsp)
    0x555555573295 <+197>: jmp    0x555555573268            ; <+152> at main.rs:14:1
    0x555555573297 <+199>: leaq   0xd88f2(%rip), %rax       ; std::io::stdio::_print::hc62f134794ba50d8 at stdio.rs:1105
    0x55555557329e <+206>: leaq   0x50(%rsp), %rdi
    0x5555555732a3 <+211>: callq  *%rax
    0x5555555732a5 <+213>: jmp    0x5555555732a7            ; <+215> at main.rs
    0x5555555732a7 <+215>: leaq   0x108(%rsp), %rdi
    0x5555555732af <+223>: movl   $0xf, %esi
->  0x5555555732b4 <+228>: callq  0x5555555714c0            <-- Where lldb actually stopped.
    0x5555555732b9 <+233>: jmp    0x5555555732bb            ; <+235> at main.rs
    0x5555555732bb <+235>: leaq   0x88(%rsp), %rdi
    0x5555555732c3 <+243>: leaq   0x108(%rsp), %rsi
    0x5555555732cb <+251>: callq  0x555555572f40            ; _$LT$F$u20$as$u20$core..future..into_future..IntoFuture$GT$::into_future::h1cf8907f0c2ba760 at into_future.rs:137
    0x5555555732d0 <+256>: jmp    0x5555555732d2            ; <+258> at main.rs:18:13
    0x5555555732d2 <+258>: movq   0x48(%rsp), %rdi
    0x5555555732d7 <+263>: leaq   0x88(%rsp), %rsi
    0x5555555732df <+271>: movl   $0x80, %edx
    0x5555555732e4 <+276>: callq  0x55555556c060            ; ___lldb_unnamed_symbol6291 + 16
    0x5555555732e9 <+281>: movq   0x48(%rsp), %rax
    0x5555555732ee <+286>: movq   %rax, 0x230(%rsp)
...
    0x555555573368 <+408>: jmp    0x555555573345            ; <+373> at main.rs:18:29
    0x55555557336a <+410>: movq   0x20(%rsp), %rdi
    0x55555557336f <+415>: movq   0x1e0(%rsp), %rsi
    0x555555573377 <+423>: callq  0x555555572f70            ; tokio_test::process_int::_$u7b$$u7b$closure$u7d$$u7d$::h8fcde729a73e470f at main.rs:9
    0x55555557337c <+428>: movl   %edx, 0x18(%rsp)
    0x555555573380 <+432>: movl   %eax, 0x1c(%rsp)
    0x555555573384 <+436>: jmp    0x555555573386            ; <+438> at main.rs
    0x555555573386 <+438>: movl   0x18(%rsp), %eax
    0x55555557338a <+442>: movl   0x1c(%rsp), %ecx
    0x55555557338e <+446>: movl   %ecx, 0x188(%rsp)
    0x555555573395 <+453>: movl   %eax, 0x18c(%rsp)
    0x55555557339c <+460>: movl   0x188(%rsp), %eax
    0x5555555733a3 <+467>: cmpq   $0x0, %rax
    0x5555555733a7 <+471>: jne    0x5555555733ca            ; <+506> at main.rs
    0x5555555733a9 <+473>: movl   0x18c(%rsp), %eax
    0x5555555733b0 <+480>: movl   %eax, 0x204(%rsp)
    0x5555555733b7 <+487>: movl   %eax, 0x84(%rsp)     <-- Third location
    0x5555555733be <+494>: movq   0x48(%rsp), %rdi
    0x5555555733c3 <+499>: callq  0x5555555748e0            ; core::ptr::drop_in_place$LT$tokio_test..process_int..$u7b$$u7b$closure$u7d$$u7d$$GT$::h16e2f156df1eb4f6 at mod.rs:507
    0x5555555733c8 <+504>: jmp    0x5555555733ef            ; <+543> at main.rs
    0x5555555733ca <+506>: movq   0x38(%rsp), %rax
    0x5555555733cf <+511>: movq   0x30(%rsp), %rcx
    0x5555555733d4 <+516>: movq   $0x1, (%rcx)
    0x5555555733db <+523>: movq   0x48(%rsp), %rcx
    0x5555555733e0 <+528>: movb   $0x3, 0x80(%rcx)
    0x5555555733e7 <+535>: addq   $0x238, %rsp              ; imm = 0x238 
    0x5555555733ee <+542>: retq

Luckily, this is generally correct. The breakpoint hits the call instruction for function. The thread is stopped again when you hit the third location when the Future is dropped, which is wacky. But that’s an issue with LLDB.

GDB has better results, since it just sets the breakpoint addresses on the ud2 instruction and on the call site, avoiding the double stoppage that LLDB has.

rustc --version --verbose:

rustc 1.77.0 (aedd173a2 2024-03-17)
binary: rustc
commit-hash: aedd173a2c086e558c2b66d3743b344f977621a7
commit-date: 2024-03-17
host: x86_64-unknown-linux-gnu
release: 1.77.0
LLVM version: 17.0.6
traviscross commented 7 months ago

@rustbot labels +AsyncAwait-Triaged

We discussed this in the async triage call and, based on the report, it sounds like a possible bug that will need some careful attention by the right person or persons familiar with this infrastructure.

brettw commented 7 months ago

My initial impression is that the ud2 instruction should be annotated as "line 0" (compiler generated) like the following instruction.

khuey commented 3 months ago

There are arguably a number of bugs here (that the instruction is marked with is_stmt=1, that LLVM doesn't remove the unreachable ud2, that the ud2 is attributed to a later line), but #128628 fixes this.

During desugaring the line with the await is desugared into a call to the relevant poll implementation followed by a match on its result. That match has an unreachable block that handles the catchall case and that unreachable block is assigned the location of the await.

Desugaring also breaks down the containing async function into a closure that matches on the state of the generated future. That match also has an unreachable block that handles the catchall case. That match goes at the very top of the resume function, but the new unreachable block is appended to the end.

Then SimplifyCFG merges the two unreachable blocks. The unreachable block that was created for the await survives because it's first in basic block order, and the match that was placed in the very first basic block is modified to use it for its catchall case.

Later the ud2 from the unreachable block is pulled forwards to fall after the match in the very first basic block. This unreachable block still has the source information for the await call, and this ends up causing the issue where the first code attributed to the await line in program order is an unreachable ud2 at the top of the function.

A solution to this is simply to erase the source information when we merge unreachable blocks and not attribute them to any line at all.

khuey commented 3 months ago

@rustbot claim

khuey commented 2 months ago

I don't have the power to close issues but this is fixed now.