Skip to content

Commit ff980ea

Browse files
cvinayakcvinayak
committed
Bluetooth: Controller: In-system profiling and CPU overhead assertions
Updated in-system profiling for CPU usage with on target measurements and added assertion checks. Signed-off-by: Vinayak Kariappa Chettimada <vich@nordicsemi.no>
1 parent bbf1c2c commit ff980ea

File tree

8 files changed

+202
-47
lines changed

8 files changed

+202
-47
lines changed

‎subsys/bluetooth/controller/hci/hci.c‎

Lines changed: 7 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -8957,13 +8957,13 @@ static void encode_control(struct node_rx_pdu *node_rx,
89578957

89588958
#if defined(CONFIG_BT_CTLR_PROFILE_ISR)
89598959
case NODE_RX_TYPE_PROFILE:
8960-
LOG_INF("l: %u, %u, %u; t: %u, %u, %u; cpu: %u (%u), %u (%u), %u (%u), %u (%u).",
8961-
pdu_data->profile.lcur, pdu_data->profile.lmin, pdu_data->profile.lmax,
8962-
pdu_data->profile.cur, pdu_data->profile.min, pdu_data->profile.max,
8963-
pdu_data->profile.radio, pdu_data->profile.radio_ticks,
8964-
pdu_data->profile.lll, pdu_data->profile.lll_ticks,
8965-
pdu_data->profile.ull_high, pdu_data->profile.ull_high_ticks,
8966-
pdu_data->profile.ull_low, pdu_data->profile.ull_low_ticks);
8960+
printk("l: %u, %u, %u; t: %u, %u, %u; cpu: %u (%u), %u (%u), %u (%u), %u (%u).\n",
8961+
pdu_data->profile.lcur, pdu_data->profile.lmin, pdu_data->profile.lmax,
8962+
pdu_data->profile.cur, pdu_data->profile.min, pdu_data->profile.max,
8963+
pdu_data->profile.radio, pdu_data->profile.radio_ticks,
8964+
pdu_data->profile.lll, pdu_data->profile.lll_ticks,
8965+
pdu_data->profile.ull_high, pdu_data->profile.ull_high_ticks,
8966+
pdu_data->profile.ull_low, pdu_data->profile.ull_low_ticks);
89678967
return;
89688968
#endif /* CONFIG_BT_CTLR_PROFILE_ISR */
89698969

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

Lines changed: 36 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -101,15 +101,19 @@ ISR_DIRECT_DECLARE(radio_nrf5_isr)
101101
{
102102
DEBUG_RADIO_ISR(1);
103103

104-
lll_prof_enter_radio();
104+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
105+
lll_prof_enter_radio();
106+
}
105107

106108
isr_radio();
107109

108110
#if !defined(CONFIG_BT_CTLR_ZLI)
109111
ISR_DIRECT_PM();
110112
#endif /* !CONFIG_BT_CTLR_ZLI */
111113

112-
lll_prof_exit_radio();
114+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
115+
lll_prof_exit_radio();
116+
}
113117

114118
DEBUG_RADIO_ISR(0);
115119

@@ -133,15 +137,19 @@ ISR_DIRECT_DECLARE(timer_nrf5_isr)
133137
{
134138
DEBUG_RADIO_ISR(1);
135139

136-
lll_prof_enter_radio();
140+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
141+
lll_prof_enter_radio();
142+
}
137143

138144
isr_radio_tmr();
139145

140146
#if !defined(CONFIG_BT_CTLR_ZLI)
141147
ISR_DIRECT_PM();
142148
#endif /* !CONFIG_BT_CTLR_ZLI */
143149

144-
lll_prof_exit_radio();
150+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
151+
lll_prof_exit_radio();
152+
}
145153

146154
DEBUG_RADIO_ISR(0);
147155

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

163-
lll_prof_enter_ull_high();
171+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
172+
lll_prof_enter_ull_high();
173+
}
164174

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

177187
mayfly_run(TICKER_USER_ID_ULL_HIGH);
178188

179-
lll_prof_exit_ull_high();
189+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
190+
lll_prof_exit_ull_high();
191+
}
180192

181193
#if !defined(CONFIG_BT_CTLR_LOW_LAT) && \
182194
(CONFIG_BT_CTLR_ULL_HIGH_PRIO == CONFIG_BT_CTLR_ULL_LOW_PRIO)
183-
lll_prof_enter_ull_low();
195+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
196+
lll_prof_enter_ull_low();
197+
}
184198

185199
mayfly_run(TICKER_USER_ID_ULL_LOW);
186200

