k_timer expiry function firing multiple times in a row

[enukic]

Hi,

I need to use timer in one of my projects.

SDK: nCS 2.3.0

Hardware: nRF52833 DK (1.0.1, 2021.37)

I have built a firmware, based on the beacon example, adding shell , ADC sampling and writing some data to flash.
Now, I want to add timer to submit some work to work queue, to sample ADC periodically.

I used k_timer API before, it worked fine, as far as I can tell. But this time, when I set it up in my code, timer expiry function gets called multiple times (4 times in a row).

Here is a snippet of the code, which is used to set up the timer:

void adc_sampling_work_handler(struct k_work *work)
{
    int16_t adc_mv;

    adc_mv = get_adc_measurement();

    if(adc_mv == m_adc_mv)
    {
        return;         // Don't update
    }

    m_adc_mv = adc_mv;
    cst_adv_data.adc1[0] = (((int16_t)m_adc_mv) >> 8) & 0xFF;
    cst_adv_data.adc1[1] = ((int16_t)m_adc_mv) & 0xFF;

    bt_le_adv_update_data(ad, ARRAY_SIZE(ad),
                    (struct bt_data*)NULL, (size_t)NULL);
}

K_WORK_DEFINE(adc_sampling_work, adc_sampling_work_handler);

static void adc_sampling_tim_handler(struct k_timer *timer_id)
{
    k_work_submit(&adc_sampling_work);
}

void app_timers_init(void)
{
    k_timer_init(&adc_sampling_timer, adc_sampling_tim_handler, NULL);
    k_timer_start(&adc_sampling_timer, K_MSEC(m_dev_cfg.tx_interval), K_MSEC(m_dev_cfg.tx_interval));
}

main
{    
    /* BLE beacon init, etc. */

    app_timers_init();
}

I also tried implementing "work" which submits itself after k_sleep(), but I'm getting the same result.

Also tried building with nCS 2.2.0, same results.

Anyone has an idea what's going on?
Thanks

Emir

[Einarh]

Hello

I also tried implementing "work" which submits itself after k_sleep(), but I'm getting the same result.

This leads me to believe this has nothing to do with k_timer at all, but rather with your expiry function in itself.

Could you show me a code snippet using k_sleep like this that produces the same result?

Best regards,

Einar

[enukic]

Hi,

thanks for the reply.

Sure, here is the implementation I had:

void adc_sampling_work_handler(struct k_work *work)
{
    // int err;
    // int16_t adc_mv;

    // adc_mv = get_adc_measurement();

    // if(adc_mv == m_adc_mv)
    // {
    //     return;         // Don't update
    // }

    // m_adc_mv = adc_mv;
    // cst_adv_data.adc1[0] = (((int16_t)m_adc_mv) >> 8) & 0xFF;
    // cst_adv_data.adc1[1] = ((int16_t)m_adc_mv) & 0xFF;

    // bt_le_adv_update_data(ad, ARRAY_SIZE(ad),
    //                 (struct bt_data*)NULL, (size_t)NULL);
    printk("TEST\n");
    k_sleep(K_MSEC(1000));
    k_work_submit(work);
}

K_WORK_DEFINE(adc_sampling_work, adc_sampling_work_handler);

void app_timers_init(void)
{
    k_work_submit(&adc_sampling_work);
}

I have also tried using k_timer_status_sync but that didn't work either:

void adc_sampling_work_handler(struct k_work *work)
{
    // int err;
    // int16_t adc_mv;

    // adc_mv = get_adc_measurement();

    // if(adc_mv == m_adc_mv)
    // {
    //     return;         // Don't update
    // }

    // m_adc_mv = adc_mv;
    // cst_adv_data.adc1[0] = (((int16_t)m_adc_mv) >> 8) & 0xFF;
    // cst_adv_data.adc1[1] = ((int16_t)m_adc_mv) & 0xFF;

    // bt_le_adv_update_data(ad, ARRAY_SIZE(ad),
    //                 (struct bt_data*)NULL, (size_t)NULL);
    printk("TEST\n");
    k_timer_status_sync(&adc_sampling_timer);
    k_work_submit(work);
}

K_WORK_DEFINE(adc_sampling_work, adc_sampling_work_handler);


void app_timers_init(void)
{
    k_timer_init(&adc_sampling_timer, NULL, NULL);
    k_timer_start(&adc_sampling_timer, K_MSEC(1000), K_MSEC(1000));
    k_work_submit(&adc_sampling_work);
}

I have also tried building and running this program on a nRF52832 DK, but I'm getting the same results.

[Einarh]

Hm this seems very strange to me.

