Unstable RTT logging

[Torsten Robitzki]

Hello,

I would love to use RTT in a nRF5340 project. I'm using Nordic Connect SDK v2.7.99-cs2. In a debug build, I very often see the problem, that some of expected log messages do not show up in JlinkRTTView:

Sometimes, I see the complete message:

00> [00:00:00.372,741] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
00> [00:00:00.372,863] <inf> bt_hci_core: HW Variant: nRF53x (0x0003)
00> [00:00:00.372,924] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 195.39642 Build 3554797951
00> [00:00:14.046,875] <inf> bluetooth: connected: 0

but most often, I see just a fraction of the log messages:

00> [00:00:00.651,824] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
00> [00:00:00.651,885] <inf> bt_hci_core: HW Variant: nRF53x (0x0003)
00> [00:00:00.651,947] <inf> bt_hci_core: Firmwa
00> 0m

The fraction is very reproducible, means whenever I see just part of the expected message, it is the very same fraction. Later, there are still log messages, so the output is not fully switched off.

This is the RTT configuration:

CONFIG_LOG=y
CONFIG_USE_SEGGER_RTT=y
CONFIG_LOG_BACKEND_RTT=y
CONFIG_LOG_BACKEND_UART=n
CONFIG_LOG_MODE_MINIMAL=n
CONFIG_LOG_PRINTK=y
CONFIG_LOG_MODE_DEFERRED=n
CONFIG_LOG_BUFFER_SIZE=65536

The used hardware is a J-Trace Pro Cortex. Any idea, what the problem could be here and how to improve the situation?

best regards

Torsten

[Charlie]

Hi Torsten,

Thank you for reaching out with your questions. I recommend switching to the formal release of NCS 2.8.0 for debugging. While NCS 2.7.99-cs2 should have the same behavior as NCS 2.8.0 regarding RTT usage, using the official release ensures stability and compatibility.

To verify if the issue is related to the logging system, I suggest switching to the UART backend and testing again.

I also found a related report on GitHub: Logging - Strange Behavior with RTT on nRF53. According to the discussion, a fix for this issue has already been implemented. If the problem persists, please feel free to continue the discussion there. The logging system a subsystem of Zephyr.

Best regards,
Charlie

[Torsten Robitzki]

Hi Charlie,

thanks for looking into this. The cited thread is already 5 years old and it's more about the missing "..."-marks that should indicate missing log messages. I've configured the log buffer to be 64k, so I would not expect overruns.

best regards

Torsten

[Nathan_49]

Hi Torsten Robitzki , hi Charlie ,

I do encounter the exact same issue, very repeatable too. Here's some info of my setup : 

• nrf52833
• NCS v2.7.0
• sysbuild with MCUboot

prj.conf

################
# Board config #
################
CONFIG_EVENTS=y
CONFIG_SMF=y

# Enable PWM led 
CONFIG_PWM=y
CONFIG_NRFX_PWM0=y
CONFIG_LED=y

# Enable ADC
CONFIG_ADC=y

# Enable log module though RTT
CONFIG_LOG=y
CONFIG_USE_SEGGER_RTT=y
CONFIG_LOG_BACKEND_RTT=y
CONFIG_LOG_BACKEND_UART=n

################
# Flash config #
################
CONFIG_FLASH=y
CONFIG_FLASH_PAGE_LAYOUT=y
CONFIG_FLASH_MAP=y
CONFIG_NVS=y
CONFIG_SETTINGS=y
CONFIG_HEAP_MEM_POOL_SIZE=1024

##############
# BLE config #
##############
CONFIG_BT=y
CONFIG_BT_CTLR=y
CONFIG_BT_PERIPHERAL=y
CONFIG_BT_DEVICE_NAME="Blinker"
CONFIG_BT_SMP=y

# Enable storing pairing key in flash
CONFIG_BT_SETTINGS=y

# BLE services
CONFIG_BT_BAS=y

# In order to correctly tune the stack sizes for the threads the following
# Configurations can enabled to print the current use:
# CONFIG_THREAD_NAME=y
# CONFIG_THREAD_ANALYZER=y
# CONFIG_THREAD_ANALYZER_AUTO=y
# CONFIG_THREAD_ANALYZER_RUN_UNLOCKED=y
# CONFIG_THREAD_ANALYZER_USE_PRINTK=y
# CONFIG_CONSOLE=y
# CONFIG_UART_CONSOLE=y
# CONFIG_SERIAL=y
# CONFIG_PRINTK=y

Here's the output i get after connecting to RTT from VScode : 

SEGGER J-Link V7.94e - Real time terminal output
SEGGER J-Link V9.6, SN=69665320
Process: JLink.exe
*** Booting nRF Connect SDK v2.7.0-5cb85570ca43 ***
*** Using Zephyr OS v3.6.99-100befc70c74 ***
[00:00:00.008,117] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.008,117] <inf> fs_nvs: alloc wra: 0, fe8
[00:00:00.008,148] <inf> fs_nvs: data wra: 0, 0
[00:00:00.008,300] <inf> bt_sdc_hci_driver: SoftDevice Controller build revision: 
                                            d6 da c7 ae 08 db 72 6f  2a a3 26 49 2a 4d a8 b3 |......ro *.&I*M..
                                            98 0e 07 7f                                      |....             
[00:00:00.010,833] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
[00:00:00.010,864] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
[00:00:00.010,894] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 214.51162 Build 1926957230
[00:00:00.011,322] <inf> bt_hci_core: No ID address. App must call settings_load()
[00:00:00.011,779] <inf> bt_0m

However if i put another log before initializing the ble stack which produce log, i can somehow reduce the output : 

SEGGER J-Link V7.94e - Real time terminal output
SEGGER J-Link V9.6, SN=69665320
Process: JLink.exe
*** Booting nRF Connect SDK v2.7.0-5cb85570ca43 ***
*** Using Zephyr OS v3.6.99-100befc70c74 ***
[00:00:00.000,366] <dbg> fsm: init_entry: 
[00:00:00.007,720] <inf> fs_nvs: 2 Sectors of 4096 bytes
[00:00:00.007,720] <inf> fs_nvs: alloc wra: 0, fe8
[00:00:00.007,720] <inf> fs_nvs: data wra: 0, 0
[00:00:00.007,873] <inf> bt_sdc_hci_driver: SoftDevice Controller build revision: 
                                            d6 da c7 ae 08 db 72 6f  2a a3 26 49 2a 4d a8 b3 |......ro *.&I*M..
                                            98 0e 07 7f                                      |....             
[00:00:00.010,437] <inf> bt_hci_core: HW Platform: Nordic Semiconductor (0x0002)
[00:00:00.010,467] <inf> bt_hci_core: HW Variant: nRF52x (0x0002)
[00:00:00.010,498] <inf> bt_hci_core: Firmware: Standard Bluetooth controller (0x00) Version 214.51162 Build 1926957230
[00:00:00.010,925] <inf> bt_hci_core: No ID address. App musload()

And this is alway the same. So i suspected an overflow somewhere but changing settings like buffer length or message index in log module or RTT backend don't make a difference.

Both our problem are linked to bt_hci_core logging maybe too much, i'm looking into that.

Best regards

Nathan