ESP32-S3: Async SPI DMA transfers stall at some point

[sourcebox]

This issue is opened by request of @bugadani at the Matrix chat.

While initially working, the call to write_async().await (and probably also other related functions) stalls at some point. It's not reproducable when this exactly happens.

HAL revision: 49e14b7ccb10dfe5b4b6ed561759372303beddb1.

I use DMA channel 1 for the SPI transfers. Channel 0 is also used for I2S transfers.

Relevant code:

pub async fn spi_write_read(
    &mut self,
    write_buffer: &[u8],
    read_buffer: &mut [u8],
) -> Result<(), Error> {
    self.cs_pin.set_low();
    let result1 = self.spi.write_async(write_buffer).await;
    let result2 = self.spi.read_async(read_buffer).await;
    self.cs_pin.set_high();

    if result1.is_err() || result2.is_err() {
        return Err(Error::SpiTransferFailed);
    }

    Ok(())
}

[bugadani]

I just want to add that #2065 was aiming at addressing this, but apparently the issue is somewhere else.

[IvanLi-CN]

Following. I think I'm having a similar issue with ESP32-C3 after updating to v0.20.1.

[bugadani]

Unfortunately my reproducers look like they started behaving so I'm back to square one here.

[Dominaezzz]

@sourcebox what other operations do you perform on the SPI? Or is that the only function that uses SPI in your project?

[sourcebox]

SPI is only used for an external flash chip. When the firmware boots, a bunch of configuration data is read from the flash using sequential-storage. It's about 16 items that are read in a loop. Sometimes, it works perfectly, sometimes only a few items are read, then it stalls. As long as the read operations succeed, the returned data seem to be correct.

No write operations are done. By putting some log statements at various points, I was able to track down that in the shown function, the write_async is called, but nothing after it.

What's also strange is the fact, that replacing the write_async/read_async sequence with transfer_asyc always leads to return garbage data. So something seems to go really wrong in the whole process.

The full code of the flash driver is this:

//! Asynchronous driver for the SPI flash chip.

use embedded_storage_async::nor_flash::{
    ErrorType, NorFlash, NorFlashError, NorFlashErrorKind, ReadNorFlash,
};

use crate::hal::{
    dma::DmaChannel1,
    gpio::*,
    peripherals::SPI2,
    spi::{master::SpiDmaBus, FullDuplexMode},
    Async,
};

/// Size of a page in bytes.
pub const PAGE_SIZE: u32 = 256;

/// Size of a sector in bytes.
pub const SECTOR_SIZE: u32 = 4096;

/// Number of pages.
pub const NUM_PAGES: u32 = 2048;

/// Number of sectors.
pub const NUM_SECTORS: u32 = NUM_PAGES / 16;

/// Total capacity in bytes.
pub const CAPACITY: u32 = PAGE_SIZE * NUM_PAGES;

/// Type alias for the SPI peripheral driver.
type SpiDriver = SpiDmaBus<'static, SPI2, DmaChannel1, FullDuplexMode, Async>;

/// Type alias for CS pin.
type CsPin = Output<'static, Gpio33>;

/// SPI flash chip.
pub struct Flash {
    /// SPI driver.
    spi: SpiDriver,

    /// Chip-select pin.
    cs_pin: CsPin,
}

impl Flash {
    /// Returns a new instance.
    pub fn new(spi: SpiDriver, mut cs_pin: CsPin) -> Self {
        cs_pin.set_high();
        Self { spi, cs_pin }
    }

    async fn read_status_async(&mut self) -> Result<u8, Error> {
        let mut buffer: [u8; 2] = [0; 2];
        buffer[0] = commands::READ_STATUS_REGISTER_1;

        self.cs_pin.set_low();
        let result = self.spi.transfer_in_place_async(&mut buffer).await;
        self.cs_pin.set_high();

        if result.is_err() {
            return Err(Error::SpiTransferFailed);
        }

        Ok(buffer[1])
    }

    /// Check the status register busy flag.
    async fn is_busy_async(&mut self) -> Result<bool, Error> {
        Ok((self.read_status_async().await? & 0x01) != 0)
    }

    /// Reads a chunk of bytes.
    pub async fn read_async(&mut self, address: u32, buffer: &mut [u8]) -> Result<(), Error> {
        if address + buffer.len() as u32 > CAPACITY {
            return Err(Error::OutOfBounds);
        }

        let address_bytes = address.to_be_bytes();

        let write_buffer = [
            commands::READ_DATA,
            address_bytes[1],
            address_bytes[2],
            address_bytes[3],
        ];
        self.spi_write_read(&write_buffer, buffer).await?;

        Ok(())
    }

