Mbed-os: NRF52_DK: Not all callbacks called when multiple Timeout objects scheduled one by one

[fkjagodzinski]

Description

• Type: Bug
• Priority: Major

Target
NRF52_DK

Toolchain:
ARM, IAR

Toolchain version:
ARM 5.24 (Flex) ARM Compiler 5.06 update 5 (build 528),
IAR ANSI C/C++ Compiler V7.80.4.12462/W32 for ARM

mbed-cli version:
1.5.0

mbed-os sha:
42d77ecd1

Code

#include "mbed.h"

#define VERBOSE 0

#define NUM_TIMEOUTS 16
#define TEST_DELAY_US 10000ULL

void cnt_callback(volatile uint32_t *cnt)
{
    (*cnt)++;
}

int main()
{
    const ticker_data_t * const us_ticker = get_us_ticker_data();
    const ticker_event_queue_t *ticker_event_q = us_ticker->queue;

    uint32_t cnt1 = 0;
    do {
#if VERBOSE
        us_timestamp_t event_timestamps[NUM_TIMEOUTS] = { 0 };
#endif
        us_timestamp_t ts0, ts1, ts2, end_ts, head_ts1, head_ts2;
        volatile uint32_t callback_count = 0;
        Timeout timeouts[NUM_TIMEOUTS];

        for (size_t i = 0; i < NUM_TIMEOUTS; i++) {
            timeouts[i].attach_us(mbed::callback(cnt_callback, &callback_count), TEST_DELAY_US);
        }
        ts0 = ticker_read_us(us_ticker);
#if VERBOSE
        ticker_event_t *te = ticker_event_q->head;
        int i = 0;
        while (te != NULL) {
            event_timestamps[i] = te->timestamp;
            i++;
            te = te->next;
        }
#endif

        end_ts = ts0 + TEST_DELAY_US;
        while (ticker_read_us(us_ticker) < end_ts) {
        };
        // At this point all callbacks should have been called,
        // so expected values are:
        // cnt1 == NUM_TIMEOUTS
        // ticker_event_q-> head == NULL
        cnt1 = callback_count;
        ts1 = ticker_read_us(us_ticker);
        head_ts1 = (ticker_event_q->head == NULL) ? 0 : ticker_event_q->head->timestamp;

        // Wait more to check if any callback was late.
        end_ts += 2 * TEST_DELAY_US;
        while (callback_count < NUM_TIMEOUTS && ticker_read_us(us_ticker) < end_ts) {
        };
        uint32_t cnt2 = callback_count;
        ts2 = ticker_read_us(us_ticker);
        head_ts2 = (ticker_event_q->head == NULL) ? 0 : ticker_event_q->head->timestamp;

#if VERBOSE
        us_timestamp_t prev_ts = event_timestamps[0];
        for (size_t i = 0; i < NUM_TIMEOUTS; i++) {
            printf("ts[%02i]=%llu, delta=%03llu\r\n", i, event_timestamps[i], event_timestamps[i] - prev_ts);
            prev_ts = event_timestamps[i];
        }
#endif
        printf("ts0=%llu, ts1=%llu, ts2=%llu, ts2-ts0=%llu, "
                "cnt1=%lu, cnt2=%lu, head_ts1=%llu, head_ts2=%llu\r\n", ts0, ts1, ts2, ts2 - ts0, cnt1, cnt2, head_ts1,
                head_ts2);
    } while (cnt1 == NUM_TIMEOUTS);
    printf("gotcha!\r\n");

    return 0;
}

Expected behavior
When multiple Timeout objects are scheduled one by one, all callbacks are called after given delay.

Actual behavior
With multiple repetitions it is possible to catch a case where not all the callbacks are called. The ticker event queue is not empty and still contains outdated events.

Steps to reproduce
mbed compile -t ARM -m NRF52_DK -f

ts0=732, ts1=10803, ts2=10833, ts2-ts0=10101, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=103119, ts1=113128, ts2=113128, ts2-ts0=10009, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=210632, ts1=220642, ts2=220642, ts2-ts0=10010, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=318176, ts1=328186, ts2=348205, ts2-ts0=30029, cnt1=15, cnt2=15, head_ts1=328145, head_ts2=328145
gotcha!

