Device PowerManagement and NRF Uarte

[C.Thilo]

Hi!

I want to integrate power management into our FW. Therefor I did enable it in the prj.conf:

CONFIG_PM_DEVICE=y
CONFIG_PM_DEVICE_RUNTIME=y

And added runtime enable and action run calls regarding this device during bootup phase:

error = pm_device_runtime_enable(dev);
....
error = pm_device_action_run(dev, PM_DEVICE_ACTION_RESUME);
....
error = uart_rx_enable(dev, buffer, UART_BUFFER_SIZE, UART_RECEIVE_TIMEOUT);
....

To test the pm of the UART, I created a timer which, when expired, switches between suspend and resume for this uart.


After BootUp, this timer is not yet started. So the uart was configured, pm runtime was enabled and the dev was resumed after runtime enable.
Therefor the device is active and I can send a message to it and receive an answer.

However, after the first message exchange, the timer (for pm tests) is activated. It does the switch between active->suspended->active and the UART stopped working.

Here the code which does the switch:

ret = pm_device_state_get(dev, &state);
if (ret == 0)
{
    if (state == PM_DEVICE_STATE_SUSPENDED)
    {
        ret = pm_device_action_run(dev, PM_DEVICE_ACTION_RESUME);
        LOG_INF("pm action run ret: %d, new state: %s", ret, pm_device_state_str_get(dev));
    }
    else if(suspend > 0)
    {
        ret = pm_device_action_run(dev, PM_DEVICE_ACTION_SUSPEND);
        LOG_INF("pm action run ret: %d, new state: %s", ret, pm_device_state_str_get(dev));
        suspend--;
    }
}

For testing, I added an counter "suspend" which is static set to 1 to suspend only once.

Any Idea, why the uart receives only Zero-Bytes after the second switch between active and suspended?
And I get some Overrun errors, but I think this is not the cause but impact of the problem, as the overrun errors start to appear after the first byte received:

[00:00:06.938,110] <inf> d_uart: pm action run ret: 0, new state: active
[00:00:09.444,946] <inf> d_uart: uart@8000: received 1 bytes from queue.
[00:00:09.444,976] <inf> m_isn_uart_if: 0x00
[00:00:11.706,573] <err> d_uart: uart@8000: RX Stopped! Reson(0x01): ERROR_OVERRUN
[00:00:11.706,634] <err> d_uart: uart@8000: RX Stopped! Reson(0x01): ERROR_OVERRUN
[00:00:11.706,726] <err> d_uart: uart@8000: RX Stopped! Reson(0x01): ERROR_OVERRUN
[00:00:11.706,817] <err> d_uart: uart@8000: RX Stopped! Reson(0x01): ERROR_OVERRUN
[00:00:11.706,878] <err> d_uart: uart@8000: RX Stopped! Reson(0x01): ERROR_OVERRUN
[00:00:11.706,970] <err> d_uart: uart@8000: RX Stopped! Reson(0x01): ERROR_OVERRUN
[00:00:11.707,092] <wrn> d_uart: uart@8000: Buffer released!
[00:00:11.707,122] <wrn> d_uart: uart@8000: Buffer released!
[00:00:11.707,122] <wrn> d_uart: uart@8000: Disabled!
[00:00:11.707,153] <wrn> d_uart: uart@8000: Buffer requested!

Cheers,
Thilo

[C.Thilo]

Forgot the pinctrl dts:

&pinctrl {
	uart0_default: uart0_default {
		group1 {
			psels = <NRF_PSEL(UART_TX, 0, 19)>,
				<NRF_PSEL(UART_RTS, 1, 3)>;
		};
		group2 {
			psels = <NRF_PSEL(UART_RX, 0, 21)>,
				<NRF_PSEL(UART_CTS, 1, 5)>;
			bias-pull-up;
		};
	};

	uart0_sleep: uart0_sleep {
		group1 {
			psels = <NRF_PSEL(UART_TX, 0, 19)>,
				<NRF_PSEL(UART_RTS, 1, 3)>,
				<NRF_PSEL(UART_RX, 0, 21)>,
				<NRF_PSEL(UART_CTS, 1, 5)>;
			low-power-enable;
		};
	};
};

And the usage of the pinctrl:

&uart0 {
	status = "okay";
	current-speed = <115200>;
	pinctrl-0 = <&uart0_default>;
	pinctrl-1 = <&uart0_sleep>;
	pinctrl-names = "default", "sleep";
};

[C.Thilo]

I managed to create a minimized sample. This did reproduce the problem on our hw (which is based on a nrf5340). So perhaps the sample runs on a nrf5340dk? .... Unsure.

main.c:

