This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

How to access the TIMER3 in wireless timer sync?

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.

  • 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

  • Hello Audun,

    thank you very much for your reply.

    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?

    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.

    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

  • 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

  • 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

  • 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.

Related