tests/kernel/timer/timer_api fails on nrf52_pca10040 board

[spoorthik]

Describe the bug
The CI run caught test_timer_periodicity test case failure in tests/kernel/timer/timer_api on nrf52_pca10040 board. This issue is sporadic and I couldn't reproduce locally.

To Reproduce
Steps to reproduce the behavior:

1. mkdir build; cd build
2. cmake -DBOARD= nrf52_pca10040
3. make flash
4. See error

Expected behavior
All test cases should pass without any assertion failure or crash.

Screenshots or console output

********** delaying boot 1000ms (per build configuration) *****
***** Booting Zephyr OS zephyr-v1.13.0-2205-g8d84f9229c (delayed boot 1000ms) *****
Running test suite timer_api
===================================================================
starting test - test_timer_duration_period
PASS - test_timer_duration_period
===================================================================
starting test - test_timer_period_0
PASS - test_timer_period_0
===================================================================
starting test - test_timer_expirefn_null
PASS - test_timer_expirefn_null
===================================================================
starting test - test_timer_periodicity

    Assertion failed at /home/jenkins/workspace/zephyr-master-ci-master/zephyr.git/tests/kernel/timer/timer_api/src/main.c:240: test_timer_periodicity: (((delta) >= (50)) && ((delta) <= (50) + (1))) is false

FAIL - test_timer_periodicity
===================================================================
starting test - test_timer_status_get
PASS - test_timer_status_get
===================================================================
starting test - test_timer_status_get_anytime
PASS - test_timer_status_get_anytime
===================================================================
starting test - test_timer_status_sync
PASS - test_timer_status_sync
===================================================================
starting test - test_timer_k_define
PASS - test_timer_k_define
===================================================================
starting test - test_timer_user_data
PASS - test_timer_user_data
===================================================================
Test suite timer_api failed.
===================================================================
PROJECT EXECUTION FAILED

Environment (please complete the following information):

• OS: Linux
• Toolchain: Zephyr SDK 0.9.5

Since the failure is not seen locally, I couldn't git bisect to find on what commit the failure was first seen.

[carlescufi]

@pizi-nordic can you take a look?

[pizi-nordic]

Interesting... We are calling _add_timeout(&timeout, handler, 5), but the handler is fired 4 ticks later.

[pizi-nordic]

starting test - test_timer_periodicity                                                                                                                                                      
PERIOD: 50, DELTA: 40                                                                                                                                                           
                                                                                                                                                                                              
    Assertion failed at /home/pizi/repos/zephyr/tests/kernel/timer/timer_api/src/main.c:250: test_timer_periodicity: (((delta) >= (50)) && ((delta) <= (50) + (1))) is false                
                                                                                                                                                                                              
