Timer intermittently finishes too soon, rare conflict between app_timer and ble_advertising

[Jake]

Config

• Using NRF52810 on a custom PCB with 32kHz + 32MHz crystals, very close to the reference schematic
• S112 with SDK 14.2.0 in SEGGER Embedded Studio V3.30

A button press from a sleeping state triggers an app_button interrupt which calls ble_advertising_start() followed by app_timer_start() and then nrf_gpio_pin_write() to turn on an LED. The timer ends after 50ms and turns off the LED. Advertising lasts 5 seconds. 

Normal behaviour

This works almost every time as expected, a 50ms LED flash when the button is pressed and 5s of advertising. 

Problem

The problem seems quite rare and I can't forcefully reproduce it because I don't yet understand how it's happening. Around 1 in 50 times (rough estimate) when pressing the button to wake from sleep, the LED will flash for a very short period (you have to hold it up to your eye to see it) and will keep doing short flashes on button presses until advertising stops 5s later. It seems that it will only get into this state when waking from sleep (4uA with 32kHz type sleep) and won't fall into this state by pressing the button if the device is already advertising. 

In this short-lived state where you see very short LED flashes, the advertising seems to work properly but connection attempts fail. The system isn't resetting, all the data is still fine after recovering from this state. Interestingly, if I put the ble_advertising_start() line at the end instead of the start; more often than not, the LED will flash but advertising fails to start completely. 

The problem is really quite hard to reproduce so I wouldn't recommend trying, I'm also unable to share my project. I'm just hoping that someone who knows more about the internals of the SDK might have a better idea of which direction to look to solve this. 

• How can starting advertising cause an app_timer to finish way too early?
• Is this even related to advertising, or does app_timer get itself confused on its own?
• Might this be 32kHz crystal related? 

Thanks for any suggestions in advance :)

[Jørgen Holmefjord]

Hi,

It sounds like what you are experiencing could be related to this issue. There is a new expermimental implementation of app_timer (app_timer2) in SDK 15.x.0, can you try to replace app_timer in your application with this implementation?

The new implementation use the same API, but is much simpler than the old one. You will have to replace the source file app_timer.c with app_timer2.c and drv_rtc.c, both found in components\libraries\timer\experimental. You also need to define the preprocessor symbols APP_TIMER_V2 and APP_TIMER_V2_RTC1_ENABLED.

Best regards,
Jørgen

[Jake]

Hi Jørgen, 

Thanks for that suggestion, certainly seems like it might make a difference. I'm trying to get app_timer2 working in my project but there are all kinds of changes I need to make (there is no nrfx in 14.2). I'll let you know if it works out and mark this as answered sometime this week

Many thanks,

q

[Jake]

I've managed to squeeze in all the new nrfx, hal and log things that app_timer2 depends on and for some reason the timer is lasting about 10x longer than it should now! I'm also getting an NRF_ERROR_NO_MEM error when trying to start a different timer on top of the first one - seems to be nrf_atfifo_item_alloc() inside timer_req_schedule() 

[Jørgen Holmefjord]

Can you upload your sdk_config.h file, and the config/init code you use for app_timer?

[Jake]

Here's my LED flash code using app_timer (stripped out error handling etc.)

Fullscreen ree.c Download

APP_TIMER_DEF(m_flash_timer_id);        /* LED flash duration timer instance */

static const uint8_t m_qt_led_list[QT_LEDS_NUMBER] = QT_LEDS_LIST;

/* ########## Private functions ########## */

static void flash_timeout_handler(void * p_context)
{
    qt_led_off((uint32_t) p_context);
}

/* ########## Initialisation functions ########## */

void qt_led_init(void)
{
    uint32_t i;
    for (i = 0; i < QT_LEDS_NUMBER; ++i)
    {
        nrf_gpio_cfg_output(m_qt_led_list[i]);
        qt_led_off(i);
    }
    
    ret_code_t err_code = app_timer_create(&m_flash_timer_id, APP_TIMER_MODE_SINGLE_SHOT, flash_timeout_handler);
    APP_ERROR_CHECK(err_code);
}

/* ########## Public utility functions ########## */

void qt_led_on(uint32_t led_idx)
{
    nrf_gpio_pin_write(m_qt_led_list[led_idx], QT_LEDS_ACTIVE_STATE ? 1 : 0);
}

void qt_led_off(uint32_t led_idx)
{
    nrf_gpio_pin_write(m_qt_led_list[led_idx], QT_LEDS_ACTIVE_STATE ? 0 : 1);
}

void qt_led_flash_for_ms(uint32_t led_idx, uint32_t timeout)
{
    ret_code_t err_code = app_timer_start(m_flash_timer_id, APP_TIMER_TICKS(timeout), (void *) led_idx);
    qt_led_on(led_idx);
}

and excuse the mess, but here is the sdk_config file. I've just copied in a lot of the defines from SDK15 until my 14.2 project would build with the new NRFX and app_timer2 stuff squashed in. 

config.h

All the RTC and crystal frequency things seem ok so I have no idea what's making it run slow. The call to flash_for_ms happens before the softdevice is initialised, could that be a problem with this new app_timer2? It worked fine with the old one. 

Thanks

[Jørgen Holmefjord]

I can't see any obvious reasons that the timer should run 10x longer. Did you start the LFCLK before app_timer? This is required if the softdevice is not initialized. The NO_MEM error is most likely caused by the OP_QUEUE being too small. Please try increasing APP_TIMER_CONFIG_OP_QUEUE_SIZE. Are you calling the timer start functions from interrupt context? Is there something else running on higher priority in your application that can delay the handling of the interrupts?

[Jake]

This is pretty much the first thing that happens in main() when the device is started. After LOG is initialised, app_timer and gpio is configured and the led_flash_for_ms() happens after. The old app_timer would work like this, regardless of whether the softdevice was enabled or not. 

Seems that when using app_timer2, the end event never actually gets called, so the LED never goes off. The long flash time I was seeing was because something else was disabling the LED much further in the program. 

The V2 timer is failing to run my timeout handler before or after softdevice is enabled, or even if I enable and select LFCLK manually. I've even tried lowering APP_TIMER_CONFIG_IRQ_PRIORITY but it still won't ever trigger my timeout handler for some reason. 

(I'll get to the memory problem after I've got the first part working! OP_QUEUE_SIZE default definitely seems large enough but I'll see if increasing it solves the problem when I get there).

[Jørgen Holmefjord]

Can you share your project? I can help you debug it and try to get it working with app_timer2.

[Jake]

Thanks Jorgen, I'm afraid I can't share the project in its current state, it's almost production firmware now with the exception of this bug! I think what I'm going to do is try the full migration from 14.2 to 15, as I'm not happy with this squashed NRFX into 14.2 and the mess I now have here! I'll get back to you at some point and let you know how it goes, for now I'll mark your first answer as suggested answer