Logging: Overhaul

[nordic-krch]

Logging v2 highlights

• log_strdup no longer needed!!
• logging long long, float and double is now possible!!
• hex dumps with formatted strings
• Self-contained messages (even transient strings are there)
• 32/64 bit timestamp
• better memory utilization - ~20% more messages fit in the logging buffer
• 6x faster logging from userspace!
• overall simplified implementation

API changes

No change in logging API! Add CONFIG_LOG2_MODE_DEFFERED=y to run sample with new version. Only backend API extended with a function for processing v2 messages. PR updates following backends to support v2:

• uart
• shell
• adsp
• rtt
• native_posix

To be added later: bluetooth monitor, net, spinel, swo, xtensa sim

Internals

It is utilizing cbprintf packages (#30675, #31102) to create self-contained log message. Using _Generic feature of C11, it is possible to act based on types of arguments. It is used to determine when formatted string requires time consuming, runtime package creation and when log message can be created as simple serialization of the arguments. When char * arguments are present in the log message then package is created at runtime. This includes copying into a message any string argument which is from rw memory.

Additionally, log messages are no longer stored as fragmented chunks allocated from a memslab. They are stored in a circular buffer. This ensures that log message is not fragmented and improves memory utilization. Circular buffer is somehow generic multi producer, single consumer packet buffer (lib/os/mpsc_pbuf). Additional requirement is to support overwrite mode where oldest packets are dropped when new message cannot be allocated. MPSC packet buffer uses alloc, commit, claim, free sequence to avoid copying. Additionally, it has functions optimized for storing single word and single word + pointer packets. It is forseen that those will be used by the tracing to logger functionality.

It pends currently on #33567 being solved. PR contains temporary workaround to get CI green.

PR content

• mpsc packet buffer
• new log_msg2 implementation
• adaptation of the logger to support both version
• adaptation of some logger backends to support v2 api

Fixes #26170
Fixes #18351
Fixes #26246
Fixes #30353

[andyross]

Haven't done much more than a cursory scan, but this looks pretty clean to my eyes.

One question I can't find an immediate answer to: is this still running the backends out of a timer vs. letting them pull the output as they have bandwidth? It looks like it might be, because I don't see anything like that removed. This has been one of my pet peeves: backends with fast transport[1] drop a LOT of messages essentially needlessly, simply because the logging core never even tries to write them.

[1] The one I work on the most right now is the intel_adsp, where trace output goes into a region of system DRAM shared with the host OS -- it can sink bytes as fast as the DSP can write them)

[nordic-krch]

@andyross following approach is used: logging operates with a circular packet buffer (contrary to list of fragmented messages allocated from memslab). When logging is processing it passes the pointer to the message from the packet buffer to each backend. Call to the backend is synchronous so logging expects that when it returns message is no longer used by the backend. Backend has two option: block the logging thread and process the message or copy the message to its own memory and return.

[SwissKnife64]

CONFIG_LOG2 with floating point output

Here is the list of the required CONFIG to get the LOG2 for floating point working.

It is mandatory to set CONFIG_CBPRINTF_FP_A_SUPPORT=y to get %f and %g working! And %a is working also ;-).

CONFIG_LOG=y
CONFIG_LOG2_MODE_DEFERRED=y

CONFIG_NEWLIB_LIBC=y
CONFIG_NEWLIB_LIBC_FLOAT_PRINTF=y

CONFIG_CBPRINTF_FP_A_SUPPORT=y

[npitre]

**It is mandatory to set `CONFIG_CBPRINTF_FP_A_SUPPORT=y`** to get `%f` and `%g` working! And `%a` is working also ;-).

No. CONFIG_CBPRINTF_FP_A_SUPPORT is for ... %a. %f and %g just need CONFIG_CBPRINTF_FP_SUPPORT.

[SwissKnife64]

THanks for clarification. I have overlooked the CONFIG_CBPRINTF_FP_SUPPORT flag.
CONFIG_CBPRINTF_FP_A_SUPPORT depends on and sets the CONFIG_CBPRINTF_FP_SUPPORT flag.

So at least one of them has to set to get some output.

[nordic-krch]

Just a note, CONFIG_CBPRINTF_FP_SUPPORT defaults to y when CONFIG_FPU is enabled so when FPU is in use you shouldn't need any additional explicit configuration.

[SwissKnife64]

The warnings are gone, may be they were present with an outdated master on my machine.

Here is my CMakeList.txt

# SPDX-License-Identifier: Apache-2.0

cmake_minimum_required(VERSION 3.13.1)

# START added for CLion
set(ENV{BOARD} nucleo_h743zi)
set(ENV{ZEPHYR_SDK_INSTALL_DIR} /usr/local/zephyr-sdk-0.12.3)
set(ENV{ZEPHYR_TOOLCHAIN_VARIANT} gnuarmemb)
[Output.txt](https://github.com/zephyrproject-rtos/zephyr/files/6456915/Output.txt)

#toolchain is: /usr/local/gcc-arm-none-eabi-10-2020-q4-major/arm-none-eabi
# STOP added for CLion

find_package(Zephyr REQUIRED HINTS $ENV{ZEPHYR_BASE})
project(blinky)

target_sources(app PRIVATE src/main.c)