nrf5340 is unable to trigger rpmsg(ipc) transfer

[Dumam]

Hi,

I have quite demanding SPI device which should send its data over BLE.
Thanks to throughput example i was able to achieve maximum transfer speeds for synthetic tests (without SPI).
Sadly after adding real data input, I noticed that no transfer is executed until I finish my commands. 

Thanks to SystemView I was able to narrow this problem to one part of configuration -> rpmsg.

Colors:

Green -> spi thread
Yellow -> bt_hci thread
Orange -> ble host TX
Red (small squere in top) - IRQ 58 from probably ipc, but i wasnt able to find it in manual (not listed)
Blue - probably openAmp mailing work queue thread
purple - systemwork queue

SystemView Data Log
4010.BleProblem.dat

Here is repo with configs etc.
https://github.com/DuMaM/bitly_nrf5x

[Edvin]

Hello,

I am not sure I understand the question? What are you seeing, and how do you expect it to work?

I noticed that no transfer is executed until I finish my commands. 

What sort of commands are you talking about here?

BR,
Edvin

[Dumam]

 Edvin Thanks for response, and sorry to not be clear enough. 

This is what i'm doing here:
-> I have ads129x communication over SPI. It's set to work in continuous mode, so every n seconds it sends data packet (24bytes). To notify that we should get them it pulls up DATA_READY pin. I detect this in ISR callback and via semaphore i'm notifying SPI thread to read data. (GREEN part in picture)
-> after SPI read this it send that data via pipe to other thread which is packing up data for BLE transfer, every time i get 251 bytes in this thread I'm sending this with `bt_gatt_write_without_response`. (YELLOW part in picture)

The question is:
why it takes so long rpmsg to start transmit data and why there are so big delays between each frame. (BLUE part in picture)

[Dumam]

Edvin I think it's more a problem of how communication between threads is set up.

I checked this with Particle Xenon board and I observed exactly the same behavior.
I also switched from pipe to ring_buffers to save copy operations. This also didn't helped.

Here is BLE thread:
https://github.com/DuMaM/bitly_nrf5x/blob/e6cf66e1655bf3da2c65d58fedb561893194ba80/src/app/cmd_run_adc.c

Here is SPI thread:
github.com/.../spi_adc.c

[Edvin]

Dumam said:

I think the issue here is that `cmd_sim` function is sending everything in one thread,

Where is this cmd_sim? Is it part of the repository that you are linking to? I am not familiar with that application, and it is not written by anyone from Nordic. 

Best regards,
Edvin

[Dumam]

Yep, this is my command i wrote for testing purposes.

Everything base on this example.
https://developer.nordicsemi.com/nRF_Connect_SDK/doc/latest/nrf/samples/bluetooth/throughput/README.html

I changed few parameters, to fit my needs. cmd_sim is basically this function from sample.
github.com/.../main.c

The problematic code do the same but gets data from SPI. 

[Edvin]

Dumam said:

The problematic code do the same but gets data from SPI. 

Can you please show me how you do that? 

In case I have follow up questions, feel free to zip and upload the entire project here (just drag and drop into the window where you are typing). 

[Dumam]

My repo is public you can download or clone it without any issues.

https://github.com/DuMaM/bitly_nrf5x
I also placed this in attachment.

SPI Thread.
More here: github.com/.../spi_adc.c

void ads129x_set_data()
{
    /* add timestamp */
    tx_data.packet.timestamp = k_uptime_get() - timestamp;
    conv_u24_to_raw(tx_data.packet.timestamp, tx_data.buffer, 0);

    /* do processing */
    /* NOTE: Work directly on a ring buffer memory */
    int ret = spi_read(ads129x_spi, &ads129x_spi_cfg, &ads129x_rx);
    if (!ret)
    {
        /* add missing leads */
        lead1 = conv_u24_to_i32(conv_raw_to_u24(tx_data.packet.leads._buffer, ADS129x_LEAD1_OFFSET));
        lead2 = conv_u24_to_i32(conv_raw_to_u24(tx_data.packet.leads._buffer, ADS129x_LEAD2_OFFSET));
        conv_u24_to_raw(ads129x_get_leadIII(lead1, lead2), tx_data.packet.leads._buffer, ADS129x_LEAD3_OFFSET);
        conv_u24_to_raw(ads129x_get_aVR(lead1, lead2), tx_data.packet.leads._buffer, ADS129x_AVR_OFFSET);
        conv_u24_to_raw(ads129x_get_aVL(lead1, lead2), tx_data.packet.leads._buffer, ADS129x_AVL_OFFSET);
        conv_u24_to_raw(ads129x_get_aVF(lead1, lead2), tx_data.packet.leads._buffer, ADS129x_AVF_OFFSET);

        //ads129x_dump_data(tx_data.packet.leads._buffer);
    }

    /* send data to consumers */
    /* send data to the consumers */
    k_pipe_put(&ads129x_pipe, &tx_data.buffer, total_size, &bytes_written, sizeof(pipe_packet_u), K_NO_WAIT);
}