    /// Erases a single sector.
    pub async fn erase_sector_async(&mut self, index: u32) -> Result<(), Error> {
        if index >= NUM_SECTORS {
            return Err(Error::OutOfBounds);
        }

        self.enable_write_async().await?;

        let address: u32 = index * SECTOR_SIZE;
        let address_bytes = address.to_be_bytes();
        let write_buffer = [
            commands::SECTOR_ERASE,
            address_bytes[1],
            address_bytes[2],
            address_bytes[3],
        ];

        self.cs_pin.set_low();
        let result = self.spi.write_async(&write_buffer).await;
        self.cs_pin.set_high();

        if result.is_err() {
            return Err(Error::SpiTransferFailed);
        }

        while self.is_busy_async().await? {}

        for offset in (0..SECTOR_SIZE).step_by(64) {
            self.readback_check_async(address + offset, &[0xFF; 64])
                .await?;
        }

        Ok(())
    }

    /// Erases a range of sectors.
    pub async fn erase_range_async(
        &mut self,
        start_address: u32,
        end_address: u32,
    ) -> Result<(), Error> {
        if start_address % (SECTOR_SIZE) != 0 {
            return Err(Error::NotAligned);
        }

        if end_address % (SECTOR_SIZE) != 0 {
            return Err(Error::NotAligned);
        }

        if start_address > end_address {
            return Err(Error::OutOfBounds);
        }

        let start_sector = start_address / SECTOR_SIZE;
        let end_sector = end_address / SECTOR_SIZE;

        for sector in start_sector..end_sector {
            self.erase_sector_async(sector).await.unwrap();
        }

        Ok(())
    }

    /// Writes a chunk of bytes.
    pub async fn write_async(&mut self, mut address: u32, mut buffer: &[u8]) -> Result<(), Error> {
        if address + buffer.len() as u32 > CAPACITY {
            return Err(Error::OutOfBounds);
        }

        // Write first chunk, taking into account that given addres might
        // point to a location that is not on a page boundary,
        let chunk_len = (PAGE_SIZE - (address & 0x000000FF)) as usize;
        let chunk_len = chunk_len.min(buffer.len());
        self.write_page_async(address, &buffer[..chunk_len]).await?;

        // Write rest of the chunks.
        let mut chunk_len = chunk_len;
        loop {
            buffer = &buffer[chunk_len..];
            address += chunk_len as u32;
            chunk_len = buffer.len().min(PAGE_SIZE as usize);
            if chunk_len == 0 {
                break;
            }
            self.write_page_async(address, &buffer[..chunk_len]).await?;
        }

        Ok(())
    }

    /// Writes a single page of data.
    pub async fn write_page_async(&mut self, address: u32, buffer: &[u8]) -> Result<(), Error> {
        if (address & 0x000000FF) + buffer.len() as u32 > PAGE_SIZE {
            return Err(Error::OutOfBounds);
        }

        self.enable_write_async().await?;

        let address_bytes = address.to_be_bytes();
        let write_buffer = [
            commands::PAGE_PROGRAM,
            address_bytes[1],
            address_bytes[2],
            address_bytes[3],
        ];
        self.cs_pin.set_low();
        let result1 = self.spi.write_async(&write_buffer).await;
        let result2 = self.spi.write_async(buffer).await;
        self.cs_pin.set_high();

        if result1.is_err() || result2.is_err() {
            return Err(Error::SpiTransferFailed);
        }

        while self.is_busy_async().await? {}

        self.readback_check_async(address, buffer).await?;

        Ok(())
    }

    /// Returns the manufacturer and device id.
    pub async fn manufacturer_device_id_async(&mut self) -> Result<(u8, u8), Error> {
        let write_buffer = [commands::MANUFACTURER_DEVICE_ID, 0, 0, 0];
        let mut read_buffer = [0; 2];
        self.spi_write_read(&write_buffer, &mut read_buffer).await?;

        Ok((read_buffer[0], read_buffer[1]))
    }

    /// Returns the JEDEC id.
    pub async fn jedec_id_async(&mut self) -> Result<(u8, u8, u8), Error> {
        let write_buffer = [commands::JEDEC_ID];
        let mut read_buffer = [0; 3];
        self.spi_write_read(&write_buffer, &mut read_buffer).await?;

        Ok((read_buffer[0], read_buffer[1], read_buffer[2]))
    }

