Bluetooth/NetCore Time capture not working 100% for LE Audio

Hi there

For proper playback of LE Audio, it's required to get the current time of the Bluetooth Controller.

In the LE Audio examples (nrf/application/nrf5340_audio) on the NRF5340 this is done with the functions in audio_sync_timer.c.

I've read the documentation and the actual code for this, which uses a combined timer of the RTC and a 1 MHz HF clock to construct the current time in us.

However, there seems to be a race condition between capturing both timers at the same time and the RTC tick resetting the HF timer.

When constantly polling audio_sync_timer_capture(), the time sometimes jumps ahead by about 30 us.

Here's sample code that could be placed at the end of the main() function to demonstrate this:

	// Test monotonicity
	uint32_t timestamps_us[10];
	int counter;
	for (counter = 0; counter < 1000000; counter++){
		// progress bar
		if ((counter % 1000) == 0) {
			LOG_ERR("%u", counter);
		}

		// get some timestamps
		int i;
		for (i=0;i<10;i++){
			timestamps_us[i] = audio_sync_timer_capture();		
		}

		// check if there's a negative delta
		int incorrect_entry = -1;
		for (i=1;i<10;i++){
			if (timestamps_us[i-1] > timestamps_us[i]){
				incorrect_entry = i-1;
			}
		}

		// report error
		if (incorrect_entry >= 0){
			LOG_ERR("\nIncorrect timestamp:");
			for (i=0;i<10;i++){
				if (incorrect_entry == i){
					LOG_ERR("t[%u] = %u <<--", i, timestamps_us[i]);
				} else {
					LOG_ERR("t[%u] = %u", i, timestamps_us[i]);
				}
			}
			break;
		}
	}

When running this, I get:

Incorrect timestamp:
HL [00:00:02.332,122] <err> main: t[0] = 88708
HL [00:00:02.332,122] <err> main: t[1] = 88712
HL [00:00:02.332,122] <err> main: t[2] = 88745 UNEXPECTED
HL [00:00:02.332,122] <err> main: t[3] = 88717
HL [00:00:02.332,122] <err> main: t[4] = 88719
HL [00:00:02.332,153] <err> main: t[5] = 88722
HL [00:00:02.332,153] <err> main: t[6] = 88725
HL [00:00:02.332,153] <err> main: t[7] = 88728
HL [00:00:02.332,153] <err> main: t[8] = 88731
HL [00:00:02.332,153] <err> main: t[9] = 88734

For testing, we've called the function twice in a row, and discarded the measurement when the difference between both readings was more than 10 us, but I imagine that code that requires the accurate Bluetooth time might even run in interrup context and/or blocked interrupts, so calling it multiple times is not ideal.

I'm not too familiar with the nRF5x peripherals. Would it be possible to correct this function to always report the correct time?

Thanks

 Matthias

