First 4 bits received by SPIM (from SPIS) are always 1?

[ryerye120]

I'm running into a weird bug where the first 4 bits received by my SPIM are always 1 - the next 64.5 bytes are all correct though...

I've built 3 FWs out of provided examples.

1. I have a single devkit acting as a spi_slave built off the spis example from SDK 17.1. It waits for a spi transaction and as soon as it occurs it increments a few bytes (including the first one) in a buffer and sets it to be sent out again. Pertinent code, below:
   

   static uint8_t       m_tx_buf[] = {2,2,2,2,2,3,3,3,3,4,5,5,6,2,2,3,3,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,
                                      19,20,21,22,23,15,15,16,17,18,19,19,1,2,3,4,5,6,7,8,9,1,2,3,4,5,6,7,16,1,1,1};
   static uint8_t       m_rx_buf[sizeof(m_tx_buf) + 1];        // RX buffer.
   ...
   ...
   void spis_event_handler(nrf_drv_spis_event_t event)
   {
       if (event.evt_type == NRF_DRV_SPIS_XFER_DONE)
       {
           spis_xfer_done = true;
           bsp_board_led_invert(BSP_BOARD_LED_2);
           NRF_LOG_INFO(" packet_id: %d",m_tx_buf[0]);
           counter = counter + 1;
   
           m_tx_buf[0] = counter;
   
           m_tx_buf[10] = m_tx_buf[10] + 3;
           m_tx_buf[20] = m_tx_buf[20] + 4;
           m_tx_buf[30] = m_tx_buf[30] + 5;
           m_tx_buf[40] = m_tx_buf[40] + 6;
           m_tx_buf[50] = m_tx_buf[50] + 7;
           m_tx_buf[60] = counter + 2;
       }
   }

