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.

[Michael01101]

Hello Audun,

thank you very much for your detailed reply. I really appreciate your help.

Audun said:

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.

This is caused by the procedure how I catched the offset in my previous reply. I generated an error at the central when the offset occurs to catch the relevant debug data. So the central stopped transmitting sync beacons when the offset occured.

I swapped my previous timers_capture() function with your timers_capture() function. Unfortunately, this does not solve the offset issue.

You can see the debug logs for the peripheral and the central in the following. These logs are generated with your recommended timers_capture() function. I also delayed the generation of the error on my central when the offset occurs. So the central does not stop immediatly transmitting sync beacons. Instead the central continues sending sync beacons for ~560ms after the offset occured before the central stops itself.

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

Peripheral

This is the debug log on the peripheral side.

[00:05:18.499,877] <info> time_sync: 39602, 5, 539575    timestamp: 1348952
[00:05:18.539,855] <info> time_sync: 39608, 8, 539588    timestamp: 1348992
[00:05:18.579,895] <info> time_sync: 39607, 24, 539588    timestamp: 1349032
[00:05:18.619,873] <info> time_sync: 39620, 1, 539627    timestamp: 1349072
[00:05:18.659,851] <info> time_sync: 39625, 4, 539640    timestamp: 1349112
[00:05:18.699,890] <info> time_sync: 39630, 7, 539653    timestamp: 1349152
[00:05:18.739,868] <info> time_sync: 39634, 10, 539666    timestamp: 1349192
[00:05:18.779,907] <info> time_sync: 39634, 26, 539666    timestamp: 1349232
[00:05:18.819,885] <info> time_sync: 39648, 3, 539705    timestamp: 1349272
[00:05:18.859,863] <info> time_sync: 39653, 6, 539718    timestamp: 1349312
[00:05:18.899,902] <info> time_sync: 39657, 9, 539731    timestamp: 1349352
[00:05:18.939,880] <info> time_sync: 39657, 25, 539731    timestamp: 1349392
[00:05:18.979,919] <info> time_sync: 39672, 2, 539770    timestamp: 1349432
[00:05:19.019,897] <info> time_sync: 39675, 5, 539783    timestamp: 1349472
[00:05:19.059,875] <info> time_sync: 39680, 8, 539796    timestamp: 1349512
[00:05:19.099,914] <info> time_sync: 39680, 24, 539796    timestamp: 1349552
[00:05:19.139,892] <info> time_sync: 39694, 1, 539835    timestamp: 1349592
[00:05:19.179,931] <info> time_sync: 39698, 4, 539848    timestamp: 1349632
[00:05:19.219,909] <info> time_sync: 39703, 7, 539861    timestamp: 1349672
[00:05:19.259,887] <info> time_sync: 39707, 10, 539874    timestamp: 1349712
[00:05:19.299,926] <info> time_sync: 39707, 26, 539874    timestamp: 1349752
[00:05:19.339,904] <info> time_sync: 39721, 3, 539913    timestamp: 1349792
[00:05:19.379,882] <info> time_sync: 39726, 6, 539926    timestamp: 1349832
[00:05:19.419,921] <info> time_sync: 39731, 9, 539939    timestamp: 1349872
[00:05:19.459,899] <info> time_sync: 39730, 25, 539939    timestamp: 1349912
[00:05:19.499,938] <info> time_sync: 39744, 2, 539978    timestamp: 1349952
[00:05:19.539,916] <info> time_sync: 39748, 5, 539991    timestamp: 1349992
[00:05:19.579,895] <info> time_sync: 39753, 8, 540004    timestamp: 1350032
[00:05:19.619,934] <info> time_sync: 39753, 24, 540004    timestamp: 1350072
[00:05:19.659,912] <info> time_sync: 39767, 1, 540043    timestamp: 1350112
[00:05:19.699,951] <info> time_sync: 39771, 4, 540056    timestamp: 1350152
[00:05:19.739,929] <info> time_sync: 39776, 7, 540069    timestamp: 1350192
[00:05:19.779,907] <info> time_sync: 39781, 10, 540082    timestamp: 1350232
[00:05:19.819,946] <info> time_sync: 39781, 26, 540082    timestamp: 1350272
[00:05:19.859,924] <info> time_sync: 39795, 3, 540121    timestamp: 1350312
[00:05:19.899,963] <info> time_sync: 39799, 6, 540134    timestamp: 1350352
[00:05:19.939,941] <info> time_sync: 39803, 9, 540147    timestamp: 1350392
[00:05:19.979,919] <info> time_sync: 39803, 25, 540147    timestamp: 1350432
[00:05:20.019,958] <info> time_sync: 39818, 2, 540186    timestamp: 1350472
[00:05:20.059,936] <info> time_sync: 39822, 5, 540199    timestamp: 1350512
[00:05:20.099,975] <info> time_sync: 39826, 8, 540212    timestamp: 1350552
[00:05:20.139,953] <info> time_sync: 39826, 24, 540212    timestamp: 1350592
[00:05:20.179,931] <info> time_sync: 39840, 1, 540251    timestamp: 1350632
[00:05:20.219,970] <info> time_sync: 39844, 4, 540264    timestamp: 1350672
[00:05:20.259,948] <info> time_sync: 39849, 7, 540277    timestamp: 1350712
[00:05:20.299,926] <info> time_sync: 39854, 10, 540290    timestamp: 1350752
[00:05:20.339,965] <info> time_sync: 39853, 26, 540290    timestamp: 1350792
[00:05:20.379,943] <info> time_sync: 39867, 3, 540329    timestamp: 1350832
[00:05:20.419,982] <info> time_sync: 39872, 6, 540342    timestamp: 1350872
[00:05:20.459,960] <info> time_sync: 39876, 9, 540355    timestamp: 1350912
[00:05:20.499,938] <info> time_sync: 39876, 25, 540355    timestamp: 1350952
[00:05:20.539,978] <info> time_sync: 39890, 2, 540394    timestamp: 1350992
[00:05:20.579,956] <info> time_sync: 39895, 5, 540407    timestamp: 1351032
[00:05:20.619,995] <info> time_sync: 39900, 8, 540420    timestamp: 1351072
[00:05:20.659,973] <info> time_sync: 39900, 24, 540420    timestamp: 1351112
[00:05:20.699,951] <info> time_sync: 39913, 1, 540459    timestamp: 1351152
[00:05:20.739,990] <info> time_sync: 39918, 4, 540472    timestamp: 1351192
[00:05:20.779,968] <info> time_sync: 39922, 7, 540485    timestamp: 1351232
[00:05:20.820,007] <info> time_sync: 39927, 10, 540498    timestamp: 1351272
[00:05:20.859,985] <info> time_sync: 39927, 26, 540498    timestamp: 1351312
[00:05:20.899,963] <info> time_sync: 39940, 3, 540537    timestamp: 1351352
[00:05:20.940,002] <info> time_sync: 39945, 6, 540550    timestamp: 1351392
[00:05:20.979,980] <info> time_sync: 39949, 9, 540563    timestamp: 1351432
[00:05:21.020,019] <info> time_sync: 39949, 25, 540563    timestamp: 1351472
[00:05:21.059,997] <info> time_sync: 39964, 2, 540602    timestamp: 1351512
[00:05:21.099,975] <info> time_sync: 39968, 5, 540615    timestamp: 1351552
[00:05:21.140,014] <info> time_sync: 39972, 8, 540628    timestamp: 1351592
[00:05:21.179,992] <info> time_sync: 39973, 24, 540628    timestamp: 1351632
[00:05:21.219,970] <info> time_sync: 39986, 1, 540667    timestamp: 1351672
[00:05:21.260,009] <info> time_sync: 39990, 4, 540680    timestamp: 1351712
[00:05:21.299,987] <info> time_sync: 39995, 7, 540693    timestamp: 1351752
[00:05:21.340,026] <info> time_sync: 0, 10, 540706    timestamp: 1351790
[00:05:21.380,004] <info> time_sync: 0, 26, 540706    timestamp: 1351830
[00:05:21.419,982] <info> time_sync: 14, 4, 540745    timestamp: 1351873
[00:05:21.460,021] <info> time_sync: 18, 7, 540758    timestamp: 1351913
[00:05:21.500,000] <info> time_sync: 23, 10, 540771    timestamp: 1351953
[00:05:21.540,039] <info> time_sync: 23, 26, 540771    timestamp: 1351993
[00:05:21.580,017] <info> time_sync: 36, 3, 540810    timestamp: 1352033
[00:05:21.619,995] <info> time_sync: 42, 6, 540823    timestamp: 1352073
[00:05:21.660,034] <info> time_sync: 45, 9, 540836    timestamp: 1352113
[00:05:21.700,012] <info> time_sync: 45, 25, 540836    timestamp: 1352153
[00:05:21.740,051] <info> time_sync: 59, 2, 540875    timestamp: 1352193
[00:05:21.780,029] <info> time_sync: 64, 5, 540888    timestamp: 1352233
[00:05:21.820,007] <info> time_sync: 68, 8, 540901    timestamp: 1352273
[00:05:21.860,046] <info> time_sync: 73, 11, 540914    timestamp: 1352313
[00:05:21.900,024] <info> time_sync: 73, 27, 540914    timestamp: 1352353
[00:05:21.940,063] <info> time_sync: 86, 4, 540953    timestamp: 1352393
[00:05:21.980,041] <info> time_sync: 74, 20, 540953    timestamp: 1352433
[00:05:22.020,019] <info> time_sync: 74, 36, 540953    timestamp: 1352473
[00:05:22.060,058] <info> time_sync: 74, 52, 540953    timestamp: 1352513
[00:05:22.100,036] <info> time_sync: 74, 68, 540953    timestamp: 1352553
[00:05:22.140,014] <info> time_sync: 74, 84, 540953    timestamp: 1352593
[00:05:22.180,053] <info> time_sync: 74, 100, 540953    timestamp: 1352633
[00:05:22.220,031] <info> time_sync: 74, 116, 540953    timestamp: 1352673
[00:05:22.260,070] <info> time_sync: 74, 132, 540953    timestamp: 1352713
[00:05:22.300,048] <info> time_sync: 74, 148, 540953    timestamp: 1352753
[00:05:22.340,026] <info> time_sync: 74, 164, 540953    timestamp: 1352793
[00:05:22.380,065] <info> time_sync: 74, 180, 540953    timestamp: 1352833
[00:05:22.420,043] <info> time_sync: 74, 196, 540953    timestamp: 1352873
[00:05:22.460,083] <info> time_sync: 74, 212, 540953    timestamp: 1352913
[00:05:22.500,061] <info> time_sync: 74, 228, 540953    timestamp: 1352953
[00:05:22.540,039] <info> time_sync: 74, 244, 540953    timestamp: 1352993
[00:05:22.580,078] <info> time_sync: 74, 260, 540953    timestamp: 1353033
[00:05:22.620,056] <info> time_sync: 74, 276, 540953    timestamp: 1353073
[00:05:22.660,095] <info> time_sync: 74, 292, 540953    timestamp: 1353113
[00:05:22.700,073] <info> time_sync: 74, 308, 540953    timestamp: 1353153
[00:05:22.740,051] <info> time_sync: 74, 324, 540953    timestamp: 1353193
[00:05:22.780,090] <info> time_sync: 74, 340, 540953    timestamp: 1353233
[00:05:22.820,068] <info> time_sync: 74, 356, 540953    timestamp: 1353273
[00:05:22.860,046] <info> time_sync: 74, 372, 540953    timestamp: 1353313
[00:05:22.900,085] <info> time_sync: 74, 388, 540953    timestamp: 1353353
[00:05:22.940,063] <info> time_sync: 74, 404, 540953    timestamp: 1353393
[00:05:22.980,102] <info> time_sync: 74, 420, 540953    timestamp: 1353433
[00:05:23.020,080] <info> time_sync: 74, 436, 540953    timestamp: 1353473
[00:05:23.060,058] <info> time_sync: 74, 452, 540953    timestamp: 1353513
[00:05:23.100,097] <info> time_sync: 74, 468, 540953    timestamp: 1353553
[00:05:23.140,075] <info> time_sync: 74, 484, 540953    timestamp: 1353593
[00:05:23.180,114] <info> time_sync: 74, 500, 540953    timestamp: 1353633
[00:05:23.220,092] <info> time_sync: 74, 516, 540953    timestamp: 1353673

