How to access the TIMER3 in wireless timer sync?

[Michael01101]

Hello,

I found this great blog entry about synchronizing timers on different devices: https://devzone.nordicsemi.com/nordic/short-range-guides/b/bluetooth-low-energy/posts/wireless-timer-synchronization-among-nrf5-devices

It works just fine on a nRF52840DK and a nRF52DK. Timers on multiple nRF5 devices are synced by one device (master) sending sync packets containing captured timer values to other devices (nodes). (TIMER3 is free running, TIMER2 counts TIMER3 overflows).

At the moment I am struggeling to access this synchronized TIMER3 on the two boards. I am familiar with setting up a TIMER without wireless timer sync. 

So here are my questions:

1. How can I define CC, Prescaler, Mode, Bitmode, the interrupt handler and so forth when using wireless timer sync?

2. Can anybody provide me some advice how to access this synchronized TIMER3 properly? 

Thank you very much in advance.

[Audun]

Hi Michael, sorry for the late reply!

Michael01101 said:

My ts_temp_disable() and my ts_re_enable(&rf_config) function work now. And the time sync works as it should when it is enabled.

At the moment I am a bit worried by simply removing this line of code. To be honest, I do not really know what this line of code does. Does this have any consequences?

Are there any side effects, which I sould be aware of?

I looked at the changes you made and the error you describe.

I assume the error you see is actually coming from main.c. The callback you commented out (m_callback(&m_trigger_evt)) is probably going to this case in main.c: https://github.com/nordic-auko/nRF5-ble-timesync-demo/blob/master/nRF5_SDK_16.0.0_98a08e2/examples/ble_peripheral/ble_app_uart/main.c#L771 , which in turn calls ts_set_trigger(). This function will return an error when m_timeslot_session_open is false. This error is probably what triggers the assert.

Considering that you only use the timestamp functionality, and not the ts_set_trigger() functionality, I think your changes should be fine. I think also that the trigger functionality isnt strictly speaking depending on that the timeslot being active, but this was probably the easiest way of checking if the required setup was done already. You could probably comment out this check and have the triggering too work fine when the radio is temporarily turned off to save power.

Audun

[Michael01101]

Hello Audun,

thank you very much for your answer.

Audun said:

sorry for the late reply!

That is absolutly no problem. I really appreciate your great help with my 'time_sync' specific problems.

At the moment I am working on my central device (nRF52840DK). I am using the following timestamp function, which I call when a GPIO changes from high to low:

uint64_t ts_timestamp_get_ticks_u64(void);

As you mentioned in your notes to this function:

 * @note When @ref TIME_SYNC_TX_OFFSET_REALIGN_TIMEOUT is non-zero,
 *       this function should be called from context priority @ref TIME_SYNC_EVT_HANDLER_IRQ_PRIORITY or lower

I have to make sure, that this function gets only called from the TIME_SYNC_EVT_HANDLER_IRQ_PRIORITY, because there are some parts in the timers_capture which are not thread safe.

At the moment TIME_SYNC_EVT_HANDLER_IRQ_PRIORITY is set to 7. This is the lowest priority, which is set by default.

Here is my problem: I need that the ts_timestamp_get_ticks_u64() gets called from a higher priority (6 or lower). I need to achieve that my GPIO capturing has a higher priority than my UART.

So here is my question:

Are there any side effects or any consequences which I sould be aware of, if I change TIME_SYNC_EVT_HANDLER_IRQ_PRIORITY to 6 or lower?

Thank you in advance.

Best regards

Michael

[Audun]

Hi Michael,

Michael01101 said:

Are there any side effects or any consequences which I sould be aware of, if I change TIME_SYNC_EVT_HANDLER_IRQ_PRIORITY to 6 or lower?

No direct side effects that I'm aware of. But there could be indirect side effects depending on what the application does with the event handler callback. If your application runs code directly in the event handler then that code could in turn have side effects.

However, I don't think your application uses any of the events in the callback anyway?

Best regards,

Audun

[Michael01101]

Hello Audun,

thank you very much for your reply.

At the moment I am having a bit of a weird problem. Hopefully you have some tips for me.

I am using the wireless timer synchronization code on a nRF52840DK (central) and a nRF52DK (peripheral). The time sync works at first as it should.

Here is my problem: About ~1180 seconds after I started the timer sync, the timer synchronization has abrupt an 3ms offset. This offset stays for exactly 10 seconds. After these 10 seconds the time sync returns to perfect operation and the offset is gone.