    /// Returns the unique id.
    pub async fn unique_id_async(&mut self) -> Result<[u8; 8], Error> {
        let write_buffer = [commands::UNIQUE_ID, 0, 0, 0, 0];
        let mut read_buffer = [0; 8];
        self.spi_write_read(&write_buffer, &mut read_buffer).await?;

        Ok(read_buffer)
    }

    /// Sets the write enable flag.
    pub async fn enable_write_async(&mut self) -> Result<(), Error> {
        let write_buffer = [commands::WRITE_ENABLE];
        self.cs_pin.set_low();
        let result = self.spi.write_async(&write_buffer).await;
        self.cs_pin.set_high();

        if result.is_err() {
            return Err(Error::SpiTransferFailed);
        }

        if !self.is_write_enabled_async().await? {
            return Err(Error::WriteNotEnabled);
        }

        Ok(())
    }

    /// Reads the write enable flag.
    pub async fn is_write_enabled_async(&mut self) -> Result<bool, Error> {
        Ok((self.read_status_async().await? & 0x02) != 0)
    }

    /// Checks if data readback matches.
    async fn readback_check_async(&mut self, mut address: u32, data: &[u8]) -> Result<(), Error> {
        const CHUNK_SIZE: usize = 64;

        let mut buf = [0; CHUNK_SIZE];

        for chunk in data.chunks(CHUNK_SIZE) {
            let buf = &mut buf[..chunk.len()];
            self.read_async(address, buf).await?;
            address += CHUNK_SIZE as u32;

            if buf != chunk {
                return Err(Error::ReadbackFailed);
            }
        }

        Ok(())
    }

    /// Issues an SPI write transfer followed by a read.
    pub async fn spi_write_read(
        &mut self,
        write_buffer: &[u8],
        read_buffer: &mut [u8],
    ) -> Result<(), Error> {
        self.cs_pin.set_low();
        let result1 = self.spi.write_async(write_buffer).await;
        let result2 = self.spi.read_async(read_buffer).await;
        self.cs_pin.set_high();

        if result1.is_err() || result2.is_err() {
            return Err(Error::SpiTransferFailed);
        }

        Ok(())
    }
}

impl ReadNorFlash for Flash {
    const READ_SIZE: usize = 1;

    async fn read(&mut self, offset: u32, bytes: &mut [u8]) -> Result<(), Self::Error> {
        self.read_async(offset, bytes).await
    }

    fn capacity(&self) -> usize {
        CAPACITY as usize
    }
}

impl NorFlash for Flash {
    const WRITE_SIZE: usize = 1;
    const ERASE_SIZE: usize = 4096;

    async fn erase(&mut self, from: u32, to: u32) -> Result<(), Self::Error> {
        self.erase_range_async(from, to).await
    }
    async fn write(&mut self, offset: u32, bytes: &[u8]) -> Result<(), Self::Error> {
        self.write_async(offset, bytes).await
    }
}

impl ErrorType for Flash {
    type Error = Error;
}

/// Errors.
#[derive(Debug)]
pub enum Error {
    /// SPI transfer error.
    SpiTransferFailed,

    /// Access not aligned.
    NotAligned,

    /// Access out of bounds.
    OutOfBounds,

    /// Write enable is not set.
    WriteNotEnabled,

    /// Readback of data failed.
    ReadbackFailed,
}

impl NorFlashError for Error {
    fn kind(&self) -> NorFlashErrorKind {
        match self {
            Error::NotAligned => NorFlashErrorKind::NotAligned,
            Error::OutOfBounds => NorFlashErrorKind::OutOfBounds,
            _ => NorFlashErrorKind::Other,
        }
    }
}

/// Flash commands.
mod commands {
    /// Read status register 1.
    pub const READ_STATUS_REGISTER_1: u8 = 0x05;

    /// Read data.
    pub const READ_DATA: u8 = 0x03;

    /// Enable writes.
    pub const WRITE_ENABLE: u8 = 0x06;

    /// Erase a sector.
    pub const SECTOR_ERASE: u8 = 0x20;

    /// Program a page.
    pub const PAGE_PROGRAM: u8 = 0x02;

    /// Read manufacturer and device ID.
    pub const MANUFACTURER_DEVICE_ID: u8 = 0x90;

    /// Read JEDEC ID.
    pub const JEDEC_ID: u8 = 0x9F;

    /// Read unique ID.
    pub const UNIQUE_ID: u8 = 0x4B;
}

[bugadani]

@sourcebox can I ask you to please retest whether you still experience this issue?

[sourcebox]

@sourcebox can I ask you to please retest whether you still experience this issue?

It looks ok now, the transfer does not stall anymore.

[MabezDev]

It looks ok now, the transfer does not stall anymore.

That's great to hear! I'll close this now :).