You can see that the offset happened in line 72. We can also see that the peripheral still receives the beacon sync pakets until line 87. At this point the central stops sending sync beacons as a consequence of the selfmade error to catch the relevant debug data. So the peripheral can not receive any sync beacon pakets anymore, because there are none.

It is also interesting that the offset occures when the sync_timer_val goes to zero.

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

Central

This is the debug log on the central side. The debug log is the corresponding one to debug log of the peripheral, which I descriped a few lines earlier.

This is pretty much the same as in my previous reply.

<info> time_sync: 32680, 540718, 0    timestamp: 1351797
<info> time_sync: 8651, 540719, 0    timestamp: 1351798
<info> time_sync: 16656, 540722, 0    timestamp: 1351806
<info> time_sync: 32656, 540722, 0    timestamp: 1351807
<info> time_sync: 8656, 540723, 0    timestamp: 1351808
<info> time_sync: 24656, 540723, 0    timestamp: 1351809
<info> time_sync: 656, 540724, 0    timestamp: 1351810
<info> time_sync: 16656, 540724, 0    timestamp: 1351811
<info> time_sync: 32656, 540724, 0    timestamp: 1351812
<info> time_sync: 8656, 540725, 0    timestamp: 1351813
<info> time_sync: 24656, 540725, 0    timestamp: 1351814
<info> time_sync: 656, 540726, 0    timestamp: 1351815
<info> time_sync: 16656, 540726, 0    timestamp: 1351816
<info> time_sync: 32656, 540726, 0    timestamp: 1351817
<info> time_sync: 8656, 540727, 0    timestamp: 1351818
<info> time_sync: 24656, 540727, 0    timestamp: 1351819
<info> time_sync: 656, 540728, 0    timestamp: 1351820
<info> time_sync: 16656, 540728, 0    timestamp: 1351821
<info> time_sync: 32657, 540728, 0    timestamp: 1351822
<info> time_sync: 8656, 540729, 0    timestamp: 1351823
<info> time_sync: 24656, 540729, 0    timestamp: 1351824
<info> time_sync: 656, 540730, 0    timestamp: 1351825
<info> time_sync: 32657, 540730, 0    timestamp: 1351827
<info> time_sync: 8647, 540731, 0    timestamp: 1351828
<info> time_sync: 24657, 540731, 0    timestamp: 1351829
<info> time_sync: 656, 540732, 0    timestamp: 1351830
<info> time_sync: 16656, 540732, 0    timestamp: 1351831
<info> app: diff: 38
<info> time_sync: 34937, 540732, 0    timestamp: 1351832
<info> app: Zeit bei Emfpfang: 1351832 ms
<info> time_sync: 37943, 540732, 0    timestamp: 1351832
<info> time_sync: 8654, 540733, 0    timestamp: 1351833
<info> time_sync: 24770, 540733, 0    timestamp: 1351834
<info> time_sync: 733, 540734, 0    timestamp: 1351835
<info> time_sync: 16680, 540734, 0    timestamp: 1351836
<info> time_sync: 32728, 540734, 0    timestamp: 1351837
<info> time_sync: 8648, 540735, 0    timestamp: 1351838
<info> time_sync: 32656, 540738, 0    timestamp: 1351847
<info> time_sync: 8656, 540739, 0    timestamp: 1351848
<info> time_sync: 24656, 540739, 0    timestamp: 1351849
<info> time_sync: 656, 540740, 0    timestamp: 1351850
<info> time_sync: 16656, 540740, 0    timestamp: 1351851
<info> time_sync: 32656, 540740, 0    timestamp: 1351852
<info> time_sync: 8656, 540741, 0    timestamp: 1351853
<info> time_sync: 24656, 540741, 0    timestamp: 1351854
<info> time_sync: 656, 540742, 0    timestamp: 1351855
<info> time_sync: 16656, 540742, 0    timestamp: 1351856
<info> time_sync: 32656, 540742, 0    timestamp: 1351857
<info> time_sync: 8656, 540743, 0    timestamp: 1351858
<info> time_sync: 24656, 540743, 0    timestamp: 1351859
<info> time_sync: 656, 540744, 0    timestamp: 1351860
<info> time_sync: 16655, 540744, 0    timestamp: 1351861
<info> time_sync: 32656, 540744, 0    timestamp: 1351862
<info> time_sync: 8655, 540745, 0    timestamp: 1351863
<info> time_sync: 24657, 540745, 0    timestamp: 1351864
<info> time_sync: 647, 540746, 0    timestamp: 1351865
<info> time_sync: 16656, 540746, 0    timestamp: 1351866
<info> time_sync: 32656, 540746, 0    timestamp: 1351867
<info> time_sync: 24657, 540747, 0    timestamp: 1351869
<info> time_sync: 647, 540748, 0    timestamp: 1351870
<info> time_sync: 16657, 540748, 0    timestamp: 1351871
<info> app: diff: 40
<info> time_sync: 37541, 540748, 0    timestamp: 1351872
<info> time_sync: 8804, 540749, 0    timestamp: 1351873
<info> time_sync: 24655, 540749, 0    timestamp: 1351874
<info> time_sync: 716, 540750, 0    timestamp: 1351875
<info> time_sync: 16697, 540750, 0    timestamp: 1351876
<info> time_sync: 32655, 540752, 0    timestamp: 1351882
<info> time_sync: 8656, 540753, 0    timestamp: 1351883
<info> time_sync: 24656, 540753, 0    timestamp: 1351884
<info> time_sync: 656, 540754, 0    timestamp: 1351885
<info> time_sync: 16656, 540754, 0    timestamp: 1351886
<info> time_sync: 32656, 540754, 0    timestamp: 1351887
<info> time_sync: 8656, 540755, 0    timestamp: 1351888
<info> time_sync: 24656, 540755, 0    timestamp: 1351889
<info> time_sync: 656, 540756, 0    timestamp: 1351890
<info> time_sync: 16656, 540756, 0    timestamp: 1351891
<info> time_sync: 32656, 540756, 0    timestamp: 1351892
<info> time_sync: 8655, 540757, 0    timestamp: 1351893
<info> time_sync: 24656, 540757, 0    timestamp: 1351894
<info> time_sync: 655, 540758, 0    timestamp: 1351895
<info> time_sync: 16657, 540758, 0    timestamp: 1351896
<info> time_sync: 32647, 540758, 0    timestamp: 1351897
<info> time_sync: 8656, 540759, 0    timestamp: 1351898
<info> time_sync: 24656, 540759, 0    timestamp: 1351899
<info> time_sync: 656, 540760, 0    timestamp: 1351900
<info> time_sync: 16657, 540760, 0    timestamp: 1351901
<info> time_sync: 32647, 540760, 0    timestamp: 1351902
<info> time_sync: 8656, 540761, 0    timestamp: 1351903
<info> time_sync: 24656, 540761, 0    timestamp: 1351904
<info> time_sync: 656, 540764, 0    timestamp: 1351910
<info> time_sync: 16656, 540764, 0    timestamp: 1351911
<info> app: diff: 43
<info> time_sync: 35004, 540764, 0    timestamp: 1351912
<info> app: Zeit bei Emfpfang: 1351912 ms
<info> time_sync: 38010, 540764, 0    timestamp: 1351912
<info> time_sync: 8701, 540765, 0    timestamp: 1351913
<info> time_sync: 24834, 540765, 0    timestamp: 1351914
<info> time_sync: 647, 540766, 0    timestamp: 1351915
<info> time_sync: 16703, 540766, 0    timestamp: 1351916
<info> time_sync: 32825, 540766, 0    timestamp: 1351917
<info> time_sync: 8655, 540767, 0    timestamp: 1351918
<info> time_sync: 24656, 540767, 0    timestamp: 1351919
<info> time_sync: 656, 540770, 0    timestamp: 1351925
<info> time_sync: 16655, 540770, 0    timestamp: 1351926
<info> time_sync: 32656, 540770, 0    timestamp: 1351927
<info> time_sync: 8655, 540771, 0    timestamp: 1351928
<info> time_sync: 24656, 540771, 0    timestamp: 1351929
<info> time_sync: 656, 540772, 0    timestamp: 1351930
<info> time_sync: 16656, 540772, 0    timestamp: 1351931
<info> time_sync: 32656, 540772, 0    timestamp: 1351932
<info> time_sync: 8656, 540773, 0    timestamp: 1351933
<info> time_sync: 24656, 540773, 0    timestamp: 1351934
<info> time_sync: 656, 540774, 0    timestamp: 1351935
<info> time_sync: 16656, 540774, 0    timestamp: 1351936
<info> time_sync: 32656, 540774, 0    timestamp: 1351937
<info> time_sync: 8656, 540775, 0    timestamp: 1351938
<info> time_sync: 24656, 540775, 0    timestamp: 1351939
<info> time_sync: 657, 540776, 0    timestamp: 1351940
<info> time_sync: 16647, 540776, 0    timestamp: 1351941
<info> time_sync: 32656, 540776, 0    timestamp: 1351942
<info> time_sync: 8656, 540777, 0    timestamp: 1351943
<info> time_sync: 24656, 540777, 0    timestamp: 1351944
<info> time_sync: 657, 540778, 0    timestamp: 1351945
<info> time_sync: 16647, 540778, 0    timestamp: 1351946
<info> time_sync: 32656, 540778, 0    timestamp: 1351947
<info> time_sync: 24657, 540779, 0    timestamp: 1351949
<info> time_sync: 647, 540780, 0    timestamp: 1351950
<info> time_sync: 16657, 540780, 0    timestamp: 1351951
<info> app: diff: 40
<info> time_sync: 37450, 540780, 0    timestamp: 1351952
<info> time_sync: 8707, 540781, 0    timestamp: 1351953
<info> time_sync: 24832, 540781, 0    timestamp: 1351954
<info> time_sync: 830, 540782, 0    timestamp: 1351955
<info> time_sync: 16813, 540782, 0    timestamp: 1351956
<info> time_sync: 32760, 540782, 0    timestamp: 1351957
<info> time_sync: 8656, 540785, 0    timestamp: 1351963
<info> time_sync: 24656, 540785, 0    timestamp: 1351964
<info> time_sync: 656, 540786, 0    timestamp: 1351965
<info> time_sync: 16656, 540786, 0    timestamp: 1351966
<info> time_sync: 32656, 540786, 0    timestamp: 1351967
<info> time_sync: 8656, 540787, 0    timestamp: 1351968
<info> time_sync: 24656, 540787, 0    timestamp: 1351969
<info> time_sync: 656, 540788, 0    timestamp: 1351970
<info> time_sync: 16656, 540788, 0    timestamp: 1351971
<info> time_sync: 32656, 540788, 0    timestamp: 1351972
<info> time_sync: 8657, 540789, 0    timestamp: 1351973
<info> time_sync: 24647, 540789, 0    timestamp: 1351974
<info> time_sync: 656, 540790, 0    timestamp: 1351975
<info> time_sync: 16656, 540790, 0    timestamp: 1351976
<info> time_sync: 32656, 540790, 0    timestamp: 1351977
<info> time_sync: 8657, 540791, 0    timestamp: 1351978
<info> time_sync: 24656, 540791, 0    timestamp: 1351979
<info> time_sync: 24656, 540793, 0    timestamp: 1351984
<info> time_sync: 656, 540794, 0    timestamp: 1351985
<info> time_sync: 16656, 540794, 0    timestamp: 1351986
<info> time_sync: 32656, 540794, 0    timestamp: 1351987
<info> time_sync: 8656, 540795, 0    timestamp: 1351988
<info> time_sync: 24656, 540795, 0    timestamp: 1351989
<info> time_sync: 656, 540796, 0    timestamp: 1351990
<info> time_sync: 16656, 540796, 0    timestamp: 1351991
<info> app: diff: 40
<info> time_sync: 37594, 540796, 0    timestamp: 1351992
<info> time_sync: 8654, 540797, 0    timestamp: 1351993
<info> time_sync: 24749, 540797, 0    timestamp: 1351994
<info> time_sync: 696, 540798, 0    timestamp: 1351995
<info> time_sync: 16744, 540798, 0    timestamp: 1351996
<info> time_sync: 32792, 540798, 0    timestamp: 1351997
<info> time_sync: 8656, 540799, 0    timestamp: 1351998
<info> time_sync: 24657, 540799, 0    timestamp: 1351999
<info> time_sync: 656, 540800, 0    timestamp: 1352000
<info> time_sync: 32656, 540802, 0    timestamp: 1352007
<info> time_sync: 8656, 540803, 0    timestamp: 1352008
<info> time_sync: 24656, 540803, 0    timestamp: 1352009
<info> time_sync: 656, 540804, 0    timestamp: 1352010
<info> time_sync: 16656, 540804, 0    timestamp: 1352011
<info> time_sync: 32656, 540804, 0    timestamp: 1352012
<info> time_sync: 8656, 540805, 0    timestamp: 1352013
<info> time_sync: 24656, 540805, 0    timestamp: 1352014
<info> time_sync: 656, 540806, 0    timestamp: 1352015
<info> time_sync: 16656, 540806, 0    timestamp: 1352016
<info> time_sync: 32656, 540806, 0    timestamp: 1352017
<info> time_sync: 8656, 540807, 0    timestamp: 1352018
<info> time_sync: 24656, 540807, 0    timestamp: 1352019
<info> time_sync: 656, 540808, 0    timestamp: 1352020
<info> time_sync: 16657, 540808, 0    timestamp: 1352021
<info> time_sync: 32656, 540808, 0    timestamp: 1352022
<info> time_sync: 8655, 540809, 0    timestamp: 1352023
<info> time_sync: 24656, 540809, 0    timestamp: 1352024
<info> time_sync: 657, 540810, 0    timestamp: 1352025
<info> time_sync: 16656, 540810, 0    timestamp: 1352026
<info> time_sync: 32656, 540810, 0    timestamp: 1352027
<info> time_sync: 24657, 540811, 0    timestamp: 1352029
<info> time_sync: 647, 540812, 0    timestamp: 1352030
<info> time_sync: 16657, 540812, 0    timestamp: 1352031
<info> app: diff: 40
<info> time_sync: 37366, 540812, 0    timestamp: 1352032
<info> time_sync: 8654, 540813, 0    timestamp: 1352033
<info> time_sync: 24819, 540813, 0    timestamp: 1352034
<info> time_sync: 800, 540814, 0    timestamp: 1352035
<info> time_sync: 16801, 540814, 0    timestamp: 1352036
<info> time_sync: 8656, 540817, 0    timestamp: 1352043
<info> time_sync: 24656, 540817, 0    timestamp: 1352044
<info> time_sync: 656, 540818, 0    timestamp: 1352045
<info> time_sync: 16656, 540818, 0    timestamp: 1352046
<info> time_sync: 32656, 540818, 0    timestamp: 1352047
<info> time_sync: 8656, 540819, 0    timestamp: 1352048
<info> time_sync: 24656, 540819, 0    timestamp: 1352049
<info> time_sync: 656, 540820, 0    timestamp: 1352050
<info> time_sync: 16656, 540820, 0    timestamp: 1352051
<info> time_sync: 32656, 540820, 0    timestamp: 1352052
<info> time_sync: 8656, 540821, 0    timestamp: 1352053
<info> time_sync: 24656, 540821, 0    timestamp: 1352054
<info> time_sync: 656, 540822, 0    timestamp: 1352055
<info> time_sync: 16655, 540822, 0    timestamp: 1352056
<info> time_sync: 32656, 540822, 0    timestamp: 1352057
<info> time_sync: 8655, 540823, 0    timestamp: 1352058
<info> time_sync: 24656, 540823, 0    timestamp: 1352059
<info> time_sync: 657, 540824, 0    timestamp: 1352060
<info> time_sync: 16647, 540824, 0    timestamp: 1352061
<info> time_sync: 32656, 540824, 0    timestamp: 1352062
<info> time_sync: 8656, 540825, 0    timestamp: 1352063
<info> time_sync: 657, 540826, 0    timestamp: 1352065
<info> time_sync: 16647, 540826, 0    timestamp: 1352066
<info> time_sync: 32647, 540826, 0    timestamp: 1352067
<info> time_sync: 8656, 540827, 0    timestamp: 1352068
<info> time_sync: 24656, 540827, 0    timestamp: 1352069
<info> time_sync: 656, 540828, 0    timestamp: 1352070
<info> time_sync: 16656, 540828, 0    timestamp: 1352071
<info> time_sync: 35509, 540828, 0    timestamp: 1352072
<info> app: diff: 40
<info> time_sync: 8699, 540829, 0    timestamp: 1352073
<info> time_sync: 24663, 540829, 0    timestamp: 1352074
<info> time_sync: 737, 540830, 0    timestamp: 1352075
<info> time_sync: 16649, 540830, 0    timestamp: 1352076
<info> time_sync: 32648, 540830, 0    timestamp: 1352077
<info> time_sync: 8648, 540831, 0    timestamp: 1352078
<info> time_sync: 657, 540832, 0    timestamp: 1352080
<info> time_sync: 16647, 540832, 0    timestamp: 1352081
<info> time_sync: 32657, 540832, 0    timestamp: 1352082
<info> time_sync: 8656, 540833, 0    timestamp: 1352083
<info> time_sync: 16656, 540836, 0    timestamp: 1352091
<info> time_sync: 32656, 540836, 0    timestamp: 1352092
<info> time_sync: 8656, 540837, 0    timestamp: 1352093
<info> time_sync: 24656, 540837, 0    timestamp: 1352094
<info> time_sync: 656, 540838, 0    timestamp: 1352095
<info> time_sync: 16656, 540838, 0    timestamp: 1352096
<info> time_sync: 32656, 540838, 0    timestamp: 1352097
<info> time_sync: 8656, 540839, 0    timestamp: 1352098
<info> time_sync: 24656, 540839, 0    timestamp: 1352099
<info> time_sync: 656, 540840, 0    timestamp: 1352100
<info> time_sync: 16656, 540840, 0    timestamp: 1352101
<info> time_sync: 32656, 540840, 0    timestamp: 1352102
<info> time_sync: 8656, 540841, 0    timestamp: 1352103
<info> time_sync: 24656, 540841, 0    timestamp: 1352104
<info> time_sync: 656, 540842, 0    timestamp: 1352105
<info> time_sync: 16656, 540842, 0    timestamp: 1352106
<info> time_sync: 32656, 540842, 0    timestamp: 1352107
<info> time_sync: 8657, 540843, 0    timestamp: 1352108
<info> time_sync: 24656, 540843, 0    timestamp: 1352109
<info> time_sync: 656, 540844, 0    timestamp: 1352110
<info> time_sync: 16656, 540844, 0    timestamp: 1352111
<info> app: diff: 40
<info> time_sync: 37632, 540844, 0    timestamp: 1352112
<info> time_sync: 8654, 540845, 0    timestamp: 1352113
<info> time_sync: 24681, 540845, 0    timestamp: 1352114
<info> time_sync: 644, 540846, 0    timestamp: 1352115
<info> time_sync: 16680, 540846, 0    timestamp: 1352116
<info> time_sync: 32728, 540846, 0    timestamp: 1352117
<info> time_sync: 8656, 540847, 0    timestamp: 1352118
<info> time_sync: 24657, 540847, 0    timestamp: 1352119
<info> time_sync: 8656, 540851, 0    timestamp: 1352128
<info> time_sync: 24656, 540851, 0    timestamp: 1352129
<info> time_sync: 656, 540852, 0    timestamp: 1352130
<info> time_sync: 16656, 540852, 0    timestamp: 1352131
<info> time_sync: 32656, 540852, 0    timestamp: 1352132
<info> time_sync: 8656, 540853, 0    timestamp: 1352133
<info> time_sync: 24656, 540853, 0    timestamp: 1352134
<info> time_sync: 656, 540854, 0    timestamp: 1352135
<info> time_sync: 16656, 540854, 0    timestamp: 1352136
<info> time_sync: 32656, 540854, 0    timestamp: 1352137
<info> time_sync: 8656, 540855, 0    timestamp: 1352138
<info> time_sync: 24656, 540855, 0    timestamp: 1352139
<info> time_sync: 656, 540856, 0    timestamp: 1352140
<info> time_sync: 16656, 540856, 0    timestamp: 1352141
<info> time_sync: 32656, 540856, 0    timestamp: 1352142
<info> time_sync: 8656, 540857, 0    timestamp: 1352143
<info> time_sync: 24656, 540857, 0    timestamp: 1352144
<info> time_sync: 656, 540858, 0    timestamp: 1352145
<info> time_sync: 16657, 540858, 0    timestamp: 1352146
<info> time_sync: 32647, 540858, 0    timestamp: 1352147
<info> time_sync: 8656, 540859, 0    timestamp: 1352148
<info> time_sync: 24656, 540859, 0    timestamp: 1352149
<info> time_sync: 656, 540860, 0    timestamp: 1352150
<info> time_sync: 16657, 540860, 0    timestamp: 1352151
<info> app: diff: 40
<info> time_sync: 37414, 540860, 0    timestamp: 1352152
<info> time_sync: 8775, 540861, 0    timestamp: 1352153
<info> time_sync: 24839, 540861, 0    timestamp: 1352154
<info> time_sync: 644, 540862, 0    timestamp: 1352155
<info> time_sync: 16718, 540862, 0    timestamp: 1352156
<info> time_sync: 32719, 540862, 0    timestamp: 1352157
<info> time_sync: 656, 540866, 0    timestamp: 1352165
<info> time_sync: 16656, 540866, 0    timestamp: 1352166
<info> time_sync: 32656, 540866, 0    timestamp: 1352167
<info> time_sync: 8656, 540867, 0    timestamp: 1352168
<info> time_sync: 24656, 540867, 0    timestamp: 1352169
<info> time_sync: 656, 540868, 0    timestamp: 1352170
<info> time_sync: 16656, 540868, 0    timestamp: 1352171
<info> time_sync: 32656, 540868, 0    timestamp: 1352172
<info> time_sync: 8656, 540869, 0    timestamp: 1352173
<info> time_sync: 24656, 540869, 0    timestamp: 1352174
<info> time_sync: 656, 540870, 0    timestamp: 1352175
<info> time_sync: 16656, 540870, 0    timestamp: 1352176
<info> time_sync: 32656, 540870, 0    timestamp: 1352177
<info> time_sync: 8656, 540871, 0    timestamp: 1352178
<info> time_sync: 24656, 540871, 0    timestamp: 1352179
<info> time_sync: 656, 540872, 0    timestamp: 1352180
<info> time_sync: 16656, 540872, 0    timestamp: 1352181
<info> time_sync: 32656, 540872, 0    timestamp: 1352182
<info> time_sync: 8657, 540873, 0    timestamp: 1352183
<info> time_sync: 24647, 540873, 0    timestamp: 1352184
<info> time_sync: 656, 540874, 0    timestamp: 1352185
<info> time_sync: 16655, 540874, 0    timestamp: 1352186
<info> time_sync: 32656, 540874, 0    timestamp: 1352187
<info> time_sync: 8657, 540875, 0    timestamp: 1352188
<info> time_sync: 24656, 540875, 0    timestamp: 1352189
<info> time_sync: 656, 540876, 0    timestamp: 1352190
<info> time_sync: 16657, 540876, 0    timestamp: 1352191
<info> app: diff: 40
<info> time_sync: 37701, 540876, 0    timestamp: 1352192
<info> time_sync: 8743, 540877, 0    timestamp: 1352193
<info> time_sync: 24807, 540877, 0    timestamp: 1352194
<info> time_sync: 644, 540878, 0    timestamp: 1352195
<info> time_sync: 16705, 540878, 0    timestamp: 1352196
<info> time_sync: 32704, 540878, 0    timestamp: 1352197
<info> time_sync: 16656, 540882, 0    timestamp: 1352206
<info> time_sync: 32656, 540882, 0    timestamp: 1352207
<info> time_sync: 8656, 540883, 0    timestamp: 1352208
<info> time_sync: 24656, 540883, 0    timestamp: 1352209
<info> time_sync: 656, 540884, 0    timestamp: 1352210
<info> time_sync: 16656, 540884, 0    timestamp: 1352211
<info> time_sync: 32656, 540884, 0    timestamp: 1352212
<info> time_sync: 8656, 540885, 0    timestamp: 1352213
<info> time_sync: 24656, 540885, 0    timestamp: 1352214
<info> time_sync: 656, 540886, 0    timestamp: 1352215
<info> time_sync: 16656, 540886, 0    timestamp: 1352216
<info> time_sync: 32656, 540886, 0    timestamp: 1352217
<info> time_sync: 8655, 540887, 0    timestamp: 1352218
<info> time_sync: 24656, 540887, 0    timestamp: 1352219
<info> time_sync: 655, 540888, 0    timestamp: 1352220
<info> time_sync: 16656, 540888, 0    timestamp: 1352221
<info> time_sync: 32656, 540888, 0    timestamp: 1352222
<info> time_sync: 8656, 540889, 0    timestamp: 1352223
<info> time_sync: 24656, 540889, 0    timestamp: 1352224
<info> time_sync: 656, 540890, 0    timestamp: 1352225
<info> time_sync: 16656, 540890, 0    timestamp: 1352226
<info> time_sync: 32657, 540890, 0    timestamp: 1352227
<info> time_sync: 8647, 540891, 0    timestamp: 1352228
<info> time_sync: 24656, 540891, 0    timestamp: 1352229
<info> time_sync: 656, 540892, 0    timestamp: 1352230
<info> time_sync: 16657, 540892, 0    timestamp: 1352231
<info> time_sync: 35557, 540892, 0    timestamp: 1352232
<info> app: diff: 40
<info> time_sync: 8747, 540893, 0    timestamp: 1352233
<info> time_sync: 24711, 540893, 0    timestamp: 1352234
<info> time_sync: 792, 540894, 0    timestamp: 1352235
<info> time_sync: 16744, 540894, 0    timestamp: 1352236
<info> time_sync: 32792, 540894, 0    timestamp: 1352237
<info> time_sync: 8651, 540895, 0    timestamp: 1352238
<info> time_sync: 16656, 540898, 0    timestamp: 1352246
<info> time_sync: 32656, 540898, 0    timestamp: 1352247
<info> time_sync: 8656, 540899, 0    timestamp: 1352248
<info> time_sync: 24656, 540899, 0    timestamp: 1352249
<info> time_sync: 656, 540900, 0    timestamp: 1352250
<info> time_sync: 16655, 540900, 0    timestamp: 1352251
<info> time_sync: 32656, 540900, 0    timestamp: 1352252
<info> time_sync: 8655, 540901, 0    timestamp: 1352253
<info> time_sync: 24656, 540901, 0    timestamp: 1352254
<info> time_sync: 656, 540902, 0    timestamp: 1352255
<info> time_sync: 16656, 540902, 0    timestamp: 1352256
<info> time_sync: 32656, 540902, 0    timestamp: 1352257
<info> time_sync: 8656, 540903, 0    timestamp: 1352258
<info> time_sync: 24656, 540903, 0    timestamp: 1352259
<info> time_sync: 656, 540904, 0    timestamp: 1352260
<info> time_sync: 16656, 540904, 0    timestamp: 1352261
<info> time_sync: 32656, 540904, 0    timestamp: 1352262
<info> time_sync: 8656, 540905, 0    timestamp: 1352263
<info> time_sync: 24657, 540905, 0    timestamp: 1352264
<info> time_sync: 647, 540906, 0    timestamp: 1352265
<info> time_sync: 16656, 540906, 0    timestamp: 1352266
<info> time_sync: 32656, 540906, 0    timestamp: 1352267
<info> time_sync: 24657, 540907, 0    timestamp: 1352269
<info> time_sync: 647, 540908, 0    timestamp: 1352270
<info> time_sync: 16657, 540908, 0    timestamp: 1352271
<info> app: diff: 40
<info> time_sync: 37433, 540908, 0    timestamp: 1352272
<info> time_sync: 8690, 540909, 0    timestamp: 1352273
<info> time_sync: 24835, 540909, 0    timestamp: 1352274
<info> time_sync: 816, 540910, 0    timestamp: 1352275
<info> time_sync: 16817, 540910, 0    timestamp: 1352276
<info> time_sync: 8655, 540913, 0    timestamp: 1352283
<info> time_sync: 24656, 540913, 0    timestamp: 1352284
<info> time_sync: 655, 540914, 0    timestamp: 1352285
<info> time_sync: 16656, 540914, 0    timestamp: 1352286
<info> time_sync: 32656, 540914, 0    timestamp: 1352287
<info> time_sync: 8656, 540915, 0    timestamp: 1352288
<info> time_sync: 24656, 540915, 0    timestamp: 1352289
<info> time_sync: 656, 540916, 0    timestamp: 1352290
<info> time_sync: 16656, 540916, 0    timestamp: 1352291
<info> time_sync: 32656, 540916, 0    timestamp: 1352292
<info> time_sync: 8656, 540917, 0    timestamp: 1352293
<info> time_sync: 24656, 540917, 0    timestamp: 1352294
<info> time_sync: 656, 540918, 0    timestamp: 1352295
<info> time_sync: 16656, 540918, 0    timestamp: 1352296
<info> time_sync: 32657, 540918, 0    timestamp: 1352297
<info> time_sync: 8647, 540919, 0    timestamp: 1352298
<info> time_sync: 24656, 540919, 0    timestamp: 1352299
<info> time_sync: 656, 540920, 0    timestamp: 1352300
<info> time_sync: 32657, 540920, 0    timestamp: 1352302
<info> time_sync: 8647, 540921, 0    timestamp: 1352303
<info> time_sync: 24647, 540921, 0    timestamp: 1352304
<info> time_sync: 656, 540922, 0    timestamp: 1352305
<info> time_sync: 16656, 540922, 0    timestamp: 1352306
<info> time_sync: 32656, 540922, 0    timestamp: 1352307
<info> time_sync: 8656, 540923, 0    timestamp: 1352308
<info> time_sync: 24657, 540923, 0    timestamp: 1352309
<info> time_sync: 647, 540924, 0    timestamp: 1352310
<info> time_sync: 16656, 540924, 0    timestamp: 1352311
<info> app: diff: 40
<info> time_sync: 37760, 540924, 0    timestamp: 1352312
<info> time_sync: 8736, 540925, 0    timestamp: 1352313
<info> time_sync: 24845, 540925, 0    timestamp: 1352314
<info> time_sync: 792, 540926, 0    timestamp: 1352315
<info> time_sync: 32644, 540926, 0    timestamp: 1352317
<info> time_sync: 8650, 540927, 0    timestamp: 1352318
<info> time_sync: 24642, 540927, 0    timestamp: 1352319
<info> time_sync: 646, 540928, 0    timestamp: 1352320
<info> time_sync: 16643, 540928, 0    timestamp: 1352321
<info> time_sync: 32656, 540928, 0    timestamp: 1352322
<info> time_sync: 8657, 540929, 0    timestamp: 1352323
<info> time_sync: 24647, 540929, 0    timestamp: 1352324
<info> time_sync: 32656, 540932, 0    timestamp: 1352332
<info> time_sync: 8656, 540933, 0    timestamp: 1352333
<info> time_sync: 24656, 540933, 0    timestamp: 1352334
<info> time_sync: 656, 540934, 0    timestamp: 1352335
<info> time_sync: 16656, 540934, 0    timestamp: 1352336
<info> time_sync: 32656, 540934, 0    timestamp: 1352337
<info> time_sync: 8656, 540935, 0    timestamp: 1352338
<info> time_sync: 24656, 540935, 0    timestamp: 1352339
<info> time_sync: 656, 540936, 0    timestamp: 1352340
<info> time_sync: 16656, 540936, 0    timestamp: 1352341
<info> time_sync: 32656, 540936, 0    timestamp: 1352342
<info> time_sync: 8656, 540937, 0    timestamp: 1352343
<info> time_sync: 24656, 540937, 0    timestamp: 1352344
<info> time_sync: 656, 540938, 0    timestamp: 1352345
<info> time_sync: 16656, 540938, 0    timestamp: 1352346
<info> time_sync: 32656, 540938, 0    timestamp: 1352347
<info> time_sync: 8656, 540939, 0    timestamp: 1352348
<info> time_sync: 24657, 540939, 0    timestamp: 1352349
<info> time_sync: 656, 540940, 0    timestamp: 1352350
<info> time_sync: 16656, 540940, 0    timestamp: 1352351
<info> app: diff: 40
<info> time_sync: 37467, 540940, 0    timestamp: 1352352
<info> time_sync: 8723, 540941, 0    timestamp: 1352353
<info> time_sync: 24813, 540941, 0    timestamp: 1352354
<info> time_sync: 760, 540942, 0    timestamp: 1352355
<info> time_sync: 16808, 540942, 0    timestamp: 1352356
<info> time_sync: 32644, 540942, 0    timestamp: 1352357
<info> time_sync: 8656, 540943, 0    timestamp: 1352358
<info> time_sync: 24657, 540943, 0    timestamp: 1352359
<info> time_sync: 652, 540944, 0    timestamp: 1352360
<info> time_sync: 8656, 540947, 0    timestamp: 1352368
<info> time_sync: 24656, 540947, 0    timestamp: 1352369
<info> time_sync: 656, 540948, 0    timestamp: 1352370
<info> time_sync: 16656, 540948, 0    timestamp: 1352371
<info> time_sync: 32656, 540948, 0    timestamp: 1352372
<info> time_sync: 8656, 540949, 0    timestamp: 1352373
<info> time_sync: 24656, 540949, 0    timestamp: 1352374
<info> time_sync: 656, 540950, 0    timestamp: 1352375
<info> time_sync: 16656, 540950, 0    timestamp: 1352376
<info> time_sync: 32656, 540950, 0    timestamp: 1352377
<info> time_sync: 8656, 540951, 0    timestamp: 1352378
<info> time_sync: 24656, 540951, 0    timestamp: 1352379
<info> time_sync: 656, 540952, 0    timestamp: 1352380
<info> time_sync: 16655, 540952, 0    timestamp: 1352381
<info> time_sync: 32656, 540952, 0    timestamp: 1352382
<info> time_sync: 8655, 540953, 0    timestamp: 1352383
<info> time_sync: 24656, 540953, 0    timestamp: 1352384
<info> time_sync: 657, 540954, 0    timestamp: 1352385
<info> time_sync: 16656, 540954, 0    timestamp: 1352386
<info> time_sync: 32656, 540954, 0    timestamp: 1352387
<info> time_sync: 8656, 540955, 0    timestamp: 1352388
<info> time_sync: 24656, 540955, 0    timestamp: 1352389
<info> time_sync: 657, 540956, 0    timestamp: 1352390
<info> time_sync: 16657, 540956, 0    timestamp: 1352391
<info> app: diff: 40
<error> app: ERROR 0 [NRF_SUCCESS] ...

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