Do you see it triggering four times in a row at each expiry, or do you see the triggers evenly spread out between each expiry?

-Einar

[enukic]

From what I can observe, it's triggered 4 times in a row.
To test this, I have changed the timer and work handlers to print out printk() messages, and this is the result I get (notice the timestamps):

08:01:38:359 -> shell:~$ Test timer expiry
08:01:40:340 -> Test work handler
08:01:40:341 -> Test timer expiry
08:01:40:343 -> Test work handler
08:01:4Test timer expiry
08:01:40:347 -> Test work handler
08:01:40:351 -> Test timer expiry
08:01:40:355 -> Test work handler
08:01:40:359 -> shell:~$ Test timer expiry
08:01:42:340 -> Test work handler
08:01:42:341 -> Test timer expiry
08:01:42:343 -> Test work handler
08:01:4Test timer expiry
08:01:42:347 -> Test work handler
08:01:42:351 -> Test timer expiry
08:01:42:355 -> Test work handler
08:01:42:359 -> shell:~$ Test timer expiry
08:01:44:340 -> Test work handler
08:01:44:341 -> Test timer expiry
08:01:44:343 -> Test work handler
08:01:4Test timer expiry
08:01:44:347 -> Test work handler
08:01:44:351 -> Test timer expiry
08:01:44:355 -> Test work handler
08:01:44:359 -> shell:~$ Test timer expiry
08:01:46:340 -> Test work handler
08:01:46:341 -> Test timer expiry
08:01:46:343 -> Test work handler
08:01:4Test timer expiry
08:01:46:347 -> Test work handler
08:01:46:351 -> Test timer expiry
08:01:46:355 -> Test work handler
08:01:46:359 -> shell:~$ Test timer expiry
08:01:48:340 -> Test work handler
08:01:48:341 -> Test timer expiry
08:01:48:343 -> Test work handler
08:01:4Test timer expiry
08:01:48:347 -> Test work handler
08:01:48:351 -> Test timer expiry
08:01:48:355 -> Test work handler
08:01:48:359 -> shell:~$ Test timer expiry
08:01:50:340 -> Test work handler
08:01:50:341 -> Test timer expiry
08:01:50:343 -> Test work handler
08:01:5Test timer expiry
08:01:50:347 -> Test work handler
08:01:50:351 -> Test timer expiry
08:01:50:355 -> Test work handler
08:01:50:359 -> shell:~$ Test timer expiry
08:01:52:340 -> Test work handler
08:01:52:341 -> Test timer expiry
08:01:52:343 -> Test work handler
08:01:5Test timer expiry
08:01:52:347 -> Test work handler
08:01:52:351 -> Test timer expiry
08:01:52:355 -> Test work handler
08:01:52:359 -> shell:~$

Also, just now, I have noticed that CONFIG_LOG_MODE_DEFERRED=n that I have set in the proj.conf is not applied to the build .config.
So I added CONFIG_LOG_MODE_IMMEDIATE=y to the proj.conf as well, and it did reduce the number of "triggers" to 2, so instead I'm getting: (I have commented the timer handler printk())

11:19:52:870 -> shell:~$ Test work handler
11:19:5Test work handler
11:19:53:869 -> shell:~$ Test work handler
11:19:5Test work handler
11:19:54:870 -> shell:~$ Test work handler
11:19:5Test work handler
11:19:55:870 -> shell:~$ Test work handler
11:19:5Test work handler
11:19:56:870 -> shell:~$ Test work handler
11:19:5Test work handler
11:19:57:869 -> shell:~$ Test work handler
11:19:5Test work handler
11:19:58:869 -> shell:~$ Test work handler
11:19:5Test work handler
11:19:59:870 -> shell:~$ Test work handler
11:20:0Test work handler
11:20:00:870 -> shell:~$ Test work handler
11:20:0Test work handler
11:20:01:870 -> shell:~$ Test work handler
11:20:0Test work handler
11:20:02:870 -> shell:~$ Test work handler
11:20:0Test work handler
11:20:03:869 -> shell:~$ Test work handler

Could this just be a logger issue? The timer interval is 1000ms, by the way.

[Einarh]

Hi

I tried reproducing your issue, but I don't get duplicate messages.

Could you share your prj.conf?

Also, if you make a simple variable that you increment in your event handler, you can know if the event happens multiple times or if it is just logged multiple times.

-Einar

[enukic]

Hi Einar,

Sure, here is my prj.conf