#include <zephyr/kernel.h>
#include <zephyr/device.h>
#include <zephyr/devicetree.h>
#include <zephyr/logging/log.h>
#include <zephyr/drivers/uart.h>
#include <zephyr/pm/pm.h>
#include <zephyr/pm/policy.h>
#include <zephyr/pm/device.h>
#include <zephyr/pm/device_runtime.h>

LOG_MODULE_REGISTER(app);

#define MSG_QUEUE_ITEM_COUNT 10
#define BUF_SIZE 10

typedef struct _st_rx_queue_msg
{
    uint8_t  *buffer;
    uint16_t length;
} st_queue_msg;

typedef struct _config
{
	const struct device *dev;
	uint8_t __aligned(4) rxQueueMsgs[sizeof(st_queue_msg) * MSG_QUEUE_ITEM_COUNT];
	struct k_msgq rxQueue;
} st_config;

static K_MEM_SLAB_DEFINE(uart_slab, BUF_SIZE, MSG_QUEUE_ITEM_COUNT, 4);

static void uart_callback(const struct device *dev,
			  struct uart_event *evt,
			  void *user_data)
{
	st_config *cfg = (st_config*)user_data;
	int err;

	switch (evt->type) {
	case UART_TX_DONE:
		LOG_INF("Tx done");
		break;

	case UART_TX_ABORTED:
		LOG_INF("Tx aborted");
		break;

	case UART_RX_RDY:
		st_queue_msg msg;

		msg.length = evt->data.rx.len;
		msg.buffer = &evt->data.rx.buf[evt->data.rx.offset];
		LOG_INF("Rx Rdy, buf: %p", (void*)msg.buffer);

		k_msgq_put(&cfg->rxQueue, &msg, K_NO_WAIT);
		break;

	case UART_RX_BUF_REQUEST:
	{
		uint8_t *buf;

		err = k_mem_slab_alloc(&uart_slab, (void **)&buf, K_NO_WAIT);
		__ASSERT(err == 0, "Failed to allocate slab");

		LOG_INF("buf request: %p", (void*)buf);

		err = uart_rx_buf_rsp(cfg->dev, buf, BUF_SIZE);
		__ASSERT(err == 0, "Failed to provide new buffer");
		break;
	}

	case UART_RX_BUF_RELEASED:
		LOG_INF("buf release: %p", (void*)evt->data.rx_buf.buf);
		k_mem_slab_free(&uart_slab, (void*)evt->data.rx_buf.buf);
		break;

	case UART_RX_DISABLED:
		break;

	case UART_RX_STOPPED:
		break;
	}
}

static void async(const struct device *uart)
{
	int err;
	uint8_t *buf;
	st_config cfg;

	cfg.dev = uart;

	err = k_mem_slab_alloc(&uart_slab, (void **)&buf, K_NO_WAIT);
	__ASSERT(err == 0, "Failed to alloc slab");

	k_msgq_init(&cfg.rxQueue, (char*)&cfg.rxQueueMsgs, sizeof(st_queue_msg), MSG_QUEUE_ITEM_COUNT);

	err = uart_callback_set(uart, uart_callback, (void *)&cfg);
	__ASSERT(err == 0, "Failed to set callback");

    err = pm_device_runtime_enable(uart);
	__ASSERT(err == 0, "Failed to powermanagement device runtime");

    err = pm_device_action_run(uart, PM_DEVICE_ACTION_RESUME);
	__ASSERT(err == 0, "Failed to resume uart device");

	err = uart_rx_enable(uart, buf, BUF_SIZE, 10000);
	__ASSERT(err == 0, "Failed to enable uart rx");

	while (1)
	{
		st_queue_msg msg;
		int err;

		k_msgq_get(&cfg.rxQueue, &msg, K_FOREVER);

		err = uart_tx(uart, msg.buffer, msg.length, 10000);
		__ASSERT(err == 0, "Failed to initiate transmission");
		k_sleep(K_MSEC(500));

		err = uart_rx_disable(uart);
		__ASSERT(err == 0, "Failed to disable uart rx");

		err = pm_device_action_run(uart, PM_DEVICE_ACTION_SUSPEND);
		__ASSERT(err == 0, "Failed to suspend uart device");
		
		k_sleep(K_MSEC(500));

		pm_device_action_run(uart, PM_DEVICE_ACTION_RESUME);
		__ASSERT(err == 0, "Failed to resume uart device");

		err = uart_rx_enable(uart, buf, BUF_SIZE, 10000);
		__ASSERT(err == 0, "Failed to enable uart rx: err: %d", err);
	}
}

int main(void)
{
	const struct device *uart = DEVICE_DT_GET(DT_NODELABEL(uart0));

	__ASSERT(device_is_ready(uart), "UART0 device not ready");

	async(uart);

	return 0;
}

overlay:

/* SPDX-License-Identifier: LicenseRef-Nordic-5-Clause */