Unfortunately, I do not know what causes this abrupt offset. Maybe these two definitions has something to do with this problem (they are exactly 10 seconds)?:

#define TIME_SYNC_DESYNC_TIMEOUT 10000000 /* Timeout for desynchronization [us] */
#define TIME_SYNC_TX_OFFSET_REALIGN_TIMEOUT 10000000 /* Set to 0 to disable [us] */

Do you have any suggestions what causes this weird behaviour? Any kind of feedback is always appreciated.

Thank you very much in advance.

Best regards,

Michael

-----------------------------------

# Edit (07.04.2021)

After some further debugging I figured the following out:

It looks like that the master-timer on the central works fine. The problem/offset occurs on the peripheral with its slave-timer. (The central sends sync beacons. The peripheral receives the sync beacons).

Here is a example of the offset, when it occures:

Timer Central: 1170003 (ms)

Timer Peripheral: 1170000 (ms)

As I already mentioned, after these 10 seconds, both timers are equal again.

Maybe the values of the sync beacon do not get applied on the peripheral in time?

I am still not able to solve this issue. Any kind of feeback is always appreciated. Thank you very much in advance.

Best regards,

Michael

[Audun]

Hi Michael,

did you try to set TIME_SYNC_TX_OFFSET_REALIGN_TIMEOUT to 0?

Another developer discovered a race condition if the timer value is updated very close to the wraparound. The workaround was to check the timer value and dont apply any adjustments close to the wraparound. This has the side effect that valid sync packets are discarded when close to the wraparound. The TIME_SYNC_TX_OFFSET_REALIGN_TIMEOUT was an attempt to avoid the issue entirely by having the transmitter send packets at "safe" times.

By setting TIME_SYNC_TX_OFFSET_REALIGN_TIMEOUT  to 0 the original workaround will be used, which might be the safest approach here.

Best regards,

Audun

[Michael01101]

Hello Audun,

thank you very much for your reply.

As you suggested, I set TIME_SYNC_TX_OFFSET_REALIGN_TIMEOUT to 0. Unfortunately, this does not fix my problem. When I set TIME_SYNC_TX_OFFSET_REALIGN_TIMEOUT  to 0, the abrupt offset is even higher. (Abrupt offset of about 99ms)

To apply this change, I had to also change a data type (uint32_t to int32_t) in time_sync.c:

From this:

static uint32_t calculate_tx_start_offset(void)
{
    return 0;
}

to this:

static int32_t calculate_tx_start_offset(void)
{
    return 0;
}

Do you know why there was an uint32_t used instead of an int32_t?

----------------------------------------------------------------------------------------

These are my definitions in time_sync.h at the moment:

#ifndef TS_SOC_OBSERVER_PRIO
#define TS_SOC_OBSERVER_PRIO 0
#endif

#ifndef TIME_SYNC_TIMER_MAX_VAL
#define TIME_SYNC_TIMER_MAX_VAL (16000) // 40000
#endif

#ifndef TIME_SYNC_RTC_MAX_VAL
#define TIME_SYNC_RTC_MAX_VAL   (0xFFFFFF)
#endif

#ifndef TIME_SYNC_DESYNC_TIMEOUT
#define TIME_SYNC_DESYNC_TIMEOUT 10000000 /* Timeout for desynchronization [us] */
#endif

#ifndef TIME_SYNC_TX_OFFSET_REALIGN_TIMEOUT
#define TIME_SYNC_TX_OFFSET_REALIGN_TIMEOUT 0 // 10000000 /* Set to 0 to disable [us] */
#endif

#ifndef TIME_SYNC_EVT_HANDLER_IRQ_PRIORITY
#define TIME_SYNC_EVT_HANDLER_IRQ_PRIORITY 6 // 7 /* Priority of event handler */
#endif

So I am still having the problem with the abrupt offset.

Do you have any other suggestions what could cause this behaviour?

Can you provide me some guidance how to solve this issue?

I am really stuck with this at the moment. It looks like the success of my project depends on your help.

Thank you very much in advance.

Best regards,

Michael

[Audun]

Hi Michael,

I've been pondering on this one, and while I don't have a clear answer yet I have some ideas for debugging further.

At first I thought the 3 ms offset was due to perhaps a corner case when capturing the local counter on the receiver side, as the value is calculated from the counter + the value received from the transmitter. The original value of TIME_SYNC_TIMER_MAX_VAL matches 3 ms when rounded up (40000/16 MHz = 2.5 ms). However, you are using value 16000 for TIME_SYNC_TIMER_MAX_VAL, which does not add up to 3 ms.

