TDA4VM: SPI bus has waveform, but TDA4 reports receiving timeout

Hello,

Can you point me to the example you are running ? and also may i know have you done any modifications to the example ?

Regards

Tarun Mukesh

Hi,

    Thanks for reply.

    We have modified the demo $pkd/packages/ti/drv/spi/example/mcspi_slavemode/src/main_mcspi_slave_mode.c in SDK7.3.
    And we have set timeout to 30ms，cbmode to true, dmamode to true. The spi transmission cycle is 10ms with 4k payload.

As shown in the code, we send a semaphore in the spi rx cbk, and block to wait for this sem after executing the SPI_transfer.
In order to locate the problem, we recode the timestamp before SPI_transfer and after SPI_osalPendLock returns.

 if(test->master == 0)
    {
        time_record[index][0] = TimerP_getTimeInUsecs();
    }

    SPI_test_xfer_ctrl((SPI_Handle)spi, 1);

    {
        transferOK = SPI_transfer((SPI_Handle)spi, &(test->transaction));
        if ((testId == SPI_TEST_ID_CB_CANCEL) || (testId == SPI_TEST_ID_DMA_CB_CANCEL))
        {
            SPI_transferCancel((SPI_Handle)spi);
        }
    }

    if(transferOK)
    {
        if (cbMode)
        {
            if (SPI_osalPendLock(test->tran_cbSem_ptr[0], timeout) != SemaphoreP_OK)
            {
               if(test->master == 0)
                {
                    time_record[index][1] = TimerP_getTimeInUsecs();
                }

                goto Err;
            }
        }
        if(test->master == 0)
        {
            time_record[index][1] = TimerP_getTimeInUsecs();
        }

In most cases, the spi rx work well, but occasionally CRC errors or timeouts occur.

Under normal conditions, the difference between the two timestamps is approximately 10ms. However, when an abnormality occurs, sometimes due to a CRC check error, the time difference significantly exceeds one cycle. In other cases, the callback is not invoked, causing the semaphore to timeout and return, resulting in a time difference of 30ms between the two timestamps.

#normal
6256.589800 6256.599428
6256.600036 6256.609316
6256.609616 6256.619334
6256.619619 6256.629365

#crc error
6256.629921 6256.647158  timediff 17ms

#30ms timeout
6256.648139 6256.677872  timediff 30ms

Hello,

Allow me some time to go through your response.

Regards

Tarun Mukesh

Hi,

I would like to update some information:

We have two requirements:

1. how to avoid occasional crc errors.

2. how to recovery quickly from crc error. We are more concerned about the second requirement at present.

We have made some attempts, for example, once a crc error orurs， we sleep for a few seconds before executing the next spi transfer in order to bypass the remaining data of the current spi frame. We have also tried to re-invoke the spi open, but none of the above measures have been able to restore normal tranmission, after the next invoke of spi transfer, the callback is still not invoked within 30ms, resulting in a timeout exception.

Hello,

You are not using DMA right?

Regards

Tarun Mukesh

Hi,

Yes, we are using DMA,

and each time before we called SPI_transfer(), we will do CacheP_wbInv() for RxBuf

Hi,

I read the spi registers at three node: before calling SPI_transfer， after calling SPI_transfer，and after sem wait returns.

And I compare the registers in two scenarios: the first transmission after power-on，and the transmission after re-opening the SPI following a CRC check failure.

In the second case of SPI re-open, rx cbk did not return, but instead a semaphore timeout occurred and returned.

Hi,

What's the size of the DMA transfer that you are trying to do? Can you please share more information on this? What is the trigger level and element size? 

Regards,

Brijesh 

Hi,

 we set trigger level to 8, datasize to 8.  payload is 3000 bytes, and the master baud rate is 12.5M.

By the way,  we have tried to set the trigger level to 1, but it did not work.

Since payload size is multiple trigger level, it should work fine. Are you seeing timeout in transferring this data? 

Regards,

Brijesh

Hi,
    In most cases, the spi rx work well, but occasionally CRC errors or timeout occur.
    And Our key concern is that once a transmission exception occurs, whether we only sleep or re-open the spi, the rx cbk will not be called after next SPI_Transfer.
    Additionally, we found another information:
    during the open process，we have tried 2 ways to initialize the SPI_HWAttrs::edmaHandle, as shown in the figure. And when executing SPI_open, it allocated to different dma channels.

    When calling SPI_open for the first time after power on, we choose the MCSPIApp_udmaInit, and we get the dma channel 98; when the first exception occurs, we call SPI_close and SPI_open, choose MCSPIApp_udmaInit1 instead of MCSPIApp_udmaInit, and we get dma channel 35， spi transmission recovery immediately. However, at the next exception, regardless of which method is chosen, it can only allocated to channel 35 or 98, and rx cbk will not be called.

the log:

//first SPI_open after power on， using MCSPIApp_udmaInit
[MCU3_0]      3.521231 s: !!!!!!txChNum = 98, rxChNum = 4294901760, chType = 9
[MCU3_0]      3.522309 s: !!!!!!txChNum = 4294901760, rxChNum = 98, chType = 10

//first error injection
[MCU3_0]     13.514885 s: !!!!!!!!!!!!!!!!!!!!!!!!!delay to triggle crc err!!!!!!!!!!!!!!!!!!!!!!!!!
[MCU3_0]     13.553630 s: CRC Error

//SPI_close
[MCU3_0]     13.539080 s: tx.txChNum = 98, rx.rxChNum = 98,tx.rxChNum = 4294901760, rx.txChNum = 4294901760, MCSPI_dmaFreeChannel 419

//SPI_open， using MCSPIApp_udmaInit1
[MCU3_0]     13.548524 s: !!!!!!txChNum = 35, rxChNum = 4294901760, chType = 9
[MCU3_0]     13.549718 s: !!!!!!txChNum = 4294901760, rxChNum = 35, chType = 10
//SPI_transfer, and recovery


//second error injection
[MCU3_0]     23.545155 s: !!!!!!!!!!!!!!!!!!!!!!!!!delay to triggle crc err!!!!!!!!!!!!!!!!!!!!!!!!!
[MCU3_0]     23.581320 s: CRC Error:


//SPI_close
[MCU3_0]     23.569496 s: tx.txChNum = 35, rx.rxChNum = 35,tx.rxChNum = 4294901760, rx.txChNum = 4294901760, MCSPI_dmaFreeChannel 419

//SPI_open， using MCSPIApp_udmaInit
[MCU3_0]     23.575178 s: !!!!!!txChNum = 98, rxChNum = 4294901760, chType = 9
[MCU3_0]     23.576688 s: !!!!!!txChNum = 4294901760, rxChNum = 98, chType = 10
//SPI_transfer, and timeout

Hi,

we have some new discoveries about DMA:
UDMA_SCFG will change from 0x400 to 0x20410 during the first SPI_open; However, after calling SPI_close, this register will not be restored and cannot be manually reset for restoration;
2. We attempted to manually disable UDMA_SRT_CTL:: EN after calling SPI_close, which would take effect. If the current exception is a receiving deviation, manually setting this register would immediately restore it the next time; But if the current exception is a timeout, then it will still not recover next time.

That is to say, by manually setting the register UDMA_SRT_CTL, although cannot solve the problem of fast recovery after timeout, can meet the fast recovery after receiving deviation occurs. can you offer  a interface for disabling this register?

Hi Wang,

but why do you require to disable the channel? Why can't you set the size of the data as per the expected transfer? In that case, you would not require to disable and clean up UDMA channel.

Regards,

Brijesh

Hi,
Perhaps I didn't express myself clearly.

1. The payload is 3000, the datazise is 8, and the trilevel is 8. There is no problem with the above settings;
2. In most cases, it can run normally, but occasionally there may be reception exceptions due to unknown reasons, such as reception shift or rx cbk not be called;
3. Once an exception occurs, rx cbk will not be called after the next call to SPI_transfer, until the semaphore timeout ;
4. To solve the issue in 3, we compared the registers of SPI and DMA and attempted to manually disable the dma registers.

Hi Wang,

But why is rx callback not called? Is it because it did not received data in some scenarios? When happens after you get semaphore timeout error? 

Regards,

Brijesh  

Hi Brijesh,

Please review the description we provided above.

But why is rx callback not called?

This is exactly the question we are asking，

 Is it because it did not received data in some scenarios? 

We confirmed that the bus data was normal when the problem occurred, but the callback function did not enter. 

And we check the register 0x212017c：WCNT is decrement.

 When happens after you get semaphore timeout error?

After this timeout error, it will still timeout next time. If we set WAIT_FOREVER for semaphore, it will never return.

After this error, We have tried several measures， such as SPI_Close() & SPI_Open(), Disable & Re-enable DMA as  we mentioned above, 

and then call next SPI_transfer, at this point, there is a certain probability of returning to normal but it's still unstable

Thanks

Hi Wang,

shicheng wang said:

This is exactly the question we are asking，

Callback would not come if the data is not received completely. Even if there is only one byte less, it will not generate the interrupt, because DMA is configured to receive full byles. 

shicheng wang said:

And we check the register 0x212017c：WCNT is decrement.

Does WCNT reach to 0? If not, it is not receiving all bytes? 

shicheng wang said:

After this timeout error, it will still timeout next time. If we set WAIT_FOREVER for semaphore, it will never return.

After this error, We have tried several measures， such as SPI_Close() & SPI_Open(), Disable & Re-enable DMA as  we mentioned above, 

and then call next SPI_transfer, at this point, there is a certain probability of returning to normal but it's still unstable

I think it is better to figure out first when SPI did not receive full data. If you are transmitting 3000 bytes everytime, and SPI is configured to receive 3000 bytes, before the start of the transmission, it should receive full data and should get the callback. 

Regards,

Brijesh

Hi，

1. Callback would not come if the data is not received completely. 

    We knew this.

2. Does WCNT reach to 0? If not, it is not receiving all bytes? 

    Yes. RX Cbk will not be called even the WCNT reach to 0.

3. I think it is better to figure out first when SPI did not receive full data.

    Nomally, next SPI_transfer() will be called right after rxcbk and data process. To solve this problem, we can create an error of receiving deviation on the test bench by delay to call SPI_transfer(). After this rx cbk  return, we can find a crc error. Then we called SPI_close() and SPI_open() to reopen this spi channel. Then the rxcbk is supposed to be called, but it never be called.

shicheng wang said:

    Yes. RX Cbk will not be called even the WCNT reach to 0.

This is not possible. If WCNT is becoming 0, then there should be completion callback. When you say post Spi_transfer, is it after calling Spi_transfer API? and just before transmitter starting the transfer? 

shicheng wang said:

After this rx cbk  return, we can find a crc error

but here there is no SPI error. SPI has completed receiving all 3000 bytes. Then there is no need to call SPI_close and SPI_open again. 

If you want to recreate similar scenario, i would suggest to reduce the size in one of the SPI_transfer API. Then callback will not come, and SPI_Close and SPI_open should cleanup the DMA channel. 

Regards,

Brijesh 

Hi，

Brijesh Jadav said:

If WCNT is becoming 0, then there should be completion callback.

I confirm that the rxcbk has not been called.

Brijesh Jadav said:

When you say post Spi_transfer, is it after calling Spi_transfer API? and just before transmitter starting the transfer? 

I mean after calling this function. You can see that WCNT is 3000 at this moment

Brijesh Jadav said:

Then there is no need to call SPI_close and SPI_open again.

Our core issue is that once there is a reception mismatch, after calling SPI_transfer() next time, rxcbk will not be called.  Executing reopen is just one of our attempts to solve the problem.

shicheng wang said:

Our core issue is that once there is a reception mismatc

but when do you see reception mismatch? Do you mean here that there is no receive callback?

shicheng wang said:

after calling SPI_transfer() next time, rxcbk will not be called. 

is transfer completed in this case? What do you see in the WCNT here? Are you seeing any issue in reopening the driver? Like any error reported in udma initialization? 

Regards,

Brijesh

HI,

Brijesh Jadav said:

but when do you see reception mismatch

Occasional reception mismatch during actual vehicle testing.

Brijesh Jadav said:

Do you mean here that there is no receive callback?

Rxcbk was supposed to be called at the end of a spi frame transmission on the bus, but in case of an exception, it was  called when the second frame was transmitted on the bus. As we previously described:

we send a semaphore in the spi rx cbk, and block to wait for this sem after executing the SPI_transfer.
In order to locate the problem, we recode the timestamp before SPI_transfer and after SPI_osalPendLock returns.

Under normal conditions, the difference between the two timestamps is approximately 10ms. However, when an abnormality occurs, sometimes due to a CRC check error, the time difference significantly exceeds one cycle. In other cases, the callback is not invoked, causing the semaphore to timeout and return, resulting in a time difference of 30ms between the two timestamps.

if(test->master == 0)
    {
        time_record[index][0] = TimerP_getTimeInUsecs();
    }

    SPI_test_xfer_ctrl((SPI_Handle)spi, 1);

    {
        transferOK = SPI_transfer((SPI_Handle)spi, &(test->transaction));
        if ((testId == SPI_TEST_ID_CB_CANCEL) || (testId == SPI_TEST_ID_DMA_CB_CANCEL))
        {
            SPI_transferCancel((SPI_Handle)spi);
        }
    }

    if(transferOK)
    {
        if (cbMode)
        {
            if (SPI_osalPendLock(test->tran_cbSem_ptr[0], timeout) != SemaphoreP_OK)
            {
               if(test->master == 0)
                {
                    time_record[index][1] = TimerP_getTimeInUsecs();
                }

                goto Err;
            }
        }
        if(test->master == 0)
        {
            time_record[index][1] = TimerP_getTimeInUsecs();
        }

if(test->master == 0)
    {
        time_record[index][0] = TimerP_getTimeInUsecs();
    }

    SPI_test_xfer_ctrl((SPI_Handle)spi, 1);

    {
        transferOK = SPI_transfer((SPI_Handle)spi, &(test->transaction));
        if ((testId == SPI_TEST_ID_CB_CANCEL) || (testId == SPI_TEST_ID_DMA_CB_CANCEL))
        {
            SPI_transferCancel((SPI_Handle)spi);
        }
    }

    if(transferOK)
    {
        if (cbMode)
        {
            if (SPI_osalPendLock(test->tran_cbSem_ptr[0], timeout) != SemaphoreP_OK)
            {
               if(test->master == 0)
                {
                    time_record[index][1] = TimerP_getTimeInUsecs();
                }

                goto Err;
            }
        }
        if(test->master == 0)
        {
            time_record[index][1] = TimerP_getTimeInUsecs();
        }

#normal
6256.589800 6256.599428
6256.600036 6256.609316
6256.609616 6256.619334
6256.619619 6256.629365

#crc error
6256.629921 6256.647158  timediff 17ms

#30ms timeout
6256.648139 6256.677872  timediff 30ms

Brijesh Jadav said:

is transfer completed in this case? What do you see in the WCNT here? Are you seeing any issue in reopening the driver? Like any error reported in udma initialization? 

transmission has completed, wcnt is 0 here. No error were found during the reopening process.

Hi,

Add a new information,

We made another new attempt： set the cbmode to FALSE, and keep the dmamode TRUE.  Under this configuration, the SPI_transfer() function will remain blocked until the transfer is completed or timeout occurs.

However, we reproduce the problem by delaying the  reception, when reception mismatch,  next time call SPI_transfer() will never return until timeout(timeout set 3000ms),  After timeout return， the WCNT is 0.

We think this is abnormal. Why the SPI_transfer() function still block to timeout even if we do not use cbmode.

Thanks

Hi,

shicheng wang said:

However, we reproduce the problem by delaying the  reception, when reception mismatch,  next time call SPI_transfer() will never return until timeout(timeout set 3000ms),  After timeout return， the WCNT is 0.

But isn't this expected? You delayed the transfer, so SPI will not receive 3000 words in time and so there will be timeout and for the next transfer, since there are some pending bytes in the fifo, timeout needs to be increased slightly to accommodate for increased side (few bytes from previous transfer and 3000 bytes for this transfer). Again, you should see receive callback after 3000 bytes of transfer, if the size is set to 3000 bytes, but WCNT may or may not be 0 depending on the where SPI is or how much data is received. 

Regards,

Brijesh 

Hi,
Thank you for patiently reply.

           But isn't this expected? You delayed the transfer, so SPI will not receive 3000 words in time and so there will be timeout and for the next transfer,

No, this is not expected. Because we transmit data period is 10ms (3000bytes / 10ms), and timeout set 3000ms (300 * 10ms).

Even if we delayed the transfer, e.g.:delay 6ms, of course we can not receive enough 3000 bytes in this cycle, for example, only received 1000 bytes,

so that the SPI_transfer()  is blocking to next transmitting cycle, when next 10ms is coming, there are new 3000 bytes on bus. In theory, this time we only need to receive the first 2000 bytes to make up 3000 bytes, since last cycle we have received 1000 bytes, and the SPI_transfer()  should return, is it right?

But the fact is, there was no return even after the timeout of 3000 ms. In other words, the master end has continuously sent 300 cycles of data(300 * 10ms), but we have never received enough 3000 bytes.
Did I explain it clearly？

Thanks

Hi,

    As we mentioned above:

UDMA_SCFG will change from 0x400 to 0x20410 during the first SPI_open; However, after calling SPI_close, this register will not be restored and cannot be manually reset for restoration;
2. We attempted to manually disable UDMA_SRT_CTL:: EN after calling SPI_close, which would take effect. If the current exception is a receiving deviation, manually setting this register would immediately restore it the next time; But if the current exception is a timeout, then it will still not recover next time.

That is to say, by manually setting the register UDMA_SRT_CTL, although cannot solve the problem of fast recovery after timeout, can meet the fast recovery after receiving deviation occurs. can you offer  a interface for disabling this register?

--------------------------------------------

How can we confirm the DMA channel reset state since the reg UDMA_SCFG keep 0x20410 after spi_close() in which MCSPI_dmaFreeChannel() is called? Or which reg can reflect DMA channel state we should observe?

And any function to disable the UDMA_SRT_CTL:: EN ?

shicheng wang said:

so that the SPI_transfer()  is blocking to next transmitting cycle, when next 10ms is coming, there are new 3000 bytes on bus. In theory, this time we only need to receive the first 2000 bytes to make up 3000 bytes, since last cycle we have received 1000 bytes, and the SPI_transfer()  should return, is it right?

Yes, that's correct. and you are getting callback after receiving 2000 bytes from the next cycle, isn't it?

shicheng wang said:

But the fact is, there was no return even after the timeout of 3000 ms. In other words, the master end has continuously sent 300 cycles of data(300 * 10ms), but we have never received enough 3000 bytes.
Did I explain it clearly？

not exactly sure why it is not, can we get the SPI register dump to figure out? and compare it against working case? any difference between them? I think this is first that we need to figure out. 

Regards,

Brijesh

Hi,

We add Udma_ChDisable() in MCSPI_dmaFreeChannel(),but timeout out error happened!

void MCSPI_dmaFreeChannel(MCSPI_Handle mcHandle)
{
    SPI_Handle         handle;
    SPI_HWAttrs const *hwAttrs;
    SPI_dmaInfo       *pDmaInfo;

    /* Get the pointer to the object and hwAttrs */
    handle   = mcHandle->handle;
    hwAttrs  = (SPI_HWAttrs const *)handle->hwAttrs;
    pDmaInfo = hwAttrs->dmaInfo;

printf("%s:%d: tx.txChNum = %u, rx.rxChNum = %u,tx.rxChNum = %u, rx.txChNum = %u, %s %d\n", __FUNCTION__, __LINE__, 
((Udma_ChHandle)(pDmaInfo->txChHandle))->txChNum, ((Udma_ChHandle)(pDmaInfo->rxChHandle))->rxChNum, 
((Udma_ChHandle)(pDmaInfo->txChHandle))->rxChNum, ((Udma_ChHandle)(pDmaInfo->rxChHandle))->txChNum, 
        __FUNCTION__, __LINE__);


printf("%s:%d: before disable \n", __FUNCTION__, __LINE__);
    Udma_chDisable(pDmaInfo->txChHandle, UDMA_DEFAULT_CH_DISABLE_TIMEOUT);
    Udma_chDisable(pDmaInfo->rxChHandle, UDMA_DEFAULT_CH_DISABLE_TIMEOUT);
printf("%s:%d: after disable \n", __FUNCTION__, __LINE__);

    /* Close the TX channel */
    (void)Udma_eventUnRegister((Udma_EventHandle)(pDmaInfo->txEventHandle));
    (void)Udma_chClose((Udma_ChHandle)(pDmaInfo->txChHandle));

    /* Close the RX channel */
    (void)Udma_eventUnRegister((Udma_EventHandle)(pDmaInfo->rxEventHandle));
    (void)Udma_chClose((Udma_ChHandle)(pDmaInfo->rxChHandle));
}

In function Udma_ChDisable(), DMA Channel teardown failed.

Besides force DMA Channel teardown also failed!

Please help me checkout it.

Thanks!

hi Wang,

Any further update on this thread? 

Regards,

Brijesh