187-
lll_prof_exit_ull_low();
201+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
202+
lll_prof_exit_ull_low();
203+
}
188204
#endif
189205

190206
DEBUG_TICKER_ISR(0);
@@ -194,11 +210,15 @@ static void swi_lll_nrf5_isr(const void *arg)
194210
{
195211
DEBUG_RADIO_ISR(1);
196212

197-
lll_prof_enter_lll();
213+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
214+
lll_prof_enter_lll();
215+
}
198216

199217
mayfly_run(TICKER_USER_ID_LLL);
200218

201-
lll_prof_exit_lll();
219+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
220+
lll_prof_exit_lll();
221+
}
202222

203223
DEBUG_RADIO_ISR(0);
204224
}
@@ -209,11 +229,15 @@ static void swi_ull_low_nrf5_isr(const void *arg)
209229
{
210230
DEBUG_TICKER_JOB(1);
211231

212-
lll_prof_enter_ull_low();
232+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
233+
lll_prof_enter_ull_low();
234+
}
213235

214236
mayfly_run(TICKER_USER_ID_ULL_LOW);
215237

216-
lll_prof_exit_ull_low();
238+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
239+
lll_prof_exit_ull_low();
240+
}
217241

218242
DEBUG_TICKER_JOB(0);
219243
}

‎subsys/bluetooth/controller/ll_sw/nordic/lll/lll_adv.c‎

Lines changed: 29 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1350,6 +1350,10 @@ static void isr_done(void *param)
13501350

13511351
pdu = chan_prepare(lll);
13521352

1353+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
1354+
lll_prof_cputime_capture();
1355+
}
1356+
13531357
#if defined(HAL_RADIO_GPIO_HAVE_PA_PIN) || defined(CONFIG_BT_CTLR_ADV_EXT)
13541358
start_us = radio_tmr_start_now(1);
13551359

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

13701374
#if defined(HAL_RADIO_GPIO_HAVE_PA_PIN)
1375+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
1376+
/* PA/LNA enable is overwriting packet end used in ISR
1377+
* profiling, hence back it up for later use.
1378+
*/
1379+
lll_prof_radio_end_backup();
1380+
}
1381+
13711382
radio_gpio_pa_setup();
13721383
radio_gpio_pa_lna_enable(start_us +
13731384
radio_tx_ready_delay_get(0, 0) -
@@ -1387,6 +1398,10 @@ static void isr_done(void *param)
13871398

13881399
radio_filter_disable();
13891400

1401+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
1402+
lll_prof_cputime_capture();
1403+
}
1404+
13901405
#if defined(CONFIG_BT_PERIPHERAL)
13911406
if (!lll->is_hdcd)
13921407
#endif /* CONFIG_BT_PERIPHERAL */
@@ -1433,6 +1448,19 @@ static void isr_done(void *param)
14331448
lll_isr_cleanup(param);
14341449
}
14351450

