F10 & F11 stepping not reliable

ghost commented 2 years ago

Code to repro.
Discussion on rs-probe:matrix.org..

hardware:

nucleo-F767ZI powered over usb, nothing attached to pins.

software:

probe-rs-debugger-0.3.3.vsix, probe-rs-debugger 0.12.0, probe-run 0.3.1
"hello world" and stm32f7xx-hal with features = ["stm32f767", "rt"].

add'l info:

'probe-run --chip stm32f767zi target/thumbv7em-none-eabihf/debug/hello' works.
'probe-rs-debugger from command line works'

partial workaround: with enable "reset after flash" but disable "halt after reset", hitting F5 builds, flashes, hits the bp in main reliably, and can hit multiple explicit bps

Initially the target was flashed and debuggee was launched, but never hit the initial bp set in main. This coincided with a notification popup with "Unable to open 'asm.S': Unable to read file '/home/jonas/dev/cortex-m-rt/asm.S' (Error: Unable to resolve nonexistent file '/home/jonas/dev/cortex-m-rt/asm.S')."

Debug output showed the following:

Received DAP Request sequence #7 : stackTrace
ERROR: [2022-01-15T20:16:32Z WARN  probe_rs::probe::stlink] send_jtag_command 242 failed: SwdApFault
ERROR: [2022-01-15T20:16:32Z INFO  probe_rs::debug] Failed to retrieve debug information for program counter 0xfffffffe: Do not have unwind info for the given address.
   Sent DAP Response sequence #7 : stackTrace

Received DAP Request sequence #8 : stackTrace
ERROR: [2022-01-15T20:16:32Z WARN  probe_rs::probe::stlink] send_jtag_command 242 failed: SwdApFault
ERROR: [2022-01-15T20:16:32Z INFO  probe_rs::debug] Failed to retrieve debug information for program counter 0xfffffffe: Do not have unwind info for the given address.
   Sent DAP Response sequence #8 : stackTrace

When I clicked the debug control restart button, then it hit the initial bp in main, but after that was not able to step reliably.

@adamgreig response on matrix: darryln: hmm, a few weird things going on - the error about asm.S indicates it's trying to work out what's happening when the program counter is inside the init code that runs before main, which comes from that file, suggesting your breakpoint has triggered too early/right at reset but later, the PC is at FFFFFFFE, which isn't a valid PC and suggests a fault has been taken, and then the chip fails to respond after that too? specifically FFFFFFFE means the processor faulted while processing a fault and therefore entered lockup.

noppej commented 2 years ago

@darryln ... Are you able to retest this with the new branches from #26?

ghost commented 2 years ago

@noppej still flaky/weird

F5, hit bkpt at top of main on defmt::println
press F10 3 times, execution point does not change
4th press of F10 jumps to ~/.cargo/registry/src/github.com-1ecc6299db9ec823/defmt-0.3.0/src/export/mod.rs:
expectation is step over to the next line in main.rs, but it seems to "step in" to the macro definition

ghost commented 2 years ago

@noppej Debug output copied below.

I noticed the

'WARNING: No source location for breakpoint. Try reducing `opt-level` in `Cargo.toml`

but I have

[profile.dev]
codegen-units = 1
debug = 2
debug-assertions = true
incremental = false
opt-level = 0
overflow-checks = true
lto = "off"

Debug output:

Received DAP Request sequence #1 : initialize
   Sent DAP Response sequence #1 : initialize

Received DAP Request sequence #2 : launch
   Sent DAP Response sequence #2 : launch
[2022-01-19T23:02:06Z WARN  probe_rs_debugger::debugger] Protocol speed 24000 kHz not supported, actual speed is 4600 kHz
[2022-01-19T23:02:06Z INFO  probe_rs::session] Custom reset sequences are not supported on ST-Link V2-1.
[2022-01-19T23:02:06Z INFO  probe_rs::session] Falling back to standard probe reset.
[2022-01-19T23:02:06Z INFO  probe_rs::probe::stlink] Target voltage (VAPP): 3.24 V
INFO: FLASHING: Starting write of "/home/embsysdev/rust/embedded/hello-probe-rs/target/thumbv7em-none-eabihf/debug/hello" to device memory

Triggered DAP Event: progressStart
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::download] Found loadable segment, physical address: 0x08000000, virtual address: 0x08000000, flags: 0x4
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::download] Matching section: ".vector_table"
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::download] Found loadable segment, physical address: 0x080001f8, virtual address: 0x080001f8, flags: 0x5
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::download] Matching section: ".text"
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::download] Found loadable segment, physical address: 0x08003110, virtual address: 0x08003110, flags: 0x4
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::download] Matching section: ".rodata"
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::download] Found loadable segment, physical address: 0x08003c00, virtual address: 0x20020000, flags: 0x6
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::download] Matching section: ".data"
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::loader] Found 4 loadable sections:
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::loader]     .vector_table at 08000000 (504 bytes)
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::loader]     .text at 080001F8 (12052 bytes)
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::loader]     .rodata at 08003110 (2800 bytes)
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::loader]     .data at 08003C00 (48 bytes)
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] chosen RAM to run the algo: RamRegion { name: None, range: 20000000..20080000, is_boot_memory: false, cores: ["main"] }

Triggered DAP Event: progressUpdate

Triggered DAP Event: progressUpdate

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Erasing sector at address 0x08000000
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Done erasing sector. Result is 0. This took 381.911762ms

Triggered DAP Event: progressUpdate

