embassy-rs / embassy

Modern embedded framework, using Rust and async.
https://embassy.dev
Apache License 2.0
5.43k stars 750 forks source link

embassy-executor LoadProhibited exception when using a large task across two different cores in release profile on ESP32 #2704

Closed manuelbaez closed 7 months ago

manuelbaez commented 7 months ago

Hi, first I'd like to thank anyone who takes the time to read this, sorry about misspellings and any weird things I'm new to Rust and English is my second language :)

I'm trying to make a flight controller with an esp32 using embassy, I started with the esp idf std template but decided to move to no_std out of curiosity and maybe to get more performance and a lighter binary for the app.

I have my application sectioned into three main tasks at the moment:

I can run those three tasks just fine if I use only one core, but that introduces some unwanted spikes in the latency for the flight controller and I want it to be as performant as possible, so that's why I want to use the second core exclusively for that. But I'm facing the following issue when trying to use the second core for any of the tasks and also spawn the flight_controller simultaneously:

Exception occured 'LoadProhibited' Context PC=0x400dc1b8 PS=0x00060930 0x400dc1b8 - embassy_executor::raw::util::SyncUnsafeCell<T>::get at /mnt/disk-2/repos/embassy/embassy-executor/src/raw/util.rs:55 0x00060930 - ?? at ??:??

This only occurs when I try to spawn any of the tasks in the second core, it runs just fine when everything is in just one. At first, I thought it was the way I was sharing the user input data between the tasks, I'm using a struct of atomic values:

pub struct AtomicControllerInput {
    pub roll: AtomicI16,
    pub pitch: AtomicI16,
    pub yaw: AtomicI16,
    pub throttle: AtomicU8,
    pub kill_motors: AtomicBool,
    pub start: AtomicBool,
    pub calibrate_esc: AtomicBool,
    pub calibrate_sensors: AtomicBool,
}

impl AtomicControllerInput {
    pub const fn new() -> Self {
        AtomicControllerInput {
            roll: AtomicI16::new(0),
            pitch: AtomicI16::new(0),
            yaw: AtomicI16::new(0),
            throttle: AtomicU8::new(0),
            kill_motors: AtomicBool::new(false),
            start: AtomicBool::new(false),
            calibrate_esc: AtomicBool::new(false),
            calibrate_sensors: AtomicBool::new(false),
        }
    }
}

pub static SHARED_CONTROLLER_INPUT: AtomicControllerInput = AtomicControllerInput::new();\

