MPSL ASSERT: 112, 2134 if using multiple BLE communication

[M__S]

If using multiple BLE communication, after some time (smaller than 1 hour) a MPSL ASSERT (112, 2134) occurs.

The function m_assert_handler was called, when MPSL_IRQ_TIMER0_Handler was called.

Mostly if the MPSL_IRQ_TIMER0_Handler was called it works fine, with no assertion.

Following clock is configured: CONFIG_CLOCK_CONTROL_NRF_K32SRC_RC=y

It does not matter, if the device works as BLE server and/or client.

It also does not matter, if the advertising is started with bt_le_adv_start_legacy or bt_le_ext_adv_start.

It also does not matter, if the debugger is connected to the device or not.

If there is only one BLE communication active, it works fine.

It is an application that uses the NCS version 2.4.0.

What could be the reason for these assertion?

Output of SEGGER J-Link:

[ 159.325408] <err> mpsl_init: m_assert_handler: MPSL ASSERT: 112, 2134[0m

[ 159.325439] <err> os: hard_fault: ***** HARD FAULT *****

[ 159.325469] <err> os: hard_fault: Fault escalation (see below)

[ 159.325469] <err> os: hard_fault: ARCH_EXCEPT with reason 3

[ 159.325500] <err> os: esf_dump: r0/a1: 0x00000003 r1/a2: 0x00000000 r2/a3: 0x000005c3

[ 159.325500] [1;31m<err> os: esf_dump: r3/a4: 0x00000000 r12/ip: 0x200055e8 r14/lr: 0x00000000

[ 159.325531] <err> os: esf_dump: xpsr: 0x41000018

[ 159.325531] [1;31m<err> os: esf_dump: Faulting instruction address (r15/pc): 0x00045740

[ 159.325592] <err> os: z_fatal_error: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0[0m

[ 159.325622] <err> os: z_fatal_error: Fault during interrupt handling

[ 159.325653] <err> os: z_fatal_error: Current thread: 0x200054f8 (idle)

[ 160.355163] [1;31m<err> fatal_error: k_sys_fatal_error_handler: Resetting system

[Vidar Berg]

Hello,

This assert is raised if the HF crystal is not running when it should be. It could indicate that the crystal oscillator ramp-up time is too slow. If you are running this on a custom board, please try to measure the crystal's startup time. You can use the use the code snippet below for this (must be run before bt_enable())

	NRF_TIMER1->BITMODE = TIMER_BITMODE_BITMODE_32Bit << TIMER_BITMODE_BITMODE_Pos;
	NRF_TIMER1->TASKS_CLEAR = 1;
	NRF_CLOCK->EVENTS_HFCLKSTARTED = 0;
	NRF_TIMER1->TASKS_START = 1;
	NRF_CLOCK->TASKS_HFCLKSTART = 1;
	while(NRF_CLOCK->EVENTS_HFCLKSTARTED == 0);
	NRF_TIMER1->TASKS_CAPTURE[0] = 1;

	printk("HF Clock has started. Startup time: %d uS\n", NRF_TIMER1->CC[0]);

Also, are you using mpsl_clock_hfclk_latency_set() in your code?

Best regards,

Vidar

[M__S]

Hello Vidar,

thank You for Your answer and information.

The crystal oscillator ramp-up is about 925 us.

No, I do not use the function  mpsl_clock_hfclk_latency_set().

Where should this be used? Also before bt_enable()?

What value should have the argument mpsl_clock_hfclk_latency_config? The exact ramp-up time?

Best regards,

Martin

[M__S]

I changed the software.

Calling the function mpsl_clock_hfclk_latency_set(MPSL_CLOCK_HF_LATENCY_WORST_CASE) directly before bt_enable().

But this error still occurs, see output of SEGGER J-Link:

[ 4631.198791] <err> mpsl_init: m_assert_handler: MPSL ASSERT: 112, 2134

[ 4631.198822] <err> os: hard_fault: ***** HARD FAULT *****

[ 4631.198822] <err> os: hard_fault: Fault escalation (see below)

[ 4631.198852] [1;31m<err> os: hard_fault: ARCH_EXCEPT with reason 3

[ 4631.198852] <err> os: esf_dump: r0/a1: 0x00000003 r1/a2: 0x00000000 r2/a3: 0x00000005

[ 4631.198883] [1;31m<err> os: esf_dump: r3/a4: 0x20002a60 r12/ip: 0x200020e0 r14/lr: 0x0002b3a9

[ 4631.198913] [1;31m<err> os: esf_dump: xpsr: 0x41000018

[ 4631.198913] <err> os: esf_dump: Faulting instruction address (r15/pc): 0x00045d08

[ 4631.198974] <err> os: z_fatal_error: >>> ZEPHYR FATAL ERROR 3: Kernel oops on CPU 0

[ 4631.199005] <err> os: z_fatal_error: Fault during interrupt handling

[ 4631.199035] [1;31m<err> os: z_fatal_error: Current thread: 0x200054f8 (idle)

[ 4632.573577] <err> fatal_error: k_sys_fatal_error_handler: Resetting system

[Vidar Berg]

Hi, 

925 us is pretty slow, the crystal on the DK took about 350 uS when I measured it here for comparison. However, 925 us should be OK considering MPSL_CLOCK_HF_LATENCY_WORST_CASE is set to 1525 us.   

Please try to request the HFXO to be always on and see if you get the same assert then. You can do this by adding CONFIG_CLOCK_CONTROL=y to your prj.conf and inserting the code below in your application.

#include <zephyr/drivers/clock_control.h>
#include <zephyr/drivers/clock_control/nrf_clock_control.h>

static void clock_init(void)
{
	int err;
	int res;
	struct onoff_manager *clk_mgr;
	struct onoff_client clk_cli;

	clk_mgr = z_nrf_clock_control_get_onoff(CLOCK_CONTROL_NRF_SUBSYS_HF);
	if (!clk_mgr) {
		printk("Unable to get the Clock manager\n");
		return;
	}

	sys_notify_init_spinwait(&clk_cli.notify);

	err = onoff_request(clk_mgr, &clk_cli);
	if (err < 0) {
		printk("Clock request failed: %d\n", err);
		return;
	}

	do {
		err = sys_notify_fetch_result(&clk_cli.notify, &res);
		if (!err && res) {
			printk("Clock could not be started: %d\n", res);
			return;
		}
	} while (err);

	printk("Clock has started\n");
}


int main(void)
{
    clock_init();
    ...

Edit: You can use the mpsl_clock_hfclk_request() function instead since you are already using the mpsl:

void clock_started_cb(void)
{
	printk("HFXO started\n");
}

int main(void)
{
	int err; 
	
	err = mpsl_clock_hfclk_request(clock_started_cb);
	if (err) {
		printk("mpsl_clock_hfclk_request() failed (err: %d)\n", err);
	}
	...

[andi.becker]

    err = mpsl_clock_hfclk_request(clock_started_cb);

worked for us.