app_timer fires timer w/o waiting if long timer running

[marto]

I'm having this issue with oldish SDK 12 but since I reproduce the issue with SDK 15: I re-used the code from https://devzone.nordicsemi.com/nordic/short-range-guides/b/software-development-kit/posts/application-timer-tutorial with SDK 15.2. 

I modified the example to add a long timer (10 minutes) started at the beginning. If there is inactivity more than 255 seconds, then the first time the single-shot timer is started, it's directly fired.

I added some traces to :

- see events

- see show how the timer is inserted.

Logs:

13:07:35.880325 <info> app: Application timer tutorial example started.
13:07:35.880399 <info> app: 648: 0x200060D4: at_start: 0, to_expire: 19660800 last:0
13:07:41.842139 <info> app: Button1
13:07:41.842201 <info> app: 648: 0x200060B4: at_start: 226187, to_expire: 232741 last:0
13:07:42.044955 <info> app: LED1::toggle()
13:07:42.045018 <info> app: 648: 0x200060B4: at_start: 232741, to_expire: 6554 last:232741
13:07:42.245050 <info> app: LED1::toggle()
13:07:42.245118 <info> app: 648: 0x200060B4: at_start: 239295, to_expire: 6554 last:239295
13:07:42.444565 <info> app: LED1::toggle()
13:07:42.444627 <info> app: 648: 0x200060B4: at_start: 245849, to_expire: 6554 last:245849
13:07:42.646043 <info> app: LED1::toggle()
13:07:42.646118 <info> app: 648: 0x200060B4: at_start: 252403, to_expire: 6554 last:252403
13:07:42.846832 <info> app: LED1::toggle()
13:07:42.846900 <info> app: 648: 0x200060B4: at_start: 258957, to_expire: 6554 last:258957
13:07:43.049107 <info> app: LED1::toggle()
13:07:43.049177 <info> app: 648: 0x200060B4: at_start: 265511, to_expire: 6554 last:265511
13:07:43.138703 <info> app: Button2
13:07:44.178113 <info> app: Button3 (timeout=1000)
13:07:44.178185 <info> app: 648: 0x200060F4: at_start: 302709, to_expire: 69966 last:265511
13:07:45.182614 <info> app: LED2::on()
13:07:46.644688 <info> app: Button3 (timeout=2000)
13:07:46.644752 <info> app: 648: 0x200060F4: at_start: 383632, to_expire: 113691 last:335477
13:07:48.643914 <info> app: LED2::on()
13:12:11.049169 <info> app: Button3 (timeout=3000)
13:12:11.049227 <info> app: 663: 0x200060F4: at_start: 9047471, to_expire: 0 last:449168, delta:8178913
13:12:11.060131 <info> app: LED2::on()

From the logs:

- I waited more that 4 minutes and 15 seconds (i.e. 255 seconds) between last action (that refreshed the m_ticks_latest) and pressing button2 (between 13:07:48 and 13:12:11)

- we can see that single_timer has been fired immediatly at 13:12:11 not waiting for expected timeout of 3 seconds

- It looks that the computation is wrong (to_expire is computed to 0)

Fullscreen main.c Download

/**
 * Copyright (c) 2014 - 2019, Nordic Semiconductor ASA
 *
 * All rights reserved.
 *
 * Redistribution and use in source and binary forms, with or without modification,
 * are permitted provided that the following conditions are met:
 *
 * 1. Redistributions of source code must retain the above copyright notice, this
 *    list of conditions and the following disclaimer.
 *
 * 2. Redistributions in binary form, except as embedded into a Nordic
 *    Semiconductor ASA integrated circuit in a product or a software update for
 *    such product, must reproduce the above copyright notice, this list of
 *    conditions and the following disclaimer in the documentation and/or other
 *    materials provided with the distribution.
 *
 * 3. Neither the name of Nordic Semiconductor ASA nor the names of its
 *    contributors may be used to endorse or promote products derived from this
 *    software without specific prior written permission.
 *
 * 4. This software, with or without modification, must only be used with a
 *    Nordic Semiconductor ASA integrated circuit.
 *
 * 5. Any software provided in binary form under this license must not be reverse
 *    engineered, decompiled, modified and/or disassembled.
 *
 * THIS SOFTWARE IS PROVIDED BY NORDIC SEMICONDUCTOR ASA "AS IS" AND ANY EXPRESS
 * OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES
 * OF MERCHANTABILITY, NONINFRINGEMENT, AND FITNESS FOR A PARTICULAR PURPOSE ARE
 * DISCLAIMED. IN NO EVENT SHALL NORDIC SEMICONDUCTOR ASA OR CONTRIBUTORS BE
 * LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
 * CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE
 * GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
 * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
 * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT
 * OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 *
 */

#include <stdbool.h>
#include "boards.h"
#include "bsp.h"
#include "nrf_drv_gpiote.h"
#include "nrf_log.h"
#include "nrf_log_ctrl.h"
#include "nrf_log_default_backends.h"

#include "app_timer.h"
#include "nrf_drv_clock.h"