FAIL - test_timer_periodicity                                                                                                                                                               
[00:00:00.827,880] <inf> nrf_rtc_timer.z_clock_set_timeout: ticks: 1                                                                                                                        
[00:00:00.827,911] <inf> timer._impl_k_timer_start: new timeout 0x200000E0 (will expire in 0 ticks)                                                                                         
[00:00:00.827,911] <inf> nrf_rtc_timer.z_clock_set_timeout: ticks: 0  <= This moves the announce on the next tick boundary.                                                                                                                       
[00:00:00.827,941] <inf> nrf_rtc_timer.z_clock_set_timeout: ticks: 0  <= This moves the announce on the next tick boundary.                                                                                                                      
[00:00:00.838,256] <inf> timeout.z_clock_announce: ticks: 2 <= Two ticks to process.                                                                                                                                
[00:00:00.838,256] <inf> timeout.z_clock_announce: timeout 0x200000E0 expired! <= First of the 2 ticks announced triggers timer.                                                                                                             
[00:00:00.838,256] <inf> timer._timer_expiration_handler: new timeout 0x200000E0 (will expire in 5 ticks) <= New timeout set.                                                                                                                                                                                                         
[00:00:00.838,256] <inf> nrf_rtc_timer.z_clock_set_timeout: ticks: 5 <= HW correctly programmed.
[00:00:00.838,287] <inf> nrf_rtc_timer.z_clock_set_timeout: ticks: 0                                                                                                                        
[00:00:00.838,287] <inf> nrf_rtc_timer.z_clock_set_timeout: ticks: 4 <= Timeout is adjusted when the second of the 2 ticks announced is processed (due to t->dticks -= announce_remaining)                                                                                                    
[00:00:00.838,317] <inf> nrf_rtc_timer.z_clock_set_timeout: ticks: 0                                                                                                                        
[00:00:00.848,236] <inf> timeout.z_clock_announce: ticks: 1                                                                                                                                 
[00:00:00.848,236] <inf> nrf_rtc_timer.z_clock_set_timeout: ticks: 3                                                                                                                        
[00:00:00.868,194] <inf> timeout.z_clock_announce: ticks: 2                                                                                                                                 
[00:00:00.868,194] <inf> nrf_rtc_timer.z_clock_set_timeout: ticks: 1                                                                                                                        
[00:00:00.878,173] <inf> timeout.z_clock_announce: ticks: 1  <= 4th tick announced.                                                                                                                               
[00:00:00.878,173] <inf> timeout.z_clock_announce: timeout 0x200000E0 expired! <= Timeout fired too early.                                                                                                          
[00:00:00.878,173] <inf> nrf_rtc_timer.z_clock_set_timeout: ticks: 5  <= Start of next timer period....                                                                                                                      
[00:00:00.878,173] <inf> timer._timer_expiration_handler: new timeout 0x200000E0 (will expire in 5 ticks)                                                                                   

@andyross:
It looks that logic around curr_tick in z_clock_announce() is not working well together with announcement of more than one tick. As result we are adjusting dticks of timeouts which were added in the previous loop iteration. IMHO we should first move all the timeouts which are supposed to be executed to a temporary list, and then just run through it.

[andyross]

Hm. That code is by design, actually. The intent is indeed that (for an example) if you have a callback that is supposed to have fired at timer T (but is actually being handled at T+3 because the interrupt arrived late), and it sets a timeout of its own to fire in 1 tick, that that tick gets handled synchronously inside the same ISR at wherever "T+2" timeouts are being issued. Doing it in a separate list would defeat that.

Will take a look. I have a 10056 board, not 10040, though it seems like they're behaving identically?

[pizi-nordic]

Yes, both 10040 and 10056 uses the same timer.

[pdunaj]

Hi @andyross , this behavior may trigger serious problems as module scheduling a timeout may require separation of T between the callbacks (e.g. because of HW constraints when you sample a sensor). When scheduling a delay you expect that your callback will be fired no sooner then T (how accurately it happens depends on how close to real time OS the system is).
The code here will not only call the first callback with a delay of 3T. It will also immediately call it second and third time without maintaining the constraint not sooner then. Module using it will not be aware of the delay at all but if you communicate with the real world this delay will be obviously seen (imagine sensor sampling).

The problem I see is that even if the callback is called with a delay, it will not know about it as curr_tick will not hold the real passing of time (as it is being updated with each cycle loop). The solution may be to update the curr_tick or actually make z_tick_get return the true information about time, before we call any callback. This way callback would have a mean to check that they are delayed.

I don't think timeout system should hide from the other modules a fact that delay happened.

Collecting expired timeouts to the local list and fireing them after the loop is done would ensure that delay is not hidden as curr_tick is updated.

[pizi-nordic]

I think we have to choose between two modes of the operation:

• Current approach, when we are trying to compensate delayed firing of the timers:

  Expected timer firing: |--5--|--5--|--5--|---> (t)
  Actual timer firing:   |--5--|---7---|-3-|---> (t)
  

  In this approach we are trying to meet expectations about number of timer firings in given time interval. However this makes system time not monotinic, and in extreme case we can timer scheduled over short period of time could file almost immediately (timer scheduled in first iteration of loop in z_clock_announce() will fire in subsequent interation(s) if it was scheduled over shorter time than the ticks parameter passed to the announcement functions).