I also understand that you see a sudden offset from 0 to 3 ms, and not a slow drift. The latter would be indicative of lost packets on the receiver, or continuous adjustments not being applied.

Did you also see this issue before adjusting TIME_SYNC_EVT_HANDLER_IRQ_PRIORITY? And if you use TIME_SYNC_TIMER_MAX_VAL value of the original 40000?

As I understand the offset is a constant 3 ms (and not drifting) during this 10 second period, I think it is worth looking more closely at the counter values.

Can you add some debug printouts to the timestamp function on both Central and Peripheral?

For example:

timers_capture(&sync_timer_val, &count_timer_val, &peer_count);
// Add printout to relevant function (ts_timestamp_get_ticks_u32 or ts_timestamp_get_ticks_u64)
NRF_LOG_INFO("%d, %d, %d", sync_timer_val, count_timer_val, peer_count);

This will hopefully help narrow down the issue

Best regards,

Audun

[Michael01101]

Hello Audun,

thank you very much for your reply.

Audun said:

At first I thought the 3 ms offset was due to perhaps a corner case when capturing the local counter on the receiver side, as the value is calculated from the counter + the value received from the transmitter.

I am so sorry for that. I used indeed a TIME_SYNC_TIMER_MAX_VAL of 40000 when I got this abrupt 3ms offset. During my troubleshooting proccess I adjusted this value and accidentally copied the wrong value in my previous reply. But I can tell definetly, that this 3ms offset is with a TIME_SYNC_TIMER_MAX_VAL of 40000. That was a big mistake on my side. 

 

So I want to clarify my actual situation and reran my tests with the default values for TIME_SYNC_TIMER_MAX_VAL and TIME_SYNC_EVT_HANDLER_IRQ_PRIORITY. 

This are my defines in time_sync.h:

#ifndef TS_SOC_OBSERVER_PRIO
#define TS_SOC_OBSERVER_PRIO 0
#endif

#ifndef TIME_SYNC_TIMER_MAX_VAL
#define TIME_SYNC_TIMER_MAX_VAL (40000) // 40000
#endif

#ifndef TIME_SYNC_RTC_MAX_VAL
#define TIME_SYNC_RTC_MAX_VAL   (0xFFFFFF)
#endif

#ifndef TIME_SYNC_DESYNC_TIMEOUT
#define TIME_SYNC_DESYNC_TIMEOUT 10000000 /* Timeout for desynchronization [us] */
#endif

#ifndef TIME_SYNC_TX_OFFSET_REALIGN_TIMEOUT
#define TIME_SYNC_TX_OFFSET_REALIGN_TIMEOUT 0 // 10000000 /* Set to 0 to disable [us] */
#endif

#ifndef TIME_SYNC_EVT_HANDLER_IRQ_PRIORITY
#define TIME_SYNC_EVT_HANDLER_IRQ_PRIORITY 7 /* Priority of event handler */
#endif

When I am using TIME_SYNC_TX_OFFSET_REALIGN_TIMEOUT = 0 the abrupt offset occurs after ~1150 seconds. With TIME_SYNC_TX_OFFSET_REALIGN_TIMEOUT = 10000000 the abrupt offset occurs after about ~ 60 seconds.

The abrupt offset is 3ms. A few times the abrupt offset is 2ms (Independently which value is used for TIME_SYNC_TX_OFFSET_REALIGN_TIMEOUT)

So your suggestion with the corner case would make a lot of sense. Is there a way to take care of these corner cases?

Audun said:

Can you add some debug printouts to the timestamp function on both Central and Peripheral?

I will try to add this printouts and I will let you know the results.

Audun said:

As I understand the offset is a constant 3 ms (and not drifting) during this 10 second period

That is correct.

If you have already any tips for me, I would be glad to here them.

Any kind of feedback is always appreciated. Thank you very much in advance.

Best regards,

Michael

[Audun]

Thanks, Michael,

looking forward to looking at the debug printouts.

I will try to do some testing on my end with the same parameters as you.

Best regards,

Audun

[Michael01101]

Hello Audun,

thank you very much for your reply.

I added the debug printouts to the ts_timestamp_get_ticks_u64() function. I also added the actual timestamp in ms to the debug printout. This is how this function looks now: 