static uint32_t timeout = 0;

APP_TIMER_DEF(m_repeated_timer_id);  /**< Handler for repeated timer used to blink LED 1. */
APP_TIMER_DEF(m_single_shot_timer_id);  /**< Handler for single shot timer used to light LED 2. */
APP_TIMER_DEF(m_single_shot_long_timer_id);


/**@brief Timeout handler for the repeated timer.
 */
static void repeated_timer_handler(void * p_context)
{
    NRF_LOG_INFO("LED1::toggle()");
    nrf_drv_gpiote_out_toggle(LED_1);
}

/**@brief Timeout handler for the single shot timer.
 */
static void single_shot_timer_handler(void * p_context)
{
    NRF_LOG_INFO("LED2::on()");
    nrf_drv_gpiote_out_clear(LED_2);
}


/**@brief Timeout handler for the single shot timer.
 */
static void single_shot_long_timer_handler(void * p_context)
{
    NRF_LOG_INFO("long-timer over");
}


/**@brief Create timers.
 */
static void create_timers()
{
    ret_code_t err_code;

    // Create timers
    err_code = app_timer_create(&m_repeated_timer_id,
                                APP_TIMER_MODE_REPEATED,
                                repeated_timer_handler);
    APP_ERROR_CHECK(err_code);
    err_code = app_timer_create(&m_single_shot_timer_id,
                                APP_TIMER_MODE_SINGLE_SHOT,
                                single_shot_timer_handler);
    APP_ERROR_CHECK(err_code);
    err_code = app_timer_create(&m_single_shot_long_timer_id,
                                APP_TIMER_MODE_SINGLE_SHOT,
                                single_shot_long_timer_handler);
    APP_ERROR_CHECK(err_code);
}


/**@brief Function starting the internal LFCLK oscillator.
 *
 * @details This is needed by RTC1 which is used by the Application Timer
 *          (When SoftDevice is enabled the LFCLK is always running and this is not needed).
 */
static void lfclk_request(void)
{
    ret_code_t err_code = nrf_drv_clock_init();
    APP_ERROR_CHECK(err_code);
    nrf_drv_clock_lfclk_request(NULL);
}

/**@brief Button event handler function.
 *
 * @details Responsible for controlling LEDs based on button presses.
 */
void button_event_handler(nrf_drv_gpiote_pin_t pin, nrf_gpiote_polarity_t action)
{
    ret_code_t err_code;

    switch (pin)
    {
    case BUTTON_1:
        // Start repeated timer (start blinking LED).
        err_code = app_timer_start(m_repeated_timer_id, APP_TIMER_TICKS(200), NULL);
        NRF_LOG_INFO("Button1");
        APP_ERROR_CHECK(err_code);
        break;
    case BUTTON_2:
        // Stop the repeated timer (stop blinking LED).
        NRF_LOG_INFO("Button2");
        err_code = app_timer_stop(m_repeated_timer_id);
        APP_ERROR_CHECK(err_code);
        break;
    case BUTTON_3:
        // Start single shot timer which turns on LED2 when it expires.
        // Increase the timeout with 1 second every time.
        timeout += 1000;
        NRF_LOG_INFO("Button3 (timeout=%u)", timeout);
        err_code = app_timer_start(m_single_shot_timer_id, APP_TIMER_TICKS(timeout), NULL);
        APP_ERROR_CHECK(err_code);
        break;
    case BUTTON_4:
        // Turn off LED 2.
        NRF_LOG_INFO("Button4");
        nrf_drv_gpiote_out_set(LED_2);
        break;
    default:
        break;
    }
}


/**@brief Function for initializing GPIO pins.
 */
static void gpio_config()
{
    ret_code_t err_code;

    // Initialize GPIOTE driver.
    err_code = nrf_drv_gpiote_init();
    APP_ERROR_CHECK(err_code);

    // Configure output pins for LEDs.
    nrf_gpio_range_cfg_output(LED_1, LED_2);

    // Set output pins (this will turn off the LEDs).
    nrf_drv_gpiote_out_set(LED_1);
    nrf_drv_gpiote_out_set(LED_2);

    // Make a configuration for input pints. This is suitable for both pins in this example.
    nrf_drv_gpiote_in_config_t in_config = GPIOTE_CONFIG_IN_SENSE_HITOLO(true);
    in_config.pull = NRF_GPIO_PIN_PULLUP;

    // Configure input pins for 4 buttons, all using the same event handler.
    err_code = nrf_drv_gpiote_in_init(BUTTON_1, &in_config, button_event_handler);
    APP_ERROR_CHECK(err_code);
    err_code = nrf_drv_gpiote_in_init(BUTTON_2, &in_config, button_event_handler);
    APP_ERROR_CHECK(err_code);
    err_code = nrf_drv_gpiote_in_init(BUTTON_3, &in_config, button_event_handler);
    APP_ERROR_CHECK(err_code);
    err_code = nrf_drv_gpiote_in_init(BUTTON_4, &in_config, button_event_handler);
    APP_ERROR_CHECK(err_code);

    // Enable input pins for buttons.
    nrf_drv_gpiote_in_event_enable(BUTTON_1, true);
    nrf_drv_gpiote_in_event_enable(BUTTON_2, true);
    nrf_drv_gpiote_in_event_enable(BUTTON_3, true);
    nrf_drv_gpiote_in_event_enable(BUTTON_4, true);
}