• Approach proposed in the previous comment, which makes system time monotonic, but accumulates error:

  Expected timer firing: |--5--|--5--|--5--|----> (t)
  Actual timer firing:   |--5--|---7---|--5--|--> (t)
  

  Here every period we are meeting the expectations (timer fires 5 ticks after scheduling or later), but error accumulates and as result timer could fire at lower rate than expected.

Also this bug shows me, that the "MIN_DELAY" concept in the RTC timer is not working perfectly, as every call to z_clock_set_timeout(0) could move the firing to the next tick boundary, introducing announcement of multiple ticks, which exposes the problem. We should not adjust the firing point if we know that the interrupt will fire in less than for example 1/2 of tick time.

[pizi-nordic]

I changed priority to high, as the problem is located in the system timers.
I also removed the nRF tag for the same reason.

[pdunaj]

I would ask a question here - which modules depend on the first approach (i.e. approach where you are interested in average number of calls, not timings).

Delayed works can execute periodically but they set new timeout from workqueue thread context (so out of this case). Also in this case you want to be called not sooner then.

For waking up threads (stopping sleep, breaking on timeouts, etc.) we also want to wait at least a given time. Plus timeout is set from thread context (so out of this case).

There are timers. We have two types of timers - one-shot and periodic.
Starting one-shot I would expect it to wait at least a given time. By itself it does not set new timeout but this can be done from attached expiry function. If timer is set again I would expect it to wait at least what is defined (against the wall clock).
Starting periodic timer I would expect to execute at given interval. There is an open question what should be done if there is a lag. I would expect the timer to execute only once even if delay happens but still keep in sync with the interval (i.e. adjust next timeout so it would fire in right place). Also I think that client of a periodic timer must be informed about a delay that happened to ignore or react).
What is happening is that we try to be in sync but this is maintained in timeout while I think it should be done in the timer module (i.e. timer should check the passed ticks, react on delay and make sure next timeout that is set will ensure calls are in sync to period given by the user).

Is there anything else?

[pizi-nordic]

@andyross: Do you have an idea how to solve this?

[andyross]

I would ask a question here - which modules depend on the first approach (i.e. approach where you are interested in average number of calls, not timings).

Anything involving k_uptime_get(). Ticks are assumed to be regular, otherwise the wall clock time you retrieve for computing delays and human-space timeouts are going to be wrong.

I guess I'm not seeing the problem here. We only show a difference between the two schemes in our code when an interrupt has been delayed for a significant fraction of a tick. That's thousands and thousands of cycles, and almost certainly means there's some other realtime promise being broken. But if we really needed to, we could expose the difference in the API somehow. There would be "here is the time your timeout callback thinks it is" and "this is the time the hardware counter actually reflects for the current instant". Drivers and subsystems that care about the difference between "time from REALTIME NOW" and "time from when this callback was scheduled" could then correct on their own. It would be a pretty special purpose API, and sort of hard to document in a way that wouldn't make it into a foot-cannon. But it would be easy to implement.

---

There's an entirely separate issue of "setting a timeout when one is about to expire can unexpectedly push it back one tick because of the MIN_DELAY check". That is fixable (I mean, yeah, don't change the timeout if we have one expiring at the next tick -- should be simple enough) and is a bug right now. I think I should be able to fix this pretty quickly.

[pizi-nordic]

I think that there is significant problem in z_clock_announce(), as current implementation adjust the the time reference of _add_timeout() . Here is the scenario:

1. The z_clock_announce() is called with argument ticks > 1.
2. The z_clock_announce() performs first iteration of the while loop. It finds expired timeout and calls the handler.
3. The timeout handler is adding new timeout to the queue (calls _add_timeout()). Let's assume that this timeout will be placed at front of timeout queue.
4. The z_clock_announce() performs second and subsequent iterations of the while loop. Any non firing timeout (including the one added in point 3) is adjusted (t->dticks -= announce_remaining).

Problem:
All code assumes that _add_timeout() uses current time ("now") as a reference. However in the scenario above the timeout added in point 3 has reference in the PAST, due to adjustment made in point 4. As result, the timeout expires prematurely which is not allowed.