1451+
static void isr_tx_done(void *param)
1452+
{
1453+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
1454+
lll_prof_latency_capture();
1455+
}
1456+
1457+
isr_done(param);
1458+
1459+
if (IS_ENABLED(CONFIG_BT_CTLR_PROFILE_ISR)) {
1460+
lll_prof_send();
1461+
}
1462+
}
1463+
14361464
static void isr_abort(void *param)
14371465
{
14381466
/* Clear radio status and events */
@@ -1513,7 +1541,7 @@ static struct pdu_adv *chan_prepare(struct lll_adv *lll)
15131541
radio_tmr_tifs_set(EVENT_IFS_US);
15141542
radio_switch_complete_and_rx(0);
15151543
} else {
1516-
radio_isr_set(isr_done, lll);
1544+
radio_isr_set(isr_tx_done, lll);
15171545

15181546
if (IS_ENABLED(CONFIG_BT_CTLR_SW_SWITCH_SINGLE_TIMER) &&
15191547
IS_ENABLED(CONFIG_BT_CTLR_ADV_EXT)) {

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

Lines changed: 83 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -12,6 +12,7 @@
1212

1313
#include "hal/ccm.h"
1414
#include "hal/radio.h"
15+
#include "hal/ticker.h"
1516

1617
#include "util/memq.h"
1718

@@ -23,12 +24,46 @@
2324

2425
#include "lll.h"
2526

27+
#include "hal/debug.h"
28+
29+
/* Below profiling measurements using a sample with:
30+
* 1 connectable legacy advertising or 1 peripheral ACL,
31+
* plus
32+
* 3 extended advertising sets, scanning on 2M PHY, scanning on Coded PHY, and
33+
* 2 auxiliary scan set.
34+
*/
35+
#if defined(CONFIG_SOC_COMPATIBLE_NRF54LX)
36+
#define LLL_PROF_RADIO_MAX_US 103 /* Max. Radio Rx/Tx ISR, O(1)*/
37+
#define LLL_PROF_LLL_MAX_US 105 /* Max. LLL prepare, O(1) */
38+
#define LLL_PROF_ULL_HIGH_MAX_US 260 /* Max. Radio + LLL + ULL High, O(1) */
39+
#define LLL_PROF_ULL_LOW_MAX_US 306 /* Max. ULL Low, O(n) n is ticker nodes */
40+
#else /* !CONFIG_SOC_COMPATIBLE_NRF54LX */
41+
#define LLL_PROF_RADIO_MAX_US 184 /* Max. Radio Rx/Tx ISR, O(1)*/
42+
#define LLL_PROF_LLL_MAX_US 245 /* Max. LLL prepare, O(1) */
43+
#define LLL_PROF_ULL_HIGH_MAX_US 458 /* Max. Radio + LLL + ULL High, O(1) */
44+
#define LLL_PROF_ULL_LOW_MAX_US 733 /* Max. ULL Low, O(n) n is ticker nodes */
45+
#endif /* !CONFIG_SOC_COMPATIBLE_NRF54LX */
46+
47+
#define LLL_PROF_ASSERT(_val, _max) \
48+
{ \
49+
LL_ASSERT_MSG(((_val) <= (_max)), \
50+
"%s: %u (%u), %u (%u), %u (%u), %u (%u)\n", __func__, \
51+
HAL_TICKER_TICKS_TO_US(cputime_ticks_radio), \
52+
LLL_PROF_RADIO_MAX_US, \
53+
HAL_TICKER_TICKS_TO_US(cputime_ticks_lll), \
54+
LLL_PROF_LLL_MAX_US, \
55+
HAL_TICKER_TICKS_TO_US(cputime_ticks_ull_high), \
56+
LLL_PROF_ULL_HIGH_MAX_US, \
57+
HAL_TICKER_TICKS_TO_US(cputime_ticks_ull_low), \
58+
LLL_PROF_ULL_LOW_MAX_US); \
59+
}
60+
2661
static int send(struct node_rx_pdu *rx);
2762
static uint16_t latency_get(void);
2863
static inline void sample(uint32_t *timestamp);
2964
static inline void sample_ticks(uint32_t *timestamp_ticks);
3065
static inline void delta(uint32_t timestamp, uint16_t *cputime);
31-
static inline void delta_ticks(uint32_t timestamp_ticks, uint8_t *cputime_ticks);
66+
static inline void delta_ticks(uint32_t timestamp_ticks, uint16_t *cputime_ticks);
3267

3368
static uint32_t timestamp_radio;
3469
static uint32_t timestamp_lll;
@@ -50,10 +85,10 @@ static uint32_t timestamp_ticks_radio;
5085
static uint32_t timestamp_ticks_lll;
5186
static uint32_t timestamp_ticks_ull_high;
5287
static uint32_t timestamp_ticks_ull_low;
53-
static uint8_t cputime_ticks_radio;
54-
static uint8_t cputime_ticks_lll;
55-
static uint8_t cputime_ticks_ull_high;
56-
static uint8_t cputime_ticks_ull_low;
88+
static uint16_t cputime_ticks_radio;
89+
static uint16_t cputime_ticks_lll;
90+
static uint16_t cputime_ticks_ull_high;
91+
static uint16_t cputime_ticks_ull_low;
5792

5893
void lll_prof_enter_radio(void)
5994
{
@@ -65,6 +100,12 @@ void lll_prof_exit_radio(void)
65100
{
66101
delta(timestamp_radio, &cputime_radio);
67102
delta_ticks(timestamp_ticks_radio, &cputime_ticks_radio);
103+
LLL_PROF_ASSERT(cputime_ticks_radio, HAL_TICKER_US_TO_TICKS(LLL_PROF_RADIO_MAX_US));
104+
}
105+
106+
uint16_t lll_prof_radio_get(void)
107+
{
108+
return HAL_TICKER_TICKS_TO_US(cputime_ticks_radio);
68109
}
69110

70111
void lll_prof_enter_lll(void)
@@ -77,6 +118,12 @@ void lll_prof_exit_lll(void)
77118
{
78119
delta(timestamp_lll, &cputime_lll);
79120
delta_ticks(timestamp_ticks_lll, &cputime_ticks_lll);
121+
LLL_PROF_ASSERT(cputime_ticks_lll, HAL_TICKER_US_TO_TICKS(LLL_PROF_LLL_MAX_US));
122+
}
123+
124+
uint16_t lll_prof_lll_get(void)
125+
{
126+
return HAL_TICKER_TICKS_TO_US(cputime_ticks_lll);
80127
}
81128

82129
void lll_prof_enter_ull_high(void)
@@ -89,6 +136,12 @@ void lll_prof_exit_ull_high(void)
89136
{
90137
delta(timestamp_ull_high, &cputime_ull_high);
91138
delta_ticks(timestamp_ticks_ull_high, &cputime_ticks_ull_high);
139+
LLL_PROF_ASSERT(cputime_ticks_ull_high, HAL_TICKER_US_TO_TICKS(LLL_PROF_ULL_HIGH_MAX_US));
140+
}
141+
142+
uint16_t lll_prof_ull_high_get(void)
143+
{
144+
return HAL_TICKER_TICKS_TO_US(cputime_ticks_ull_high);
92145
}
93146

94147
void lll_prof_enter_ull_low(void)
@@ -101,6 +154,12 @@ void lll_prof_exit_ull_low(void)
101154
{
102155
delta(timestamp_ull_low, &cputime_ull_low);
103156
delta_ticks(timestamp_ticks_ull_low, &cputime_ticks_ull_low);
157+
LLL_PROF_ASSERT(cputime_ticks_ull_low, HAL_TICKER_US_TO_TICKS(LLL_PROF_ULL_LOW_MAX_US));
158+
}
159+
160+
uint16_t lll_prof_ull_low_get(void)
161+
{
162+
return HAL_TICKER_TICKS_TO_US(cputime_ticks_ull_low);
104163
}
105164

106165
void lll_prof_latency_capture(void)
@@ -120,7 +179,7 @@ uint16_t lll_prof_latency_get(void)
120179
{
121180
uint16_t latency;
122181

123-
/* We are here before lll_prof_cputime_capture was called */
182+
/* We are here before latency timestamp was fetched */
124183
if (timestamp_latency == UINT16_MAX) {
125184
/* get the ISR latency sample */
126185
timestamp_latency = radio_tmr_sample_get();
@@ -150,15 +209,28 @@ uint32_t lll_prof_radio_end_backup(void)
150209

151210
void lll_prof_cputime_capture(void)
152211
{
153-
/* get the ISR latency sample */
154-
timestamp_latency = radio_tmr_sample_get();
212+
/* We are here before latency timestamp was fetched */
213+
if (timestamp_latency == UINT16_MAX) {
214+
/* get the ISR latency sample */
215+
timestamp_latency = radio_tmr_sample_get();
216+
}
155217

156218
/* sample the packet timer again, use it to calculate ISR execution time
157219
* and use it in profiling event
158220
*/
159221
radio_tmr_sample();
160222
}
161223

224+
uint16_t lll_prof_cputime_get(void)
225+
{
226+
uint16_t cputime;
227+
228+
/* calculate the elapsed time in us since ISR entry */
229+
cputime = radio_tmr_sample_get() - timestamp_latency;
230+
231+
return cputime;
232+
}
233+
162234
void lll_prof_send(void)
163235
{
164236
struct node_rx_pdu *rx;
@@ -228,7 +300,7 @@ static int send(struct node_rx_pdu *rx)
228300
}
229301

230302
/* calculate the elapsed time in us since ISR entry */
231-
cputime = radio_tmr_sample_get() - timestamp_latency;
303+
cputime = lll_prof_cputime_get();
232304

233305
/* check changes in min, avg and max */
234306
if (cputime > cputime_max) {
@@ -329,12 +401,12 @@ static inline void delta(uint32_t timestamp, uint16_t *cputime)
329401
}
330402
}
331403

332-
static inline void delta_ticks(uint32_t timestamp_ticks, uint8_t *cputime_ticks)
404+
static inline void delta_ticks(uint32_t timestamp_ticks, uint16_t *cputime_ticks)
333405
{
334406
uint32_t delta;
335407

336408
delta = ticker_ticks_now_get() - timestamp_ticks;
337-
if (delta < UINT8_MAX && delta > *cputime_ticks) {
409+
if (delta < UINT16_MAX && delta > *cputime_ticks) {
338410
*cputime_ticks = delta;
339411
}
340412
}

0 commit comments

Comments
 (0)