Triggered DAP Event: progressUpdate

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Took 6.538445ms to download 1024 byte page into ram

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Took 7.528881ms to download 1024 byte page into ram

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Took 7.490748ms to download 1024 byte page into ram

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Took 7.371387ms to download 1024 byte page into ram

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Took 7.480481ms to download 1024 byte page into ram

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Took 7.408962ms to download 1024 byte page into ram

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Took 7.55193ms to download 1024 byte page into ram

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Took 7.479852ms to download 1024 byte page into ram

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Took 7.59153ms to download 1024 byte page into ram

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Took 7.485579ms to download 1024 byte page into ram

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Took 7.523853ms to download 1024 byte page into ram

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Took 7.473147ms to download 1024 byte page into ram

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Took 7.409869ms to download 1024 byte page into ram

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Took 7.435502ms to download 1024 byte page into ram

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Took 7.468468ms to download 1024 byte page into ram

Triggered DAP Event: progressUpdate
[2022-01-19T23:02:06Z INFO  probe_rs::flashing::flasher] Took 7.69371ms to download 1024 byte page into ram

Triggered DAP Event: progressUpdate

Triggered DAP Event: progressUpdate

Triggered DAP Event: progressEnd
INFO: FLASHING: Completed write of "/home/embsysdev/rust/embedded/hello-probe-rs/target/thumbv7em-none-eabihf/debug/hello" to device memory

Triggered DAP Event: initialized

Received DAP Request sequence #3 : setBreakpoints
WARNING: No source location for breakpoint. Try reducing `opt-level` in `Cargo.toml`

Triggered DAP Event: probe-rs-show-message
   Sent DAP Response sequence #3 : setBreakpoints

Received DAP Request sequence #4 : configurationDone
   Sent DAP Response sequence #4 : configurationDone

Triggered DAP Event: stopped

Received DAP Request sequence #5 : threads
   Sent DAP Response sequence #5 : threads

Received DAP Request sequence #6 : threads
   Sent DAP Response sequence #6 : threads

Received DAP Request sequence #7 : stackTrace
   Sent DAP Response sequence #7 : stackTrace

Received DAP Request sequence #8 : stackTrace
   Sent DAP Response sequence #8 : stackTrace

Received DAP Request sequence #9 : scopes
   Sent DAP Response sequence #9 : scopes

Received DAP Request sequence #10 : next
   Sent DAP Response sequence #10 : next

Triggered DAP Event: stopped

Received DAP Request sequence #11 : threads
   Sent DAP Response sequence #11 : threads

Received DAP Request sequence #12 : stackTrace
   Sent DAP Response sequence #12 : stackTrace

Received DAP Request sequence #13 : stackTrace
   Sent DAP Response sequence #13 : stackTrace

Received DAP Request sequence #14 : scopes
   Sent DAP Response sequence #14 : scopes

Received DAP Request sequence #15 : next
   Sent DAP Response sequence #15 : next

Triggered DAP Event: stopped

Received DAP Request sequence #16 : threads
   Sent DAP Response sequence #16 : threads

Received DAP Request sequence #17 : stackTrace
   Sent DAP Response sequence #17 : stackTrace

Received DAP Request sequence #18 : stackTrace
   Sent DAP Response sequence #18 : stackTrace

Received DAP Request sequence #19 : scopes
   Sent DAP Response sequence #19 : scopes

Received DAP Request sequence #20 : next
   Sent DAP Response sequence #20 : next

Triggered DAP Event: stopped

Received DAP Request sequence #21 : threads
   Sent DAP Response sequence #21 : threads

Received DAP Request sequence #22 : stackTrace
   Sent DAP Response sequence #22 : stackTrace

Received DAP Request sequence #23 : stackTrace
   Sent DAP Response sequence #23 : stackTrace

Received DAP Request sequence #24 : scopes
   Sent DAP Response sequence #24 : scopes

Received DAP Request sequence #25 : next
   Sent DAP Response sequence #25 : next

Triggered DAP Event: stopped

Received DAP Request sequence #26 : threads
   Sent DAP Response sequence #26 : threads

Received DAP Request sequence #27 : stackTrace
   Sent DAP Response sequence #27 : stackTrace

Received DAP Request sequence #28 : scopes
   Sent DAP Response sequence #28 : scopes

Yatekii commented 2 years ago

So the stepping is a known issue and expected behavior. It steps on the instruction level and not on a rust statement level. It's not trivial to get this right on embedded because you either need to insert a breakpoint instruction in flash (which is terrible in perf and for the life of the flash) or you need to utilize a breakpoint unit which is not nice because you loose a breakpoint. Maybe it would be possible to single step until the next instruction is reached, but I am not sure that works well performance wise. So ultimately I think we have to sacrifice a breakpoint unit @noppej @Tiwalun what do you think about this? :)

noppej commented 2 years ago

@darryln Further to the above, if you look at the Registers while you are stepping, you will see that register 15 (PC for ARM) will step forward by one instruction every time you step. This way you can keep track of forward (albeit painful) progress.

@Yatekii I've been experimenting, and I think the best way to do this is a hybrid, where ...

If a hardware breakpoint is available, use it, and immediately release it.
If there are no more hardware breakpoints available, then do automatic single-steps until you reach the next instruction.

My other thoughts ...

The value of 'next instruction' will depend on 'step in', 'step out', step-over' requirement.
I agree that we should avoid inserting a breakpoint in flash if we can. Let's defer that until we can measure if the 'automatic single-steps' is really that bad. My sense is that if we do auto single-steps right, it should perform ok'ish.

noppej commented 2 years ago

@darryln I've implemented statement level stepping. I'd really appreciate if you'd be willing to give me feedback on https://github.com/probe-rs/probe-rs/pull/1056

noppej commented 2 years ago

I believe this is addressed with https://github.com/probe-rs/probe-rs/pull/1056

probe-rs / vscode

F10 & F11 stepping not reliable #25