uint64_t ts_timestamp_get_ticks_u64(void)
{
    uint32_t sync_timer_val;
    uint32_t count_timer_val;
    uint64_t timestamp;
    uint32_t  peer_count;

    //DEBUG
    uint32_t timestamp_ms;

    timers_capture(&sync_timer_val, &count_timer_val, &peer_count);

    timestamp  = (uint64_t) count_timer_val;
    timestamp += (uint64_t) peer_count;
    timestamp *= TIME_SYNC_TIMER_MAX_VAL;
    timestamp += (uint64_t) sync_timer_val;

    // DEBUG
    timestamp_ms = (uint32_t) ROUNDED_DIV(timestamp, 16000);
    NRF_LOG_INFO("%d, %d, %d    timestamp: %d", sync_timer_val, count_timer_val, peer_count,timestamp_ms);

    return timestamp;
}

Peripheral side

I am using the timestamp function on the peripheral every 40ms to timestamp a NUS paket. This is the log:

[00:01:16.065,795] <info> time_sync: 8740, 27, 30875    timestamp: 77256
[00:01:16.105,773] <info> time_sync: 8753, 4, 30914    timestamp: 77296
[00:01:16.145,751] <info> time_sync: 8758, 7, 30927    timestamp: 77336
[00:01:16.185,791] <info> time_sync: 8763, 10, 30940    timestamp: 77376
[00:01:16.225,769] <info> time_sync: 8763, 26, 30940    timestamp: 77416
[00:01:16.265,808] <info> time_sync: 8777, 3, 30979    timestamp: 77456
[00:01:16.305,786] <info> time_sync: 8781, 6, 30992    timestamp: 77496
[00:01:16.345,764] <info> time_sync: 8786, 9, 31005    timestamp: 77536
[00:01:16.385,803] <info> time_sync: 8791, 12, 31018    timestamp: 77576
[00:01:16.425,781] <info> time_sync: 8791, 28, 31018    timestamp: 77616
[00:01:16.465,759] <info> time_sync: 8805, 5, 31057    timestamp: 77656
[00:01:16.505,798] <info> time_sync: 8809, 8, 31070    timestamp: 77696
[00:01:16.545,776] <info> time_sync: 8814, 11, 31083    timestamp: 77736
[00:01:16.585,815] <info> time_sync: 8814, 27, 31083    timestamp: 77776
[00:01:16.625,793] <info> time_sync: 8828, 4, 31122    timestamp: 77816
[00:01:16.665,771] <info> time_sync: 8833, 7, 31135    timestamp: 77856
[00:01:16.705,810] <info> time_sync: 8837, 10, 31148    timestamp: 77896
[00:01:16.745,788] <info> time_sync: 8837, 26, 31148    timestamp: 77936
[00:01:16.785,827] <info> time_sync: 8851, 3, 31187    timestamp: 77976
[00:01:16.825,805] <info> time_sync: 8856, 6, 31200    timestamp: 78016
[00:01:16.865,783] <info> time_sync: 8861, 9, 31213    timestamp: 78056
[00:01:16.905,822] <info> time_sync: 8866, 12, 31226    timestamp: 78096
[00:01:16.945,800] <info> time_sync: 8866, 28, 31226    timestamp: 78136
[00:01:16.985,839] <info> time_sync: 8879, 5, 31265    timestamp: 78176
[00:01:17.025,817] <info> time_sync: 8884, 8, 31278    timestamp: 78216
[00:01:17.065,795] <info> time_sync: 8888, 11, 31291    timestamp: 78256
[00:01:17.105,834] <info> time_sync: 8888, 27, 31291    timestamp: 78296
[00:01:17.145,812] <info> time_sync: 8903, 4, 31330    timestamp: 78336
[00:01:17.185,852] <info> time_sync: 8907, 7, 31343    timestamp: 78376
[00:01:17.225,830] <info> time_sync: 8912, 10, 31356    timestamp: 78416
[00:01:17.265,808] <info> time_sync: 8920, 26, 31356    timestamp: 78456
[00:01:17.305,847] <info> time_sync: 8925, 3, 31395    timestamp: 78496
[00:01:17.345,825] <info> time_sync: 8931, 5, 31408    timestamp: 78533
[00:01:17.385,803] <info> time_sync: 8936, 8, 31421    timestamp: 78573
[00:01:17.425,842] <info> time_sync: 8936, 24, 31421    timestamp: 78613
[00:01:17.465,820] <info> time_sync: 8936, 40, 31421    timestamp: 78653
[00:01:17.505,859] <info> time_sync: 8936, 56, 31421    timestamp: 78693
[00:01:17.545,837] <info> time_sync: 8936, 72, 31421    timestamp: 78733
[00:01:17.585,815] <info> time_sync: 8936, 88, 31421    timestamp: 78773
[00:01:17.625,854] <info> time_sync: 8936, 104, 31421    timestamp: 78813
[00:01:17.665,832] <info> time_sync: 8936, 120, 31421    timestamp: 78853
[00:01:17.705,871] <info> time_sync: 8936, 136, 31421    timestamp: 78893
[00:01:17.745,849] <info> time_sync: 8936, 152, 31421    timestamp: 78933
[00:01:17.785,827] <info> time_sync: 8936, 168, 31421    timestamp: 78973
[00:01:17.825,866] <info> time_sync: 8936, 184, 31421    timestamp: 79013
[00:01:17.865,844] <info> time_sync: 8936, 200, 31421    timestamp: 79053
[00:01:17.905,883] <info> time_sync: 8936, 216, 31421    timestamp: 79093
[00:01:17.945,861] <info> time_sync: 8936, 232, 31421    timestamp: 79133
[00:01:17.985,839] <info> time_sync: 8936, 248, 31421    timestamp: 79173
[00:01:18.025,878] <info> time_sync: 8936, 264, 31421    timestamp: 79213
[00:01:18.065,856] <info> time_sync: 8936, 280, 31421    timestamp: 79253
[00:01:18.105,895] <info> time_sync: 8936, 296, 31421    timestamp: 79293
[00:01:18.145,874] <info> time_sync: 8936, 312, 31421    timestamp: 79333
[00:01:18.185,852] <info> time_sync: 8936, 328, 31421    timestamp: 79373
[00:01:18.225,891] <info> time_sync: 8936, 344, 31421    timestamp: 79413
[00:01:18.265,869] <info> time_sync: 8936, 360, 31421    timestamp: 79453
[00:01:18.305,847] <info> time_sync: 8936, 376, 31421    timestamp: 79493
[00:01:18.345,886] <info> time_sync: 8936, 392, 31421    timestamp: 79533
[00:01:18.385,864] <info> time_sync: 8936, 408, 31421    timestamp: 79573
[00:01:18.425,903] <info> time_sync: 8936, 424, 31421    timestamp: 79613
[00:01:18.465,881] <info> time_sync: 8936, 440, 31421    timestamp: 79653
[00:01:18.505,859] <info> time_sync: 8936, 456, 31421    timestamp: 79693
[00:01:18.545,898] <info> time_sync: 8936, 472, 31421    timestamp: 79733
[00:01:18.585,876] <info> time_sync: 8936, 488, 31421    timestamp: 79773
[00:01:18.625,915] <info> time_sync: 8936, 504, 31421    timestamp: 79813
[00:01:18.665,893] <info> time_sync: 8936, 520, 31421    timestamp: 79853

