applications: nrf_audio: Fixes to TX timestamp handling.

Fixes an issue where too many SDUs were lost when using an
unsynchronized audio source (such as async USB).
Reworked timestamp handling to be more robust and added better logging.

OCT-3710

Signed-off-by: Kristoffer Skøien <kristoffer.skoien@nordicsemi.no>

Author: koffes

applications/nrf_audio/src/audio/le_audio_rx.c

@@ -22,10 +22,8 @@
 LOG_MODULE_REGISTER(le_audio_rx, CONFIG_LE_AUDIO_RX_LOG_LEVEL);
 
 struct rx_stats {
-	uint32_t recv_cnt;
-	uint32_t good_frame_cnt;
-	uint32_t bad_frame_cnt;
-	bool prev_bad_data;
+	uint64_t good_frame_cnt;
+	uint64_t bad_or_empty_frame_cnt;
 };
 
 static bool initialized;
@@ -109,33 +107,37 @@ void le_audio_rx_data_handler(struct net_buf *audio_frame_rx, struct audio_metad
 	static uint32_t num_overruns;
 	static uint32_t num_thrown;
 
+	__ASSERT_NO_MSG(audio_frame_rx != NULL);
+	__ASSERT_NO_MSG(meta != NULL);
+
 	if (!initialized) {
 		ERR_CHK_MSG(-EPERM, "Data received but le_audio_rx is not initialized");
 	}
 
-	rx_stats[location_index].recv_cnt++;
-
 	if (meta->bad_data) {
-		rx_stats[location_index].bad_frame_cnt++;
+		rx_stats[location_index].bad_or_empty_frame_cnt++;
 	} else {
 		rx_stats[location_index].good_frame_cnt++;
 	}
 
-	if ((rx_stats[location_index].recv_cnt % 100) == 0 && rx_stats[location_index].recv_cnt) {
-		/* NOTE: The string below is used by the Nordic CI system */
-		LOG_DBG("ISO RX SDUs: Loc: %d Total: %d Bad: %d", location_index,
-			rx_stats[location_index].recv_cnt, rx_stats[location_index].bad_frame_cnt);
-	}
+	uint64_t total_frames = rx_stats[location_index].good_frame_cnt +
+				rx_stats[location_index].bad_or_empty_frame_cnt;
+	double bad_frame_percentage =
+		(total_frames > 0) ? (((double)rx_stats[location_index].bad_or_empty_frame_cnt /
+				       total_frames) *
+				      100)
+				   : 0.0;
 
-	if (meta->bad_data && !rx_stats[location_index].prev_bad_data) {
-		LOG_INF_RATELIMIT_RATE(1000,
-				       "Bad or 0 SDU: Loc: %u Total: %u Bad: %u. (Prints "
-				       "good->bad transition)",
-				       location_index, rx_stats[location_index].recv_cnt,
-				       rx_stats[location_index].bad_frame_cnt);
+	if ((total_frames % 100) == 0 && (total_frames != 0)) {
+		/* NOTE: The string below is used by the Nordic CI system */
+		LOG_DBG("ISO RX SDUs: Loc: %u Total: %llu Bad: %llu", location_index, total_frames,
+			rx_stats[location_index].bad_or_empty_frame_cnt);
 	}
 
-	rx_stats[location_index].prev_bad_data = meta->bad_data;
+	LOG_DBG_RATELIMIT_RATE(
+		10000, "Bad or 0 SDU: Loc: %u Total: %llu Empty/bad: %llu (%2.3f %%)",
+		location_index, total_frames, rx_stats[location_index].bad_or_empty_frame_cnt,
+		bad_frame_percentage);
 
 	if (stream_state_get() != STATE_STREAMING) {
 		/* Throw away data */
@@ -264,6 +266,10 @@ void le_audio_rx_data_handler(struct net_buf *audio_frame_rx, struct audio_metad
  */
 static void audio_datapath_thread(void *dummy1, void *dummy2, void *dummy3)
 {
+	ARG_UNUSED(dummy1);
+	ARG_UNUSED(dummy2);
+	ARG_UNUSED(dummy3);
+
 	int ret;
 	struct net_buf *audio_frame = NULL;
 

applications/nrf_audio/src/bluetooth/bt_stream/bt_le_audio_tx/Kconfig

@@ -9,6 +9,7 @@ config NRF_AUDIO_TX_TGT_LEAD_TIME_US
 	  Used to make sure that the data is sent to controller just in time for the next SDU,
 	  which can help with reducing the overall latency and power consumption.
 	  Setting this too low may lead to flushed data, and too high will increase latency.
+	  Must be higher than HCI_ISO_TX_SDU_ARRIVAL_MARGIN_US + plus a margin depending on SoC.
 
 config NRF_AUDIO_TX_LEAD_TIME_DEVIATION_US
 	int