/**@brief Function for initializing logging.
 */
static void log_init(void)
{
    ret_code_t err_code = NRF_LOG_INIT(NULL);
    APP_ERROR_CHECK(err_code);

    NRF_LOG_DEFAULT_BACKENDS_INIT();
}


/**@brief Main function.
 */
int main(void)
{
    ret_code_t err_code;

    log_init();
    gpio_config();
    lfclk_request();
    app_timer_init();
    create_timers();

    NRF_LOG_INFO("Application timer tutorial example started.");

    err_code = app_timer_start(m_single_shot_long_timer_id, APP_TIMER_TICKS(10 * 60* 1000), NULL); // 10 minutes
    APP_ERROR_CHECK(err_code);

    // Enter main loop.
    while (true)
    {
        __WFI();
    }
}

 

Fullscreen app_timer.diff Download

diff --git a/components/libraries/timer/app_timer.c b/components/libraries/timer/app_timer.c
index 639a905..1fc49ce 100644
--- a/components/libraries/timer/app_timer.c
+++ b/components/libraries/timer/app_timer.c
@@ -51,6 +51,11 @@
 #include "app_scheduler.h"
 #endif
 
+#include "nrf_log.h"
+#define DBG(fmt, ...) NRF_LOG_INFO("%d: " fmt, __LINE__, ##__VA_ARGS__)
+
+
+
 #define RTC1_IRQ_PRI            APP_TIMER_CONFIG_IRQ_PRIORITY               /**< Priority of the RTC1 interrupt (used for checking for timeouts and executing timeout handlers). */
 #define SWI_IRQ_PRI             APP_TIMER_CONFIG_IRQ_PRIORITY               /**< Priority of the SWI  interrupt (used for updating the timer list). */
 
@@ -640,6 +645,7 @@ static bool list_insertions_handler(timer_node_t * p_restart_list_head)
         {
             p_timer->ticks_to_expire = ticks_diff_get(p_timer->ticks_at_start, m_ticks_latest) +
                                        p_timer->ticks_first_interval;
+            DBG("%p: at_start: %d, to_expire: %d last:%d", (uint32_t)p_timer, p_timer->ticks_at_start, p_timer->ticks_to_expire, m_ticks_latest);
         }
         else
         {
@@ -654,6 +660,7 @@ static bool list_insertions_handler(timer_node_t * p_restart_list_head)
             {
                 p_timer->ticks_to_expire = 0;
             }
+            DBG("%p: at_start: %d, to_expire: %d last:%d, delta:%d", (uint32_t)p_timer, p_timer->ticks_at_start, p_timer->ticks_to_expire, m_ticks_latest, delta_current_start);
         }
 
         p_timer->ticks_at_start       = 0;

I feel that a workaround could be to split my long-running timer (10 minutes) into smaller timers of < 255 (or 127 ??) but I'd rather have a real patch (backportable to SDK12).

Thanks,

Marc.

[Kenneth]

If you are using app_timer with very long timeout. You should know that the longest timeout allowed with PRESCALER = 0 is 256 seconds (< RTC overflow/2). Using longer timeout can give strange results (for instance timeout handlers might execute several times with smaller delays), since likely the timeout counter will wrap around.

[marto]

It's what I thought once but since:

- it usually works with long timers (except in this case)

- I could not see any limitations in documentation nor code

- the code does not enforce it (it seems easy to assert/return an error when the parameter is invalid)

- only the RTC timer uses 24 bits values, interface is 32-bit ticks

I concluded that only the resolution (and app_timer implementation, not interface) would be impacted, not the overall timer values.

To me, the interface is 32-bits ticks which gives (with PRESCALER =0) 36h24m32s (2**32 / 32768).

[Kenneth]

It's a limitation in hardware also, since the RTC hw module features a 24-bit COUNTER (even if the register is 32bits wide). You can find a table here that show PRESCALER vs overflow values:
https://infocenter.nordicsemi.com/topic/com.nordic.infocenter.nrf52832.ps.v1.1/rtc.html?cp=3_1_0_24_1#concept_iwc_1mj_sr 

The problem start once the next scheduled wakeup exceed RTC overflow/2, however as long as you have multiple app_timers running and at least one of them is waking up every <RTC overflow/2 it will work since the app_timer module will wakeup frequently enough. But the safest is to make sure that all app_timers running don't have a wakeup interval longer than 255 seconds (when prescaler = 0).

[marto]

> but I may be wrong.

What do you mean ? Is it regarding the doc or the limitation ? Who could tell ?

[Kenneth]

I was referring to the fact that app_timer does not explicit state this limitation. I removed the text you quote to avoid confusion.