Bizarre problem with SPI DMA on K22F

[scottm]

I've just run into a problem on the MK22FN1M0AVLH12 that has me scratching my head, in large part because the code has been working fine until now and I'm not sure what might have changed.

The project runs FreeRTOS 10, and at one point in the startup process it has to search a table in external SPI flash for a particular record.  It does a bunch of reads using DMA and ordinarily it runs fast.  Today I noticed a lag of seconds in startup and found that during this series of reads the flash CS line was staying low for a bit over 2 ms after each transfer.  The RTOS tick time is about 4.1 ms (240 Hz) so it's not waiting a whole tick.

The SPI read function sets up the DMA transfer and then uses xSemaphoreTake() to block the calling task until the DMA completion ISR gives the semaphore.  I figured the first thing to check would be whether the interrupt was getting delayed, or if it was a problem on the RTOS side.  I've got macros called DBG_HI and DBG_LO that control a spare GPIO, in this case PTC7, and I put a DBG_HI at the start of the DMA transfer and a DBG_LO as the first line in the ISR, planning to watch the output on the logic analyzer and see if it matched up with the SPI CS line.

As soon as I put in the DBG_ lines, it started working normally.  That's only slightly weird, so I took out the DBGs and the problem came back, and I put just a DBG_LO as the first line in main(), before even configuring any clock gating or DDRs, and it ran with no delay.

To see if it was something specific to PTC7, I changed pins.  The macro evaluates to (GPIOC_PCOR = (1 << 7)), and I tried it with PTC6 and PTC2 and it ran with no delay.  With PTC9 there was a delay.  I tried it on PTA, and found that bits 0 to 7 would 'fix' the delay, but 8 and up wouldn't.  The code generated for GPIOx_PCOR = (1 << n) is different for n = 0 to 7, so it appears to be not related to the GPIO peripheral but to some code alignment, timing, or other side effect.

I took all of that out and tried moving the SPI CS low command to the ISR, but again it ran normally.  I replaced that command with a NOP and it worked - at this point the only difference between the non-working (slow) code and the working code was one NOP in the ISR.

It was around this time that I changed something unrelated in the external SPI flash memory's file system, and now after changing it back I can't reproduce the problem.  I've tried adding random numbers of NOPs to change the startup timing and code position, to no effect.  When it was still showing the problem I also tried various numbers of NOPs in main() and didn't ever find one that fixed the delay.

I can't think of any significance to the 2 ms time interval, and it was fairly consistent.  I just checked that my tick rate is indeed what I thought it was.  It's still possible the task was blocking until the next tick because I'm not sure what the duration of the rest of its activities was, because my logic analyzer software crashed before I could save the last trace that showed the problem.  Hasn't crashed in weeks, but of course it would choose to now.

I'm baffled.  There's some behavior in the hardware here that I don't understand, and I"m afraid it's going to come back to bite me.  Any ideas?  I'm including the relevant code below.

Thanks,

Scott

/**
 * Reads a block of data from SPI using DMA, and blocks until the transfer completes.
 * This isn't quite as fast as the non-DMA transfer due to the fact that that one uses
 * 16-bit transfers when possible, but it allows other processes to continue running.
 *
 * @param data Pointer to data buffer
 * @param len Number of bytes to read
 */
void spi_block_read_dma(void *data, uint32_t len)
{
     const uint32_t cmd = 0x80000000L;

     taskENTER_CRITICAL();
    SPI_PDD_EnableTxFIFO(SPI0_BASE_PTR, PDD_ENABLE);
    SPI_PDD_EnableRxFIFO(SPI0_BASE_PTR, PDD_ENABLE);
     // Clear completion flags
     SPI0_SR |= SPI_SR_TFFF_MASK | SPI_SR_RFDF_MASK;
    DMA_CDNE = SPI_RX_DMA_CHANNEL;
    DMA_CDNE = SPI_TX_DMA_CHANNEL;
    DMA_DADDR_REG(DMA_BASE_PTR, SPI_RX_DMA_CHANNEL) = DMA_DADDR_DADDR(data);
    DMA_PDD_WriteBeginningMajorLoopCountReg(DMA_BASE_PTR, SPI_RX_DMA_CHANNEL, len);
    DMA_PDD_WriteCurrentMajorLoopCountReg(DMA_BASE_PTR, SPI_RX_DMA_CHANNEL, len);
    // No increment on TX source - use single word
    DMA_PDD_SetSourceAddressOffset(DMA_BASE_PTR, SPI_TX_DMA_CHANNEL, 0);
    DMA_PDD_SetSourceAddress(DMA_BASE_PTR, SPI_TX_DMA_CHANNEL, &cmd);
    DMA_PDD_WriteBeginningMajorLoopCountReg(DMA_BASE_PTR, SPI_TX_DMA_CHANNEL, len);
    DMA_PDD_WriteCurrentMajorLoopCountReg(DMA_BASE_PTR, SPI_TX_DMA_CHANNEL, len);
    DMA_CSR_REG(DMA_BASE_PTR, SPI_TX_DMA_CHANNEL) = DMA_CSR_DREQ_MASK;
    // Set up SPI for DMA - RX FIFO request enable w/ DMA
    SPI0_RSER |= SPI_RSER_TFFF_RE_MASK | SPI_RSER_TFFF_DIRS_MASK | SPI_RSER_RFDF_RE_MASK |
              SPI_RSER_RFDF_DIRS_MASK;
    // Enable request to start transfer
    NVIC_ClearPendingIRQ(INT_DMA0 + SPI_RX_DMA_CHANNEL);
    SPI_PDD_ClearTxFIFO(SPI0_BASE_PTR);
    SPI_PDD_ClearRxFIFO(SPI0_BASE_PTR);
    SPI_PDD_ClearTxRxActiveFlag(SPI0_BASE_PTR);
    taskEXIT_CRITICAL();
    // Set DREQ and enable completion interrupt
    DMA_CSR_REG(DMA_BASE_PTR, SPI_RX_DMA_CHANNEL) = (DMA_CSR_DREQ_MASK | DMA_CSR_INTMAJOR_MASK);
    DMA_SERQ = SPI_RX_DMA_CHANNEL;
    DMA_SERQ = SPI_TX_DMA_CHANNEL;
    // Wait here for DMA completion
    if (!xSemaphoreTake(spi_rx_semaphore, pdMS_TO_TICKS(5000)))
    {
         debug_print(ANSI_RED "SPI DMA timeout\r\n" ANSI_RESET);
    }

    return;
}


/**
 * DMA channel ISR for end of SPI DMA transfer.
 */
void spi_rx_dma_done_isr(void)
{
     BaseType_t xHigherPriorityTaskWoken = pdFALSE;

     DMA_CINT = SPI_RX_DMA_CHANNEL;
    DMA_CDNE = SPI_RX_DMA_CHANNEL;
    DMA_CDNE = SPI_TX_DMA_CHANNEL;
    SPI0_RSER &= ~(SPI_RSER_TFFF_RE_MASK | SPI_RSER_TFFF_DIRS_MASK | SPI_RSER_RFDF_RE_MASK |
              SPI_RSER_RFDF_DIRS_MASK);
     xSemaphoreGiveFromISR(spi_rx_semaphore, &xHigherPriorityTaskWoken);
     portYIELD_FROM_ISR(xHigherPriorityTaskWoken);
}‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍‍

[danielchen]

Hi Scott:

About the latency, I think the RTOS may temporarily disable the interrupts when accessing critical resources. The latency is longer if the interrupt request asserts during the interrupt is disabled.

Regards

Daniel