Parents
  • Hi Matthias,

    Thank you for reporting this issue.

    Which NCS version do you use?

    EDIT:
    Did you make any other changes to the nrf5340_audio application apart from adding your sample code at the end of main() function?

    Best regards,
    Dejan

  • Hi Dejan

    I first run into this using a copy of the time capture code from NCS 2.6 added to the HCI UART bridge code.

    For easier reproduction, I've added the code above to the unicast server main() of the nrf5340_audio application of NCS 2.8. (I get 2 warnings for not including the appropriate headers).

    I started with clean checkout or 2.8 and made no other code changes to the application. I've configured the project to send output to RTT which should not be relevant as the output runs after an issue was detected. Please let me know if you can reproduce this.

    Best regards,

    Matthias

  • Hi Matthias,

    Below is the result of testing on our side (audio unicast server in NCS v2.8.0 with your modifications).

    *** Booting nRF Connect SDK v2.8.0-a2386bfc8401 ***
    *** Using Zephyr OS v3.7.99-0bc3393fb112 ***
    HL [00:00:00.266,998] <inf> board_version: Compatible board/HW version found: 1.0.0
    HL [00:00:00.299,346] <inf> fw_info: 
             nRF5340 Audio nRF5340 Audio DK cpuapp                      
             NCS base version: 2.8.0                            
             Cmake run : Wed Dec 04 16:15:18 2024
    HL [00:00:00.299,346] <inf> fw_info: ------- DEBUG BUILD -------
    HL [00:00:00.299,346] <inf> fw_info: HEADSET left device
    HL [00:00:00.369,384] <inf> bt_mgmt_ctlr_cfg: Controller: SoftDevice: Version 6.0 (0x0e), Revision 8270
    HL [00:00:00.369,598] <inf> bt_mgmt: Local identity addr: D1:D9:6F:57:FD:47 (random)
    HL [00:00:00.398,437] <wrn> unicast_server: CSIP using the default SIRK, must be changed before production
    HL [00:00:00.401,367] <err> main: 0
    HL [00:00:00.402,099] <inf> bt_mgmt_adv: Local addr: 7F:08:BA:D2:35:06 (random)
    HL [00:00:00.402,587] <inf> bt_mgmt_adv: Advertising successfully started
    HL [00:00:00.403,198] <err> main: 
                                      Incorrect timestamp:
    HL [00:00:00.403,198] <err> main: t[0] = 91413
    HL [00:00:00.403,198] <err> main: t[1] = 91416
    HL [00:00:00.403,198] <err> main: t[2] = 91419
    HL [00:00:00.403,228] <err> main: t[3] = 91422
    HL [00:00:00.403,228] <err> main: t[4] = 91425
    HL [00:00:00.403,228] <err> main: t[5] = 91428
    HL [00:00:00.403,228] <err> main: t[6] = 91461 <<--
    HL [00:00:00.403,228] <err> main: t[7] = 91432
    HL [00:00:00.403,228] <err> main: t[8] = 91435
    HL [00:00:00.403,259] <err> main: t[9] = 91438

    We will look into this issue internally. I expect to get back to you by the end of next week.

    Best regards,
    Dejan

Reply
  • Hi Matthias,

    Below is the result of testing on our side (audio unicast server in NCS v2.8.0 with your modifications).

    *** Booting nRF Connect SDK v2.8.0-a2386bfc8401 ***
    *** Using Zephyr OS v3.7.99-0bc3393fb112 ***
    HL [00:00:00.266,998] <inf> board_version: Compatible board/HW version found: 1.0.0
    HL [00:00:00.299,346] <inf> fw_info: 
             nRF5340 Audio nRF5340 Audio DK cpuapp                      
             NCS base version: 2.8.0                            
             Cmake run : Wed Dec 04 16:15:18 2024
    HL [00:00:00.299,346] <inf> fw_info: ------- DEBUG BUILD -------
    HL [00:00:00.299,346] <inf> fw_info: HEADSET left device
    HL [00:00:00.369,384] <inf> bt_mgmt_ctlr_cfg: Controller: SoftDevice: Version 6.0 (0x0e), Revision 8270
    HL [00:00:00.369,598] <inf> bt_mgmt: Local identity addr: D1:D9:6F:57:FD:47 (random)
    HL [00:00:00.398,437] <wrn> unicast_server: CSIP using the default SIRK, must be changed before production
    HL [00:00:00.401,367] <err> main: 0
    HL [00:00:00.402,099] <inf> bt_mgmt_adv: Local addr: 7F:08:BA:D2:35:06 (random)
    HL [00:00:00.402,587] <inf> bt_mgmt_adv: Advertising successfully started
    HL [00:00:00.403,198] <err> main: 
                                      Incorrect timestamp:
    HL [00:00:00.403,198] <err> main: t[0] = 91413
    HL [00:00:00.403,198] <err> main: t[1] = 91416
    HL [00:00:00.403,198] <err> main: t[2] = 91419
    HL [00:00:00.403,228] <err> main: t[3] = 91422
    HL [00:00:00.403,228] <err> main: t[4] = 91425
    HL [00:00:00.403,228] <err> main: t[5] = 91428
    HL [00:00:00.403,228] <err> main: t[6] = 91461 <<--
    HL [00:00:00.403,228] <err> main: t[7] = 91432
    HL [00:00:00.403,228] <err> main: t[8] = 91435
    HL [00:00:00.403,259] <err> main: t[9] = 91438

    We will look into this issue internally. I expect to get back to you by the end of next week.

    Best regards,
    Dejan

Children
Related