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]

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.