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

[enukic]

I just read my post again, and maybe I didn't explain well enough what's going on.

The expiry functions is called 4 times on each expiry (the timer is a repeating timer).

[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.