High level effect:
The result is clearly visible in the k_timer tests: N k_timer periods of TIME/N is much shorter than 1 period of TIME (the difference is one tick or larger). I rather expect something opposite, as N k_timer periods needs more computation than single one.

I hope you see the problem now.

[andyross]

Oh oh, I see it now. Actually this has nothing to do with adding timeout entries inside a handler (which really is as intended, I swear[1]). This affects the loop any time there are two or more timeouts scheduled to happen in the same tick.

The loop will adjust the notion of "current time" at the end of the loop iteration, meaning the next timeout which "should" have happened at the same time and with the same state gets adjusted incorrectly.

Pretty sure I know what to do. Need to find a cleaner way to express that logic than testing at both the top and bottom of the loop though. Should have something ready today.

[1] We really do want to adjust times of timeouts added inside the handler if the handler was late. Otherwise periodic timers like k_timer will reflect late timer interrupts and not tick regularly. We're just not doing the adjustment correctly.

[pdunaj]

@andyross

We really do want to adjust times of timeouts added inside the handler if the handler was late. Otherwise periodic timers like k_timer will reflect late timer interrupts and not tick regularly.

I think the problem is just here. The fact is that due to whatever caused scheduling delay, periodic timer is late. It will be late whatever SW trick is done. We can lie about it as we do now or allow the timer callback to accept the reality.
Catching up with rapidly calling missed timer events would have a point if what matters is a number of timer events executed whenever they are actually called. I strongly believe however that what really matters in periodic timer is to have a regular interval between timer events. If the later is correct current implementation is not only late but also breaking the contract about minimum time between timer events.

[pdunaj]

I thought about it for a minute and found two examples with slightly different needs.

1. square wave generator
   If implemented by simple swap, missing a callback will switch phase and affect the correctness of the signal.
   E.g.

expected:     0101010101010101
current imp:  0101000101010101 (assuming rapid change 0->1->0 is not observable)
skip missed:  0101001010101010 (phase changed after missed event)

If we skip missed callbacks but keep correct information about time, the phase change problem could be corrected as state can be derived from system time (i.e. ticks).

2. ADC sampling
   We would like to have evenly distributed samples. When missed callbacks are rapidly fired we just multiply the last value
   E.g.

expected:     ABCDEFGHIJKL
current imp:  ABCFFFGHIJKL (3 rapid samples are collected on one callback)
skip missed:  ABC..FGHIJKL (two samples are not collected due to delay)

If we skip missed callbacks but check time we will know some samples are missed.
In the current implementation there is no way to find this out and timer user will assume that it sampled D and E correctly which is not true.

[andyross]

We may just need to table this discussion for now. The cases you mention are clearly realtime applications. This behavior happens only when you miss more than a whole tick due to interrupt delay, which is going to wreck any waveform generator or ADC sampler right out of the gate.

The case I'm looking at is someone implementing a "clock" (or clock-like thingy) with k_timer, which is (1) not realtime and (2) clearly "wrong" in one case and "right" in the other. It's also (3) somewhat simpler to implement and (4) actually required by some of our tests right now (which is why the feature got added, though I forget exactly where, and wouldn't cry if we wanted to take that case out).

That said:

If we skip missed callbacks [...]

We can't skip a missed callback ever, a periodic timer (the k_timer API one level up) might do that, I guess, but the low level k_timeout interface is oneshot, once registered you have to call it when it expires, otherwise the user never knows what happened.

The question we're arguing about is whether or not the "current tick" seen by the callback (e.g. when setting new timeouts) is (1) the current "real" time or (2) a simulated time that corresponds to when the timer was scheduled. Currently we do 2, for the reasons listed above.

[pizi-nordic]

I see a bit different problem than @pdunaj: Due to the "corrections" timers scheduled in some specific point of time are fired prematurely. As result, the time flow in application is not "steady" - sometimes 5 ticks takes as little as 4 ticks ;-). While delayed handler firing is something we should expect, the premature fire is something we cannot tolerate.