# RESET button pressed
ts0=732, ts1=10742, ts2=10742, ts2-ts0=10010, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=103180, ts1=113189, ts2=113189, ts2-ts0=10009, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=210663, ts1=220703, ts2=220703, ts2-ts0=10040, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=318298, ts1=328308, ts2=328308, ts2-ts0=10010, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=425872, ts1=435882, ts2=455902, ts2-ts0=30030, cnt1=3, cnt2=3, head_ts1=435323, head_ts2=435323
gotcha!

# RESET button pressed
ts0=732, ts1=10742, ts2=10742, ts2-ts0=10010, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=103210, ts1=113220, ts2=113220, ts2-ts0=10010, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=210754, ts1=220825, ts2=220825, ts2-ts0=10071, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=318451, ts1=328460, ts2=328460, ts2-ts0=10009, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=426025, ts1=436035, ts2=436035, ts2-ts0=10010, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=533600, ts1=543640, ts2=543640, ts2-ts0=10040, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=641143, ts1=651153, ts2=671173, ts2-ts0=30030, cnt1=12, cnt2=12, head_ts1=650991, head_ts2=650991
gotcha!

# RESET button pressed
ts0=732, ts1=10742, ts2=10742, ts2-ts0=10010, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=103180, ts1=113189, ts2=113189, ts2-ts0=10009, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=210724, ts1=220733, ts2=220733, ts2-ts0=10009, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=318329, ts1=328338, ts2=348358, ts2-ts0=30029, cnt1=13, cnt2=13, head_ts1=328237, head_ts2=328237
gotcha!

[marcuschangarm]

@mprse @bulislaw

I would expect this PR https://github.com/ARMmbed/mbed-os/pull/5629 to fix it?

[mprse]

I would expect this PR #5629 to fix it?

Mentioned PR is only for NRF51_DK board. I didn't have NRF52_DK while I was porting the ticker driver. I know that implementation should be mainly the same, only NRF52_DK offers 32-bit high speed counter which can be used for us ticker instead of 16-bit one.
I don't want to add anything to this PR since it hangs long enough - mainly waiting for the review. So I think we can try to enable NRF52_DK support in additional PR when this on is finally merged.