void ads129x_th(void)
{
    /* setup ecg */
    ads129x_setup();

    for (;;)
    {
        /*
         * Wait for semaphore from ISR; if acquired, do related work, then
         * go to next loop iteration (the semaphore might have been given
         * again); else, make the CPU idle.
         */
        if (k_sem_take(&ads129x_new_data, K_FOREVER) == 0)
        {
            ads129x_set_data();
        }
    }
}

K_THREAD_DEFINE(thread_ads129x, STACKSIZE, ads129x_th, NULL, NULL, NULL, PRIORITY, K_ESSENTIAL, 0);

BLE Thread:
More here: https://github.com/DuMaM/bitly_nrf5x/blob/e6cf66e1655bf3da2c65d58fedb561893194ba80/src/app/cmd_run_adc.c#L104

K_THREAD_STACK_DEFINE(ecg_ble_stack, 4096);
struct k_thread ecg_ble_thread;
static uint32_t bytes_to_send = 1024;

static uint32_t send_test_ecg_data(uint32_t _bytes_to_send)
{
    uint32_t prog = 0;
    uint8_t *analog_data_ptr = test_data_buffer;
    uint32_t analog_data_size = 0;
    int err = 0;

    /*
     * we always waiting for data to match whole buffer
     * so data requested should also match it
     * otherwise we should ignore it
     */
    uint16_t remainder = _bytes_to_send % ADS129x_DATA_BUFFER_SIZE;
    if (remainder) {
        _bytes_to_send = ((_bytes_to_send / ADS129x_DATA_BUFFER_SIZE) + 1) * ADS129x_DATA_BUFFER_SIZE;
    }
    LOG_INF("Sending %"PRIu32" bytes (value after rounding to max packet size)", _bytes_to_send);

    while (prog < _bytes_to_send)
    {
        analog_data_size = _bytes_to_send - prog;
        if (test_params.data_len->tx_max_len <= analog_data_size) {
            analog_data_size = test_params.data_len->tx_max_len;
        }

        /*
         * TODO: add scaling from shell
         * It would be good to send optimal number of data
         * during each transfer
         * also when we change a number o leads
         */
        if (!ads129x_get_data(analog_data_ptr, analog_data_size))
        {
            continue;
        }

        err = bt_performance_test_write(&performance_test, analog_data_ptr, analog_data_size);
        if (err)
        {
            LOG_ERR("GATT write failed (err %d)", err);
            break;
        }

        prog += analog_data_size;
    }
    return prog;
}

bitly_nrf5x-main.zip

[Edvin]

Oh, my impression was that this was someone else's repository. I understand. I will have a look at it as soon as possible.