&uart0 {
	status = "okay";
	current-speed = <115200>;

	pinctrl-0 = <&uart0_default>;
	pinctrl-1 = <&uart0_sleep>;
	pinctrl-names = "default", "sleep";
};

&uart0_default {
	/* Disconnect CTS and RTS lines from pins.
	 * This is a temporary workaround for increased current consumption
	 * observed on nRF5340 DKs only (~200 uA more on v0.9.0 and ~400 uA
	 * more on v2.0.0).
	 */
	group1 {
		psels = <NRF_PSEL(UART_TX, 0, 19)>,
				<NRF_PSEL_DISCONNECTED(UART_RTS)>;
	};
	group2 {
		psels = <NRF_PSEL(UART_RX, 0, 21)>,
				<NRF_PSEL_DISCONNECTED(UART_CTS)>;
		bias-pull-up;
	};
};

&uart0_sleep {
	group1 {
		psels = <NRF_PSEL(UART_TX, 0, 19)>,
			<NRF_PSEL_DISCONNECTED(UART_RTS)>,
			<NRF_PSEL(UART_RX, 0, 21)>,
			<NRF_PSEL_DISCONNECTED(UART_CTS)>;
		low-power-enable;
	};
};

&gpiote {
	interrupts = <13 NRF_DEFAULT_IRQ_PRIORITY>;
};

&gpio0 {
	status = "okay";
};

&gpio1 {
	status = "okay";
};

prj.conf:

CONFIG_UART_ASYNC_API=y

CONFIG_UART_0_ASYNC=y
CONFIG_UART_0_NRF_HW_ASYNC=y
CONFIG_UART_0_NRF_HW_ASYNC_TIMER=2
CONFIG_NRFX_TIMER2=y

CONFIG_LOG=y
CONFIG_NO_OPTIMIZATIONS=y
CONFIG_ASSERT=y
CONFIG_LOG_PROCESS_THREAD_STACK_SIZE=2048
CONFIG_MAIN_STACK_SIZE=2048
CONFIG_USE_SEGGER_RTT=y
CONFIG_LOG_BACKEND_RTT=y
CONFIG_LOG_PRINTK=y
CONFIG_LOG_BACKEND_UART=n
CONFIG_LOG_BACKEND_SHOW_COLOR=y

CONFIG_PM_DEVICE=y
CONFIG_PM_DEVICE_RUNTIME=y

And here is the log from the RTT Viewer which shows the assert of the uart_rx_enable after the suspend in the while which is the second suspend. The first suspend was done by pm_device_runtime_enable.

RTT Viewer Log:

*** Booting nRF Connect SDK v2.7.0-5cb85570ca43 ***
*** Using Zephyr OS v3.6.99-100befc70c74 ***
[00:00:00.354,766] <inf> app: buf request: 0x20003800
[00:00:08.222,106] <inf> app: Rx Rdy, buf: 0x2000380c[00:00:08.222,259] <inf> app: Tx done
ASSERTION FAIL [err == 0] @ CMAKE_SOURCE_DIR/src/main.c:138
  Failed to enable uart rx: err: -16
[00:00:09.222,412] <err> os: r0/a1:  0x00000004  r1/a2:  0x0000008a  r2/a3:  0x000000020m
[00:00:09.222,442] <err> os: r3/a4:  0x00000004 r12/ip:  0x00000004 r14/lr:  0x00000777
[00:00:09.222,442] <err> os:  xpsr:  0x09000000
[00:00:09.222,442] <err> os: Faulting instruction address (r15/pc): 0x0000d106
[00:00:09.222,503] <err> os: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0
[00:00:09.222,534] <err> os: Current thread: 0x20000960 (main)
[00:00:09.454,559] <err> os: Halting system

Any hint would be very appriciated!

Cheers,
Thilo

[C.Thilo]

If I ignore the -16 of uart_rx_enable, as it is -EBUSY, which means rx is already enabled, like so:

		err = uart_rx_enable(uart, buf, BUF_SIZE, 10000);
		__ASSERT(err == 0 || err == -EBUSY, "Failed to enable uart rx: err: %d", err);

Then the Rx stopped with reason 1 appears in the sample too. Like in our normal App.

*** Booting nRF Connect SDK v2.7.0-5cb85570ca43 ***
*** Using Zephyr OS v3.6.99-100befc70c74 ***
[00:00:00.366,363] <inf> app: buf request: 0x20003800
[00:00:15.027,465] <inf> app: Rx Rdy, buf: 0x2000380c
[00:00:15.027,618] <inf> app: Tx done
[00:00:24.912,933] <wrn> app: Rx stopped: reason: 1
[00:00:24.913,482] <inf> app: buf release: 0x2000380c
[00:00:24.913,513] <inf> app: buf release: 0x20003800
[00:00:24.913,513] <wrn> app: Rx disabled
[00:00:24.913,543] <inf> app: buf request: 0x20003800
ASSERTION FAIL [err == 0] @ CMAKE_SOURCE_DIR/src/main.c:67
        Failed to provide new buffer