So I removed that to test and the executor, where the flight controller is, kept crashing (also I use relaxed ordering, not sure if that's important), so I started to comment code to see at what point it crashes, and I found out it was crashing on an async function that used the I2C but interestingly when I made the function sync it stopped crashing at that point, but when I added some code back it started crashing again.

Then I saw in the docs about the task arena and I enabled the nightly feature, this Increased the amount of my code that I could put back into the function but still crashed at some point on some random arithmetic function, nothing that should cause problems. This is why I think this has something to do with the size of the task( call stack? or Future) since it seems to be trying to access memory out of bounds for the executor.

I decided to clone the embassy repo and tracked down the crash to this function call:

image

This is line 405 of the src/raw/mod.rs in the embassy-executor, but I'm at a loss here since I'm quite new to rust(I picked this project to start learning it) and I don't understand much of what's going on here, but I guess that wherever that poll_fn is getting assigned for that task it's assigning it a pointer that leads to some wrong memory address.

Important to note, This only happens in a release build, somehow debug builds are fine but the code runs 20 to 30x slower so that might be something worth mentioning, no idea why though.

This is the function that crashes in the executor.

Here is the full app code that's crashing.

This is what my main looks like when spawning to the second core:

static CLOCKS: StaticCell<Clocks> = StaticCell::new();
static mut APP_CORE_STACK: Stack<8192> = Stack::new();

#[main]
async fn main(spawner: Spawner) -> ! {
    // init_heap();
    let peripherals = Peripherals::take();
    let system = peripherals.SYSTEM.split();
    let clocks = ClockControl::max(system.clock_control).freeze();
    let clocks = CLOCKS.init(clocks);

    let timer = esp_hal::timer::TimerGroup::new(peripherals.TIMG0, clocks);
    embassy::init(clocks, timer);

    let mut cpu_control = CpuControl::new(system.cpu_control);

    // This line is for Wokwi only so that the console output is formatted correctly
    // print!("\x1b[20h");

    let io = IO::new(peripherals.GPIO, peripherals.IO_MUX);

    spawner.spawn(telemetry_task()).unwrap();

    spawner
        .spawn(controller_input_task(
            io.pins.gpio17,
            io.pins.gpio16,
            peripherals.UART2,
            clocks,
        ))
        .unwrap();

    let cpu1_fn = || {
        static APP_CORE_EXECUTOR: StaticCell<Executor> = StaticCell::new(); // I move this here to test, there's no difference
        let executor = APP_CORE_EXECUTOR.init(Executor::new());
        executor.run(|spawner| {
            spawner
                .spawn(flight_controller_task(
                    peripherals.I2C0,
                    io.pins.gpio21,
                    io.pins.gpio22,
                    peripherals.LEDC,
                    io.pins.gpio13.into_push_pull_output(),
                    io.pins.gpio12.into_push_pull_output(),
                    io.pins.gpio14.into_push_pull_output(),
                    io.pins.gpio27.into_push_pull_output(),
                    clocks,
                ))
                .unwrap();
        });
    };
    let _guard = cpu_control
        .start_app_core(unsafe { &mut APP_CORE_STACK }, cpu1_fn)
        .unwrap();

    let mut count = 0;
    loop {
        esp_println::println!("Main Task Count: {} ", count);
        count += 1;
        Timer::after_millis(u32::MAX as u64).await;
    }
}

This is the full console output when the app crashes:

[2024-03-16T18:43:24Z INFO ] Flashing has completed!
Commands:
    CTRL+R  Reset chip
    CTRL+C  Exit

������������������������

rst:0x1 (POWERON_RESET),boot:0x13 (SPI_FAST_FLASH_BOOT)
configsip: 0, SPIWP:0xee
clk_drv:0x00,q_drv:0x00,d_drv:0x00,cs0_drv:0x00,hd_drv:0x00,wp_drv:0x00
mode:DIO, clock div:2
load:0x3fff0030,len:7104
0x3fff0030 - _ZN12embassy_time13queue_generic5QUEUE17ha6ddcddb6f3e2583E
    at ??:??
load:0x40078000,len:15576
0x40078000 - _ZN12embassy_time13queue_generic5QUEUE17ha6ddcddb6f3e2583E
    at ??:??
load:0x40080400,len:4
0x40080400 - _DoubleExceptionVector
    at ??:??
ho 8 tail 4 room 4
load:0x40080404,len:3876
0x40080404 - _DoubleExceptionVector
    at ??:??
entry 0x4008064c
0x4008064c - esp_storage::chip_specific::esp_rom_spiflash_read::{{closure}}
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp-storage-0.3.0/src/esp32.rs:127
I (30) boot: ESP-IDF v5.1-beta1-378-gea5e0ff298-dirt 2nd stage bootloader
I (30) boot: compile time Jun  7 2023 07:48:23
I (33) boot: Multicore bootloader
I (37) boot: chip revision: v1.0
I (41) boot.esp32: SPI Speed    : 40MHz
I (45) boot.esp32: SPI Mode     : DIO
I (50) boot.esp32: SPI Flash Size : 4MB
I (54) boot: Enabling RNG early entropy source...
I (60) boot: Partition Table:
I (63) boot: ## Label           Usage       Type ST Offset   Length
I (71) boot:  0 nvs             WiFi data       01 02 00009000 00006000
I (78) boot:  1 phy_init        RF data         01 01 0000f000 00001000
I (86) boot:  2 factory         factory app     00 00 00010000 003f0000
I (93) boot: End of partition table
I (97) esp_image: segment 0: paddr=00010020 vaddr=3f400020 size=02dach ( 11692) map
I (110) esp_image: segment 1: paddr=00012dd4 vaddr=3ffb0000 size=00018h (   24) load
I (114) esp_image: segment 2: paddr=00012df4 vaddr=40080000 size=02010h (  8208) load
I (126) esp_image: segment 3: paddr=00014e0c vaddr=00000000 size=0b20ch ( 45580)
I (147) esp_image: segment 4: paddr=00020020 vaddr=400d0020 size=0c9cch ( 51660) map
I (167) boot: Loaded app from partition at offset 0x10000
I (167) boot: Disabling RNG early entropy source...
Main Task Count: 0
Flash Capacity 4194304

Exception occured 'LoadProhibited'
Context
PC=0x400dc96c       PS=0x00060930
0x400dc96c - embassy_executor::raw::util::SyncUnsafeCell<T>::get
    at /mnt/disk-2/repos/embassy/embassy-executor/src/raw/util.rs:55
0x00060930 - ??
    at ??:??
A0=0x800d3861       A1=0x3ffb2300       A2=0x3ffb2370       A3=0x3ffb0020       A4=0x3ffb2378
0x800d3861 - _ZN4core3ops8function6FnOnce9call_once17h16a8461cf8bbe284E.llvm.10835848324489580207
    at ??:??
0x3ffb2300 - _ZN23flight_controller_nostd14APP_CORE_STACK17he79d40bb23e68291E
    at ??:??
0x3ffb2370 - _ZN23flight_controller_nostd21____embassy_main_task28_$u7b$$u7b$closure$u7d$$u7d$28_$u7b$$u7b$closure$u7d$$u7d$17APP_CORE_EXECUTOR17heea9e4306717ebe5E
    at ??:??
0x3ffb0020 - _ZN23flight_controller_nostd7threads22flight_controller_task4POOL17hbaacbe7ba84f0f83E.llvm.461495821013083691
    at ??:??
0x3ffb2378 - _ZN23flight_controller_nostd21____embassy_main_task28_$u7b$$u7b$closure$u7d$$u7d$28_$u7b$$u7b$closure$u7d$$u7d$17APP_CORE_EXECUTOR17heea9e4306717ebe5E
    at ??:??
A5=0x00000001       A6=0xfffffffd       A7=0x00000001       A8=0x800dc993       A9=0x3ffb21f0
0x00000001 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0xfffffffd - _ZN4core3ops8function6FnOnce9call_once17h16a8461cf8bbe284E.llvm.10835848324489580207
    at ??:??
0x00000001 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x800dc993 - _ZN4core3ops8function6FnOnce9call_once17h16a8461cf8bbe284E.llvm.10835848324489580207
    at ??:??
0x3ffb21f0 - _ZN23flight_controller_nostd14APP_CORE_STACK17he79d40bb23e68291E
    at ??:??
A10=0x00000001      A11=0x3ffb0020      A12=0x3ffb0044      A13=0x3ffb003c      A14=0x3ffb00fc
0x00000001 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x3ffb0020 - _ZN23flight_controller_nostd7threads22flight_controller_task4POOL17hbaacbe7ba84f0f83E.llvm.461495821013083691
    at ??:??
0x3ffb0044 - _ZN23flight_controller_nostd7threads22flight_controller_task4POOL17hbaacbe7ba84f0f83E.llvm.461495821013083691
    at ??:??
0x3ffb003c - _ZN23flight_controller_nostd7threads22flight_controller_task4POOL17hbaacbe7ba84f0f83E.llvm.461495821013083691
    at ??:??
0x3ffb00fc - _ZN23flight_controller_nostd7threads22flight_controller_task4POOL17hbaacbe7ba84f0f83E.llvm.461495821013083691
    at ??:??
A15=0x00000000
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
SAR=00000011
EXCCAUSE=0x0000001c EXCVADDR=0x00000005
0x0000001c - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1532
0x00000005 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
LBEG=0x4000c2e0     LEND=0x4000c2f6     LCOUNT=0x00000000
0x4000c2e0 - _ZN12embassy_time13queue_generic5QUEUE17ha6ddcddb6f3e2583E
    at ??:??
0x4000c2f6 - _ZN12embassy_time13queue_generic5QUEUE17ha6ddcddb6f3e2583E
    at ??:??
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
THREADPTR=0x00000000
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
SCOMPARE1=0x00000100
0x00000100 - esp_hal::sha::Sha::finish
    at ??:??
BR=0x00000000
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
ACCLO=0x00000000    ACCHI=0x00000000
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
M0=0x00000000       M1=0x00000000       M2=0x00000000       M3=0x00000000
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
F64R_LO=0x00000000  F64R_HI=0x00000000  F64S=0x00000000
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
FCR=0x00000000      FSR=0x00000000
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
F0=0x00000000       F1=0x00000000       F2=0x00000000       F3=0x00000000       F4=0x00000000
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
F5=0x00000000       F6=0x00000000       F7=0x00000000       F8=0x00000000       F9=0x00000000
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
F10=0x00000000      F11=0x00000000      F12=0x00000000      F13=0x00000000      F14=0x00000000
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531
F15=0x00000000
0x00000000 - <esp32::RMT as core::fmt::Debug>::fmt
    at ~/.cargo/registry/src/index.crates.io-6f17d22bba15001f/esp32-0.29.0/src/lib.rs:1531

0x400d4a47
0x400d4a47 - _ZN7esp_hal3soc14implementation11cpu_control10CpuControl16start_core1_init17h8a56d85e6dac564bE.llvm.534746425162065537
    at ??:??
0x40000000
0x40000000 - _ZN12embassy_time13queue_generic5QUEUE17ha6ddcddb6f3e2583E
    at ??:??
0x40000740
0x40000740 - _ZN12embassy_time13queue_generic5QUEUE17ha6ddcddb6f3e2583E
    at ??:??
0x40000000
0x40000000 - _ZN12embassy_time13queue_generic5QUEUE17ha6ddcddb6f3e2583E
    at ??:??

Again thanks in advance for your time and any comments!

MabezDev commented 7 months ago

I can't see what esp-hal version your using, but ensure it includes https://github.com/esp-rs/esp-hal/pull/1286 if you're using the second core at all. For the original ESP32, you will also want to have https://github.com/esp-rs/esp-hal/pull/1289 included.

manuelbaez commented 7 months ago

Hey, thanks for your answer! I pulled again from main and it seems to have fixed the issue, also it fixed the I2c frequency that was way off before. The I2c still crashes with AckCheckFailed when used in the second core and the SCL line locks forever, though for my use case, I can just run that task in core 0 as it works fine. I think I'll open an issue in the esp-hal about this later.

This is what I meant about the SCL line: image