printk() low power bug report

[Jayant Tang]

Hello DevZone,

I just located a mysterious bug, it's about printk() and low power.

Environment:

• NCS v2.8.0 and v2.9.0
• nRF52840DK v3.0.2
• PC: Ubuntu 22.04
• Zephyr Hello World sample

Condition:

• Use ASYNC UART as log backend and as console backend
• Use `CONFIG_LOG_PRINTK=y` to redirect the message to logging subsystem.
• Only use `printk()`, (no `printf` or `LOG_INF`, etc.), to print 33 bytes. no more, no less.

Result：

Very high bottom current:

 

But when my print is not 33 bytes, or just set `CONFIG_LOG_PRINTK=n`, the power consumption is very nice:

How do I know it's 33 bytes? Because:

printk("Hello World! %s\n", CONFIG_BOARD_TARGET);

// "Hello World! nrf52840dk/nrf52840\n" is just 33 bytes!!!!

That wastes me lot of times...

My code is very simple, just use `zephyr/samples/hello_world`, you can try yourself.

prj.conf

# Enable UART LOG
CONFIG_LOG=y
CONFIG_LOG_MODE_DEFERRED=y
CONFIG_LOG_BACKEND_UART=y

# Enable Async uart
CONFIG_LOG_BACKEND_UART_ASYNC=y
CONFIG_UART_ASYNC_API=y
CONFIG_UART_0_INTERRUPT_DRIVEN=n
CONFIG_UART_0_ASYNC=y

## Hardware counter for Async UART is only for RX
## we don't need it here
# CONFIG_UART_0_NRF_HW_ASYNC=y
# CONFIG_UART_0_NRF_HW_ASYNC_TIMER=1
# CONFIG_NRFX_TIMER1=y

# enable console
CONFIG_PRINTK=y
CONFIG_UART_CONSOLE=y

# disable all input feature
CONFIG_SHELL=n
CONFIG_CONSOLE_HANDLER=n

# printk redirect to log
CONFIG_LOG_PRINTK=y

# Enable runtime PM
CONFIG_PM_DEVICE_RUNTIME=y
CONFIG_PM_DEVICE=y

# Disable RTT
CONFIG_USE_SEGGER_RTT=n
CONFIG_RTT_CONSOLE=n

nrf52840dk_nrf52840.overlay

&adc {
    status = "disabled";
};

&i2c0 {
    status = "disabled";
};

&spi1 {
    status = "disabled";
};

&pwm0 {
    status = "disabled";
};

&spi3 {
    status = "disabled";
};

&qspi {
    status = "disabled";
};

&usbd {
    status = "disabled";
};

&uart0 {
    status = "okay";
    zephyr,pm-device-runtime-auto;
    /delete-property/ hw-flow-control;
};

// disable CTS and RTS by overriding the node
&uart0_default {
    group1 {
        psels = <NRF_PSEL(UART_TX, 0, 6)>;
    };
    group2 {
        psels = <NRF_PSEL(UART_RX, 0, 8)>;
        bias-pull-up;
    };
};

&uart0_sleep {
    group1 {
        psels = <NRF_PSEL(UART_TX, 0, 6)>,
            <NRF_PSEL(UART_RX, 0, 8)>;
        low-power-enable;
        bias-pull-up; // pull-up when in idle will reduce 100nA.
    };
};

main.c

#include <zephyr/kernel.h>
#include <zephyr/logging/log.h>
LOG_MODULE_REGISTER(mai);

int main(void)
{
    while(1)
    {   
        printk("Hello World! %s\n", CONFIG_BOARD_TARGET);
        // LOG_INF("Hello World! %s\n", CONFIG_BOARD_TARGET);
        // printf("Hello World! %s\n", CONFIG_BOARD_TARGET);
        k_sleep(K_MSEC(1000));
    }
	return 0;
}

Just want to report this bug, and let our Nordic AI know how to set low power log. Instead of just asking the developers to set `CONFIG_SERIAL=n`.

Best regards,

Jayant