CONFIG_BT=y
CONFIG_BT_DEBUG_LOG=y
CONFIG_BT_DEVICE_NAME="Test beacon"
CONFIG_BT_PERIPHERAL=y
CONFIG_BT_LL_SW_SPLIT=y
CONFIG_BT_DEVICE_APPEARANCE=833
CONFIG_BT_CTLR_ADVANCED_FEATURES=n
CONFIG_BT_CTLR_CONN_RSSI=y
CONFIG_BT_CTLR_TX_PWR_DYNAMIC_CONTROL=y

# Enable Shell and disable default commands
CONFIG_SHELL=y
CONFIG_CLOCK_CONTROL_NRF_SHELL=n
CONFIG_SHELL_PROMPT_UART="shell:~$ "
CONFIG_SHELL_HELP=y
CONFIG_SHELL_STATS=n
CONFIG_SHELL_CMDS=n
CONFIG_KERNEL_SHELL=n
CONFIG_SHELL_LOG_LEVEL_INF=n
CONFIG_DEVICE_SHELL=n
CONFIG_DEVMEM_SHELL=n
CONFIG_LOG_CMDS=n
CONFIG_LOG_BACKEND_UART=y
CONFIG_LOG_BACKEND_RTT=n
CONFIG_LOG=y
CONFIG_LOG_PRINTK=y
CONFIG_PRINTK=y

# Enable Flash
CONFIG_FLASH=y
CONFIG_FLASH_PAGE_LAYOUT=y
CONFIG_MPU_ALLOW_FLASH_WRITE=y
CONFIG_SOC_FLASH_NRF_EMULATE_ONE_BYTE_WRITE_ACCESS=y
CONFIG_FLASH_SHELL=n

# Enable ADC
CONFIG_ADC=y
CONFIG_ADC_SHELL=n

Also, I did try incrementing a variable, the first time I encountered this, and I retried now as well. The variable is incremented twice in a row, on every timer expiry for me.

I also tested this with the shell_module sample, and I had the same issue there. I only modified the timer expiry handler in that example.

Best regards

Emir

[Einarh]

Ok so when I copy your prj.conf I get the same behavior as you.

But if I simply remove CONFIG_LOG_PRINTK=y and CONFIG_PRINTK=y, then I no longer get any duplicate messages.

This is definitely an issue with how the logging is set up, I suggest you go through your prj.conf file and make sure you know what each line actually does.

-Einar

[enukic]

Thanks for the support Einarh It works now.

For me, removing CONFIG_LOG_PRINTK=y and CONFIG_PRINTK=y didn't work, I still had the issue. But I did go through the prj.conf and noticed CONFIG_LOG_BACKEND_UART=y. I set it to n, and the issue was gone. (I had to disable deferred logging as well).

Here is the resulting .conf file for reference:

CONFIG_BT=y
CONFIG_BT_DEBUG_LOG=y
CONFIG_BT_DEVICE_NAME="Test beacon"
CONFIG_BT_PERIPHERAL=y
CONFIG_BT_LL_SW_SPLIT=y
CONFIG_BT_DEVICE_APPEARANCE=833
CONFIG_BT_CTLR_ADVANCED_FEATURES=n
CONFIG_BT_CTLR_CONN_RSSI=y
CONFIG_BT_CTLR_TX_PWR_DYNAMIC_CONTROL=y

# Enable Shell and disable default commands
CONFIG_SHELL=y
CONFIG_CLOCK_CONTROL_NRF_SHELL=n
CONFIG_SHELL_PROMPT_UART="shell:~$ "
CONFIG_SHELL_HELP=y
CONFIG_SHELL_STATS=n
CONFIG_SHELL_CMDS=n
CONFIG_KERNEL_SHELL=n
CONFIG_SHELL_LOG_LEVEL_INF=n
CONFIG_DEVICE_SHELL=n
CONFIG_DEVMEM_SHELL=n
CONFIG_LOG_CMDS=n
CONFIG_LOG_BACKEND_UART=n
CONFIG_LOG_BACKEND_RTT=n
CONFIG_LOG=y
# CONFIG_LOG_PRINTK=y
# CONFIG_PRINTK=y
CONFIG_LOG_MODE_DEFERRED=n
CONFIG_LOG_MODE_IMMEDIATE=y

# Enable Flash
CONFIG_FLASH=y
CONFIG_FLASH_PAGE_LAYOUT=y
CONFIG_MPU_ALLOW_FLASH_WRITE=y
CONFIG_SOC_FLASH_NRF_EMULATE_ONE_BYTE_WRITE_ACCESS=y
CONFIG_FLASH_SHELL=n

# Enable ADC
CONFIG_ADC=y
CONFIG_ADC_SHELL=n

Thanks again for the support.
All the best.

Emir.