I think that might have to move handling periodic timers down to _add_timeout() to satisfy both @pdunaj and @andyross: If the timeout is periodic, reschedule with correction, if not, do not apply correction.

[andyross]

Right, the premature timeouts are a bug. Fixing that right now.

[andyross]

Please try the attached patch, which should fix the bug reported. We'll have to continue arguing about the proper behavior in the face of very late interrupt delivery -- I'm hopeful this can be addressed with clearer documentation and maybe a simple API option somewhere.

[pizi-nordic]

Unfortunately the problem still exists on top of the #12204.
The test failed 2 times during during my test run (160 iterations).

===================================================================
starting test - test_timer_periodicity

    Assertion failed at /home/pizi/repos/zephyr/tests/kernel/timer/timer_api/src/main.c:240: test_timer_periodicity: (((delta) >= (50)) && ((delta) <= (50) + (1))) is false

FAIL - test_timer_periodicity

[andyross]

Do you have a rig or something that you use to get those measurements? Does it work to hack the test to execute the particular case in a loop? All I'm know to do right now on a nrf52840_pca10056 is to hit the reset button hundreds of times....

[pizi-nordic]

I am using simple shell one liner ( for i in $(seq 1 100); do echo $i; nrfjprog -f NRF52 -r; sleep 3; done) capturing console output to a file. Then I just grep the file looking for "Assert" or "FAIL".

[pabigot]

Running it in a loop (by editing the test program) works.

As another clue: when the test fails, it fails on the first iteration (of the for loop over EXPIRE_TIMES).

Which probably means a ticksomething clock related is occurring between k_timer_status_sync and the fetch of the first timestamp.

[pizi-nordic]

As another clue: when the test fails, it fails on the first iteration (of the for loop over EXPIRE_TIMES).

Yes. Feel free to look into #11722 (comment) where I traced this.

[andyross]

I'm still having zero luck reproducing this on a 10056 board (which of course I left at home post-vacation and am going to have to run back at some point today to continue testing).

