possible app_timer race condition SDK 14.0

[Allen]

Hello,

We are experiencing 2 different but related app_timer failure conditions.

1. app_timer_create() returns NRF_ERROR_INVALID_STATE
   
   
2. app_timer_start() does not return an error but the timer does not start
   
   

According to the documentation, both of these failure conditions are caused by app_timer_id_t being in the "running" state. We created a app_timer_pool.c module which manages a pool of timers. This has been working flawlessly for 4 years. If try to restart a running timer. The current timer is stopped. A new timer is retrieved from the pool, configured and started.

I have instrumented the code to monitor for various resource issues. Everything looks good.

 0> Stack: max used=1872 remaining=2224
 0> schedule: state=23, index=6, exec_state=1, residual=0
 0> timers: max=3, pool: cur=7,max=12  eventq: max=9

• 3K stack configured, max used 1872 bytes
• APP_TIMER_CONFIG_OP_QUEUE_SIZE 10, monitor reports max used = 3
• APP_SCHED_INIT(EVENT_SIZE, 32), monitor reports max used = 9
• APP_TIMER_POOL_SIZE 15, monitor reports max used = 12, currently using 7

The timer pool app_timer_create() 15 timers at startup. Starting a timer allocates a free timer from the pool, configures and starts it. Stopping a timer calls app_timer_stop() and then returns the timer to the pool.

The log demonstrates app_timer_start(), not actually starting the timer. You can see the timer was Taken from the pool but since it is not running the application stops.

 0> ReleaseTimer ID 11
 0> 0:08:14.108  RAMPING STOP RAMPING -> IDLE
 0> 0:08:14.108  STIM EVENT: RAMP STOP DONE 
 0> TakeTimer ID 12
 0> ReleaseTimer ID 12
 0> 0:08:14.220  STIM EVENT: DISCHARGE DONE 
 0> 0:08:14.220  STIM STATE: SCHEDULED IDLE
 0> 0:08:14.221  SCHEDULE EVENT: STIM RUNNING -> STIM START
 0> 0:08:14.221  Schedule started: residual=x00002800, stop=x0007E0E3, now=x0007B8E3
 0> 0:08:14.222  schedule_stim_start_state_event_handler start timer
 0> TakeTimer ID 13
 0> 0:08:14.222  SCHEDULE STATE: STIM RUN
 0> 0:08:14.300  ADV: Sys=FFFFFFFF Dev=1 VBat=3897 Amp={25 63 63 63} Sched=17/12 Err=00 Col=02 Prg=2 Ins=1 Post=2 Stim=0 LowP=0 LowB=0 Sess=1 Buzz=1
 0> 0:08:15.222  schedule_timer_handler RUNNING
 0> 0:08:15.662  STIM EVENT: STIM SETUP STARTED 
 0> Program dequeued
 0> Schedule IDLE started
 0> 0:08:24.222  SCHEDULE EVENT: TIMEOUT -> STIM RUN
 0> Schedule: Starvation_period[0]=50
 0> Schedule: Starvation_period[1]=40
 0> Schedule: Starvation_period[2]=30
 0> Schedule: Starvation_period[3]=20
 0> Schedule: Starvation_period[4]=10
 0> Schedule: Starvation_period[5]=0
 0> Schedule: Starvation_period[6]=150
 0> Schedule: Starvation_period[7]=140
 0> Schedule: Starvation_period[8]=130
 0> Schedule: Starvation_period[9]=120
 0> Schedule: Starvation_period[10]=110
 0> Schedule: Starvation_period[11]=100
 0> Schedule: max_starve_time=0 sec
 0> 0:08:24.224  STIM EVENT: STOP (3)
 0> Selected Program=3
 0> Program queued, ID=3
 0> Program queued, ID=3
 0> 0:08:24.225  STIM STATE: CONNECTED IDLE
 0> Program queued, ID=3
 0> Program change request during program startup, queued=3
 0> Next Program=3
 0> Current program set to committed program 3
 0> 0:08:24.234  STIM EVENT: START 
 0> MRU program ID=3
 0> Program dequeued
 0> 0:08:24.241  Auto timer stopped
 0> 0:08:24.242  STIM STATE: STIM REQUESTED
 0> 0:08:24.263  ADV: Sys=FFFFFFFF Dev=1 VBat=3868 Amp={25 63 63 63} Sched=17/12 Err=00 Col=02 Prg=3 Ins=1 Post=2 Stim=2 LowP=0 LowB=0 Sess=1 Buzz=1
 0> 0:08:25.386  STIM EVENT: STIM SETUP STARTED 
 0> Program dequeued
 0> Stim setup started, current=3, queued=255
 0> 0:08:25.386  STIM STATE: RAMP TO TARGET
 0> 0:08:25.387  RAMPING IDLE -> STARTING
 0> TakeTimer ID 14
 0> 0:08:25.457  ADV: Sys=FFFFFFFF Dev=1 VBat=3868 Amp={25 63 63 63} Sched=17/12 Err=00 Col=02 Prg=3 Ins=1 Post=2 Stim=3 LowP=0 LowB=0 Sess=1 Buzz=1
 0> Stack: max used=1872 remaining=2224
 0> schedule: state=23, index=6, exec_state=1, residual=0
 0> timers: max=3, pool: cur=7,max=12  eventq: max=9
 0> Stack: max used=1872 remaining=2224

