The erase-all flag erases entire chip unnecessarily on nrf5340 which affects performance

[ninjasource]

Describe the bug
Hi, I am using the latest version of probe-run (built from git) to flash my nrf5340-dk. When using probe-run --chip nRF5340_xxAA --erase-all for a cargo runner the process erases the entire flash area every time which takes about 35 seconds. It does this regardless or weather or not it needs to. I believe that the nrf5340 requires an erasure of certain flash areas after power on or hard reset to unlock the device before a debugger like probe-run can work with it. If you don't do this you get the following error message from probe-run: An operation could not be performed because it lacked the permission to do so: erase_all

The probe-rs-cli tool has a flag called allow-erase-all which will only erase appropriate flash areas if required. That means that erasing the entire chip is not required once it has already been powered up and unlocked (power cycle or hard reset ends this). Additionally, I noticed that probe-rs-cli only requires an additional 10ms to flash the device upon power up so I don't believe that it erases the entire chip, or if it does, it is many times faster than probe-run at doing it.

Looking at the code, I see that when the --erase-all flag is passed to probe-run the -allow-erase-all permission is set when interacting with probe-rs. Redundantly, I believe, the probe-run tool is also performing a full erasure of the chip before flashing.

To Reproduce
Steps to reproduce the behavior:
TLDR: Use the following runner in cargo config: probe-run --chip nRF5340_xxAA --erase-all

1. Write .cargo/config.toml

[target.'cfg(all(target_arch = "arm", target_os = "none"))']
runner = "probe-run --chip nRF5340_xxAA --erase-all" 
#runner = "probe-run --chip nRF5340_xxAA"
#runner = "probe-rs-cli run --chip nRF5340_xxAA --allow-erase-all"

rustflags = [
  "-C", "link-arg=-Tlink.x",
  "-C", "link-arg=-Tdefmt.x",
]

[build]
target = "thumbv8m.main-none-eabihf" # = ARM Cortex-M33

[env]
DEFMT_LOG = "info"

2. Write src/main.rs

#![no_std]
#![no_main]

use cortex_m_rt::entry;
use defmt::info;
use {defmt_rtt as _, panic_probe as _};

#[entry]
fn main() -> ! {
    info!("Started");
    loop {
        cortex_m::asm::nop();
    }
}

3. Write memory.x

MEMORY
{
  FLASH : ORIGIN = 0x00000000, LENGTH = 1024K
  RAM : ORIGIN = 0x20000000, LENGTH = 256K
}

4. Write Cargo.toml

[package]
name = "nrf5340-test"
version = "0.1.0"
edition = "2021"

[dependencies]
cortex-m = { version = "0.7.6", features = ["critical-section-single-core"] }
cortex-m-rt = "0.6.10"
defmt-rtt = "0.4"
panic-probe = { version = "0.3", features = ["print-defmt"] }
defmt = "0.3"

[profile.release]
debug = true

4. Plug in an nrf5340-dk or equivalent and run the program with cargo run --release

5. (Optional) Install probe-rs-cliand uncomment the other runners configured in config.toml to se how they run

Example output when run with the --verbose flag

david@mint-pc:~/source/nrf5340-test$ cargo run --release
    Finished release [optimized + debuginfo] target(s) in 0.02s
     Running `probe-run --chip nRF5340_xxAA --erase-all --verbose target/thumbv8m.main-none-eabihf/release/nrf5340-test`
(HOST) DEBUG found 1 probes
└─ probe_run::probe @ src/probe.rs:25
(HOST) DEBUG opened probe
└─ probe_run::probe @ src/probe.rs:33
(HOST) DEBUG started session
└─ probe_run @ src/main.rs:154
(HOST) INFO  flashing program (2 pages / 8.00 KiB)
└─ probe_run @ src/main.rs:188
(HOST) DEBUG Erased sector of size 4096 bytes in 134 ms
└─ probe_run @ src/main.rs:191
(HOST) DEBUG Erased sector of size 4096 bytes in 106 ms
└─ probe_run @ src/main.rs:191
(HOST) DEBUG Programmed page of size 4096 bytes in 113 ms
└─ probe_run @ src/main.rs:196
(HOST) DEBUG Programmed page of size 4096 bytes in 115 ms
└─ probe_run @ src/main.rs:196
(HOST) INFO  success!
└─ probe_run @ src/main.rs:175
(HOST) DEBUG vector table: VectorTable { initial_stack_pointer: 20040000, hard_fault: 1b29 }
└─ probe_run::elf @ src/elf.rs:41
(HOST) DEBUG RAM region: 0x20000000-0x2003FFFF
└─ probe_run::target_info @ src/target_info.rs:121
(HOST) DEBUG section `.data` is in RAM at 0x20000000..=0x20000037
└─ probe_run::target_info @ src/target_info.rs:159
(HOST) DEBUG section `.bss` is in RAM at 0x20000038..=0x2000003F
└─ probe_run::target_info @ src/target_info.rs:159
(HOST) DEBUG section `.uninit` is in RAM at 0x20000040..=0x2000043F
└─ probe_run::target_info @ src/target_info.rs:159
(HOST) DEBUG valid SP range: 0x20000440..=0x2003FFFC
└─ probe_run::target_info @ src/target_info.rs:172
(HOST) DEBUG 261052 bytes of stack available (0x20000440 ..= 0x2003FFFC), using 26108 byte canary
└─ probe_run::canary @ src/canary.rs:83
(HOST) TRACE setting up canary took 0.025s (1036.37 KiB/s)
└─ probe_run::canary @ src/canary.rs:97
(HOST) DEBUG starting device
└─ probe_run @ src/main.rs:217
(HOST) DEBUG Successfully attached RTT
└─ probe_run @ src/main.rs:372
────────────────────────────────────────────────────────────────────────────────
INFO  Started
└─ nrf5340_test::__cortex_m_rt_main @ src/main.rs:10

