printk becomes slow when CONFIG_LOG=y and trying to recieve serial communication over uart

[Richard11115]

I'm using a nRF52840 with the nRF Connect SDK version 2.4.1. I've been using Zephyr's logging module however now I want to also receive data over UART. I followed the Serial Communication (UART) example in nRF Connect SDK Fundamentals course however I've noticed it's very unresponsive (takes ~3 seconds to indicate that data was recieved). I found that this was due to enabling logging (removing CONFIG_LOG makes it responsive).

As an example, take the Lesson 5 Exercise 1 Solution repo from the course NRF Connect Fundamentals and add

case UART_RX_RDY:
        printk("Recieved!");

Then upload normally, when you type into the terminal it instantly prints backed Recieved!

However, if in prj.conf you add

CONFIG_LOG=y

You can see that it takes ~2 seconds before Received! is printed to the console

I thought this may be an issue with both the trying to receive logs and communication over uart0 so I tried switching the logging backend to RTT

CONFIG_LOG_BACKEND_UART=n
CONFIG_LOG_BACKEND_RTT=y

However, it still takes ~2 seconds for Received! to be printed

[Menon]

Hello,

While checking the time stamps I can see some milliseconds delay but isn't that usual? I can't find a delay greater than or equal to 1 second like you pointed out. Please excuse if I missed something.

Kind Regards,

Abhijith

[Richard11115]

Are you using a nrf52840 with the modified Lesson 5 Exercise 1 Solution repo code from the course NRF Connect Fundamentals? Millisecond delays would be fine but these are second delays so are causing serious issues

[Menon]

Hello Richard,

I was answering to the other person(poplitard) who pasted a screenshot with time stamps. Yes, I tried devacademy sample and I can see the delay that you mentioned (not exactly sure how much). I am still on this case and will try to find the cause of delay happening.

Kind Regards,

Abhijith

[poplitard]

Hey, so the first screenshot shows a batch of prints at 50s followed by a second batch of prints at 51s. The second screenshot shows printks without buffering.

I think I figured it out, it seems like in ncs 2.2.0 i didnt have to explicitly use CONFIG_LOG_PRINTK=n  because it was disabled by default

the newer version of zephyr in ncs 2.4.0 has CONFIG_LOG_PRINTK enabled by default, so you have to disable it to prevent printk buffering

printk and logs share the same output backend according to the documentation, which means that printks will be buffered before they outputting anything

https://docs.zephyrproject.org/latest/services/logging/index.html#printk

the config files in the lesson needs to include CONFIG_LOG_PRINTK= to reflect this change (to print instantly)

im a relatively new dev, and i havent really contributed to opensource projects yet, let me know if I can open a pr for this and contribute, thanks!