Skip to content

Bluetooth: Controller: In-system profiling and CPU overhead assertions #95391

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 2 commits into
base: main
Choose a base branch
from
Open

Bluetooth: Controller: In-system profiling and CPU overhead assertions #95391

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
74a2dfc
Bluetooth: Controller: In-system ticker_start and ticker_stop tests
cvinayak Aug 15, 2025
e648609
Bluetooth: Controller: In-system profiling and CPU overhead assertions
cvinayak Aug 14, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
14 changes: 7 additions & 7 deletions subsys/bluetooth/controller/hci/hci.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -8951,13 +8951,13 @@ static void encode_control(struct node_rx_pdu *node_rx,

#if defined(CONFIG_BT_CTLR_PROFILE_ISR)
case NODE_RX_TYPE_PROFILE:
LOG_INF("l: %u, %u, %u; t: %u, %u, %u; cpu: %u (%u), %u (%u), %u (%u), %u (%u).",
pdu_data->profile.lcur, pdu_data->profile.lmin, pdu_data->profile.lmax,
pdu_data->profile.cur, pdu_data->profile.min, pdu_data->profile.max,
pdu_data->profile.radio, pdu_data->profile.radio_ticks,
pdu_data->profile.lll, pdu_data->profile.lll_ticks,
pdu_data->profile.ull_high, pdu_data->profile.ull_high_ticks,
pdu_data->profile.ull_low, pdu_data->profile.ull_low_ticks);
printk("l: %u, %u, %u; t: %u, %u, %u; cpu: %u (%u), %u (%u), %u (%u), %u (%u).\n",
pdu_data->profile.lcur, pdu_data->profile.lmin, pdu_data->profile.lmax,
pdu_data->profile.cur, pdu_data->profile.min, pdu_data->profile.max,
pdu_data->profile.radio, pdu_data->profile.radio_ticks,
pdu_data->profile.lll, pdu_data->profile.lll_ticks,
pdu_data->profile.ull_high, pdu_data->profile.ull_high_ticks,
pdu_data->profile.ull_low, pdu_data->profile.ull_low_ticks);
return;
#endif /* CONFIG_BT_CTLR_PROFILE_ISR */

Expand Down
48 changes: 36 additions & 12 deletions subsys/bluetooth/controller/ll_sw/nordic/lll/lll.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -101,15 +101,19 @@ ISR_DIRECT_DECLARE(radio_nrf5_isr)
{
DEBUG_RADIO_ISR(1);

lll_prof_enter_radio();
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
lll_prof_enter_radio();
}

isr_radio();

#if !defined(CONFIG_BT_CTLR_ZLI)
ISR_DIRECT_PM();
#endif /* !CONFIG_BT_CTLR_ZLI */

lll_prof_exit_radio();
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
lll_prof_exit_radio();
}

DEBUG_RADIO_ISR(0);

Expand All @@ -133,15 +137,19 @@ ISR_DIRECT_DECLARE(timer_nrf5_isr)
{
DEBUG_RADIO_ISR(1);

lll_prof_enter_radio();
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
lll_prof_enter_radio();
}

isr_radio_tmr();

#if !defined(CONFIG_BT_CTLR_ZLI)
ISR_DIRECT_PM();
#endif /* !CONFIG_BT_CTLR_ZLI */

lll_prof_exit_radio();
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
lll_prof_exit_radio();
}

DEBUG_RADIO_ISR(0);

Expand All @@ -160,7 +168,9 @@ static void rtc0_nrf5_isr(const void *arg)
{
DEBUG_TICKER_ISR(1);

lll_prof_enter_ull_high();
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
lll_prof_enter_ull_high();
}

/* On compare0 run ticker worker instance0 */
#if defined(CONFIG_BT_CTLR_NRF_GRTC)
Expand All @@ -176,15 +186,21 @@ static void rtc0_nrf5_isr(const void *arg)

mayfly_run(TICKER_USER_ID_ULL_HIGH);

lll_prof_exit_ull_high();
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
lll_prof_exit_ull_high();
}

#if !defined(CONFIG_BT_CTLR_LOW_LAT) && \
(CONFIG_BT_CTLR_ULL_HIGH_PRIO == CONFIG_BT_CTLR_ULL_LOW_PRIO)
lll_prof_enter_ull_low();
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
lll_prof_enter_ull_low();
}