[Dumam]

 Edvin I'm soo grateful for this. I'm trying to figure it out for 2 months without any luck. :(

[Edvin]

Ok, I am trying to navigate your project. I am struggling to see exactly how it relates to the throughput sample. Where exactly are you sending the BLE packets. Can you please point to it? Where it sends, and how long are the packets that you are sending? There should be a call to bt_gatt_notify_cb() or bt_gatt_write() or something like that.

You say that your throughput is much higher when you disable the SPI and just use dummy data. So the MTU and connection interval and everything else is the same, just that you wait for the SPI to finish? 

What is it that triggers send_test_ecg_data()? 

ads129x_get_data() only triggers a read from a buffer? No actual peripheral transferring data? When will it continue; and when will it send data (which I assume it does inside bt_performance_test_write(). And when bt_performance_test_write() is called, what is the length of the data that is being sent?

Sorry, a lot of unstructured questions, but I was reading more and more into your project. So the question is, how often is send_test_ecg_data() called, and how often is bt_performance_test_write() called? Is bt_performance_test_write() called every time send_test_ecg_data() is called, or does it often skip it because of continue; ?

[Dumam]

> Ok, I am trying to navigate your project. I am struggling to see exactly how it relates to the throughput sample. 

I renamed it to performance_tests
I wanted to extract this form nrf sdk, mostly because in feature I'm going to modify it.
This also helped me to have a stable code base.

> Where exactly are you sending the BLE packets. Can you please point to it?

Sure. I'm using writes here, as it was in example. I'm sending packages here: 
https://github.com/DuMaM/bitly_nrf5x/blob/e6cf66e1655bf3da2c65d58fedb561893194ba80/src/app/cmd_run_adc.c#L61

> Where it sends, and how long are the packets that you are sending? There should be a call to bt_gatt_notify_cb() or bt_gatt_write() or something like that.

I'm trying to fill package as much as possible. Until there are data in buffer I'm sending `data_len->tx_max_len`, otherwise when there will be some leftovers I placing them as a whole.

> You say that your throughput is much higher when you disable the SPI and just use dummy data. So the MTU and connection interval and everything else is the same, just that you wait for the SPI to finish? 

I think yes.  
SPI is driven by GPIO called DRDY. This pin is used by hooked up device to notify master that it should fetch data. Maximum speed here is 32000 samples/s, but with current BLE capabilities the maximum reasonable value is 4000k samples/s (1400kbps), for tests i'm using 2000k samples/s.

> What is it that triggers send_test_ecg_data()? 

This semaphore and GPIO callback:
https://github.com/DuMaM/bitly_nrf5x/blob/e6cf66e1655bf3da2c65d58fedb561893194ba80/src/app/spi_adc.c#L442
github.com/.../spi_adc.c

> ads129x_get_data() only triggers a read from a buffer? No actual peripheral transferring data? > When will it continue; and when will it send data (which I assume it does inside bt_performance_test_write()

It triggers only on when there is a timeout on pipe k_polling or requested number of data was delivered from SPI pipe. I'm not sure what you mean by `No actual peripheral transferring data?`
Anyway when it fetch data from pipe it will transfer them to `bt_performance_test_write` which is wrapper for `bt_gatt_write_without_response`
It's a bit stupid but thats how it was designed in example. I didnt have time to change it too much.
github.com/.../performance_test.c


> And when bt_performance_test_write() is called, what is the length of the data that is being sent?

As I said before it's max len set for single connection event - mostly 251 bytes.
If SPI finish it's data transfer and it's not aligned to 251 bytes I send this remainder.

> Sorry, a lot of unstructured questions? I was reading more and more into your project.

No problem, I really appreciate it.

> So the question is, how often is send_test_ecg_data() called, and how often is bt_performance_test_write() called? Is bt_performance_test_write() called every time send_test_ecg_data() is called, or does it often skip it because of continue; ?

It will be hard to answer for this, because it's constantly changing. Depending on priories I set for threads and ISR. What I can tell for sure is that it's able to pull data from pipe without issue.
I started to suspect that bt_gatt_write_without_response waits for something. I'm not sure what, but when I interrupt it with SPI ISR, this event is lost.
This behavior would explain why synthetic dummy tests are ok. 

[Edvin]

Dumam said:

I'm not sure what you mean by `No actual peripheral transferring data?`

I mean that you are not doing any SPI transactions inside that function, which means that you need to wait for the transaction to finish inside this callback? If so, that will introduce a delay. 

Ok, we have a more similar understanding of what your project does now, which is a good thing

My claim is that bt_performance_test_write() does not care whether the data comes from a buffer of all 0's or a buffer consisting of SPI data. So the lower throughput has to come from elsewhere. 

For debugging purposes, what if you instead of calling bt_performance_test_write(), just add up the length of what you were going to send, and look at what sort of total length/throughput you would have got without actually sending the data? Is it still lower than only sending dummy data without the SPI?

BR,

Edvin