Attachments (0)
Nordic Case Info
  • Case ID: 290625
Options

performance issue with multi threadn in ncs with nrf52832

ziv123

hello Nordic

i am working with nrf52832, with zephyr, ncs v1.7.1,

the device has a sensor that sample at 26khz each sample is 3 channels of 2 bytes data. the sensor use spi1 and has high thread priority (cooperative) the samples are then stream via a double buffer to the flash which uses spi2.

when tying to write a page (256 bytes) to the flash at a test in the beginning of the app it take 1ms to write that page but when trying to write within the app, while the other sensor is sampling, it takes 3ms and also i get a BUS FAULT. here is the log:

Fullscreen
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
[00000018] <err> os: ***** BUS FAULT *****
[00000018] <err> os: Unstacking error
[00000018] <err> os: ***** HARD FAULT *****
[00000018] [1;31m<err> os: Fault escalation (see below)
[00000018] <err> os: ***** BUS FAULT *****
[00000018] <err> os: Precise data bus error
[00000018] <err> os: BFAR Address: 0xfe80fec0
[00000018] <err> os: r0/a1: 0x2000bef0 r1/a2: 0xfe80fec0 r2/a3: 0xfe80ff28
[00000018] <err> os: r3/a4: 0x2000beef r12/ip: 0xfa000000 r14/lr: 0x00016d79
[00000018] <err> os: xpsr: 0x81000005
[00000018] <err> os: s[ 0]: 0x00000000 s[ 1]: 0x00000000 s[ 2]: 0x00000000 s[ 3]: 0x00000000
[00000018] <err> os: s[ 4]: 0x00000000 s[ 5]: 0x00000000 s[ 6]: 0x00000000 s[ 7]: 0x00000000
[00000018] <err> os: s[ 8]: 0x00000000 s[ 9]: 0x00000000 s[10]: 0x00000000 s[11]: 0x00000000
[00000018] <err> os: s[12]: 0x00000000 s[13]: 0x00000000 s[14]: 0x00000000 s[15]: 0x00000000
[00000018] <err> os: fpscr: 0x20001d78
[00000018] <err> os: Faulting instruction address (r15/pc): 0x0003ef10
[00000018] <err> os: >>> ZEPHYR FATAL ERROR 0: CPU exception on CPU 0
[00000018] <err> os: Fault during interrupt handling
[00000018] <err> os: Current thread: 0x20003210 (unknown)
[00000018] <err> fatal_error: Resetting system
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

now i do have in the app another driver that uses spi (at the same time (getting samples and writing samples to flash), but it uses a different instance of spi so i don't see why it shell create such a delay .. here is my complete .dts file:

Fullscreen
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
// Copyright (c) 2022 Nordic Semiconductor ASA
// SPDX-License-Identifier: Apache-2.0
/dts-v1/;
#include <nordic/nrf52832_qfaa.dtsi>
/ {
model = "halo_ep2";
compatible = "halo-ep2";
chosen {
zephyr,sram = &sram0;
zephyr,flash = &flash0;
zephyr,code-partition = &slot0_partition;
nordic,pm-ext-flash = &augu_flash_is25lp128;
};
sensors_on: sensors_on_node {
compatible = "augury,gpio-power";
power_gpios = <&gpio0 22 GPIO_ACTIVE_LOW>;
label = "SENSORS_ON";
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

(running the app on another board with nrd52840, with nand flash that writes 2k each time, works well, so i don't know if it is a performance issue or something else.. i will also mention that the RAM take on the nrf52832 with zephyr and all is high:

Fullscreen
1
2
3
4
5
6
7
8
9
10
[567/572] Linking C executable zephyr/zephyr.elf
Memory region Used Size Region Size %age Used
FLASH: 253604 B 419328 B 60.48%
SRAM: 60282 B 64 KB 91.98%
IDT_LIST: 0 GB 2 KB 0.00%
[568/572] Generating zephyr/mcuboot_primary_app.hex
[569/572] Generating zephyr/mcuboot_primary.hex
[570/572] Generating ../../zephyr/app_update.bin, ../../zephyr/app_signed.hex, ../../zephyr/app_test_update.hex, ../../zephyr/app_moved_test_update.hex
[571/572] Generating ../../zephyr/dfu_application.zip
[572/572] Generating zephyr/merged.hex
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

any idea why i get the BUS FAULT ? 

p.s. i don't know if it has any affect but the page data is saved in a heap section previously allocated like so

Fullscreen
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
K_HEAP_DEFINE(my_heap, 3072); // 256*3*2 = 1536 + safe buffer
int mem_heap_alloc(int size, struct k_mem_block *block)
{
block->data = NULL;
block->data = k_heap_alloc(&my_heap, size, K_NO_WAIT);
if (block->data == NULL)
{
return -ENOMEM;
}
return 0;
}
void mem_heap_free(struct k_mem_block *block)
{
k_heap_free(&my_heap, block->data);
}
and the call is for
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

the other question i will leave for now it is also regarding a try to improve the current spi_nor_write function but anyhow it will not solve the 3ms issue and if it will remain on 1ms per page write as seen in the first test then we will be ok 

we think it is a performance issue (which we don't see when the same code runs on nrf52840 with a nand flash, which also writes 2k each time and not 256 pages)

one of the possible solutions is to change the api of the sensor driver so instead of using many time fetch and get, to get one api for fetching a pointer to a buffer of the samples stored in the driver, another idea is to have the driver use easy dma to put the samples to a buffer in memory with an interrupt after reaching 256 bytes, and then write to flash from this buffer. any idea if there is some support for one of this operations in zephyr/ncs ?,

any ideas as for which is better ?

any ideas of beast way to do preferred one ?

hope to read from you soon

best regards

Ziv

Parents
  • 0

    Hi Ziv

    How are you reading the sensor over SPI? 

    Are you using the normal or the async driver?

    Running an SPI transaction every ~38us is not ideal, but it is very odd that the 256 byte write should slow down when it is running on a separate SPI bus. At the lower levels the SPI peripheral should use DMA, which means the 256 byte transaction should go through in the background (unfortunately it would have to be split in 2 transactions, since the maximum length of one transaction is 255 bytes in the nRF52832) . 

    The nRF52840 allows you to send much longer packets in a single transaction, which might be why it is working better. 

    I agree that sampling the sensor in a more automated way would be a better approach. The SPIM module in the nRF52 devices support a so called list feature, which allows you to queue a list of transactions and have them triggered in the background from a hardware event (such as a timer compare event). In this setup you could have the SPIM module run several operations in the background until you have filled the flash buffer, and run the processing and SPI interaction at a less frequent rate. 

    You will need to use the nrfx_spim driver directly in this case, since the generic Zephyr SPI driver doesn't support the list feature of the SPIM peripheral. 

    Best regards
    Torbjørn

  • 0 in reply to ovrebekk

    hi overbekk

    ovrebekk said:
    How are you reading the sensor over SPI?

    yes spi1, the flash works on spi2

    ovrebekk said:
    Are you using the normal or the async driver?

    i have CONFIG_SPI_ASYNC=y in my .config file under the build/zephyr, so async is how i work.

    ovrebekk said:
    In this setup you could have the SPIM module run several operations in the background until you have filled the flash buffer

    maybe i misunderstood your intended use, but 1. i need to be writing while sampling for a second so if my buffers is filling up faster then the are dequeued then its not good enough, also since nrf52832 have 1/4 the ram the nrf52840 has, i need to find a way to reduce my buffers and not put more cause i am already around 90% ram take. 2. there is some unclear issue to work with spim in the flash cause of  CONFIG_SOC_NRF52832_ALLOW_SPIM_DESPITE_PAN_58=y,

    it fails here (on the spi_nrfx_spim.c file on the ncs (1.7.1 v): 

    Fullscreen
    1
    2
    3
    4
    5
    6
    7
    /* This SPIM driver is only used by the NRF52832 if
    SOC_NRF52832_ALLOW_SPIM_DESPITE_PAN_58 is enabled */
    if (IS_ENABLED(CONFIG_SOC_NRF52832) &&
    (xfer.rx_length == 1 && xfer.tx_length <= 1)) {
    LOG_WRN("Transaction aborted since it would trigger nRF52832 PAN 58");
    error = -EIO;
    }
    XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

    i had to change to spi

    ovrebekk said:
    Running an SPI transaction every ~38us is not ideal,

    the 38us spi call is called via ppi and i was thinking that what slows the flash page write is not the spi itself but available cpu and ram .. but i am not sure anymore and the coming questions are about that: 

    1. i sometimes get this error, and i wonder if it is related to the 90% ram take or is it something else ??

    Fullscreen
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    [00000078] <err> spi_nrfx_spi: chunk_length - 4
    [00000078] <err> spi_nrfx_spi: chunk_length - 256
    [00000078] <err> spi_nrfx_spi: chunk_length - 0
    [00000078] <err> os: ***** MPU FAULT *****
    [00000078] <err> os: Stacking error (context area might be not valid)
    [00000078] <err> os: r0/a1: 0xbc1c36a8 r1/a2: 0xfcb9b13f r2/a3: 0x00000000
    [00000078] <err> os: r3/a4: 0x20007080 r12/ip: 0x00000010 r14/lr: 0x00000000
    [00000078] <err> os: xpsr: 0x81000000
    [00000078] [1;31m<err> os: s[ 0]: 0x00000000 s[ 1]: 0x00000000 s[ 2]: 0x00000000 s[ 3]: 0x00000000
    [00000078] <err> os: s[ 4]: 0x00000000 s[ 5]: 0x00000000 s[ 6]: 0x00000000 s[ 7]: 0x00000000
    [00000078] <err> os: s[ 8]: 0x00000000 s[ 9]: 0x00000000 s[10]: 0x00000000 s[11]: 0x00000000
    [00000078] <err> os: s[12]: 0x00000000 s[13]: 0x00000000 s[14]: 0x00000000 s[15]: 0x00000000
    [00000078] <err> os: fpscr: 0x0000dd9e
    [00000078] <err> os: Faulting instruction address (r15/pc): 0x0003efe6
    [00000078] <err> os: >>> ZEPHYR FATAL ERROR 2: Stack overflow on CPU 0
    [00000078] <err> os: Current thread: 0x20003210 (unknown)
    [00000079] <err> fatal_error: Resetting system
    *** Booting Zephyr OS build v2.6.99-ncs1-1 ***
    XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

    2. i used ppk with nrf connect power manager desktop application to monitor some gpios and this is the outcome 

    (line 0 - iis3dwb sensor int1 

    line 3 - flash spi chip select 

    line 2 - gpio(0,26) which is up at the beginning of 'spi_nor_cmd_addr_write(...)' and down before the return from it.

    line 4 - gpio(0,27) - the flash_write api function ( 'spi_nor_write(...) ' ), gpio is up at entry and down before return.

    as can be seen in the following code parts:

    Fullscreen
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    /* i dismissed some 'if's in the function them seems not so importent in my case
    static int spi_nor_write(const struct device *dev, off_t addr, const void *src, size_t size)
    {
    int ret = 0;
    uint32_t start_time_ms, end_time_ms;
    static int counter = 0;
    gpio_pin_set(gpio_dev_blue, 27, 1);
    acquire_device(dev);
    while (size > 0) {
    size_t to_write = size;
    /* Don't write more than a page. */
    if (to_write >= page_size) {
    to_write = page_size;
    }
    /* Don't write across a page boundary */
    if (((addr + to_write - 1U) / page_size)
    XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

    (after i moved the ' spi_nor_wait_until_ready(dev); ' from its original place to just before the ' spi_nor_cmd_write(dev, SPI_NOR_CMD_WREN); '  it did go faster but still i see there is a long delay between first read of the flash ready state to the second one, almost 1ms which is a lot in my case .. so why is it and how can i reduce it ??

    3. spi speed is set to 8mhz so passing 256 bytes should take around 250us but, looking at the nrf ppk image above, it looks like it actually takes almost 1ms for chip select to go back up..  what can cause this delay ? the flash itself can work up to 133mhz so it should not be the source for the delay

    4. going in to the  ' spi_nrfx_spi.c ' and ' spi_context.h ' for the implementation of the ' transceive(...) ' i don't understand how the ' transfer_next_chunk( ..) '  is called twice and if i understand it correct then the event handler when first spi is done calls it again, but do no check the count there only later after some if's 

    which also brings to to the efficiency question we have double calls with chunk 0 and chunk 1 for simple WREN command instead of only one dive into functions ? and the "count check" also seems wasteful sorry to say again if i understood it right then a lot of operations can be saved by checking it earlier

    and i wonder if instead of having this structure :

    Fullscreen
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    struct spi_buf spi_buf[2] = {
    {
    .buf = buf,
    .len = 1,
    },
    {
    .buf = data,
    .len = length
    }
    };
    XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

    ,which do save coping of the data to one buffer, is actually more efficient then having one spi_buf struct ? so instead of having a chunk of 4 and another chunk of 256 bytes with 2 separate spi calls, i will have one with 260 bytes ?

    5. in the following function in the spi_context.h file:

    Fullscreen
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    static inline int spi_context_wait_for_completion(struct spi_context *ctx)
    {
    int status = 0;
    uint32_t timeout_ms;
    timeout_ms = MAX(ctx->tx_len, ctx->rx_len) * 8 * 1000 /
    ctx->config->frequency;
    timeout_ms += CONFIG_SPI_COMPLETION_TIMEOUT_TOLERANCE;
    #ifdef CONFIG_SPI_ASYNC
    if (!ctx->asynchronous) {
    if (k_sem_take(&ctx->sync, K_MSEC(timeout_ms))) {
    LOG_ERR("Timeout waiting for transfer complete");
    return -ETIMEDOUT;
    }
    status = ctx->sync_status;
    }...
    XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

    i see that  CONFIG_SPI_COMPLETION_TIMEOUT_TOLERANCE=200ms by default, what should happen if i change it to '0' and is that what maybe slows the re-checking of the 'is flash ready' read command ?  also maybe i am missing something but 8000/8000000 (8Mhz = 8000000) will always come out as '0' cause 'timeout_ms' is not a double or float am i wrong ?

    6. i tried to improve the - spi_nor_cmd_addr_write(dev, opcode, addr, src, length)

    with my own specific program page function: 

    p.s. also tried to implement a page program leaner function instead of the  ' spi_nor_cmd_addr_write '  which is here

    Fullscreen
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    static int augu_flash_page_program(const struct device *const dev, uint32_t addr, const void* data, size_t data_length)
    {
    const struct spi_nor_config *const driver_cfg = dev->config;
    uint8_t buf[4] = { SPI_NOR_CMD_PP, 0, 0, 0 };
    struct spi_buf spi_buf[2] = {
    {
    .buf = buf,
    .len = 4,
    },
    {
    .buf = data,
    .len = data_length,
    }
    };
    union {
    uint32_t u32;
    uint8_t u8[4];
    } addr32 = {
    XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

    but it actually took longer time which i can't understand why ?

     

    sorry it is a long question but i am really trying to get to the bottom of it and see how i can improve and maybe even change configurations to use the spi_nrfx_spi driver in a better way or if i have a way to make modification without changing the ncs or rewriting an spi driver myself (which i don't want to do)

    hope to read from you soon  

    best regards

    Ziv

  • 0 in reply to ziv123

    You'll need to provide an .elf file via the -e switch:

    Håkon Alseth said:
    c:\path\to\gnuarmemb\bin\arm-none-eabi-addr2line -e zephyr\zephyr.elf 0xFAULTING_ADDRESSES

     

    Cheers,

    Håkon

  • 0 in reply to Håkon Alseth

    unfortunately the outcome does not help to find where it fails in my part of the app code

     

    Fullscreen
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    // Cases:
    // 1) RdOff <= WrOff => Space until wrap-around is sufficient
    // 2) RdOff <= WrOff => Space after wrap-around needed (copy in 2 chunks)
    // 3) RdOff < WrOff => No space in buf
    // 4) RdOff > WrOff => Space is sufficient
    // 5) RdOff > WrOff => No space in buf
    //
    // 1) is the most common case for large buffers and assuming that J-Link reads the data fast enough
    //
    pData = (const char *)pBuffer;
    pRing = (SEGGER_RTT_BUFFER_UP*)((char*)&_SEGGER_RTT.aUp[BufferIndex] + SEGGER_RTT_UNCACHED_OFF); // Access uncached to make sure we see changes made by the J-Link side and all of our changes go into HW directly
    RdOff = pRing->RdOff;
    WrOff = pRing->WrOff;
    if (RdOff <= WrOff) { // Case 1), 2) or 3)
    Avail = pRing->SizeOfBuffer - WrOff - 1u; // Space until wrap-around (assume 1 byte not usable for case that RdOff == 0)
    if (Avail >= NumBytes) { // Case 1)?
    CopyStraight:
    pDst = (pRing->pBuffer + WrOff) + SEGGER_RTT_UNCACHED_OFF;
    memcpy((void*)pDst, pData, NumBytes);
    RTT__DMB(); // Force data write to be complete before writing the <WrOff>, in case CPU is allowed to change the order of memory accesses
    pRing->WrOff = WrOff + NumBytes;
    XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

  • 0 in reply to ziv123

    Hi,

     

    Could you share your logging configuration?

    With SEGGER RTT, you should have the logging backend in CONFIG_LOG_MODE_DEFERRED, and not LOG_IMMEDIATE. This is to ensure that logging happens in its own thread and not in-place (ie. when you call the printk or LOG_*("some log entry");)

     

    Kind regards,

    Håkon

  • 0 in reply to Håkon Alseth

    hi 

    specifically the config you mentioned is set as you suggested

    this is my complete .config file:

    Fullscreen
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    14
    15
    16
    17
    18
    19
    20
    21
    CONFIG_GPIO=y
    CONFIG_SPI=y
    # CONFIG_I2C is not set
    # CONFIG_KSCAN is not set
    # CONFIG_WIFI is not set
    # CONFIG_FT800 is not set
    # CONFIG_ADC_LMP90XXX is not set
    # CONFIG_ADC_MCP320X is not set
    # CONFIG_MODEM is not set
    # CONFIG_BT_HCI_ACL_FLOW_CONTROL is not set
    # CONFIG_BT_HCI_VS_EXT is not set
    CONFIG_BOARD="halo_ep2"
    CONFIG_BT_CTLR=y
    CONFIG_FLASH_25LP128=y
    # CONFIG_FLASH_TESTS is not set
    CONFIG_SOC="nRF52832_QFAA"
    CONFIG_SOC_SERIES="nrf52"
    CONFIG_NUM_IRQS=39
    CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC=32768
    CONFIG_WATCHDOG=y
    CONFIG_HEAP_MEM_POOL_SIZE=4096
    XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

    hope to read you soon 

    best regards

    Ziv

  • 0 in reply to ziv123

    Hi Ziv,

     

    Is it still the logger thread that faults with MPU fault? If yes, then just double/triple the stack size of the logger thread to see if this helps. I see that your segger rtt buffer is quite large, which again will take a chunk out of the logger thread.

     

    Kind regards,

    Håkon

Reply
  • 0 in reply to ziv123

    Hi Ziv,

     

    Is it still the logger thread that faults with MPU fault? If yes, then just double/triple the stack size of the logger thread to see if this helps. I see that your segger rtt buffer is quite large, which again will take a chunk out of the logger thread.

     

    Kind regards,

    Håkon

Children
Terms of service