mayfly_run(TICKER_USER_ID_ULL_LOW);

lll_prof_exit_ull_low();
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
lll_prof_exit_ull_low();
}
#endif

DEBUG_TICKER_ISR(0);
Expand All @@ -194,11 +210,15 @@ static void swi_lll_nrf5_isr(const void *arg)
{
DEBUG_RADIO_ISR(1);

lll_prof_enter_lll();
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
lll_prof_enter_lll();
}

mayfly_run(TICKER_USER_ID_LLL);

lll_prof_exit_lll();
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
lll_prof_exit_lll();
}

DEBUG_RADIO_ISR(0);
}
Expand All @@ -209,11 +229,15 @@ static void swi_ull_low_nrf5_isr(const void *arg)
{
DEBUG_TICKER_JOB(1);

lll_prof_enter_ull_low();
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
lll_prof_enter_ull_low();
}

mayfly_run(TICKER_USER_ID_ULL_LOW);

lll_prof_exit_ull_low();
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
lll_prof_exit_ull_low();
}

DEBUG_TICKER_JOB(0);
}
Expand Down
30 changes: 29 additions & 1 deletion subsys/bluetooth/controller/ll_sw/nordic/lll/lll_adv.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1350,6 +1350,10 @@ static void isr_done(void *param)

pdu = chan_prepare(lll);

if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
lll_prof_cputime_capture();
}

#if defined(HAL_RADIO_GPIO_HAVE_PA_PIN) || defined(CONFIG_BT_CTLR_ADV_EXT)
start_us = radio_tmr_start_now(1);

Expand All @@ -1368,6 +1372,13 @@ static void isr_done(void *param)
#endif /* !CONFIG_BT_CTLR_ADV_EXT */

#if defined(HAL_RADIO_GPIO_HAVE_PA_PIN)
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
/* PA/LNA enable is overwriting packet end used in ISR
* profiling, hence back it up for later use.
*/
lll_prof_radio_end_backup();
}

radio_gpio_pa_setup();
radio_gpio_pa_lna_enable(start_us +
radio_tx_ready_delay_get(0, 0) -
Expand All @@ -1387,6 +1398,10 @@ static void isr_done(void *param)

radio_filter_disable();

if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
lll_prof_cputime_capture();
}

#if defined(CONFIG_BT_PERIPHERAL)
if (!lll->is_hdcd)
#endif /* CONFIG_BT_PERIPHERAL */
Expand Down Expand Up @@ -1433,6 +1448,19 @@ static void isr_done(void *param)
lll_isr_cleanup(param);
}

static void isr_tx_done(void *param)
{
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
lll_prof_latency_capture();
}

isr_done(param);

if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
lll_prof_send();
}
}

