Bluetooth: Controller: Verbose radio is ready assertion

Provide Radio ISR latency in microseconds when asserting due
to high ISR latency.

Signed-off-by: Vinayak Kariappa Chettimada <[email protected]>

Author: cvinayak

subsys/bluetooth/controller/ll_sw/nordic/lll/lll_conn.c

@@ -396,7 +396,12 @@ void lll_conn_isr_rx(void *param)
 #endif /* HAL_RADIO_GPIO_HAVE_PA_PIN */
 
 	/* assert if radio packet ptr is not set and radio started tx */
-	LL_ASSERT(!radio_is_ready());
+	if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
+		LL_ASSERT_MSG(!radio_is_ready(), "%s: Radio ISR latency: %u", __func__,
+			      lll_prof_latency_get());
+	} else {
+		LL_ASSERT(!radio_is_ready());
+	}
 
 lll_conn_isr_rx_exit:
 	/* Save the AA captured for the first Rx in connection event */
@@ -504,6 +509,10 @@ void lll_conn_isr_tx(void *param)
 	struct lll_conn *lll;
 	uint32_t hcto;
 
+	if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
+		lll_prof_latency_capture();
+	}
+
 	/* Clear radio tx status and events */
 	lll_isr_tx_status_reset();
 
@@ -573,7 +582,12 @@ void lll_conn_isr_tx(void *param)
 	lll_conn_rx_pkt_set(lll);
 
 	/* assert if radio packet ptr is not set and radio started rx */
-	LL_ASSERT(!radio_is_ready());
+	if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
+		LL_ASSERT_MSG(!radio_is_ready(), "%s: Radio ISR latency: %u", __func__,
+			      lll_prof_latency_get());
+	} else {
+		LL_ASSERT(!radio_is_ready());
+	}
 
 #if defined(CONFIG_BT_CTLR_DF_CONN_CTE_TX)
 	pdu_tx = get_last_tx_pdu(lll);

subsys/bluetooth/controller/ll_sw/nordic/lll/lll_prof.c

@@ -24,6 +24,7 @@
 #include "lll.h"
 
 static int send(struct node_rx_pdu *rx);
+static uint16_t latency_get(void);
 static inline void sample(uint32_t *timestamp);
 static inline void sample_ticks(uint32_t *timestamp_ticks);
 static inline void delta(uint32_t timestamp, uint16_t *cputime);
@@ -108,6 +109,29 @@ void lll_prof_latency_capture(void)
 	 * and generate the profiling event at the end of the ISR.
 	 */
 	radio_tmr_sample();
+
+	/* Initialize so that if we call lll_prof_latency_get before it is
+	 * set, we can set it.
+	 */
+	timestamp_latency = UINT16_MAX;
+}
+
+uint16_t lll_prof_latency_get(void)
+{
+	uint16_t latency;
+
+	/* We are here before lll_prof_cputime_capture was called */
+	if (timestamp_latency == UINT16_MAX) {
+		/* get the ISR latency sample */
+		timestamp_latency = radio_tmr_sample_get();
+	}
+
+	/* Get the elapsed time in us since on-air radio packet end to ISR
+	 * entry.
+	 */
+	latency = latency_get();
+
+	return latency;
 }
 
 #if defined(HAL_RADIO_GPIO_HAVE_PA_PIN)
@@ -181,14 +205,10 @@ static int send(struct node_rx_pdu *rx)
 	struct profile *p;
 	uint8_t chg = 0U;
 
-	/* calculate the elapsed time in us since on-air radio packet end
-	 * to ISR entry
+	/* Get the elapsed time in us since on-air radio packet end to ISR
+	 * entry.
 	 */
-#if defined(HAL_RADIO_GPIO_HAVE_PA_PIN)
-	latency = timestamp_latency - timestamp_radio_end;
-#else /* !HAL_RADIO_GPIO_HAVE_PA_PIN */
-	latency = timestamp_latency - radio_tmr_end_get();
-#endif /* !HAL_RADIO_GPIO_HAVE_PA_PIN */
+	latency = latency_get();
 
 	/* check changes in min, avg and max of latency */
 	if (latency > latency_max) {
@@ -267,6 +287,22 @@ static int send(struct node_rx_pdu *rx)
 	return 0;
 }
 
+static uint16_t latency_get(void)
+{
+	uint16_t latency;
+
+	/* calculate the elapsed time in us since on-air radio packet end
+	 * to ISR entry
+	 */
+#if defined(HAL_RADIO_GPIO_HAVE_PA_PIN)
+	latency = timestamp_latency - timestamp_radio_end;
+#else /* !HAL_RADIO_GPIO_HAVE_PA_PIN */
+	latency = timestamp_latency - radio_tmr_end_get();
+#endif /* !HAL_RADIO_GPIO_HAVE_PA_PIN */
+
+	return latency;
+}
+
 static inline void sample(uint32_t *timestamp)
 {
 	radio_tmr_sample();

subsys/bluetooth/controller/ll_sw/nordic/lll/lll_prof_internal.h

@@ -25,6 +25,7 @@ static inline void lll_prof_exit_ull_low(void) {}
 #endif
 
 void lll_prof_latency_capture(void);
+uint16_t lll_prof_latency_get(void);
 void lll_prof_radio_end_backup(void);
 void lll_prof_cputime_capture(void);
 void lll_prof_send(void);