The main issue if there is a 35 second delay between this line:

(HOST) DEBUG started session
└─ probe_run @ src/main.rs:154

and this line

(HOST) INFO  flashing program (2 pages / 8.00 KiB)
└─ probe_run @ src/main.rs:188

When powering up the device for the first time and using the probe-rs-cli tool I get the following output:

david@mint-pc:~/source/nrf5340-test$ cargo run --release
    Finished release [optimized + debuginfo] target(s) in 0.02s
     Running `probe-rs-cli run --chip nRF5340_xxAA --allow-erase-all target/thumbv8m.main-none-eabihf/release/nrf5340-test`
     Erasing sectors ✔ [00:00:00] [########################################################] 8.00 KiB/8.00 KiB @ 20.37 KiB/s (eta 0s )
 Programming pages   ✔ [00:00:00] [########################################################] 8.00 KiB/8.00 KiB @ 15.73 KiB/s (eta 0s )    
Finished in 0.993s
INFO Started
└─ src/main.rs:10

As can be seen, it runs in under a second.

Suggested fix
I would like to suggest that we remove the following code in the flash function of main.rs:164 since probe-rs already handles this:

if opts.erase_all {
    flashing::erase_all(sess, fp.clone())?;
}

I would also like to suggest that the flag be renamed to allow-erase-all which I think is more appropriate. Please let me know and I can create a PR but this is such a tiny fix that one of the maintainers might want to just throw it in quickly.

David

[ninjasource]

I have tested the suggested fix above on an nrf5340-dk but, unfortunately, I do not have an nrf52840-dk rev 3 to test with.
This is related to: #368

[Urhengulas]

Hi @ninjasource, thank you for your report.

Two observations:

1. For me running a simple hello world program on the nrf52840-dk takes 1.179s without --erase-all and 1.494s with --erase-all. So I can't observe the big difference you are experiencing.

2. Secondly, I don't think that the probe-rs-cli command you are using is actually triggering an erase_all. There is the --allow-erase-all (which you are setting) and the --chip-erase (which you are not setting).

   Can you please try running probe-rs-cli with --chip-erase and report what happens?

   As far as I understand the "erasing sectors" in the probe-rs-cli output does not refer to the erase_all. If you run probe-run without --erase-all but with -vv (double verbose) you can atill observe (HOST) DEBUG Erased sector of size 4096 bytes in 180 ms two times which adds up to the 8.00 KiB reported by probe-rs-cli.

[ninjasource]

My sincere apologies for the late reply, I have been away.

@Urhengulas, I ran the chip erase function. Oddly enough the nrf5340 still needs that --allow-erase-all flag to unlock the chip on power up even though it is erasing the chip anyway.

This completes successfully on the nrf52840 in about half a second so this confirms your observation (in point 1):

probe-rs-cli erase --chip nRF52840_xxAA --allow-erase-all

To answer point 2, this completes on the nrf5340 after 34 seconds although on most runs it simply times out:

probe-rs-cli erase --chip nRF5340_xxAA --allow-erase-all

So I guess the issue is with the probe-rs chip erase command because nordic's programmer app takes about 5 seconds to do a full chip erase (and then some). I have come to realize that the --erase-all and --allow-erase-all commands are completely different things, the latter command being responsible for unlocking the chip.

[ninjasource]

I also ran probe-run with the -vv flag and the nrf52840 generated a 7MB log whereas the nrf5340 generates a 38MB file. Too big to pollute this thread with though and github does not allow zip files to be attached to issues. I couldn't spot anything obvious other than the fact that the nrf5340 was doing a hell of a lot of register reading and writing for something that is supposed to be erasing a chip. Let me know if you'd like me to attach the log file to this thread.

[jonathanpallant]

Can you verify which version of the nRF52 you have? Apparently some later revisions changed how flash erasing works.

[Urhengulas]

I also ran probe-run with the -vv flag and the nrf52840 generated a 7MB log whereas the nrf5340 generates a 38MB file. Too big to pollute this thread with though and github does not allow zip files to be attached to issues.

I think you can attach files by either drag-and-drop or by clicking on the bottom edge of the text input field. And I just tried and was able to upload a zip file.

[Urhengulas]

So I guess the issue is with the probe-rs chip erase command because nordic's programmer app takes about 5 seconds to do a full chip erase (and then some). I have come to realize that the --erase-all and --allow-erase-all commands are completely different things, the latter command being responsible for unlocking the chip.

Can you please report the issue to probe-rs and reference this issue there?