2. I have a spi master (built off the ble_app_uart and the nrfx_spim examples from SDK 16). Ultimately it triggers spi transactions based on a timer interrupt and then sends the 65 received bytes over BLE to a central device. Pertinent code below:
   

   static uint8_t       spi_tx_buf[] = {0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,
                                       0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,16,0,0,0};
   static uint8_t        ble_tx_buff_t[] = {0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,
                                      0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0};
   static uint8_t       spi_rx_buf[sizeof(spi_tx_buf) + 1];        /**< RX buffer. */
   
   ...
   
   static void trx_timer_handler(void * p_context)
   {
     // update spi_tx_buff to have read data commands
     spi_tx_buf[0]   = read_data_instr[0];
     spi_tx_buf[1]   = read_data_instr[1];
     spi_tx_buf[63]  = read_data_instr[2];
     spi_tx_buf[64]  = read_data_instr[3];
   
     // fire off a SPI transaction
     NRF_LOG_INFO("%s", spi_tx_buf);
     if (spi_xfer_done == true)
     {
       spi_xfer_done = false;
       nrfx_spim_xfer_desc_t xfer_desc = NRFX_SPIM_XFER_TRX(spi_tx_buf, spi_length, ble_tx_buff_t, spi_length);
       APP_ERROR_CHECK(nrfx_spim_xfer(&spi, &xfer_desc, 0));
   
   }
   
   
   void spim_event_handler(nrfx_spim_evt_t const * p_event,
                          void *                  p_context)
   {
       spi_xfer_done = true;
       NRF_LOG_INFO("SPI TRX COMPLETE");
       
       if (spi_cmd_flag == SPI_STREAM) {
   
         // block to convert and send single char packet
         char buf[131];
         uint16_t size_of_buff = sizeof(char)*131;
         for (int i = 0 ; i != 65 ; i++) 
         {
           sprintf(buf + (2*i), "%02x", ble_tx_buff_t[i]);
         }
         NRF_LOG_INFO("packet_id: %d",buf[0]);
         while(ble_nus_data_send(&m_nus, (uint8_t *) buf, &size_of_buff, m_conn_handle) != NRF_SUCCESS);
       }
   }

   
   
   
3. A central device that I use to send commands to and read data from the spi_master (built on top of ble_usbd_c from SDK 16).
   
   

My issues and current debugging steps are below:

• The slave has the correct data in its tx buff but the received data is 'incorrect' on the SPIM side. It's odd because it's just the first 4 bits - everything else is correct. The ble_tx_buff_t[0] contents will increment from 128 to 255 and then wrap back to 255 instead of 0. I don't have access to an oscope right now but I'm trying to get one to take a look at the MISO line. Dollars to donuts that the problem is somewhere on the master side...
• When I try running the SPIM at 4M or above all the data gets corrupted. Are the limits to what the spis default pins can handle? Or are there other issues I have to keep in mind for running spi at faster speeds?
• This is just a question - not an issue - why is the spi_rx_buff +1 element larger than the tx_buff? This is something I copied over from the examples but never understood why. I tried making the buffers the same size and that didn't seem to change anything...

Thank you for your help!

Ryan

[Kenneth]

It might be timing related, so try to ensure some delays between nrfx_spim_xfer() transfers and also I suspect that you are letting the driver handle the timing of the chip select pin, and the time between chip select go low and actual data on SPI likely is shorter than what the SPIS can handle. So I suggest edit nrfx_spim_xfer() and add a 10us delay (e.g. #include nrf_delay.h) by calling nrf_delay_us(10); right before spim_xfer() in nrfx_spim_xfer() in nrfx_spim.c.

If that doesn't help then a logic analyzer trace would be useful.

Best regards,
Kenneth

[ryerye120]

Hi Kenneth,

So I've been a little dumb. Incrementing an 8 bit number from 128 to 255 and wrapping just means the MSB is always 1. So my biggest problem is not that the first 4 bits are always 1 ... just the first bit.

Regardless, I tried adding the delay and that didn't seem to make a difference, unfortunately.

I did manage to get my hands on an oscope and probed the SS, MISO, and SCLK lines. The MISO is indeed first sending a 1 (which corresponds to the MSB). CS and SCLK seemed just fine as well. Is there some config bit that I'm ignoring that always sets the first bit to 1? I've copied my short spi_slave code below in case you have any suggestions.

Lastly, I confirmed that within a single spi transaction (CS going low and then high again), 520 clock cycles occur over miso. This means I'm definitely sending the proper amount of bytes (65*8 = 520? yes!)

Thank you so much for your help.

Kindest regards,

Ryan

#include "sdk_config.h"
#include "nrf_drv_spis.h"
#include "nrf_gpio.h"
#include "boards.h"
#include "app_error.h"
#include <string.h>

#include "nrf_log.h"
#include "nrf_log_ctrl.h"
#include "nrf_log_default_backends.h"

#define SPIS_INSTANCE 1 /**< SPIS instance index. */
static const nrf_drv_spis_t spis = NRF_DRV_SPIS_INSTANCE(SPIS_INSTANCE);/**< SPIS instance. */

// SPI transfer buffer
static uint8_t       m_tx_buf[] = {2,2,2,2,2,3,3,3,3,4,5,5,6,2,2,3,3,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,
                                   19,20,21,22,23,15,15,16,17,18,19,19,1,2,3,4,5,6,7,8,9,1,2,3,4,5,6,7,16,1,1,1};
static uint8_t       m_rx_buf[sizeof(m_tx_buf) + 1];        // RX buffer.
static const uint8_t m_length = sizeof(m_tx_buf);        // Transfer length.
static uint8_t       counter = 0;


void spis_event_handler(nrf_drv_spis_event_t event)
{
    if (event.evt_type == NRF_DRV_SPIS_XFER_DONE)
    {
        spis_xfer_done = true;
        bsp_board_led_invert(BSP_BOARD_LED_2);
        NRF_LOG_INFO(" packet_id: %d",m_tx_buf[0]);
        counter = counter + 1;

        m_tx_buf[0] = counter;

        m_tx_buf[10] = m_tx_buf[10] + 3;
        m_tx_buf[20] = m_tx_buf[20] + 4;
        m_tx_buf[30] = m_tx_buf[30] + 5;
        m_tx_buf[40] = m_tx_buf[40] + 6;
        m_tx_buf[50] = m_tx_buf[50] + 7;
        m_tx_buf[60] = counter + 2;
    }
}

int main(void)
{
    NRF_POWER->TASKS_CONSTLAT = 1;

    bsp_board_init(BSP_INIT_LEDS);

    APP_ERROR_CHECK(NRF_LOG_INIT(NULL));
    NRF_LOG_DEFAULT_BACKENDS_INIT();

    NRF_LOG_INFO("SPIS example");

    nrf_drv_spis_config_t spis_config = NRF_DRV_SPIS_DEFAULT_CONFIG;
    spis_config.csn_pin               = APP_SPIS_CS_PIN;
    spis_config.miso_pin              = APP_SPIS_MISO_PIN;
    spis_config.mosi_pin              = APP_SPIS_MOSI_PIN;
    spis_config.sck_pin               = APP_SPIS_SCK_PIN;

    // APP_SPIS_CS_PIN 31
    // APP_SPIS_MOSI_PIN 29
    // APP_SPIS_MISO_PIN 30
    // APP_SPIS_SCK_PIN 26

    APP_ERROR_CHECK(nrf_drv_spis_init(&spis, &spis_config, spis_event_handler));
    bsp_board_led_invert(BSP_BOARD_LED_0);
    while (1)
    {
        memset(m_rx_buf, 0, m_length);
        spis_xfer_done = false;

        APP_ERROR_CHECK(nrf_drv_spis_buffers_set(&spis, m_tx_buf, m_length, m_rx_buf, m_length));

        while (!spis_xfer_done)
        {
            __WFE();
        }

        NRF_LOG_FLUSH();

        bsp_board_led_invert(BSP_BOARD_LED_1);
    }
}

 

[Kenneth]

I suggest continue debugging, not sure if I understand your current problem. Think it will be better if you for instance send a fixed tx_buffer and for instance share a logic analyzer trace of the first byte and describe what you expect to see.

Kenneth

[ryerye120]

Hi Kenneth,

Sorry for being unclear. After some further debugging I can say that my main problem is:

When I ask my spi slave to send the following 65 byte packet:

static uint8_t       m_tx_buf[] = {0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,
                                   0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,
                                   0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,
                                   0,0,0,2,2};

My spi master will receive:

{8,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,
 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,
 0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,
 0,0,0,2,2};

With the only difference is that the 0 index's MSB is 1. I've tried out a number of different numbers in the first byte (m_tx_buf[0]) and it seems like the first 4 bits of my SPI packet always end up being something weird. E.g. if I want to send the decimal number 80 then I receive 0xd0 (instead of 0x50). If I try to send decimal127 then the master receives 0xff (instead of 0x0f). The bottom line is some values seem to confuse the SPI driver. Am I not setting m_tx_buf properly?

For the send decimal 0 and receive 0x80 case:
I probed the SCLK, CS, and MISO lines with an oscilloscope and observed that CS and SCLK behave properly (65 bytes worth of data are indeed shifted out over MISO). The odd thing is that the first bit sent over MISO is 1! Regardless of what I try to send. This means the master is reading everything in properly and the issue seems to be with the spi slave...

To make things weirder I have the spi slave print out what m_tx_buf[0] is with NRF_LOG_INFO before and after each spi transaction and it is always 0 (as it should be) but again - the received first byte is 8 (which is 1000000 - meaning the msb is erroneously 1).

To belabor the point some more here is a screenshot of the oscilloscope with the following signals (SCLK, CS, and MISO):

That first bit on MISO should be 0!!

Also as reference here is a copy of my spi_slave code:

#include "sdk_config.h"
#include "nrf_drv_spis.h"
#include "nrf_gpio.h"
#include "boards.h"
#include "app_error.h"
#include <string.h>

#include "nrf_log.h"
#include "nrf_log_ctrl.h"
#include "nrf_log_default_backends.h"

#define SPIS_INSTANCE 1 /**< SPIS instance index. */
static const nrf_drv_spis_t spis = NRF_DRV_SPIS_INSTANCE(SPIS_INSTANCE);/**< SPIS instance. */

// SPI transfer buffer
static uint8_t       m_tx_buf[] = {0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,
                                   0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,
                                   0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,0,
                                   0,0,0,2,2};


static uint8_t       m_rx_buf[sizeof(m_tx_buf) + 1];        // RX buffer.
static const uint8_t m_length = sizeof(m_tx_buf);        // Transfer length.
static uint8_t       counter = 0;


static volatile bool spis_xfer_done; /**< Flag used to indicate that SPIS instance completed the transfer. */


void spis_event_handler(nrf_drv_spis_event_t event)
{
    if (event.evt_type == NRF_DRV_SPIS_XFER_DONE)
    {
        spis_xfer_done = true;
        bsp_board_led_invert(BSP_BOARD_LED_2);
        NRF_LOG_INFO(" packet_id: %d",m_tx_buf[0]);
        
    }
}

int main(void)
{
    NRF_POWER->TASKS_CONSTLAT = 1;

    bsp_board_init(BSP_INIT_LEDS);

    APP_ERROR_CHECK(NRF_LOG_INIT(NULL));
    NRF_LOG_DEFAULT_BACKENDS_INIT();

    NRF_LOG_INFO("SPIS example");

    nrf_drv_spis_config_t spis_config = NRF_DRV_SPIS_DEFAULT_CONFIG;
    spis_config.csn_pin               = APP_SPIS_CS_PIN;
    spis_config.miso_pin              = APP_SPIS_MISO_PIN;
    spis_config.mosi_pin              = APP_SPIS_MOSI_PIN;
    spis_config.sck_pin               = APP_SPIS_SCK_PIN;

    // APP_SPIS_CS_PIN 31
    // APP_SPIS_MOSI_PIN 29
    // APP_SPIS_MISO_PIN 30
    // APP_SPIS_SCK_PIN 26

    APP_ERROR_CHECK(nrf_drv_spis_init(&spis, &spis_config, spis_event_handler));
    bsp_board_led_invert(BSP_BOARD_LED_0);
    while (1)
    {
        NRF_LOG_INFO("before memset - packet_id: %d",m_tx_buf[0]);
        memset(m_rx_buf, 0, m_length);
        spis_xfer_done = false;

        APP_ERROR_CHECK(nrf_drv_spis_buffers_set(&spis, m_tx_buf, m_length, m_rx_buf, m_length));
        NRF_LOG_INFO(" packet_id after check: %d",m_tx_buf[0]);

        while (!spis_xfer_done)
        {
            __WFE();
        }

        NRF_LOG_FLUSH();

        bsp_board_led_invert(BSP_BOARD_LED_1);
    }
}

Thank you so much for your help. I'm so confused about how this can be happening...

Ryan

p.s. it seems like I'm not the only one to have dealt with this error - unfortunately, they stopped responding - Furthermore this post is for the 52832 so it may be completely irrelevant : https://devzone.nordicsemi.com/f/nordic-q-a/28265/spis-communication-corrupted

[Kenneth]

I can see there is no delay between CS going low and first SCK. Can you on the master SPI add a 10us delay between the two as earlier suggested, I want to see how that affect what you are seeing.

Kenneth

[ryerye120]

Hi Kenneth,

I'm trying this out but it doesn't seem to be changing the time between CS going low and SCK's first clock cycle. I added nrf_delay.h and the delay right before spim_xfer() (my nrfx_spim_xfer function is copied below).

nrfx_err_t nrfx_spim_xfer(nrfx_spim_t     const * const p_instance,
                          nrfx_spim_xfer_desc_t const * p_xfer_desc,
                          uint32_t                      flags)
{
    spim_control_block_t * p_cb = &m_cb[p_instance->drv_inst_idx];
    NRFX_ASSERT(p_cb->state != NRFX_DRV_STATE_UNINITIALIZED);
    NRFX_ASSERT(p_xfer_desc->p_tx_buffer != NULL || p_xfer_desc->tx_length == 0);
    NRFX_ASSERT(p_xfer_desc->p_rx_buffer != NULL || p_xfer_desc->rx_length == 0);
    NRFX_ASSERT(SPIM_LENGTH_VALIDATE(p_instance->drv_inst_idx,
                                     p_xfer_desc->rx_length,
                                     p_xfer_desc->tx_length));

    nrfx_err_t err_code = NRFX_SUCCESS;

    if (p_cb->transfer_in_progress)
    {
        err_code = NRFX_ERROR_BUSY;
        NRFX_LOG_WARNING("Function: %s, error code: %s.",
                         __func__,
                         NRFX_LOG_ERROR_STRING_GET(err_code));
        return err_code;
    }
    else
    {
        if (p_cb->handler && !(flags & (NRFX_SPIM_FLAG_REPEATED_XFER |
                                        NRFX_SPIM_FLAG_NO_XFER_EVT_HANDLER)))
        {
            p_cb->transfer_in_progress = true;
        }
    }

    p_cb->evt.xfer_desc = *p_xfer_desc;

    if (p_cb->ss_pin != NRFX_SPIM_PIN_NOT_USED)
    {
#if NRFX_CHECK(NRFX_SPIM_EXTENDED_ENABLED)
        if (!p_cb->use_hw_ss)
#endif
        {
            if (p_cb->ss_active_high)
            {
                nrf_gpio_pin_set(p_cb->ss_pin);
            }
            else
            {
                nrf_gpio_pin_clear(p_cb->ss_pin);
            }
        }
    }
    
    nrf_delay_us(10);
    return spim_xfer(p_instance->p_reg, p_cb,  p_xfer_desc, flags);
}

Am I doing something wrong? I tried 10us and 100us of delay and couldn't observe any delay over the oscope. Is there another way to add this delay?