@pabigot - Yeah, it makes sense that repeated loops might end up aligning the same way on tick boundaries and show the same behavior. If you have the rig ready and have seen the error, can you try stuffing a locked random delay (e.g. "irq_lock(); k_busy_wait(nnn); irq_unlock();" with a randomized delay of between 0 and 1 ticks (should be 0-10000 us on this app unless it's changed the tick rate).

Note that I think I stumbled on a plausible issue though -- I managed to confuse the previous fix from @pdunaj (synchronizing set-last-time) with the other issue we were discussing, where a timeout set very close to a timeout expiration would push it forward by a full tick, thus entering the "late interrupt" case (which @pizi-nordic has seen) erroneously. We don't have a fix for that even though my brain thought we did, and we for sure need one. Will do that today and maybe we'll get lucky...

[pabigot]

I think we still haven't fully prised apart all the pieces of this issue and how they relate to the semantics of interval timers. With the reproducing modification described here I only ever see the failure on the first iteration of the loop in test_timer_periodicity, when it's the first expiration after k_timer_status_sync that calls back early. I think this is a clue, and maybe the problem lies there, but I haven't pursued that.

The comment above by @pizi-nordic is tempting because it explains the failure as a situation where the delay would be short because the hardware timer was asked to wait for less time than it should, because the delay was reduced by time that had already passed before when the timeout was rescheduled. The k_uptime_delta() in the test sees a time that wasn't the same as the one used to schedule the wakeup.

That "undesirable extra" reduction could be removed by ensuring newly scheduled delays were not affected by adjustments intended for subsequent expirations. So I did this in pabigot/zephyr:wip/2019010a, splitting the timeout_list so that everything that was due at or before the tick-to-come was removed before any callbacks were invoked, so any new timeouts added during callbacks would not be adjusted. I believe this has an effect similar to changing the interval increment behavior to the alternate choice described in #12247.

The timer_api test that fails for this issue passes with flying colors with that change, though several other tests fail. Which suggests that both update models may be required to handle all use cases, or that there's a different error in that solution.

[andyross]

I'm telling you guys again: the issue here is going to turn out to be a delayed interrupt or callback. It's not an API bug. There's a valid argument to be had about the API, but you can't fix it that way (c.f. the tests you discovered that assume the current behavior -- I bumped into those too during the rewrite, which is why this feature exists at all).

The root cause is unexpected timing of the z_clock_announce() call. I promise.

Still struggling with seeing a reproduction. I'm guessing at this point it's my programming methodology: I'm using the MBED filesystem interface, and not the SEGGER/J-link/nrfjprog layer. My guess is that this boots the system with a more reliably synchronized clock or something, where the direct stuff might do the programming and reboot synchronously with the clock in an arbitrary state? I'm currently torn trying to figure out whether it's easier to install new tooling or to start doing invasive random waits at the start of the test...

[andyross]

Got it. See comment in #12204

[pabigot]

Excellent.

I'm leaving my reproducer on top of your PR running overnight, and will take a look tomorrow when I'm fresh. Assuming there isn't anything obvious, I'll sign off on the PR. These points are outside the scope of this issue but remain to be addressed:

• I will continue to push for extend dlist to detect unlinked nodes and avoid double-remove bugs #12248 to replace the local workaround in Timer fixes #12204. There are also patches in my wip/20190101a branch that eliminate the magic dticks flag value to detect inactive timeouts. If kernel: poll: outdated check for expired timeout #12264 can be cleaned up too then all that hackery can go away in time for 1.14.
• Timer interval support is still needed for both use case (a) fixed interval regardless of latency and (b) offset from actual time of last callback, but IMO that can be dealt with in the 1.15 development unless some new misbehavior is revealed.
• That an application has to do a fancy dance with k_timer_status_sync() to make basic time-difference--based calculations work reliably is ridiculous and fragile. I believe this can be addressed in the context of Use counter drivers as a system clock source #12068: both k_uptime_get() and timers should be driven by the same underlying counter at the resolution of that counter. Let's argue that elsewhere.

@andyross Thanks for tracking this down, and well-done. It was a nasty one.

[andyross]

That an application has to do a fancy dance with k_timer_status_sync() to make basic time-difference--based calculations work reliably is ridiculous and fragile.

No, this is sort of a generic thing with time APIs. "Time" is a real function of the universe and can't be made atomic. Here's POSIX code that exhibits exactly the same bug:

time_t t0 = time(NULL);
sleep(4);
time_t t1 = time(NULL);
assert(t1 - t0 == 4);

If you play with that enough, you'll eventually hit a situation where the current time in seconds changes between the first call to time() and the entry to sleep(), and the assert will fail. This is exactly what our test code was doing. That's not a bug in the API, it's just how time works.

But if you're careful to arrange things by ensuring you start just after a seconds boundary, you (might[1]) can make that assertion always true by controlling the initial conditions:

time_t init = time(NULL);
while(init == time(NULL)) { /* spin until it changes */ }

And that's fundamentally what the patch is doing. Except that we work in units of ticks and not seconds, and have different APIs for "wait until the next tick" than crude spinning.

Heh, actually spinning would work too, but I happen to know that tickles qemu bugs on x86. And in fact we could have just thrown in a k_sleep() to do the same thing, but this is a lower level test of the k_timer API and I felt that sleeping would be a layering violation of the test intent.

[1] POSIX itself doesn't guarantee that kind of precision of course. On most systems there's still an internal tick granularity like ours. But this would surely work in practice.

[pabigot]

@carlescufi @pizi-nordic I propose that the specific problem covered by this issue has been resolved in #12204 by adding the required synchronization code to make the test pass reliably, so this should be closed. I don't think keeping it open is going to contribute to addressing the other anomalous behavior and functional gaps identified in the discussion here. But it's assigned to you two so I won't presume to close it.

[carlescufi]

@pizi-nordic I am closing this since the test itself has been fixed. Additional bugs have their own GitHub issues. Please let me know if you want me to reopen this.