Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

F10 & F11 stepping not reliable #25

Closed
ghost opened this issue Jan 16, 2022 · 7 comments
Closed

F10 & F11 stepping not reliable #25

ghost opened this issue Jan 16, 2022 · 7 comments

Comments

@ghost
Copy link

ghost commented Jan 16, 2022

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
Copy link
Contributor

noppej commented Jan 19, 2022

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

@ghost
Copy link
Author

ghost commented Jan 19, 2022 •
edited by ghost
Loading

@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

image

@ghost
Copy link
Author

ghost commented Jan 19, 2022 •
edited by ghost
Loading

@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
Copy link
Member

Yatekii commented Jan 20, 2022

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
Copy link
Contributor

noppej commented Jan 20, 2022

@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 ...

  1. If a hardware breakpoint is available, use it, and immediately release it.
  2. 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
Copy link
Contributor

noppej commented Mar 28, 2022

@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

@noppej
Copy link
Contributor

noppej commented Apr 6, 2022

I believe this is addressed with probe-rs/probe-rs#1056

@noppej noppej closed this as completed Apr 6, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@Yatekii @noppej