You can see that the offset happend in line 32. Each timestamp should have a gap of 40 ms to the next timestamp. From line 32 to 33 there is only a gap of 37ms.

Central side

On the central side I am using the timestamp function every 1ms. This is the log:

<info> time_sync: 639, 31360, 0    timestamp: 78400
<info> time_sync: 16639, 31360, 0    timestamp: 78401
<info> time_sync: 32639, 31360, 0    timestamp: 78402
<info> time_sync: 8639, 31361, 0    timestamp: 78403
<info> time_sync: 24639, 31361, 0    timestamp: 78404
<info> time_sync: 639, 31362, 0    timestamp: 78405
<info> time_sync: 16640, 31362, 0    timestamp: 78406
<info> time_sync: 32639, 31362, 0    timestamp: 78407
<info> time_sync: 8639, 31363, 0    timestamp: 78408
<info> time_sync: 24639, 31363, 0    timestamp: 78409
<info> time_sync: 639, 31364, 0    timestamp: 78410
<info> time_sync: 16641, 31364, 0    timestamp: 78411
<info> time_sync: 32636, 31364, 0    timestamp: 78412
<info> time_sync: 8640, 31365, 0    timestamp: 78413
<info> time_sync: 24639, 31365, 0    timestamp: 78414
<info> time_sync: 639, 31366, 0    timestamp: 78415
<info> time_sync: 16639, 31366, 0    timestamp: 78416
<info> time_sync: 32640, 31366, 0    timestamp: 78417
<info> time_sync: 8639, 31367, 0    timestamp: 78418
<info> time_sync: 24639, 31367, 0    timestamp: 78419
<info> time_sync: 16640, 31368, 0    timestamp: 78421
<info> time_sync: 32635, 31368, 0    timestamp: 78422
<info> time_sync: 9965, 31369, 0    timestamp: 78423
<info> time_sync: 24639, 31369, 0    timestamp: 78424
<info> time_sync: 639, 31370, 0    timestamp: 78425
<info> time_sync: 16639, 31370, 0    timestamp: 78426
<info> time_sync: 32639, 31370, 0    timestamp: 78427
<info> time_sync: 8639, 31371, 0    timestamp: 78428
<info> time_sync: 24640, 31371, 0    timestamp: 78429
<info> time_sync: 635, 31372, 0    timestamp: 78430
<info> time_sync: 16639, 31372, 0    timestamp: 78431
<info> time_sync: 32639, 31372, 0    timestamp: 78432
<info> time_sync: 8639, 31373, 0    timestamp: 78433
<info> time_sync: 24639, 31373, 0    timestamp: 78434
<info> time_sync: 640, 31374, 0    timestamp: 78435
<info> time_sync: 16635, 31374, 0    timestamp: 78436
<info> time_sync: 32639, 31374, 0    timestamp: 78437
<info> time_sync: 8639, 31375, 0    timestamp: 78438
<info> time_sync: 24639, 31375, 0    timestamp: 78439
<info> time_sync: 639, 31376, 0    timestamp: 78440
<info> time_sync: 16640, 31376, 0    timestamp: 78441
<info> time_sync: 32635, 31376, 0    timestamp: 78442
<info> time_sync: 8639, 31377, 0    timestamp: 78443
<info> time_sync: 24639, 31377, 0    timestamp: 78444
<info> time_sync: 639, 31378, 0    timestamp: 78445
<info> time_sync: 32640, 31378, 0    timestamp: 78447
<info> time_sync: 8635, 31379, 0    timestamp: 78448
<info> time_sync: 24635, 31379, 0    timestamp: 78449
<info> time_sync: 639, 31380, 0    timestamp: 78450
<info> time_sync: 16640, 31380, 0    timestamp: 78451
<info> time_sync: 32638, 31380, 0    timestamp: 78452
<info> time_sync: 8640, 31381, 0    timestamp: 78453
<info> app: diff: 40
<info> time_sync: 24657, 31381, 0    timestamp: 78454
<info> app: diff: 40
<info> time_sync: 7619, 31382, 0    timestamp: 78455
<info> time_sync: 16634, 31382, 0    timestamp: 78456
<info> time_sync: 32634, 31382, 0    timestamp: 78457
<info> time_sync: 8628, 31383, 0    timestamp: 78458
<info> time_sync: 24632, 31383, 0    timestamp: 78459
<info> time_sync: 632, 31384, 0    timestamp: 78460
<info> time_sync: 16634, 31384, 0    timestamp: 78461
<info> time_sync: 32634, 31384, 0    timestamp: 78462
<info> time_sync: 10198, 31385, 0    timestamp: 78463
<info> time_sync: 24639, 31387, 0    timestamp: 78469
<info> time_sync: 637, 31388, 0    timestamp: 78470
<info> time_sync: 16641, 31388, 0    timestamp: 78471
<info> time_sync: 32636, 31388, 0    timestamp: 78472
<info> time_sync: 8639, 31389, 0    timestamp: 78473
<info> time_sync: 24639, 31389, 0    timestamp: 78474
<info> time_sync: 639, 31390, 0    timestamp: 78475
<info> time_sync: 16639, 31390, 0    timestamp: 78476
<info> time_sync: 32639, 31390, 0    timestamp: 78477
<info> time_sync: 8639, 31391, 0    timestamp: 78478
<info> time_sync: 24639, 31391, 0    timestamp: 78479
<info> time_sync: 640, 31392, 0    timestamp: 78480
<info> time_sync: 16639, 31392, 0    timestamp: 78481
<info> time_sync: 32639, 31392, 0    timestamp: 78482
<info> time_sync: 8639, 31393, 0    timestamp: 78483
<info> time_sync: 24639, 31393, 0    timestamp: 78484
<info> time_sync: 639, 31394, 0    timestamp: 78485
<info> time_sync: 16638, 31394, 0    timestamp: 78486
<info> time_sync: 32639, 31394, 0    timestamp: 78487
<info> time_sync: 24640, 31395, 0    timestamp: 78489
<info> time_sync: 635, 31396, 0    timestamp: 78490
<info> time_sync: 16641, 31396, 0    timestamp: 78491
<info> time_sync: 32638, 31396, 0    timestamp: 78492
<info> time_sync: 8640, 31397, 0    timestamp: 78493
<info> app: diff: 40
<info> time_sync: 24639, 31397, 0    timestamp: 78494
<info> time_sync: 637, 31398, 0    timestamp: 78495
<info> time_sync: 16634, 31398, 0    timestamp: 78496
<info> time_sync: 32628, 31398, 0    timestamp: 78497
<info> time_sync: 8628, 31399, 0    timestamp: 78498
<info> time_sync: 24633, 31399, 0    timestamp: 78499
<info> time_sync: 634, 31400, 0    timestamp: 78500
<info> time_sync: 16633, 31400, 0    timestamp: 78501
<info> time_sync: 32639, 31400, 0    timestamp: 78502
<info> time_sync: 24639, 31403, 0    timestamp: 78509
<info> time_sync: 639, 31404, 0    timestamp: 78510
<info> time_sync: 16639, 31404, 0    timestamp: 78511
<info> time_sync: 32639, 31404, 0    timestamp: 78512
<info> time_sync: 8639, 31405, 0    timestamp: 78513
<info> time_sync: 24639, 31405, 0    timestamp: 78514
<info> time_sync: 639, 31406, 0    timestamp: 78515
<info> time_sync: 16639, 31406, 0    timestamp: 78516
<info> time_sync: 32639, 31406, 0    timestamp: 78517
<info> time_sync: 8639, 31407, 0    timestamp: 78518
<info> time_sync: 24638, 31407, 0    timestamp: 78519
<info> time_sync: 645, 31408, 0    timestamp: 78520
<info> time_sync: 16640, 31408, 0    timestamp: 78521
<info> time_sync: 32639, 31408, 0    timestamp: 78522
<info> time_sync: 8639, 31409, 0    timestamp: 78523
<info> time_sync: 24639, 31409, 0    timestamp: 78524
<info> time_sync: 639, 31410, 0    timestamp: 78525
<info> time_sync: 16639, 31410, 0    timestamp: 78526
<info> time_sync: 32639, 31410, 0    timestamp: 78527
<info> time_sync: 8640, 31411, 0    timestamp: 78528
<info> time_sync: 24639, 31411, 0    timestamp: 78529
<info> time_sync: 639, 31412, 0    timestamp: 78530
<info> time_sync: 16640, 31412, 0    timestamp: 78531
<info> time_sync: 32638, 31412, 0    timestamp: 78532
<info> time_sync: 8640, 31413, 0    timestamp: 78533
<info> app: diff: 40
<info> time_sync: 24639, 31413, 0    timestamp: 78534
<info> time_sync: 665, 31414, 0    timestamp: 78535
<info> time_sync: 16704, 31414, 0    timestamp: 78536
<info> time_sync: 32637, 31414, 0    timestamp: 78537
<info> time_sync: 8634, 31415, 0    timestamp: 78538
<info> time_sync: 24628, 31415, 0    timestamp: 78539
<info> time_sync: 639, 31416, 0    timestamp: 78540
<info> time_sync: 16639, 31416, 0    timestamp: 78541
<info> time_sync: 32639, 31418, 0    timestamp: 78547
<info> time_sync: 8639, 31419, 0    timestamp: 78548
<info> time_sync: 24639, 31419, 0    timestamp: 78549
<info> time_sync: 639, 31420, 0    timestamp: 78550
<info> time_sync: 16638, 31420, 0    timestamp: 78551
<info> time_sync: 32639, 31420, 0    timestamp: 78552
<info> time_sync: 8640, 31421, 0    timestamp: 78553
<info> time_sync: 24639, 31421, 0    timestamp: 78554
<info> time_sync: 639, 31422, 0    timestamp: 78555
<info> time_sync: 16639, 31422, 0    timestamp: 78556
<info> time_sync: 32639, 31422, 0    timestamp: 78557
<info> time_sync: 8639, 31423, 0    timestamp: 78558
<info> time_sync: 24639, 31423, 0    timestamp: 78559
<info> time_sync: 639, 31424, 0    timestamp: 78560
<info> time_sync: 16639, 31424, 0    timestamp: 78561
<info> time_sync: 32639, 31424, 0    timestamp: 78562
<info> time_sync: 8639, 31425, 0    timestamp: 78563
<info> time_sync: 24639, 31425, 0    timestamp: 78564
<info> time_sync: 639, 31426, 0    timestamp: 78565
<info> time_sync: 16640, 31426, 0    timestamp: 78566
<info> time_sync: 32639, 31426, 0    timestamp: 78567
<info> time_sync: 8639, 31427, 0    timestamp: 78568
<info> time_sync: 24639, 31427, 0    timestamp: 78569
<info> time_sync: 639, 31428, 0    timestamp: 78570
<info> time_sync: 16641, 31428, 0    timestamp: 78571
<info> time_sync: 32636, 31428, 0    timestamp: 78572
<info> time_sync: 8640, 31429, 0    timestamp: 78573
<info> app: diff: 37