# Logging stopped @ 09 Apr 2020 15:24:06

Notes:
1. Changed timer to use app_scheduler for callbacks
2. Enabled app_scheduler monitor. Max queue size 9. Allocated size 32.
3. No INVALID_STATE errors in this log.
4. Fails starting the stimulation ramp timer.

For the app_timer_create() returning NRF_ERROR_INVALID_STATE, I was able to add code to continue and get the next timer in the pool. Invariably the log would show the "running" timer being used sometime in the future. Unfortunately there is no error indication in the app_timer_start() case.

Log of allocate and free only.

 0> TakeTimer ID 18
 0> ReleaseTimer ID 18
 0> TakeTimer ID 19
 0> ReleaseTimer ID 19
 0> TakeTimer ID 0
 0> ReleaseTimer ID 0
 0> TakeTimer ID 2
 0> ReleaseTimer ID 2
 0> TakeTimer ID 4
 0> TakeTimer ID 5
 0> TakeTimer ID 7
 0> TakeTimer ID 8
 0> TakeTimer ID 9
 0> TakeTimer ID 11
 0> ReleaseTimer ID 8
 0> ReleaseTimer ID 7
 0> TakeTimer ID 12
 0> TakeTimer ID 13
 0> ReleaseTimer ID 13
 0> ReleaseTimer ID 9
 0> ReleaseTimer ID 11
 0> TakeTimer ID 14
 0> ReleaseTimer ID 14
 0> ReleaseTimer ID 4
 0> TakeTimer ID 15
 0> ReleaseTimer ID 15
 0> TakeTimer ID 16
 0> ReleaseTimer ID 16
 0> TakeTimer ID 17
 0> ReleaseTimer ID 17
 0> ReleaseTimer ID 12
 0> TakeTimer ID 18
 0> ReleaseTimer ID 18
 0> TakeTimer ID 19
 0> TakeTimer ID 0
 0> ReleaseTimer ID 0
 0> TakeTimer ID 2
 0> ReleaseTimer ID 19
 0> TakeTimer ID 4
 0> ReleaseTimer ID 4
 0> TakeTimer ID 7
 0> ReleaseTimer ID 2
 0> TakeTimer ID 8
 0> ReleaseTimer ID 8
 0> TakeTimer ID 9
 0> ReleaseTimer ID 9
 0> TakeTimer ID 11
 0> ReleaseTimer ID 11
 0> ReleaseTimer ID 7
 0> TakeTimer ID 12
 0> ReleaseTimer ID 12
 0> TakeTimer ID 13
 0> TakeTimer ID 14
 0> ReleaseTimer ID 14
 0> TakeTimer ID 15
 0> ReleaseTimer ID 15
 0> TakeTimer ID 16
 0> ReleaseTimer ID 16
 0> TakeTimer ID 17
 0> ReleaseTimer ID 17
 0> TakeTimer ID 18
 0> ReleaseTimer ID 18
 0> TakeTimer ID 19
 0> ReleaseTimer ID 19
 0> TakeTimer ID 0
 0> ReleaseTimer ID 0
 0> ReleaseTimer ID 13
 0> TakeTimer ID 2
 0> ReleaseTimer ID 2
 0> TakeTimer ID 4
 0> TakeTimer ID 7
 0> ReleaseTimer ID 7
 0> TakeTimer ID 8
 0> ReleaseTimer ID 8
 0> TakeTimer ID 9
 0> ReleaseTimer ID 9
 0> TakeTimer ID 11

[Jørgen Holmefjord]

Hi,

I'm not sure if this is related to your issue, but there have been some known issues with app_timer is older SDK's. Due to this, we have created a new and simplified version in SDK 15 and above, app_timer2, which is API compatible with the old app_timer. In SDK 16, app_timer2 is the default used in all examples, and it is in production quality, passing all tests from the old implementation, in addition to more new testes.

If possible, I would highly recommend migrating to the new implementation.

Best regards,
Jørgen

[Allen]

Is it possible to update the one module in SDK14? That would be the preferred approach at this time.

[Jørgen Holmefjord]

That has not been tested, but it could be possible. The app_timer2 library is self-contained with its own RTC driver, but it does depend on the atomic_fifo and sortlist libraries. Both are available in SDK 14.2.0 at least, and they seem to have only marginal changes in SDK 16.0.0 (mainly related to added logging, etc.). You may need to make some modifications to the app_timer2 source file and your project sdk_config.h file to make it compile with SDK 14, but I would recommend you to give it a try before migrating the entire SDK if you have a large project that is at a late stage of the development.

[Allen]

Please refer to this new ticket for more information.  devzone.nordicsemi.com/.../request-for-review-of-app_timer2-backport-to-sdk14-0