I ran my tests multiple times. It looks like that the offset always occures when the sync_timer_val goes from 40000 to 0. Sometimes I also saw a bit of "jumping" of the sync_timer_val. This is the debug log of the peripheral of another test run:

[00:07:02.453,063] <info> time_sync: 39724, 3, 174194    timestamp: 435495
[00:07:02.493,041] <info> time_sync: 39729, 6, 174207    timestamp: 435535
[00:07:02.533,081] <info> time_sync: 39730, 22, 174207    timestamp: 435575
[00:07:02.573,120] <info> time_sync: 101, 0, 174246    timestamp: 435615
[00:07:02.613,098] <info> time_sync: 39747, 2, 174259    timestamp: 435655
[00:07:02.653,076] <info> time_sync: 39752, 5, 174272    timestamp: 435695
[00:07:02.693,054] <info> time_sync: 39756, 8, 174285    timestamp: 435735
[00:07:02.733,093] <info> time_sync: 39757, 24, 174285    timestamp: 435775
[00:07:02.773,071] <info> time_sync: 39770, 1, 174324    timestamp: 435815
[00:07:02.813,110] <info> time_sync: 39775, 4, 174337    timestamp: 435855
[00:07:02.853,088] <info> time_sync: 39779, 7, 174350    timestamp: 435895
[00:07:02.893,066] <info> time_sync: 39780, 23, 174350    timestamp: 435935
[00:07:02.933,105] <info> time_sync: 39793, 0, 174389    timestamp: 435975
[00:07:02.973,083] <info> time_sync: 39798, 3, 174402    timestamp: 436015
[00:07:03.013,122] <info> time_sync: 39802, 6, 174415    timestamp: 436055
[00:07:03.053,100] <info> time_sync: 39803, 22, 174415    timestamp: 436095
[00:07:03.093,139] <info> time_sync: 102, 0, 174454    timestamp: 436135
[00:07:03.133,117] <info> time_sync: 39820, 2, 174467    timestamp: 436175
[00:07:03.173,095] <info> time_sync: 39825, 5, 174480    timestamp: 436215
[00:07:03.213,134] <info> time_sync: 39829, 8, 174493    timestamp: 436255
[00:07:03.253,112] <info> time_sync: 39830, 24, 174493    timestamp: 436295
[00:07:03.293,090] <info> time_sync: 39843, 1, 174532    timestamp: 436335
[00:07:03.333,129] <info> time_sync: 39848, 4, 174545    timestamp: 436375
[00:07:03.373,107] <info> time_sync: 39853, 7, 174558    timestamp: 436415
[00:07:03.413,085] <info> time_sync: 39854, 23, 174558    timestamp: 436455
[00:07:03.453,125] <info> time_sync: 39866, 0, 174597    timestamp: 436495
[00:07:03.493,103] <info> time_sync: 39871, 3, 174610    timestamp: 436535
[00:07:03.533,142] <info> time_sync: 39875, 6, 174623    timestamp: 436575
[00:07:03.573,120] <info> time_sync: 39876, 22, 174623    timestamp: 436615
[00:07:03.613,159] <info> time_sync: 100, 0, 174662    timestamp: 436655
[00:07:03.653,137] <info> time_sync: 39894, 2, 174675    timestamp: 436695
[00:07:03.693,115] <info> time_sync: 39898, 5, 174688    timestamp: 436735
[00:07:03.733,154] <info> time_sync: 39903, 8, 174701    timestamp: 436775
[00:07:03.773,132] <info> time_sync: 39904, 24, 174701    timestamp: 436815
[00:07:03.813,110] <info> time_sync: 39916, 1, 174740    timestamp: 436855
[00:07:03.853,149] <info> time_sync: 39921, 4, 174753    timestamp: 436895
[00:07:03.893,127] <info> time_sync: 39926, 7, 174766    timestamp: 436935
[00:07:03.933,166] <info> time_sync: 39927, 23, 174766    timestamp: 436975
[00:07:03.973,144] <info> time_sync: 39939, 0, 174805    timestamp: 437015
[00:07:04.013,122] <info> time_sync: 39944, 3, 174818    timestamp: 437055
[00:07:04.053,161] <info> time_sync: 39948, 6, 174831    timestamp: 437095
[00:07:04.093,139] <info> time_sync: 39949, 22, 174831    timestamp: 437135
[00:07:04.133,178] <info> time_sync: 102, 0, 174870    timestamp: 437175
[00:07:04.173,156] <info> time_sync: 39967, 2, 174883    timestamp: 437215
[00:07:04.213,134] <info> time_sync: 39971, 5, 174896    timestamp: 437255
[00:07:04.253,173] <info> time_sync: 39976, 8, 174909    timestamp: 437295
[00:07:04.293,151] <info> time_sync: 39977, 24, 174909    timestamp: 437335
[00:07:04.333,129] <info> time_sync: 39990, 1, 174948    timestamp: 437375
[00:07:04.373,168] <info> time_sync: 39994, 4, 174961    timestamp: 437415
[00:07:04.413,146] <info> time_sync: 39999, 7, 174974    timestamp: 437455
[00:07:04.453,186] <info> time_sync: 0, 23, 174974    timestamp: 437493

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

Finally I want to point something out regarding the priority.

Audun said:

Either way, since you are calling the timestamp function from a lower priority that SWI3_EGU3_IRQHandler

This is not fully correct. I would like to call the timestamp function from the same priority than the SWI3_EGU3_IRQHandler (If this is possible?). The timestamp function gets called with priority 6. In order to match this line in your timers_capture() function:

APP_ERROR_CHECK_BOOL(current_int_priority_get() > TIME_SYNC_EVT_HANDLER_IRQ_PRIORITY);

I have to set TIME_SYNC_EVT_HANDLER_IRQ_PRIORITY at least to 5. Which could cause an unwanted behaviour. Is it possible to call it from the same priority?

Another consequence of this APP_ERROR_CHECK_BOOL(...) line is, that I have to use

#define TIME_SYNC_TX_OFFSET_REALIGN_TIMEOUT 0

because every other value would cause an error with this function:

static int32_t calculate_tx_start_offset(void)

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

So I am still having the abrupt offset issue.

Do you have any other suggestions on how to solve this issue. We highly appreciate your help with our problem. It still looks like that the success of our project depends on your help.

Thank you very much in advance.

Best regards,

Michael