I use "diff" to catch the offset. The variable "diff" shows the difference between the timestamp value of two received NUS pakets. If this difference is higher than 41 or smaller than 39, the program generates an error.

I am using TIME_SYNC_FREQ_AUTO as sync frequency.

Hopefully this helps to narrow down my issue. If you need anything more, please let me know.

I am looking forward to hearing from you. Thank you very much in advance.

Best regards,

Michael

[Audun]

Hi Michael,

thanks for the logs! This was very helpful.

The NRF_LOG timestamp, which uses the 32 kHz RTC, confirms that the timestamp function is called every 40 ms.

The "sync_timer_val" value is pretty much equal in every printout, which looks good for a printout interval of 40 ms, or 16 * 40000 (timer max value).

The "peer_count" value is changing right around where the problem occurs, which I think makes i more likely that there is a race condition when the timestamp function is called at the same time as a local timer adjustment is being made.

I think the underlying problem might be that the timestamp function was not updated with an appropriate critical section during a previous code refactoring. Receiver time adjustment is essentially a two-step process, where the first step is using PPI (hardware) to adjust the running timers, and the second step is to update the m_master_counter variable. If the timestamp function is run in between these two steps, there could be an offset.

I don't quite understand why the offset lasts for 10 seconds, but I see that the log that the "peer_count" value stays the same from line 34 and on, which means there either isn't any more sync packets from the transmitter received, or that there is an issue with appying a received packet.