[00:00:24.913,635] <err> os: r0/a1:  0x00000004  r1/a2:  0x00000043  r2/a3:  0x00000006
[00:00:24.913,635] <err> os: r3/a4:  0x00000004 r12/ip:  0x00000004 r14/lr:  0x000005b3
[00:00:24.913,635] <err> os:  xpsr:  0x01000018
[00:00:24.913,665] <err> os: Faulting instruction address (r15/pc): 0x0000d142
[00:00:24.913,726] <err> os: >>> ZEPHYR FATAL ERROR 4: Kernel panic on CPU 0
[00:00:24.913,726] <err> os: Fault during interrupt handling

[00:00:24.913,757] <err> os: Current thread: 0x200008a0 (idle)
[00:00:25.246,734] <err> os: Halting system

The assert is the impact from the previous rx disabled which is the impact of the rx stopped probelem.
So the cause is whatever caused the rx stopped overrun. And I don't get it.

Another thing is, that the uart_rx_disabled in the while seems to not work, as the next uart_rx_enable will report -EBUSY (already running). Why is that so? Perhaps thats the root cause?

Cheers
Thilo

[Sigurd Hellesvik]

Hi,

Which version of the SDK do you use?

Any Idea, why the uart receives only Zero-Bytes after the second switch between active and suspended?
And I get some Overrun errors, but I think this is not the cause but impact of the problem, as the overrun errors start to appear after the first byte received:

So first you got an error with wrong bytes read on the UART.

But then later in comments you get the Assert from UART enable?

I do not think I follow completely here. Is the Assert something you get when trying to finx the first issue, or?

Regards,
Sigurd Hellesvik

[C.Thilo]

Hi

Sorry, that I missed to tell the SDK Version. 

The test project is currently build with NRF SDK 2.7.0.

Sigurd Hellesvik said:

I do not think I follow completely here. Is the Assert something you get when trying to finx the first issue, or?

Before I send the uart into sleep, I disabled the rx in the while loop.
Therefor I tried to enable the rx after resume. Thats the while loop, which doesn't know that the RX_STOPPED Interruppt occured. So the assert is not the problem but might show the problem.
As the returned -EBUSY tells me, the the uart_rx was still enabled, altough I disabled it before sleep.

To reproduce the Error, just use the Test Project and open a UART to the uart0. Type in some keys I think three keys is enough, and the error occurs on my side.

<EDIT>
I even tested it now, with a nrf5340dk. The RTT Output looks very similar. Just the UART 0 Pins changed in the dts.

&uart0_default {
	/* Disconnect CTS and RTS lines from pins.
	 * This is a temporary workaround for increased current consumption
	 * observed on nRF5340 DKs only (~200 uA more on v0.9.0 and ~400 uA
	 * more on v2.0.0).
	 */
	group1 {
		psels = <NRF_PSEL(UART_TX, 0, 20)>,
			<NRF_PSEL_DISCONNECTED(UART_RTS)>;
	};
	group2 {
		psels = <NRF_PSEL(UART_RX, 0, 22)>,
			<NRF_PSEL_DISCONNECTED(UART_CTS)>;
		bias-pull-up;
	};


};

&uart0_sleep {
	group1 {
		psels = <NRF_PSEL(UART_TX, 0, 20)>,
			<NRF_PSEL(UART_RX, 0, 22)>,
			<NRF_PSEL_DISCONNECTED(UART_RTS)>,
			<NRF_PSEL_DISCONNECTED(UART_CTS)>;
		low-power-enable;
	};
};

and the RTT Output:

*** Booting nRF Connect SDK v2.7.0-5cb85570ca43 ***
*** Using Zephyr OS v3.6.99-100befc70c74 ***
[00:00:00.386,413] <inf> app: buf request: 0x20003800
[00:00:10.072,540] <inf> app: Rx Rdy, buf: 0x2000380c
[00:00:10.072,692] <inf> app: Tx done
[00:00:16.526,184] <wrn> app: Rx stopped: reason: 1
[00:00:16.526,733] <inf> app: buf release: 0x2000380c
[00:00:16.526,763] <inf> app: buf release: 0x20003800
[00:00:16.526,763] <wrn> app: Rx disabled
[00:00:16.526,794] <inf> app: buf request: 0x20003800
ASSERTION FAIL [err == 0] @ CMAKE_SOURCE_DIR/src/main.c:67
  Failed to provide new buffer: err: -13

</EDIT>

Cheers,
Thilo