static void isr_abort(void *param)
{
/* Clear radio status and events */
Expand Down Expand Up @@ -1513,7 +1541,7 @@ static struct pdu_adv *chan_prepare(struct lll_adv *lll)
radio_tmr_tifs_set(EVENT_IFS_US);
radio_switch_complete_and_rx(0);
} else {
radio_isr_set(isr_done, lll);
radio_isr_set(isr_tx_done, lll);

if (IS_ENABLED(CONFIG_BT_CTLR_SW_SWITCH_SINGLE_TIMER) &&
IS_ENABLED(CONFIG_BT_CTLR_ADV_EXT)) {
Expand Down
73 changes: 66 additions & 7 deletions subsys/bluetooth/controller/ll_sw/nordic/lll/lll_prof.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -12,6 +12,7 @@

#include "hal/ccm.h"
#include "hal/radio.h"
#include "hal/ticker.h"

#include "util/memq.h"

Expand All @@ -23,12 +24,46 @@

#include "lll.h"

#include "hal/debug.h"

/* Below profiling measurements using a sample with:
* 1 connectable legacy advertising or 1 peripheral ACL,
* plus
* 3 extended advertising sets, scanning on 2M PHY, scanning on Coded PHY, and
* 2 auxiliary scan set.
*/
#if defined(CONFIG_SOC_COMPATIBLE_NRF54LX)
#define LLL_PROF_RADIO_MAX_US 103 /* Max. Radio Rx/Tx ISR, O(1)*/
#define LLL_PROF_LLL_MAX_US 105 /* Max. LLL prepare, O(1) */
#define LLL_PROF_ULL_HIGH_MAX_US 260 /* Max. Radio + LLL + ULL High, O(1) */
#define LLL_PROF_ULL_LOW_MAX_US 306 /* Max. ULL Low, O(n) n is ticker nodes */
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If this is O(n), shouldn't the value here be something like TICKER_NODE_CNT * X?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The measured value are restricted to the use case mentioned in the comments above. Other scenarios, or increased nodes are not profiled.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

But if you have 306 for the above use case (number of nodes = 6?), then you can define this as 51 * NODES which gives the same result, while also fitting better to the O(n) description.

Why not do it that way?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It does not work like this. The ISRs are of different priority and pre-empt, .i.e. in the default values, Radio = LLL ISR has higher priority, that means ULL High == ULL_LOW measured account for CPU execution of Radio and/or LLL executing over their execution time :-( . Actually, ULL_LOW CPU time is more like x + 85 + 75 + (2 x ISR Latency) = 306.

Also, TICKER_NODES are 16 for this case based on other instances needed to schedule auxiliary transmission, receptions and timeouts. And, the CPU execution time is very depended on difference in optimization (and h/w runtime caching) with any code changes.

I will take these numbers with a pinch of salt!

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

x + 85 + 75 + (2 x ISR Latency) = 306.

That is far from clear from the text and descriptions here :) It may be useful to include the actual calculations behind these numbers, and how they were measured so that others can reproduce the same numbers in case something changes

#else /* !CONFIG_SOC_COMPATIBLE_NRF54LX */
#define LLL_PROF_RADIO_MAX_US 184 /* Max. Radio Rx/Tx ISR, O(1)*/
#define LLL_PROF_LLL_MAX_US 245 /* Max. LLL prepare, O(1) */
#define LLL_PROF_ULL_HIGH_MAX_US 458 /* Max. Radio + LLL + ULL High, O(1) */
#define LLL_PROF_ULL_LOW_MAX_US 733 /* Max. ULL Low, O(n) n is ticker nodes */
#endif /* !CONFIG_SOC_COMPATIBLE_NRF54LX */

#define LLL_PROF_ASSERT(_val, _max) \
{ \
LL_ASSERT_MSG(((_val) <= (_max)), \
"%s: %u (%u), %u (%u), %u (%u), %u (%u)\n", __func__, \
HAL_TICKER_TICKS_TO_US(cputime_ticks_radio), \
LLL_PROF_RADIO_MAX_US, \
HAL_TICKER_TICKS_TO_US(cputime_ticks_lll), \
LLL_PROF_LLL_MAX_US, \
HAL_TICKER_TICKS_TO_US(cputime_ticks_ull_high), \
LLL_PROF_ULL_HIGH_MAX_US, \
HAL_TICKER_TICKS_TO_US(cputime_ticks_ull_low), \
LLL_PROF_ULL_LOW_MAX_US); \
}

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);
static inline void delta_ticks(uint32_t timestamp_ticks, uint8_t *cputime_ticks);
static inline void delta_ticks(uint32_t timestamp_ticks, uint16_t *cputime_ticks);

static uint32_t timestamp_radio;
static uint32_t timestamp_lll;
Expand All @@ -50,10 +85,10 @@ static uint32_t timestamp_ticks_radio;
static uint32_t timestamp_ticks_lll;
static uint32_t timestamp_ticks_ull_high;
static uint32_t timestamp_ticks_ull_low;
static uint8_t cputime_ticks_radio;
static uint8_t cputime_ticks_lll;
static uint8_t cputime_ticks_ull_high;
static uint8_t cputime_ticks_ull_low;
static uint16_t cputime_ticks_radio;
static uint16_t cputime_ticks_lll;
static uint16_t cputime_ticks_ull_high;
static uint16_t cputime_ticks_ull_low;

void lll_prof_enter_radio(void)
{
Expand All @@ -65,6 +100,12 @@ void lll_prof_exit_radio(void)
{
delta(timestamp_radio, &cputime_radio);
delta_ticks(timestamp_ticks_radio, &cputime_ticks_radio);
LLL_PROF_ASSERT(cputime_ticks_radio, HAL_TICKER_US_TO_TICKS(LLL_PROF_RADIO_MAX_US));
Copy link

Copilot AI Sep 3, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The LLL_PROF_ASSERT macro is called in every exit function, but the macro performs multiple HAL_TICKER_TICKS_TO_US conversions for the assertion message formatting. These conversions are expensive and only needed if the assertion fails. Consider moving the conversions inside a conditional block that only executes when the assertion would fail.

Copilot uses AI. Check for mistakes.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

HAL_TICKER_US_TO_TICKS(LLL_PROF_RADIO_MAX_US) is constant, expect the compiler to not do conversions at runtime.

}

uint16_t lll_prof_radio_get(void)
{
return HAL_TICKER_TICKS_TO_US(cputime_ticks_radio);
}

void lll_prof_enter_lll(void)
Expand All @@ -77,6 +118,12 @@ void lll_prof_exit_lll(void)
{
delta(timestamp_lll, &cputime_lll);
delta_ticks(timestamp_ticks_lll, &cputime_ticks_lll);
LLL_PROF_ASSERT(cputime_ticks_lll, HAL_TICKER_US_TO_TICKS(LLL_PROF_LLL_MAX_US));
}

uint16_t lll_prof_lll_get(void)
{
return HAL_TICKER_TICKS_TO_US(cputime_ticks_lll);
}

void lll_prof_enter_ull_high(void)
Expand All @@ -89,6 +136,12 @@ void lll_prof_exit_ull_high(void)
{
delta(timestamp_ull_high, &cputime_ull_high);
delta_ticks(timestamp_ticks_ull_high, &cputime_ticks_ull_high);
LLL_PROF_ASSERT(cputime_ticks_ull_high, HAL_TICKER_US_TO_TICKS(LLL_PROF_ULL_HIGH_MAX_US));
}

uint16_t lll_prof_ull_high_get(void)
{
return HAL_TICKER_TICKS_TO_US(cputime_ticks_ull_high);
}

void lll_prof_enter_ull_low(void)
Expand All @@ -101,6 +154,12 @@ void lll_prof_exit_ull_low(void)
{
delta(timestamp_ull_low, &cputime_ull_low);
delta_ticks(timestamp_ticks_ull_low, &cputime_ticks_ull_low);
LLL_PROF_ASSERT(cputime_ticks_ull_low, HAL_TICKER_US_TO_TICKS(LLL_PROF_ULL_LOW_MAX_US));
}

uint16_t lll_prof_ull_low_get(void)
{
return HAL_TICKER_TICKS_TO_US(cputime_ticks_ull_low);
}

void lll_prof_latency_capture(void)
Expand Down Expand Up @@ -329,12 +388,12 @@ static inline void delta(uint32_t timestamp, uint16_t *cputime)
}
}

