F10 & F11 stepping not reliable
Opened this issue · 7 comments
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 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
@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
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? :)
@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.
@DarrylN I've implemented statement level stepping. I'd really appreciate if you'd be willing to give me feedback on probe-rs/probe-rs#1056
I believe this is addressed with probe-rs/probe-rs#1056