Either way, since you are calling the timestamp function from a lower priority that SWI3_EGU3_IRQHandler, I recommend trying the following change:

static void timers_capture(uint32_t * p_sync_timer_val, uint32_t * p_count_timer_val, uint32_t * p_peer_counter)
{
    static nrf_atomic_flag_t m_timestamp_capture_flag = 0;

    uint32_t peer_counter;
    nrf_atomic_flag_t adjustment_in_progress;

    if (nrf_atomic_flag_set_fetch(&m_timestamp_capture_flag) != 0)
    {
        // Not thread-safe
        APP_ERROR_CHECK_BOOL(false);
    }

    nrf_ppi_channel_t ppi_chn;
    nrfx_err_t ret = nrfx_ppi_channel_alloc(&ppi_chn);
    ASSERT(ret == NRFX_SUCCESS);

    ppi_counter_timer_capture_configure(ppi_chn);

    // Make sure current execution priority is lower than EGU IRQ
    APP_ERROR_CHECK_BOOL(current_int_priority_get() > TIME_SYNC_EVT_HANDLER_IRQ_PRIORITY);

    // Loop until adjustment is no longer in progress
    // NOTE: Only works when this function is called from a lower priority than the EGU IRQ.
    do
    {
        // Critical section begin
        NVIC_DisableIRQ(RADIO_IRQn);
        NVIC_DisableIRQ(m_params.egu_irq_type);

        adjustment_in_progress = m_timer_update_in_progress;
        if (!adjustment_in_progress) {
            m_params.egu->TASKS_TRIGGER[1] = 1;
            (void) m_params.egu->EVENTS_TRIGGERED[1];
            peer_counter = m_master_counter;
        }

        // Critical section end
        NVIC_EnableIRQ(RADIO_IRQn);
        NVIC_EnableIRQ(m_params.egu_irq_type);
    } while (adjustment_in_progress);

    ppi_counter_timer_capture_disable(ppi_chn);
    nrfx_ppi_channel_free(ppi_chn);

    *p_sync_timer_val  = m_params.high_freq_timer[0]->CC[3];
    *p_count_timer_val = (m_params.high_freq_timer[1]->CC[0]);
    *p_peer_counter    = peer_counter;

    nrf_atomic_flag_clear(&m_timestamp_capture_flag);
}

Note: I have not been able to properly test this code yet (home office woes).

Also note: the ts_set_trigger() calls in the original code will start producing errors with this code change. So comment out these functions if they are still there (and you're not using them, that is)

Edit: Expanded critical section to also stop radio IRQ

Edit 2: This change will create a fairly long worst-case duration for the timestamp function, but I think its worth testing this out now to see if the race condition theory is correct, and then look for a better solution once the issue is confirmed.