static inline void delta_ticks(uint32_t timestamp_ticks, uint8_t *cputime_ticks)
static inline void delta_ticks(uint32_t timestamp_ticks, uint16_t *cputime_ticks)
{
uint32_t delta;

delta = ticker_ticks_now_get() - timestamp_ticks;
if (delta < UINT8_MAX && delta > *cputime_ticks) {
if (delta < UINT16_MAX && delta > *cputime_ticks) {
*cputime_ticks = delta;
}
}
15 changes: 4 additions & 11 deletions subsys/bluetooth/controller/ll_sw/nordic/lll/lll_prof_internal.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,25 +4,18 @@
* SPDX-License-Identifier: Apache-2.0
*/

#if defined(CONFIG_BT_CTLR_PROFILE_ISR)
void lll_prof_enter_radio(void);
void lll_prof_exit_radio(void);
uint16_t lll_prof_radio_get(void);
void lll_prof_enter_lll(void);
void lll_prof_exit_lll(void);
uint16_t lll_prof_lll_get(void);
void lll_prof_enter_ull_high(void);
void lll_prof_exit_ull_high(void);
uint16_t lll_prof_ull_high_get(void);
void lll_prof_enter_ull_low(void);
void lll_prof_exit_ull_low(void);
#else
static inline void lll_prof_enter_radio(void) {}
static inline void lll_prof_exit_radio(void) {}
static inline void lll_prof_enter_lll(void) {}
static inline void lll_prof_exit_lll(void) {}
static inline void lll_prof_enter_ull_high(void) {}
static inline void lll_prof_exit_ull_high(void) {}
static inline void lll_prof_enter_ull_low(void) {}
static inline void lll_prof_exit_ull_low(void) {}
#endif
uint16_t lll_prof_ull_low_get(void);

void lll_prof_latency_capture(void);
uint16_t lll_prof_latency_get(void);
Expand Down
Loading