I tried to run code from this issue on mprse:nrf5x_use_high_speed_timer_for_us_timer branch (PR #5629) with enabled lp/us ticker support for NRF52_DK board and it looks like this issue does not exist in the new implementation (NRF52_DK/ARM).

[marcuschangarm]

Sounds good! Let's get your PR in and I'll rebase mine around it and then we'll see if more work needs to be done.

[fkjagodzinski]

Update:

• the issue can be also reproduced on NRF52840_DK,
• unfortunately #6515 does not fix the issue (as I wrote in https://github.com/ARMmbed/mbed-os/pull/6534#issuecomment-382660644), just makes it less often,
• I suppose the problem lies in common_rtc_set_interrupt(), where the code is not protected in any way against changes of RTC COUNTER register value.

https://github.com/ARMmbed/mbed-os/blob/675528b6c0d5b7a51fecc6dcf0e09e63bdee57b5/targets/TARGET_NORDIC/TARGET_NRF5/us_ticker.c#L245-L259

According to nrf52832 spec, the interrupt is guaranteed to fire if CC is set to COUNTER+2 or more. Since the actual value of RTC COUNTER register may increment between read (line 251) and write (line 256) operations, the value written to CC register may be invalid and the interrupt won't fire. The actual value written to CC would be COUNTER+1 instead of COUNTER+2.

[0xc0170]

@fkjagodzinski How shall this be fixed?

[marcuschangarm]

@fkjagodzinski

I tried to run code from this issue on mprse:nrf5x_use_high_speed_timer_for_us_timer branch (PR #5629) with enabled lp/us ticker support for NRF52_DK board and it looks like this issue does not exist in the new implementation (NRF52_DK/ARM).

According to @mprse this PR https://github.com/ARMmbed/mbed-os/pull/5629 should fix it.

@0xc0170 let's get that PR merged and see where we stand. Any fixes should be build on top of that anyway.

[fkjagodzinski]

As the ticker implementation for NRF51/52 will get updated soon, I also think this issue is not worth our time now.

---

Below are my notes collected so far for this issue.

@fkjagodzinski How shall this be fixed?

@0xc0170, I tried this way, but it didn't work.

diff --git a/targets/TARGET_NORDIC/TARGET_NRF5/us_ticker.c b/targets/TARGET_NORDIC/TARGET_NRF5/us_ticker.c
index a830545d5..09d2ba87f 100644
--- a/targets/TARGET_NORDIC/TARGET_NRF5/us_ticker.c
+++ b/targets/TARGET_NORDIC/TARGET_NRF5/us_ticker.c
@@ -248,7 +248,8 @@ void common_rtc_set_interrupt(uint32_t us_timestamp, uint32_t cc_channel,
     // difference between the compare value to be set and the current counter
     // value is 2 ticks. This guarantees that the compare trigger is properly
     // setup before the compare condition occurs.
-    uint32_t closest_safe_compare = common_rtc_32bit_ticks_get() + 2;
+    uint32_t rtc_tick1 = common_rtc_32bit_ticks_get();
+    uint32_t closest_safe_compare = rtc_tick1 + 2;
     if ((int)(compare_value - closest_safe_compare) <= 0) {
         compare_value = closest_safe_compare;
     }
@@ -256,6 +257,13 @@ void common_rtc_set_interrupt(uint32_t us_timestamp, uint32_t cc_channel,
     nrf_rtc_cc_set(COMMON_RTC_INSTANCE, cc_channel, RTC_WRAP(compare_value));
     nrf_rtc_event_enable(COMMON_RTC_INSTANCE, int_mask);

+    uint32_t rtc_tick2 = common_rtc_32bit_ticks_get();
+    if (rtc_tick1 != rtc_tick2) {
+        compare_value++;
+        nrf_rtc_cc_set(COMMON_RTC_INSTANCE, cc_channel, RTC_WRAP(compare_value));
+        nrf_rtc_event_enable(COMMON_RTC_INSTANCE, int_mask);
+    }
+
     core_util_critical_section_exit();
 }
 //------------------------------------------------------------------------------

---

Interestingly, simply increasing the closest_safe_compare value does the trick!

diff --git a/targets/TARGET_NORDIC/TARGET_NRF5/us_ticker.c b/targets/TARGET_NORDIC/TARGET_NRF5/us_ticker.c
index a830545d5..6bc3b7805 100644
--- a/targets/TARGET_NORDIC/TARGET_NRF5/us_ticker.c
+++ b/targets/TARGET_NORDIC/TARGET_NRF5/us_ticker.c
@@ -248,7 +248,7 @@ void common_rtc_set_interrupt(uint32_t us_timestamp, uint32_t cc_channel,
     // difference between the compare value to be set and the current counter
     // value is 2 ticks. This guarantees that the compare trigger is properly
     // setup before the compare condition occurs.
-    uint32_t closest_safe_compare = common_rtc_32bit_ticks_get() + 2;
+    uint32_t closest_safe_compare = common_rtc_32bit_ticks_get() + 3;
     if ((int)(compare_value - closest_safe_compare) <= 0) {
         compare_value = closest_safe_compare;
     }

ts0=732, ts1=10833, ts2=10833, ts2-ts0=10101, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=103058, ts1=113067, ts2=113098, ts2-ts0=10040, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=210540, ts1=220581, ts2=220581, ts2-ts0=10041, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=318145, ts1=328186, ts2=328186, ts2-ts0=10041, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=425659, ts1=435699, ts2=435699, ts2-ts0=10040, cnt1=16, cnt2=16, head_ts1=0, head_ts2=0
ts0=533203, ts1=543213, ts2=543274, ts2-ts0=10071, cnt1=15, cnt2=16, head_ts1=543172, head_ts2=0
gotcha!

Sometimes only 15 callbacks fire in time (see cnt1 in the log above), but eventually all do fire (see cnt2 in the log above).

[0xc0170]

@fkjagodzinski Can you retest after the latest updates to nrf code base? Or is this waiting for ticker feature branch ? Please update

[marcuschangarm]

I made some small changes to the tickers that might have fixed this issue, but I would be more comfortable to wait for the new tickers in 5.9.

[fkjagodzinski]

I checked the code with:

• the new ticker implementation for NRF52_DK from https://github.com/mprse/mbed-os/commit/727d50bf9978da94231b88dc7cb45422b59821fc -- no issues,
• the current master, https://github.com/ARMmbed/mbed-os/commit/3bcc076c0c08a4f411bfbeb9fcf173bb1343cd8c -- the issue does not show up, I suppose https://github.com/ARMmbed/mbed-os/commit/b8f22bbec17e94f700fadda428c37a37dba11713 fixed it.

[ciarmcom]

ARM Internal Ref: MBOTRIAGE-65

[cmonr]

Closing since it appears the issue has been resolved.