From e7efb10f56c64129717b79d130297542a2b3678e Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Mon, 29 Mar 2021 22:38:03 +0200 Subject: [PATCH 01/22] doc: misc: formatted_output: Add section for cbprintf packaging Add documentation for cbprintf packaging. Signed-off-by: Krzysztof Chruscinski --- doc/reference/misc/formatted_output.rst | 78 +++++++++++++++++++++++++ 1 file changed, 78 insertions(+) diff --git a/doc/reference/misc/formatted_output.rst b/doc/reference/misc/formatted_output.rst index ccca29200e9f3..7bb0ce2a2f317 100644 --- a/doc/reference/misc/formatted_output.rst +++ b/doc/reference/misc/formatted_output.rst @@ -40,6 +40,84 @@ In addition :option:`CONFIG_CBPRINTF_NANO` can be used to revert back to the very space-optimized but limited formatter used for :c:func:`printk` before this capability was added. +.. _cbprintf_packaging: + +Cbprintf Packaging +****************** + +Typically, strings are formatted synchronously when a function from ``printf`` +family is called. However, there are cases when it is beneficial that formatting +is deferred. In that case, a state (format string and arguments) must be captured. +Such state forms a self-contained package which contains format string and +arguments. Additionally, package contains copies of all strings which are +part of a format string (format string or any ``%s`` argument) and are identifed +as the one located in the read write memory. Package primary content resembles +va_list stack frame thus standard formatting functions are used to process a +package. Since package contains data which is processed as va_list frame, +strict alignment must be maintained. Due to required padding, size of the +package depends on alignment. When package is copied, it should be copied to a +memory block with the same alignment as origin. + +Package can be created using two methods: + +* runtime - using :c:func:`cbprintf_package` or :c:func:`cbvprintf_package`. This + method scans format string and based on detected format specifiers builds the + package. +* static - types of arguments are detected at compile time by the preprocessor + and package is created as simple assignments to a provided memory. This method + is significantly faster than runtime (more than 15 times) but has following + limitations: requires ``_Generic`` keyword (C11 feature) to be supported by + the compiler and can only create a package that is known to have no string + arguments (``%s``). :c:macro:`CBPRINTF_MUST_RUNTIME_PACKAGE` can be used to + determine at compile time if static packaging can be applied. Macro determines + need for runtime packaging based on presence of char pointers in the argument + list so there are cases when it will be false positive, e.g. ``%p`` with char + pointer. + +Several Kconfig options control behavior of the packaging: + +* :option:`CONFIG_CBPRINTF_PACKAGE_LONGDOUBLE` +* :option:`CONFIG_CBPRINTF_STATIC_PACKAGE_CHECK_ALIGNMENT` + +Cbprintf package format +======================= + +Format of the package contains paddings which are platform specific. Package consists +of header which contains size of package (excluding appended strings) and number of +appended strings. It is followed by the arguments which contains alignment paddings +and resembles *va_list* stack frame. Finally, package optionally contains appended +strings. Each string contains 1 byte header which contains index of the location +where address argument is stored. During packaging address is set to null and +before string formatting it is updated to point to the current string location +within the package. Updating address argument must happen just before string +formatting since address changes whenever package is copied. + ++------------------+-------------------------------------------------------------------------+ +| Header | 1 byte: Argument list size including header and *fmt* (in 32 bit words) | +| +-------------------------------------------------------------------------+ +| | sizeof(void \*)| 1 byte: Number of appended strings | +| +-------------------------------------------------------------------------+ +| | platform specific padding to sizeof(void \*) | ++------------------+-------------------------------------------------------------------------+ +| Arguments | Pointer to *fmt* (or null if *fmt* is appended to the package) | +| +-------------------------------------------------------------------------+ +| | (optional padding for platform specific alignment) | +| +-------------------------------------------------------------------------+ +| | argument 0 | +| +-------------------------------------------------------------------------+ +| | (optional padding for platform specific alignment) | +| +-------------------------------------------------------------------------+ +| | argument 1 | +| +-------------------------------------------------------------------------+ +| | ... | ++------------------+-------------------------------------------------------------------------+ +| Appended | 1 byte: Index within the package to the location of associated argument | +| +-------------------------------------------------------------------------+ +| strings | Null terminated string | +| +-------------------------------------------------------------------------+ +| | ... | ++------------------+-------------------------------------------------------------------------+ + .. warning:: If :option:`CONFIG_MINIMAL_LIBC` is selected in combination with From 36c1c1298e9b68bd392a60eb7f5a723cb353f807 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Thu, 14 Jan 2021 07:59:52 +0100 Subject: [PATCH 02/22] lib: os: Add mpsc (multiple producer, single consumer) packet buffer Added module for storing variable length packets in a ring buffer. Implementation assumes multiple producing contexts and single consumer. API provides zero copy functionality with alloc, commit, claim, free scheme. Additionally, there are functions optimized for storing single word packets and packets consisting of a word and a pointer. Buffer can work in two modes: saturation or overwriting the oldest packets when buffer has no space to allocate for a new buffer. Signed-off-by: Krzysztof Chruscinski --- include/sys/mpsc_packet.h | 63 ++++++ include/sys/mpsc_pbuf.h | 245 +++++++++++++++++++++++ lib/os/CMakeLists.txt | 2 + lib/os/Kconfig | 8 + lib/os/mpsc_pbuf.c | 404 ++++++++++++++++++++++++++++++++++++++ 5 files changed, 722 insertions(+) create mode 100644 include/sys/mpsc_packet.h create mode 100644 include/sys/mpsc_pbuf.h create mode 100644 lib/os/mpsc_pbuf.c diff --git a/include/sys/mpsc_packet.h b/include/sys/mpsc_packet.h new file mode 100644 index 0000000000000..cb815a5d5c71a --- /dev/null +++ b/include/sys/mpsc_packet.h @@ -0,0 +1,63 @@ +/* + * Copyright (c) 2021 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#ifndef ZEPHYR_INCLUDE_SYS_MPSC_PACKET_H_ +#define ZEPHYR_INCLUDE_SYS_MPSC_PACKET_H_ + +#include +#include +#include + +#ifdef __cplusplus +extern "C" { +#endif + +/** + * @brief Multi producer, single consumer packet header + * @defgroup mpsc_packet MPSC (Multi producer, single consumer) packet header + * @ingroup mpsc_buf + * @{ + */ + +/** @brief Number of bits in the first word which are used by the buffer. */ +#define MPSC_PBUF_HDR_BITS 2 + +/** @brief Header that must be added to the first word in each packet. + * + * This fields are controlled by the packet buffer and unless specified must + * not be used. Fields must be added at the top of the packet header structure. + */ +#define MPSC_PBUF_HDR \ + uint32_t valid: 1; \ + uint32_t busy: 1 + +/** @brief Generic packet header. */ +struct mpsc_pbuf_hdr { + MPSC_PBUF_HDR; + uint32_t data: 32 - MPSC_PBUF_HDR_BITS; +}; + +/** @brief Skip packet used internally by the packet buffer. */ +struct mpsc_pbuf_skip { + MPSC_PBUF_HDR; + uint32_t len: 32 - MPSC_PBUF_HDR_BITS; +}; + +/** @brief Generic packet header. */ +union mpsc_pbuf_generic { + struct mpsc_pbuf_hdr hdr; + struct mpsc_pbuf_skip skip; + uint32_t raw; +}; + +/** + * @} + */ + +#ifdef __cplusplus +} +#endif + +#endif /* ZEPHYR_INCLUDE_SYS_MPSC_PACKET_H_ */ diff --git a/include/sys/mpsc_pbuf.h b/include/sys/mpsc_pbuf.h new file mode 100644 index 0000000000000..11d9b0e79da04 --- /dev/null +++ b/include/sys/mpsc_pbuf.h @@ -0,0 +1,245 @@ + +/* + * Copyright (c) 2021 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#ifndef ZEPHYR_INCLUDE_SYS_MPSC_PBUF_H_ +#define ZEPHYR_INCLUDE_SYS_MPSC_PBUF_H_ + +#include +#include +#include +#include +#include + +#ifdef __cplusplus +extern "C" { +#endif + +/** + * @brief Multi producer, single consumer packet buffer API + * @defgroup mpsc_buf MPSC (Multi producer, single consumer) packet buffer API + * @ingroup kernel_apis + * @{ + */ + +/* + * Multi producer, single consumer packet buffer allows to allocate variable + * length consecutive space for storing a packet. When space is allocated + * it can be filled by the user (except for the first 2 bits) and when packet + * is ready it is commited. It is allowed to allocate another packet before + * commiting the previous one. + * + * If buffer is full and packet cannot be allocated then null is returned unless + * overwrite mode is selected. In that mode, oldest entry are dropped (user is + * notified) until allocation succeeds. It can happen that candidate for + * dropping is currently being claimed. In that case, it is ommited and next + * packet is dropped and claimed packet is marked as invalid when freeing. + * + * Reading packets is performed in two steps. First packet is claimed. Claiming + * returns pointer to the packet within the buffer. Packet is freed when no + * longer in use. + */ + +/**@defgroup MPSC_PBUF_FLAGS MPSC packet buffer flags + * @{ */ + +/** @brief Flag indicating that buffer size is power of 2. + * + * When buffer size is power of 2 then optimizations are applied. + */ +#define MPSC_PBUF_SIZE_POW2 BIT(0) + +/** @brief Flag indicating buffer full policy. + * + * If flag is set then when allocating from a full buffer oldest packets are + * dropped. When flag is not set then allocation returns null. + */ +#define MPSC_PBUF_MODE_OVERWRITE BIT(1) + +/**@} */ + +/* Forward declaration */ +struct mpsc_pbuf_buffer; + +/** @brief Callback prototype for getting length of a packet. + * + * @param packet User packet. + * + * @return Size of the packet in 32 bit words. + */ +typedef uint32_t (*mpsc_pbuf_get_wlen)(union mpsc_pbuf_generic *packet); + +/** @brief Callback called when packet is dropped. + * + * @param buffer Packet buffer. + * + * @param packet Packet that is being dropped. + */ +typedef void (*mpsc_pbuf_notify_drop)(struct mpsc_pbuf_buffer *buffer, + union mpsc_pbuf_generic *packet); + +/** @brief MPSC packet buffer structure. */ +struct mpsc_pbuf_buffer { + /** Temporary write index. */ + uint32_t tmp_wr_idx; + + /** Write index. */ + uint32_t wr_idx; + + /** Temporary read index. */ + uint32_t tmp_rd_idx; + + /** Read index. */ + uint32_t rd_idx; + + /** Flags. */ + uint32_t flags; + + /** Lock. */ + struct k_spinlock lock; + + /** User callback called whenever packet is dropped. */ + mpsc_pbuf_notify_drop notify_drop; + + /** Callback for getting packet length. */ + mpsc_pbuf_get_wlen get_wlen; + + /* Buffer. */ + uint32_t *buf; + + /* Buffer size in 32 bit words. */ + uint32_t size; + + struct k_sem sem; +}; + +/** @brief MPSC packet buffer configuration. */ +struct mpsc_pbuf_buffer_config { + /* Pointer to a memory used for storing packets. */ + uint32_t *buf; + + /* Buffer size in 32 bit words. */ + uint32_t size; + + /* Callbacks. */ + mpsc_pbuf_notify_drop notify_drop; + mpsc_pbuf_get_wlen get_wlen; + + /* Configuration flags. */ + uint32_t flags; +}; + +/** @brief Initnialize a packet buffer. + * + * @param buffer Buffer. + * + * @param config Configuration. + */ +void mpsc_pbuf_init(struct mpsc_pbuf_buffer *buffer, + const struct mpsc_pbuf_buffer_config *config); + +/** @brief Allocate a packet. + * + * If a buffer is configured to overwrite mode then if there is no space to + * allocated a new buffer, oldest packets are dropped. Otherwise allocation + * fails and null pointer is returned. + * + * @param buffer Buffer. + * + * @param wlen Number of words to allocate. + * + * @param timeout Timeout. If called from thread context it will pend for given + * timeout if packet cannot be allocated before dropping the oldest or + * returning null. + * + * @return Pointer to the allocated space or null if it cannot be allocated. + */ +union mpsc_pbuf_generic *mpsc_pbuf_alloc(struct mpsc_pbuf_buffer *buffer, + size_t wlen, k_timeout_t timeout); + +/** @brief Commit a packet. + * + * @param buffer Buffer. + * + * @param packet Pointer to a packet allocated by @ref mpsc_pbuf_alloc. + */ +void mpsc_pbuf_commit(struct mpsc_pbuf_buffer *buffer, + union mpsc_pbuf_generic *packet); + +/** @brief Put single word packet into a buffer. + * + * Function is optimized for storing a packet which fit into a single word. + * Note that 2 bits of that word is used by the buffer. + * + * @param buffer Buffer. + * + * @param word Packet content consisting of MPSC_PBUF_HDR with valid bit set + * and data on remaining bits. + */ +void mpsc_pbuf_put_word(struct mpsc_pbuf_buffer *buffer, + union mpsc_pbuf_generic word); + +/** @brief Put a packet consisting of a word and a pointer. + * * + * Function is optimized for storing packet consisting of a word and a pointer. + * Note that 2 bits of a first word is used by the buffer. + * + * @param buffer Buffer. + * + * @param word First word of a packet consisting of MPSC_PBUF_HDR with valid + * bit set and data on remaining bits. + * + * @param data User data. + */ +void mpsc_pbuf_put_word_ext(struct mpsc_pbuf_buffer *buffer, + union mpsc_pbuf_generic word, void *data); + +/** @brief Put a packet into a buffer. + * + * Copy data into a buffer. + * Note that 2 bits of a first word is used by the buffer. + * + * @param buffer Buffer. + * + * @param data First word of data must contain MPSC_PBUF_HDR with valid set. + * + * @param wlen Packet size in words. + */ +void mpsc_pbuf_put_data(struct mpsc_pbuf_buffer *buffer, + uint32_t *data, size_t wlen); + +/** @brief Claim the first pending packet. + * + * @param buffer Buffer. + */ +union mpsc_pbuf_generic *mpsc_pbuf_claim(struct mpsc_pbuf_buffer *buffer); + +/** @brief Free a packet. + * + * @param buffer Buffer. + * + * @param packet Packet. + */ +void mpsc_pbuf_free(struct mpsc_pbuf_buffer *buffer, + union mpsc_pbuf_generic *packet); + +/** @brief Check if there are any message pending. + * + * @param buffer Buffer. + * + * @retval true if pending. + * @retval false if no message is pending. + */ +bool mpsc_pbuf_is_pending(struct mpsc_pbuf_buffer *buffer); + +/** + * @} + */ + +#ifdef __cplusplus +} +#endif + +#endif /* ZEPHYR_INCLUDE_SYS_MPSC_PBUF_H_ */ diff --git a/lib/os/CMakeLists.txt b/lib/os/CMakeLists.txt index 155e26c58814f..dcd7b4930fd74 100644 --- a/lib/os/CMakeLists.txt +++ b/lib/os/CMakeLists.txt @@ -35,6 +35,8 @@ zephyr_sources_ifdef(CONFIG_ASSERT assert.c) zephyr_sources_ifdef(CONFIG_USERSPACE mutex.c user_work.c) +zephyr_sources_ifdef(CONFIG_MPSC_PBUF mpsc_pbuf.c) + zephyr_sources_ifdef(CONFIG_SCHED_DEADLINE p4wq.c) zephyr_library_include_directories( diff --git a/lib/os/Kconfig b/lib/os/Kconfig index dfffc03b976d6..262f71aaebb3a 100644 --- a/lib/os/Kconfig +++ b/lib/os/Kconfig @@ -60,6 +60,14 @@ config PRINTK_SYNC interleaving with concurrent usage from another CPU or an preempting interrupt. +config MPSC_PBUF + bool "Multi producer, single consumer packet buffer" + select TIMEOUT_64BIT + help + Enable usage of mpsc packet buffer. Packet buffer is capable of + storing variable length packets in a circular way and operate directly + on the buffer memory. + rsource "Kconfig.cbprintf" endmenu diff --git a/lib/os/mpsc_pbuf.c b/lib/os/mpsc_pbuf.c new file mode 100644 index 0000000000000..67695b8c17abf --- /dev/null +++ b/lib/os/mpsc_pbuf.c @@ -0,0 +1,404 @@ +/* + * Copyright (c) 2021 Nordic Semiconductor + * + * SPDX-License-Identifier: Apache-2.0 + */ +#include + +void mpsc_pbuf_init(struct mpsc_pbuf_buffer *buffer, + const struct mpsc_pbuf_buffer_config *cfg) +{ + int err; + + memset(buffer, 0, offsetof(struct mpsc_pbuf_buffer, buf)); + buffer->get_wlen = cfg->get_wlen; + buffer->notify_drop = cfg->notify_drop; + buffer->buf = cfg->buf; + buffer->size = cfg->size; + buffer->flags = cfg->flags; + + if (is_power_of_two(buffer->size)) { + buffer->flags |= MPSC_PBUF_SIZE_POW2; + } + + err = k_sem_init(&buffer->sem, 0, 1); + __ASSERT_NO_MSG(err == 0); +} + +static inline bool free_space(struct mpsc_pbuf_buffer *buffer, uint32_t *res) +{ + if (buffer->rd_idx > buffer->tmp_wr_idx) { + *res = buffer->rd_idx - buffer->tmp_wr_idx - 1; + + return false; + } else if (!buffer->rd_idx) { + *res = buffer->size - buffer->tmp_wr_idx - 1; + return false; + } + + *res = buffer->size - buffer->tmp_wr_idx; + + return true; +} + +static inline bool available(struct mpsc_pbuf_buffer *buffer, uint32_t *res) +{ + if (buffer->tmp_rd_idx <= buffer->wr_idx) { + *res = (buffer->wr_idx - buffer->tmp_rd_idx); + + return false; + } + + *res = buffer->size - buffer->tmp_rd_idx; + + return true; +} + +static inline bool is_valid(union mpsc_pbuf_generic *item) +{ + return item->hdr.valid; +} + +static inline bool is_invalid(union mpsc_pbuf_generic *item) +{ + return !item->hdr.valid && !item->hdr.busy; +} + +static inline uint32_t idx_inc(struct mpsc_pbuf_buffer *buffer, + uint32_t idx, uint32_t val) +{ + uint32_t i = idx + val; + + if (buffer->flags & MPSC_PBUF_SIZE_POW2) { + return i & (buffer->size - 1); + } + + return (i >= buffer->size) ? i - buffer->size : i; +} + +static inline uint32_t idx_dec(struct mpsc_pbuf_buffer *buffer, + uint32_t idx, uint32_t val) +{ + uint32_t i = idx - val; + + if (buffer->flags & MPSC_PBUF_SIZE_POW2) { + return idx & (buffer->size - 1); + } + + return (i >= buffer->size) ? i + buffer->size : i; +} + +static inline uint32_t get_skip(union mpsc_pbuf_generic *item) +{ + if (item->hdr.busy && !item->hdr.valid) { + return item->skip.len; + } + + return 0; +} + +static void add_skip_item(struct mpsc_pbuf_buffer *buffer, uint32_t wlen) +{ + union mpsc_pbuf_generic skip = { + .skip = { .valid = 0, .busy = 1, .len = wlen } + }; + + buffer->buf[buffer->tmp_wr_idx] = skip.raw; + buffer->tmp_wr_idx = idx_inc(buffer, buffer->tmp_wr_idx, wlen); + buffer->wr_idx = idx_inc(buffer, buffer->wr_idx, wlen); +} + +static union mpsc_pbuf_generic *drop_item_locked(struct mpsc_pbuf_buffer *buffer, + uint32_t free_wlen) +{ + union mpsc_pbuf_generic *item; + uint32_t rd_wlen; + uint32_t skip_wlen; + + item = (union mpsc_pbuf_generic *)&buffer->buf[buffer->rd_idx]; + skip_wlen = get_skip(item); + + rd_wlen = skip_wlen ? skip_wlen : buffer->get_wlen(item); + if (skip_wlen) { + item = NULL; + } else if (item->hdr.busy) { + /* item is currently processed and cannot be overwritten. */ + add_skip_item(buffer, free_wlen + 1); + buffer->wr_idx = idx_inc(buffer, buffer->wr_idx, rd_wlen); + buffer->tmp_wr_idx = idx_inc(buffer, buffer->tmp_wr_idx, rd_wlen); + + /* Get next itme followed the busy one. */ + uint32_t next_rd_idx = idx_inc(buffer, buffer->rd_idx, rd_wlen); + + item = (union mpsc_pbuf_generic *)&buffer->buf[next_rd_idx]; + skip_wlen = get_skip(item); + if (skip_wlen) { + item = NULL; + rd_wlen += skip_wlen; + } else { + rd_wlen += buffer->get_wlen(item); + } + } + + buffer->rd_idx = idx_inc(buffer, buffer->rd_idx, rd_wlen); + buffer->tmp_rd_idx = buffer->rd_idx; + + return item; +} + +void mpsc_pbuf_put_word(struct mpsc_pbuf_buffer *buffer, + union mpsc_pbuf_generic item) +{ + bool cont; + uint32_t free_wlen; + k_spinlock_key_t key; + union mpsc_pbuf_generic *dropped_item = NULL; + + do { + cont = false; + key = k_spin_lock(&buffer->lock); + (void)free_space(buffer, &free_wlen); + if (free_wlen) { + buffer->buf[buffer->tmp_wr_idx] = item.raw; + buffer->tmp_wr_idx = idx_inc(buffer, + buffer->tmp_wr_idx, 1); + buffer->wr_idx = idx_inc(buffer, buffer->wr_idx, 1); + } else if (buffer->flags & MPSC_PBUF_MODE_OVERWRITE) { + dropped_item = drop_item_locked(buffer, free_wlen); + cont = true; + } else { + /* empty */ + } + + k_spin_unlock(&buffer->lock, key); + + if (cont && dropped_item) { + /* Notify about item being dropped. */ + buffer->notify_drop(buffer, dropped_item); + } + } while (cont); + +} + +union mpsc_pbuf_generic *mpsc_pbuf_alloc(struct mpsc_pbuf_buffer *buffer, + size_t wlen, k_timeout_t timeout) +{ + union mpsc_pbuf_generic *item = NULL; + union mpsc_pbuf_generic *dropped_item = NULL; + bool cont; + uint32_t free_wlen; + + do { + k_spinlock_key_t key; + bool wrap; + + cont = false; + key = k_spin_lock(&buffer->lock); + wrap = free_space(buffer, &free_wlen); + + if (free_wlen >= wlen) { + item = + (union mpsc_pbuf_generic *)&buffer->buf[buffer->tmp_wr_idx]; + item->hdr.valid = 0; + item->hdr.busy = 0; + buffer->tmp_wr_idx = idx_inc(buffer, + buffer->tmp_wr_idx, wlen); + } else if (wrap) { + add_skip_item(buffer, free_wlen); + cont = true; + } else if (!K_TIMEOUT_EQ(timeout, K_NO_WAIT) && + !k_is_in_isr()) { + int err; + + k_spin_unlock(&buffer->lock, key); + err = k_sem_take(&buffer->sem, timeout); + key = k_spin_lock(&buffer->lock); + if (err == 0) { + cont = true; + } + } else if (buffer->flags & MPSC_PBUF_MODE_OVERWRITE) { + dropped_item = drop_item_locked(buffer, free_wlen); + cont = true; + } + + k_spin_unlock(&buffer->lock, key); + + if (cont && dropped_item) { + /* Notify about item being dropped. */ + buffer->notify_drop(buffer, dropped_item); + dropped_item = NULL; + } + } while (cont); + + return item; +} + +void mpsc_pbuf_commit(struct mpsc_pbuf_buffer *buffer, + union mpsc_pbuf_generic *item) +{ + uint32_t wlen = buffer->get_wlen(item); + + k_spinlock_key_t key = k_spin_lock(&buffer->lock); + + item->hdr.valid = 1; + buffer->wr_idx = idx_inc(buffer, buffer->wr_idx, wlen); + k_spin_unlock(&buffer->lock, key); +} + +void mpsc_pbuf_put_word_ext(struct mpsc_pbuf_buffer *buffer, + union mpsc_pbuf_generic item, void *data) +{ + static const size_t l = + (sizeof(item) + sizeof(data)) / sizeof(uint32_t); + union mpsc_pbuf_generic *dropped_item = NULL; + bool cont; + + do { + k_spinlock_key_t key; + uint32_t free_wlen; + bool wrap; + + cont = false; + key = k_spin_lock(&buffer->lock); + wrap = free_space(buffer, &free_wlen); + + if (free_wlen >= l) { + buffer->buf[buffer->tmp_wr_idx] = item.raw; + void **p = + (void **)&buffer->buf[buffer->tmp_wr_idx + 1]; + + *p = data; + buffer->tmp_wr_idx = + idx_inc(buffer, buffer->tmp_wr_idx, l); + buffer->wr_idx = idx_inc(buffer, buffer->wr_idx, l); + } else if (wrap) { + add_skip_item(buffer, free_wlen); + cont = true; + } else if (buffer->flags & MPSC_PBUF_MODE_OVERWRITE) { + dropped_item = drop_item_locked(buffer, free_wlen); + cont = true; + } else { + /* empty */ + } + + k_spin_unlock(&buffer->lock, key); + + if (cont && dropped_item) { + /* Notify about item being dropped. */ + buffer->notify_drop(buffer, dropped_item); + dropped_item = NULL; + } + } while (cont); +} + +void mpsc_pbuf_put_data(struct mpsc_pbuf_buffer *buffer, uint32_t *data, + size_t wlen) +{ + bool cont; + union mpsc_pbuf_generic *dropped_item = NULL; + + do { + uint32_t free_wlen; + k_spinlock_key_t key; + bool wrap; + + cont = false; + key = k_spin_lock(&buffer->lock); + wrap = free_space(buffer, &free_wlen); + + if (free_wlen >= wlen) { + memcpy(&buffer->buf[buffer->tmp_wr_idx], data, + wlen * sizeof(uint32_t)); + buffer->tmp_wr_idx = + idx_inc(buffer, buffer->tmp_wr_idx, wlen); + buffer->wr_idx = idx_inc(buffer, buffer->wr_idx, wlen); + } else if (wrap) { + add_skip_item(buffer, free_wlen); + cont = true; + } else if (buffer->flags & MPSC_PBUF_MODE_OVERWRITE) { + dropped_item = drop_item_locked(buffer, free_wlen); + cont = true; + } + + k_spin_unlock(&buffer->lock, key); + + if (cont && dropped_item) { + /* Notify about item being dropped. */ + buffer->notify_drop(buffer, dropped_item); + dropped_item = NULL; + } + } while (cont); +} + +union mpsc_pbuf_generic *mpsc_pbuf_claim(struct mpsc_pbuf_buffer *buffer) +{ + union mpsc_pbuf_generic *item; + bool cont; + + do { + uint32_t a; + k_spinlock_key_t key; + bool wrap; + + cont = false; + key = k_spin_lock(&buffer->lock); + wrap = available(buffer, &a); + item = (union mpsc_pbuf_generic *) + &buffer->buf[buffer->tmp_rd_idx]; + + if (!a || is_invalid(item)) { + item = NULL; + } else { + uint32_t skip = get_skip(item); + + if (skip || !is_valid(item)) { + uint32_t inc = + skip ? skip : buffer->get_wlen(item); + + buffer->tmp_rd_idx = + idx_inc(buffer, buffer->tmp_rd_idx, inc); + buffer->rd_idx = + idx_inc(buffer, buffer->rd_idx, inc); + cont = true; + } else { + item->hdr.busy = 1; + buffer->tmp_rd_idx = + idx_inc(buffer, buffer->tmp_rd_idx, + buffer->get_wlen(item)); + } + } + + k_spin_unlock(&buffer->lock, key); + } while (cont); + + return item; +} + +void mpsc_pbuf_free(struct mpsc_pbuf_buffer *buffer, + union mpsc_pbuf_generic *item) +{ + uint32_t wlen = buffer->get_wlen(item); + k_spinlock_key_t key = k_spin_lock(&buffer->lock); + + item->hdr.valid = 0; + if (!(buffer->flags & MPSC_PBUF_MODE_OVERWRITE) || + ((uint32_t *)item == &buffer->buf[buffer->rd_idx])) { + item->hdr.busy = 0; + buffer->rd_idx = idx_inc(buffer, buffer->rd_idx, wlen); + } else { + item->skip.len = wlen; + } + + k_spin_unlock(&buffer->lock, key); + k_sem_give(&buffer->sem); +} + +bool mpsc_pbuf_is_pending(struct mpsc_pbuf_buffer *buffer) +{ + uint32_t a; + + (void)available(buffer, &a); + + return a ? true : false; +} + From d163a83ef9529c1875a2a27ab66d33479a371eba Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Fri, 19 Mar 2021 08:30:29 +0100 Subject: [PATCH 03/22] lib: os: mpsc_pbuf: Add optional debug features Added optional debug prints. Logging cannot be used because mpsc pbuf is used by the logging. Added option to clear packet memory after allocation. Option is enabled in Kconfig. Signed-off-by: Krzysztof Chruscinski --- lib/os/Kconfig | 7 +++++++ lib/os/mpsc_pbuf.c | 33 +++++++++++++++++++++++++++++++++ 2 files changed, 40 insertions(+) diff --git a/lib/os/Kconfig b/lib/os/Kconfig index 262f71aaebb3a..481bd47bc7a05 100644 --- a/lib/os/Kconfig +++ b/lib/os/Kconfig @@ -68,6 +68,13 @@ config MPSC_PBUF storing variable length packets in a circular way and operate directly on the buffer memory. +if MPSC_PBUF +config MPSC_CLEAR_ALLOCATED + bool "Clear allocated packet" + help + When enabled packet space is zeroed before returning from allocation. +endif + rsource "Kconfig.cbprintf" endmenu diff --git a/lib/os/mpsc_pbuf.c b/lib/os/mpsc_pbuf.c index 67695b8c17abf..4673aa8077141 100644 --- a/lib/os/mpsc_pbuf.c +++ b/lib/os/mpsc_pbuf.c @@ -5,6 +5,26 @@ */ #include +#define MPSC_PBUF_DEBUG 0 + +#define MPSC_PBUF_DBG(buffer, ...) do { \ + if (MPSC_PBUF_DEBUG) { \ + printk(__VA_ARGS__); \ + if (buffer) { \ + mpsc_state_print(buffer); \ + } \ + } \ +} while (0) + +static inline void mpsc_state_print(struct mpsc_pbuf_buffer *buffer) +{ + if (MPSC_PBUF_DEBUG) { + printk("wr:%d/%d, rd:%d/%d\n", + buffer->wr_idx, buffer->tmp_wr_idx, + buffer->rd_idx, buffer->tmp_rd_idx); + } +} + void mpsc_pbuf_init(struct mpsc_pbuf_buffer *buffer, const struct mpsc_pbuf_buffer_config *cfg) { @@ -188,6 +208,7 @@ union mpsc_pbuf_generic *mpsc_pbuf_alloc(struct mpsc_pbuf_buffer *buffer, bool cont; uint32_t free_wlen; + MPSC_PBUF_DBG(buffer, "alloc %d words, ", (int)wlen); do { k_spinlock_key_t key; bool wrap; @@ -230,6 +251,13 @@ union mpsc_pbuf_generic *mpsc_pbuf_alloc(struct mpsc_pbuf_buffer *buffer, } } while (cont); + MPSC_PBUF_DBG(buffer, "allocated %p ", item); + + if (IS_ENABLED(CONFIG_MPSC_CLEAR_ALLOCATED) && item) { + /* During test fill with 0's to simplify message comparison */ + memset(item, 0, sizeof(int) * wlen); + } + return item; } @@ -243,6 +271,7 @@ void mpsc_pbuf_commit(struct mpsc_pbuf_buffer *buffer, item->hdr.valid = 1; buffer->wr_idx = idx_inc(buffer, buffer->wr_idx, wlen); k_spin_unlock(&buffer->lock, key); + MPSC_PBUF_DBG(buffer, "committed %p ", item); } void mpsc_pbuf_put_word_ext(struct mpsc_pbuf_buffer *buffer, @@ -368,6 +397,9 @@ union mpsc_pbuf_generic *mpsc_pbuf_claim(struct mpsc_pbuf_buffer *buffer) } } + if (!cont) { + MPSC_PBUF_DBG(buffer, "claimed: %p ", item); + } k_spin_unlock(&buffer->lock, key); } while (cont); @@ -388,6 +420,7 @@ void mpsc_pbuf_free(struct mpsc_pbuf_buffer *buffer, } else { item->skip.len = wlen; } + MPSC_PBUF_DBG(buffer, "freed: %p ", item); k_spin_unlock(&buffer->lock, key); k_sem_give(&buffer->sem); From ad4fc0717898b1a212e6c5d4cf5900f44fefa28a Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Thu, 14 Jan 2021 08:02:35 +0100 Subject: [PATCH 04/22] tests: lib: Add test for mpsc_pbuf Added suite for multiple producer, single consumer packet buffer. Signed-off-by: Krzysztof Chruscinski --- include/sys/mpsc_pbuf.h | 8 +- lib/os/mpsc_pbuf.c | 1 - tests/lib/mpsc_pbuf/CMakeLists.txt | 8 + tests/lib/mpsc_pbuf/prj.conf | 3 + tests/lib/mpsc_pbuf/src/main.c | 1053 ++++++++++++++++++++++++++++ tests/lib/mpsc_pbuf/testcase.yaml | 7 + 6 files changed, 1075 insertions(+), 5 deletions(-) create mode 100644 tests/lib/mpsc_pbuf/CMakeLists.txt create mode 100644 tests/lib/mpsc_pbuf/prj.conf create mode 100644 tests/lib/mpsc_pbuf/src/main.c create mode 100644 tests/lib/mpsc_pbuf/testcase.yaml diff --git a/include/sys/mpsc_pbuf.h b/include/sys/mpsc_pbuf.h index 11d9b0e79da04..931dc7ab0a387 100644 --- a/include/sys/mpsc_pbuf.h +++ b/include/sys/mpsc_pbuf.h @@ -1,4 +1,3 @@ - /* * Copyright (c) 2021 Nordic Semiconductor ASA * @@ -28,8 +27,8 @@ extern "C" { * Multi producer, single consumer packet buffer allows to allocate variable * length consecutive space for storing a packet. When space is allocated * it can be filled by the user (except for the first 2 bits) and when packet - * is ready it is commited. It is allowed to allocate another packet before - * commiting the previous one. + * is ready it is committed. It is allowed to allocate another packet before + * committing the previous one. * * If buffer is full and packet cannot be allocated then null is returned unless * overwrite mode is selected. In that mode, oldest entry are dropped (user is @@ -43,7 +42,8 @@ extern "C" { */ /**@defgroup MPSC_PBUF_FLAGS MPSC packet buffer flags - * @{ */ + * @{ + */ /** @brief Flag indicating that buffer size is power of 2. * diff --git a/lib/os/mpsc_pbuf.c b/lib/os/mpsc_pbuf.c index 4673aa8077141..0d23aac1b6ebc 100644 --- a/lib/os/mpsc_pbuf.c +++ b/lib/os/mpsc_pbuf.c @@ -434,4 +434,3 @@ bool mpsc_pbuf_is_pending(struct mpsc_pbuf_buffer *buffer) return a ? true : false; } - diff --git a/tests/lib/mpsc_pbuf/CMakeLists.txt b/tests/lib/mpsc_pbuf/CMakeLists.txt new file mode 100644 index 0000000000000..2c217cb0c9f71 --- /dev/null +++ b/tests/lib/mpsc_pbuf/CMakeLists.txt @@ -0,0 +1,8 @@ +# SPDX-License-Identifier: Apache-2.0 + +cmake_minimum_required(VERSION 3.13.1) +find_package(Zephyr REQUIRED HINTS $ENV{ZEPHYR_BASE}) +project(mpsc_pbuf) + +FILE(GLOB app_sources src/*.c) +target_sources(app PRIVATE ${app_sources}) diff --git a/tests/lib/mpsc_pbuf/prj.conf b/tests/lib/mpsc_pbuf/prj.conf new file mode 100644 index 0000000000000..0c4c1dcb6f596 --- /dev/null +++ b/tests/lib/mpsc_pbuf/prj.conf @@ -0,0 +1,3 @@ +CONFIG_ZTEST=y +CONFIG_MPSC_PBUF=y +CONFIG_TEST_RANDOM_GENERATOR=y diff --git a/tests/lib/mpsc_pbuf/src/main.c b/tests/lib/mpsc_pbuf/src/main.c new file mode 100644 index 0000000000000..9fc68be533755 --- /dev/null +++ b/tests/lib/mpsc_pbuf/src/main.c @@ -0,0 +1,1053 @@ +/* + * Copyright (c) 2021 Nordic Semiconductor + * + * SPDX-License-Identifier: Apache-2.0 + */ + +/** + * @file + * @brief Test log message + */ + +#include + +#include +#include +#include +#include +#include + +#define PUT_EXT_LEN \ + ((sizeof(union mpsc_pbuf_generic) + sizeof(void *)) / sizeof(uint32_t)) + +#define LEN_BITS 9 + +struct test_data { + MPSC_PBUF_HDR; + uint32_t len : LEN_BITS; + uint32_t data : 32 - MPSC_PBUF_HDR_BITS - LEN_BITS; +}; + +struct test_data_ext { + struct test_data hdr; + void *data; +} __packed; + +struct test_data_var { + struct test_data hdr; + uint32_t data[]; +}; + +union test_item { + struct test_data data; + struct test_data_ext data_ext; + union mpsc_pbuf_generic item; +}; + +static uint32_t get_wlen(union mpsc_pbuf_generic *item) +{ + union test_item *t_item = (union test_item *)item; + + return t_item->data.len; +} + +static uint32_t drop_cnt; +static uintptr_t exp_dropped_data[10]; +static uint32_t exp_dropped_len[10]; + +static void drop(struct mpsc_pbuf_buffer *buffer, union mpsc_pbuf_generic *item) +{ + struct test_data_var *packet = (struct test_data_var *)item; + + zassert_equal(packet->hdr.data, exp_dropped_data[drop_cnt], NULL); + zassert_equal(packet->hdr.len, exp_dropped_len[drop_cnt], NULL); + for (int i = 0; i < exp_dropped_len[drop_cnt] - 1; i++) { + int err = memcmp(packet->data, &exp_dropped_data[drop_cnt], + sizeof(uint32_t)); + + zassert_equal(err, 0, NULL); + } + + drop_cnt++; +} + +static uint32_t buf32[512]; + +static struct mpsc_pbuf_buffer_config cfg = { + .buf = buf32, + .size = ARRAY_SIZE(buf32), + .notify_drop = drop, + .get_wlen = get_wlen +}; + +static void init(struct mpsc_pbuf_buffer *buffer, bool overwrite, bool pow2) +{ + drop_cnt = 0; + cfg.flags = overwrite ? MPSC_PBUF_MODE_OVERWRITE : 0; + cfg.size = ARRAY_SIZE(buf32) - (pow2 ? 0 : 1); + mpsc_pbuf_init(buffer, &cfg); + +#if CONFIG_SOC_SERIES_NRF52X + CoreDebug->DEMCR |= CoreDebug_DEMCR_TRCENA_Msk; + DWT->CTRL |= DWT_CTRL_CYCCNTENA_Msk; + DWT->CYCCNT = 0; +#endif +} + +static inline uint32_t get_cyc(void) +{ +#if CONFIG_SOC_SERIES_NRF52X + return DWT->CYCCNT; +#else + return k_cycle_get_32(); +#endif +} + +void item_put_no_overwrite(bool pow2) +{ + struct mpsc_pbuf_buffer buffer; + + init(&buffer, false, pow2); + + int repeat = buffer.size*2; + union test_item test_1word = {.data = {.valid = 1, .len = 1 }}; + + for (int i = 0; i < repeat; i++) { + union test_item *t; + + test_1word.data.data = i; + mpsc_pbuf_put_word(&buffer, test_1word.item); + + t = (union test_item *)mpsc_pbuf_claim(&buffer); + zassert_true(t, NULL); + zassert_equal(t->data.data, i, NULL); + mpsc_pbuf_free(&buffer, &t->item); + + } + + zassert_equal(mpsc_pbuf_claim(&buffer), NULL, NULL); +} + +void test_item_put_no_overwrite(void) +{ + item_put_no_overwrite(true); + item_put_no_overwrite(false); +} + +void item_put_overwrite(bool pow2) +{ + struct mpsc_pbuf_buffer buffer; + + init(&buffer, true, pow2); + + union test_item test_1word = {.data = {.valid = 1, .len = 1 }}; + + exp_dropped_data[0] = 0; + exp_dropped_len[0] = 1; + + for (int i = 0; i < buffer.size; i++) { + test_1word.data.data = i; + mpsc_pbuf_put_word(&buffer, test_1word.item); + } + + zassert_equal(drop_cnt, 1, + "Unexpected number of dropped messages: %d", drop_cnt); +} + +void test_item_put_overwrite(void) +{ + item_put_overwrite(true); + item_put_overwrite(false); +} + +void item_put_saturate(bool pow2) +{ + struct mpsc_pbuf_buffer buffer; + + init(&buffer, false, pow2); + + int repeat = buffer.size; + union test_item test_1word = {.data = {.valid = 1, .len = 1 }}; + union test_item *t; + + zassert_false(mpsc_pbuf_is_pending(&buffer), NULL); + + for (int i = 0; i < repeat/2; i++) { + test_1word.data.data = i; + mpsc_pbuf_put_word(&buffer, test_1word.item); + + zassert_true(mpsc_pbuf_is_pending(&buffer), NULL); + + t = (union test_item *)mpsc_pbuf_claim(&buffer); + zassert_true(t, NULL); + zassert_equal(t->data.data, i, NULL); + mpsc_pbuf_free(&buffer, &t->item); + } + + for (int i = 0; i < repeat; i++) { + test_1word.data.data = i; + mpsc_pbuf_put_word(&buffer, test_1word.item); + } + + for (int i = 0; i < (repeat-1); i++) { + t = (union test_item *)mpsc_pbuf_claim(&buffer); + zassert_true(t, NULL); + zassert_equal(t->data.data, i, NULL); + mpsc_pbuf_free(&buffer, &t->item); + } + + zassert_equal(mpsc_pbuf_claim(&buffer), NULL, NULL); +} + +void test_item_put_saturate(void) +{ + item_put_saturate(true); + item_put_saturate(false); +} + +void benchmark_item_put(bool pow2) +{ + struct mpsc_pbuf_buffer buffer; + + init(&buffer, true, pow2); + + int repeat = buffer.size - 1; + union test_item test_1word = {.data = {.valid = 1, .len = 1 }}; + uint32_t t = get_cyc(); + + for (int i = 0; i < repeat; i++) { + test_1word.data.data = i; + mpsc_pbuf_put_word(&buffer, test_1word.item); + } + + t = get_cyc() - t; + PRINT("%s buffer\n", pow2 ? "pow2" : "non-pow2"); + PRINT("single word put time: %d cycles\n", t/repeat); + + t = get_cyc(); + for (int i = 0; i < repeat; i++) { + union test_item *t; + + t = (union test_item *)mpsc_pbuf_claim(&buffer); + zassert_true(t, NULL); + zassert_equal(t->data.data, i, NULL); + mpsc_pbuf_free(&buffer, &t->item); + } + + t = get_cyc() - t; + PRINT("single word item claim,free: %d cycles\n", t/repeat); + + zassert_equal(mpsc_pbuf_claim(&buffer), NULL, NULL); +} + +void test_benchmark_item_put(void) +{ + benchmark_item_put(true); + benchmark_item_put(false); +} + +void item_put_ext_no_overwrite(bool pow2) +{ + struct mpsc_pbuf_buffer buffer; + + init(&buffer, false, pow2); + + int repeat = buffer.size * 2; + union test_item test_ext_item = { + .data = { + .valid = 1, + .len = PUT_EXT_LEN + } + }; + void *data; + + for (uintptr_t i = 0; i < repeat; i++) { + union test_item *t; + + data = (void *)i; + test_ext_item.data.data = i; + mpsc_pbuf_put_word_ext(&buffer, test_ext_item.item, data); + + t = (union test_item *)mpsc_pbuf_claim(&buffer); + zassert_true(t, NULL); + zassert_equal(t->data_ext.hdr.data, i, NULL); + zassert_equal(t->data_ext.data, (void *)i, NULL); + mpsc_pbuf_free(&buffer, &t->item); + } + + zassert_equal(mpsc_pbuf_claim(&buffer), NULL, NULL); +} + +void test_item_put_ext_no_overwrite(void) +{ + item_put_ext_no_overwrite(true); + item_put_ext_no_overwrite(false); +} + +void item_put_word_ext_overwrite(bool pow2) +{ + struct mpsc_pbuf_buffer buffer; + + init(&buffer, true, pow2); + + size_t w = (sizeof(uint32_t) + sizeof(void *)) / sizeof(uint32_t); + int repeat = 1 + (buffer.size - 1) / w; + union test_item test_ext_item = { + .data = { + .valid = 1, + .len = PUT_EXT_LEN + } + }; + + exp_dropped_data[0] = 0; + exp_dropped_len[0] = w; + exp_dropped_data[1] = 1; + exp_dropped_len[1] = w; + + for (uintptr_t i = 0; i < repeat; i++) { + test_ext_item.data.data = i; + mpsc_pbuf_put_word_ext(&buffer, test_ext_item.item, (void *)i); + } + + uint32_t exp_drop_cnt = (sizeof(void *) == sizeof(uint32_t)) ? + (pow2 ? 1 : 2) : 2; + + zassert_equal(drop_cnt, exp_drop_cnt, + "Unexpected number of dropped messages: %d", drop_cnt); +} + +void test_item_put_word_ext_overwrite(void) +{ + item_put_word_ext_overwrite(true); + item_put_word_ext_overwrite(false); +} + +void item_put_ext_saturate(bool pow2) +{ + struct mpsc_pbuf_buffer buffer; + + init(&buffer, false, pow2); + + int repeat = buffer.size / PUT_EXT_LEN; + union test_item test_ext_item = { + .data = { + .valid = 1, + .len = PUT_EXT_LEN + } + }; + void *data; + union test_item *t; + + for (uintptr_t i = 0; i < repeat/2; i++) { + test_ext_item.data.data = i; + data = (void *)i; + mpsc_pbuf_put_word_ext(&buffer, test_ext_item.item, data); + + t = (union test_item *)mpsc_pbuf_claim(&buffer); + zassert_true(t, NULL); + zassert_equal(t->data.data, i, NULL); + mpsc_pbuf_free(&buffer, &t->item); + } + + for (uintptr_t i = 0; i < repeat; i++) { + test_ext_item.data.data = i; + data = (void *)i; + mpsc_pbuf_put_word_ext(&buffer, test_ext_item.item, data); + } + + for (uintptr_t i = 0; i < (repeat-1); i++) { + t = (union test_item *)mpsc_pbuf_claim(&buffer); + zassert_true(t, NULL); + zassert_equal(t->data_ext.data, (void *)i, NULL); + zassert_equal(t->data_ext.hdr.data, i, NULL); + mpsc_pbuf_free(&buffer, &t->item); + } + + zassert_equal(mpsc_pbuf_claim(&buffer), NULL, NULL); +} + +void test_item_put_ext_saturate(void) +{ + item_put_ext_saturate(true); + item_put_ext_saturate(false); +} + +void benchmark_item_put_ext(bool pow2) +{ + struct mpsc_pbuf_buffer buffer; + + init(&buffer, false, pow2); + + int repeat = (buffer.size - 1) / PUT_EXT_LEN; + union test_item test_ext_item = { + .data = { + .valid = 1, + .len = PUT_EXT_LEN + } + }; + void *data = NULL; + uint32_t t = get_cyc(); + + for (int i = 0; i < repeat; i++) { + test_ext_item.data.data = i; + mpsc_pbuf_put_word_ext(&buffer, test_ext_item.item, data); + } + + t = get_cyc() - t; + PRINT("%spow2 buffer\n", pow2 ? "" : "non-"); + PRINT("put_ext time: %d cycles\n", t/repeat); + + t = get_cyc(); + for (int i = 0; i < repeat; i++) { + union test_item *t; + + t = (union test_item *)mpsc_pbuf_claim(&buffer); + zassert_true(t, NULL); + zassert_equal(t->data.data, i, NULL); + mpsc_pbuf_free(&buffer, &t->item); + } + + t = get_cyc() - t; + PRINT("ext item claim,free: %d cycles\n", t/repeat); + + zassert_equal(mpsc_pbuf_claim(&buffer), NULL, NULL); +} + +void test_benchmark_item_put_ext(void) +{ + benchmark_item_put_ext(true); + benchmark_item_put_ext(false); +} + +void benchmark_item_put_data(bool pow2) +{ + struct mpsc_pbuf_buffer buffer; + + init(&buffer, false, pow2); + + int repeat = (buffer.size - 1) / PUT_EXT_LEN; + union test_item test_ext_item = { + .data_ext = { + .hdr = { + .valid = 1, + .len = PUT_EXT_LEN + }, + .data = NULL + } + }; + uint32_t t = get_cyc(); + + for (uintptr_t i = 0; i < repeat; i++) { + test_ext_item.data_ext.hdr.data = i; + test_ext_item.data_ext.data = (void *)i; + mpsc_pbuf_put_data(&buffer, (uint32_t *)&test_ext_item, + PUT_EXT_LEN); + } + + t = get_cyc() - t; + PRINT("%spow2 buffer\n", pow2 ? "" : "non-"); + PRINT("put_ext time: %d cycles\n", t/repeat); + + t = get_cyc(); + for (int i = 0; i < repeat; i++) { + union test_item *t; + + t = (union test_item *)mpsc_pbuf_claim(&buffer); + zassert_true(t, NULL); + zassert_equal(t->data.data, i, NULL); + mpsc_pbuf_free(&buffer, &t->item); + } + + t = get_cyc() - t; + PRINT("ext item claim,free: %d cycles\n", t/repeat); + + zassert_equal(mpsc_pbuf_claim(&buffer), NULL, NULL); +} + +void test_benchmark_item_put_data(void) +{ + benchmark_item_put_data(true); + benchmark_item_put_data(false); +} + +void item_put_data_overwrite(bool pow2) +{ + struct mpsc_pbuf_buffer buffer; + + init(&buffer, true, pow2); + + size_t w = (sizeof(uint32_t) + sizeof(void *)) / sizeof(uint32_t); + int repeat = 1 + (buffer.size - 1) / w; + static const int len = sizeof(struct test_data_ext) / sizeof(uint32_t); + struct test_data_ext item = { + .hdr = { + .valid = 1, + .len = len + } + }; + + exp_dropped_data[0] = 0; + exp_dropped_len[0] = w; + exp_dropped_data[1] = 1; + exp_dropped_len[1] = w; + + for (uintptr_t i = 0; i < repeat; i++) { + item.data = (void *)i; + item.hdr.data = i; + mpsc_pbuf_put_data(&buffer, (uint32_t *)&item, len); + } + + uint32_t exp_drop_cnt = (sizeof(void *) == sizeof(uint32_t)) ? + (pow2 ? 1 : 2) : 2; + + zassert_equal(drop_cnt, exp_drop_cnt, + "Unexpected number of dropped messages: %d", drop_cnt); +} + +void test_put_data_overwrite(void) +{ + item_put_data_overwrite(true); + item_put_data_overwrite(false); +} + +void item_alloc_commit(bool pow2) +{ + struct mpsc_pbuf_buffer buffer; + + init(&buffer, false, pow2); + + struct test_data_var *packet; + uint32_t len = 5; + int repeat = 1024; + + for (int i = 0; i < repeat; i++) { + packet = (struct test_data_var *)mpsc_pbuf_alloc(&buffer, len, + K_NO_WAIT); + packet->hdr.len = len; + for (int j = 0; j < len - 1; j++) { + packet->data[j] = i + j; + } + + mpsc_pbuf_commit(&buffer, (union mpsc_pbuf_generic *)packet); + + packet = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_true(packet, NULL); + zassert_equal(packet->hdr.len, len, NULL); + + for (int j = 0; j < len - 1; j++) { + zassert_equal(packet->data[j], i + j, NULL); + } + + mpsc_pbuf_free(&buffer, (union mpsc_pbuf_generic *)packet); + } +} + +void test_item_alloc_commit(void) +{ + item_alloc_commit(true); + item_alloc_commit(false); +} + +static uint32_t saturate_buffer_uneven(struct mpsc_pbuf_buffer *buffer, + uint32_t len) +{ + struct test_data_var *packet; + uint32_t uneven = 5; + uint32_t cnt = 0; + int repeat = + uneven - 1 + ((buffer->size - (uneven * len)) / len); + + /* Put some data to include wrapping */ + for (int i = 0; i < uneven; i++) { + packet = (struct test_data_var *)mpsc_pbuf_alloc(buffer, len, + K_NO_WAIT); + packet->hdr.len = len; + mpsc_pbuf_commit(buffer, (union mpsc_pbuf_generic *)packet); + + packet = (struct test_data_var *)mpsc_pbuf_claim(buffer); + zassert_true(packet, NULL); + mpsc_pbuf_free(buffer, (union mpsc_pbuf_generic *)packet); + } + + for (int i = 0; i < repeat; i++) { + packet = (struct test_data_var *)mpsc_pbuf_alloc(buffer, len, + K_NO_WAIT); + zassert_true(packet, NULL); + packet->hdr.len = len; + packet->hdr.data = i; + for (int j = 0; j < len - 1; j++) { + packet->data[j] = i + j; + } + + mpsc_pbuf_commit(buffer, (union mpsc_pbuf_generic *)packet); + cnt++; + } + + return cnt; +} + +void item_alloc_commit_saturate(bool pow2) +{ + struct mpsc_pbuf_buffer buffer; + + init(&buffer, false, pow2); + + saturate_buffer_uneven(&buffer, 5); + + struct test_data_var *packet; + uint32_t len = 5; + + packet = (struct test_data_var *)mpsc_pbuf_alloc(&buffer, len, + K_NO_WAIT); + zassert_equal(packet, NULL, NULL); + + /* Get one packet from the buffer. */ + packet = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_true(packet, NULL); + mpsc_pbuf_free(&buffer, (union mpsc_pbuf_generic *)packet); + + /* and try to allocate one more time, this time with success. */ + packet = (struct test_data_var *)mpsc_pbuf_alloc(&buffer, len, + K_NO_WAIT); + zassert_true(packet, NULL); +} + +void test_item_alloc_commit_saturate(void) +{ + item_alloc_commit_saturate(true); + item_alloc_commit_saturate(false); +} + +void item_alloc_preemption(bool pow2) +{ + struct mpsc_pbuf_buffer buffer; + + init(&buffer, false, pow2); + + struct test_data_var *p0; + struct test_data_var *p1; + struct test_data_var *p; + + p0 = (struct test_data_var *)mpsc_pbuf_alloc(&buffer, 10, K_NO_WAIT); + zassert_true(p0, NULL); + p0->hdr.len = 10; + + /* Check that no packet is yet available */ + p = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_equal(p, NULL, NULL); + + p1 = (struct test_data_var *)mpsc_pbuf_alloc(&buffer, 20, K_NO_WAIT); + zassert_true(p1, NULL); + p1->hdr.len = 20; + + /* Commit p1, p0 is still not committed, there should be no packets + * available for reading. + */ + mpsc_pbuf_commit(&buffer, (union mpsc_pbuf_generic *)p1); + + /* Check that no packet is yet available */ + p = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_equal(p, NULL, NULL); + + mpsc_pbuf_commit(&buffer, (union mpsc_pbuf_generic *)p0); + + /* Validate that p0 is the first one. */ + p = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_true(p, NULL); + zassert_equal(p->hdr.len, 10, NULL); + mpsc_pbuf_free(&buffer, (union mpsc_pbuf_generic *)p); + + /* Validate that p1 is the next one. */ + p = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_true(p, NULL); + zassert_equal(p->hdr.len, 20, NULL); + mpsc_pbuf_free(&buffer, (union mpsc_pbuf_generic *)p); + + /* No more packets. */ + p = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_equal(p, NULL, NULL); +} + +void test_item_alloc_preemption(void) +{ + item_alloc_preemption(true); + item_alloc_preemption(false); +} + +void overwrite(bool pow2) +{ + struct test_data_var *p; + uint32_t fill_len = 5; + uint32_t len0, len1; + struct mpsc_pbuf_buffer buffer; + + init(&buffer, true, pow2); + uint32_t packet_cnt = saturate_buffer_uneven(&buffer, fill_len); + + exp_dropped_data[0] = 0; + exp_dropped_len[0] = fill_len; + len0 = 6; + p = (struct test_data_var *)mpsc_pbuf_alloc(&buffer, len0, K_NO_WAIT); + + p->hdr.len = len0; + mpsc_pbuf_commit(&buffer, (union mpsc_pbuf_generic *)p); + zassert_equal(drop_cnt, 1, NULL); + + /* Request allocation which will require dropping 2 packets. */ + len1 = 9; + exp_dropped_data[1] = 1; + exp_dropped_len[1] = fill_len; + exp_dropped_data[2] = 2; + exp_dropped_len[2] = fill_len; + + p = (struct test_data_var *)mpsc_pbuf_alloc(&buffer, len1, K_NO_WAIT); + + p->hdr.len = len1; + mpsc_pbuf_commit(&buffer, (union mpsc_pbuf_generic *)p); + zassert_equal(drop_cnt, 3, NULL); + + for (int i = 0; i < (packet_cnt - drop_cnt); i++) { + p = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_true(p, NULL); + zassert_equal(p->hdr.len, fill_len, NULL); + zassert_equal(p->hdr.data, i + drop_cnt, NULL); + for (int j = 0; j < fill_len - 1; j++) { + zassert_equal(p->data[j], p->hdr.data + j, NULL); + } + + mpsc_pbuf_free(&buffer, (union mpsc_pbuf_generic *)p); + } + + p = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_true(p, NULL); + zassert_equal(p->hdr.len, len0, NULL); + mpsc_pbuf_free(&buffer, (union mpsc_pbuf_generic *)p); + + p = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_true(p, NULL); + zassert_equal(p->hdr.len, len1, NULL); + mpsc_pbuf_free(&buffer, (union mpsc_pbuf_generic *)p); + + p = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_equal(p, NULL, NULL); +} + +void test_overwrite(void) +{ + overwrite(true); + overwrite(false); +} + +void overwrite_while_claimed(bool pow2) +{ + struct test_data_var *p0; + struct test_data_var *p1; + struct mpsc_pbuf_buffer buffer; + + init(&buffer, true, pow2); + + uint32_t fill_len = 5; + uint32_t len = 6; + uint32_t packet_cnt = saturate_buffer_uneven(&buffer, fill_len); + + /* Start by claiming a packet. Buffer is now full. Allocation shall + * skip claimed packed and drop the next one. + */ + p0 = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_true(p0, NULL); + zassert_equal(p0->hdr.len, fill_len, NULL); + + exp_dropped_data[0] = p0->hdr.data + 1; /* next packet is dropped */ + exp_dropped_len[0] = fill_len; + exp_dropped_data[1] = p0->hdr.data + 2; /* next packet is dropped */ + exp_dropped_len[1] = fill_len; + p1 = (struct test_data_var *)mpsc_pbuf_alloc(&buffer, 6, K_NO_WAIT); + + zassert_equal(drop_cnt, 2, NULL); + p1->hdr.len = len; + mpsc_pbuf_commit(&buffer, (union mpsc_pbuf_generic *)p1); + + mpsc_pbuf_free(&buffer, (union mpsc_pbuf_generic *)p0); + + for (int i = 0; i < packet_cnt - drop_cnt - 1; i++) { + p0 = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_true(p0, NULL); + zassert_equal(p0->hdr.len, fill_len, NULL); + zassert_equal(p0->hdr.data, i + drop_cnt + 1, NULL); + mpsc_pbuf_free(&buffer, (union mpsc_pbuf_generic *)p0); + } + + p0 = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_true(p0, NULL); + zassert_equal(p0->hdr.len, len, NULL); + + p0 = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_equal(p0, NULL, NULL); +} + +void test_overwrite_while_claimed(void) +{ + overwrite_while_claimed(true); + overwrite_while_claimed(false); +} + +void overwrite_while_claimed2(bool pow2) +{ + struct test_data_var *p0; + struct test_data_var *p1; + struct mpsc_pbuf_buffer buffer; + + init(&buffer, true, pow2); + + uint32_t fill_len = 1; + uint32_t len = 3; + uint32_t packet_cnt = saturate_buffer_uneven(&buffer, fill_len); + + /* Start by claiming a packet. Buffer is now full. Allocation shall + * skip claimed packed and drop the next one. + */ + p0 = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_true(p0, NULL); + zassert_equal(p0->hdr.len, fill_len, NULL); + + exp_dropped_data[0] = p0->hdr.data + 1; /* next packet is dropped */ + exp_dropped_len[0] = fill_len; + exp_dropped_data[1] = p0->hdr.data + 2; /* next packet is dropped */ + exp_dropped_len[1] = fill_len; + exp_dropped_data[2] = p0->hdr.data + 3; /* next packet is dropped */ + exp_dropped_len[2] = fill_len; + exp_dropped_data[3] = p0->hdr.data + 4; /* next packet is dropped */ + exp_dropped_len[3] = fill_len; + p1 = (struct test_data_var *)mpsc_pbuf_alloc(&buffer, len, K_NO_WAIT); + + zassert_equal(drop_cnt, 4, NULL); + p1->hdr.len = len; + mpsc_pbuf_commit(&buffer, (union mpsc_pbuf_generic *)p1); + + mpsc_pbuf_free(&buffer, (union mpsc_pbuf_generic *)p0); + + for (int i = 0; i < packet_cnt - drop_cnt - 1; i++) { + p0 = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_true(p0, NULL); + zassert_equal(p0->hdr.len, fill_len, NULL); + zassert_equal(p0->hdr.data, i + drop_cnt + 1, NULL); + mpsc_pbuf_free(&buffer, (union mpsc_pbuf_generic *)p0); + } + + p0 = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_true(p0, NULL); + zassert_equal(p0->hdr.len, len, NULL); + + p0 = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + zassert_equal(p0, NULL, NULL); +} + +void test_overwrite_while_claimed2(void) +{ + overwrite_while_claimed2(true); + overwrite_while_claimed2(false); +} + +static uintptr_t current_rd_idx; + +static void validate_packet(struct test_data_var *packet) +{ + zassert_equal((uintptr_t)packet->hdr.data, current_rd_idx, + "Got %d, expected: %d", + (uintptr_t)packet->hdr.data, current_rd_idx); + current_rd_idx++; +} + +static void consistent_drop(struct mpsc_pbuf_buffer *buffer, + union mpsc_pbuf_generic *item) +{ + validate_packet((struct test_data_var *)item); +} + +uint32_t rand_get(uint32_t min, uint32_t max) +{ + return min + (sys_rand32_get() % max); +} + +void test_overwrite_consistency(void) +{ + struct mpsc_pbuf_buffer buffer; + static struct mpsc_pbuf_buffer_config cfg = { + .buf = buf32, + .size = ARRAY_SIZE(buf32), + .notify_drop = consistent_drop, + .get_wlen = get_wlen, + .flags = MPSC_PBUF_MODE_OVERWRITE + }; + + mpsc_pbuf_init(&buffer, &cfg); + int repeat = 50000; + int id = 0; + + while (id < repeat) { + struct test_data_var *t = NULL; + bool alloc_during_claim = (rand_get(1, 5) <= 2); + + /* Occasionally claim buffer to simulate that claiming is + * interrupted by allocation. + */ + if (alloc_during_claim) { + t = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + if (t) { + validate_packet(t); + } + } + + uint32_t wr_cnt = rand_get(1, 200); + + for (int i = 0; i < wr_cnt; i++) { + uint32_t wlen = rand_get(1, 15); + struct test_data_var *t; + + t = (struct test_data_var *)mpsc_pbuf_alloc(&buffer, + wlen, + K_NO_WAIT); + t->hdr.len = wlen; + t->hdr.data = id++; + mpsc_pbuf_commit(&buffer, (union mpsc_pbuf_generic *)t); + } + + /* Put back item claimed before committing new items. */ + if (t) { + mpsc_pbuf_free(&buffer, (union mpsc_pbuf_generic *)t); + } + + uint32_t rd_cnt = rand_get(1, 30); + + for (int i = 0; i < rd_cnt; i++) { + struct test_data_var *t; + + t = (struct test_data_var *)mpsc_pbuf_claim(&buffer); + if (!t) { + continue; + } + + validate_packet(t); + mpsc_pbuf_free(&buffer, (union mpsc_pbuf_generic *)t); + } + } +} + +K_THREAD_STACK_DEFINE(t1_stack, 1024); +K_THREAD_STACK_DEFINE(t2_stack, 1024); + +static k_thread_stack_t *stacks[2] = {t1_stack, t2_stack}; +static struct k_thread threads[2]; +static k_tid_t tids[2]; + +void t_entry(void *p0, void *p1, void *p2) +{ + struct mpsc_pbuf_buffer *buffer = p0; + uintptr_t wait_ms = (uintptr_t)p1; + struct test_data_ext *t; + + t = (struct test_data_ext *)mpsc_pbuf_alloc(buffer, + sizeof(*t) / sizeof(uint32_t), + K_MSEC(1)); + zassert_equal(t, NULL, NULL); + + t = (struct test_data_ext *)mpsc_pbuf_alloc(buffer, + sizeof(*t) / sizeof(uint32_t), + K_MSEC(wait_ms)); + t->hdr.len = PUT_EXT_LEN; + t->data = k_current_get(); + + mpsc_pbuf_commit(buffer, (union mpsc_pbuf_generic *)t); + while (1) { + k_sleep(K_MSEC(10)); + } +} + +void start_threads(struct mpsc_pbuf_buffer *buffer) +{ + int prio = 2; + uintptr_t wait_ms = 1000; + + for (int i = 0; i < ARRAY_SIZE(threads); i++) { + tids[i] = k_thread_create(&threads[i], stacks[i], 1024, t_entry, + buffer, (void *)wait_ms, NULL, + prio--, + 0, K_NO_WAIT); + } + + k_sleep(K_MSEC(10)); + + for (int i = 0; i < ARRAY_SIZE(threads); i++) { + k_ticks_t t = k_thread_timeout_remaining_ticks(tids[i]); + k_ticks_t exp_wait = k_ms_to_ticks_ceil32(wait_ms); + + /* Threads shall be blocked, waiting for available space. */ + zassert_within(t, exp_wait, k_ms_to_ticks_ceil32(2), NULL); + } +} + +/* Test creates two threads which pends on the buffer until there is a space + * available. When engough buffers is released threads are waken up and they + * allocate packets. + */ +void test_pending_alloc(void) +{ + int prio = k_thread_priority_get(k_current_get()); + struct mpsc_pbuf_buffer buffer; + + k_thread_priority_set(k_current_get(), 3); + + init(&buffer, true, false); + + uint32_t fill_len = 1; + uint32_t packet_cnt = saturate_buffer_uneven(&buffer, fill_len); + + start_threads(&buffer); + + k_sleep(K_MSEC(1)); + + for (int i = 0; i < packet_cnt; i++) { + union test_item *t = (union test_item *)mpsc_pbuf_claim(&buffer); + + mpsc_pbuf_free(&buffer, (union mpsc_pbuf_generic *)t); + } + + + for (int i = 0; i < 2; i++) { + struct test_data_ext *t = + (struct test_data_ext *)mpsc_pbuf_claim(&buffer); + + zassert_true(t, NULL); + zassert_equal(t->data, tids[ARRAY_SIZE(tids) - 1 - i], NULL); + mpsc_pbuf_free(&buffer, (union mpsc_pbuf_generic *)t); + } + + zassert_equal(mpsc_pbuf_claim(&buffer), NULL, "No more packets."); + k_thread_priority_set(k_current_get(), prio); +} + +/*test case main entry*/ +void test_main(void) +{ + ztest_test_suite(test_log_buffer, + ztest_unit_test(test_benchmark_item_put), + ztest_unit_test(test_item_put_saturate), + ztest_unit_test(test_item_put_no_overwrite), + ztest_unit_test(test_item_put_overwrite), + ztest_unit_test(test_item_put_ext_no_overwrite), + ztest_unit_test(test_item_put_word_ext_overwrite), + ztest_unit_test(test_item_put_ext_saturate), + ztest_unit_test(test_put_data_overwrite), + ztest_unit_test(test_benchmark_item_put_ext), + ztest_unit_test(test_benchmark_item_put_data), + ztest_unit_test(test_item_alloc_commit), + ztest_unit_test(test_item_alloc_commit_saturate), + ztest_unit_test(test_item_alloc_preemption), + ztest_unit_test(test_overwrite), + ztest_unit_test(test_overwrite_while_claimed), + ztest_unit_test(test_overwrite_while_claimed2), + ztest_unit_test(test_overwrite_consistency), + ztest_unit_test(test_pending_alloc) + ); + ztest_run_test_suite(test_log_buffer); +} diff --git a/tests/lib/mpsc_pbuf/testcase.yaml b/tests/lib/mpsc_pbuf/testcase.yaml new file mode 100644 index 0000000000000..07bccad031c52 --- /dev/null +++ b/tests/lib/mpsc_pbuf/testcase.yaml @@ -0,0 +1,7 @@ +tests: + lib.mpsc_pbuf: + tags: mpsc_pbuf + platform_allow: > + qemu_arc_em qemu_arc_hs qemu_cortex_a53 qemu_cortex_m0 qemu_cortex_m3 + qemu_cortex_r5 qemu_leon3 qemu_nios2 qemu_riscv32 qemu_riscv64 qemu_x86 + qemu_x86_64 qemu_xtensa From 9db6abb68e60b90c395d12a39530fdab3a8c1ce7 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Wed, 31 Mar 2021 13:13:43 +0200 Subject: [PATCH 05/22] doc: misc: Add documentation for MPSC Packet Buffer Add documentation for Multi Producer Single Consumer Packet Buffer. Signed-off-by: Krzysztof Chruscinski --- doc/reference/data_structures/index.rst | 1 + doc/reference/data_structures/mpsc_pbuf.rst | 147 ++++++++++++++++++++ 2 files changed, 148 insertions(+) create mode 100644 doc/reference/data_structures/mpsc_pbuf.rst diff --git a/doc/reference/data_structures/index.rst b/doc/reference/data_structures/index.rst index a0eb2523fa26d..6786bd44e03c1 100644 --- a/doc/reference/data_structures/index.rst +++ b/doc/reference/data_structures/index.rst @@ -30,5 +30,6 @@ needed will be provided by the user. slist.rst dlist.rst + mpsc_pbuf.rst rbtree.rst ring_buffers.rst diff --git a/doc/reference/data_structures/mpsc_pbuf.rst b/doc/reference/data_structures/mpsc_pbuf.rst new file mode 100644 index 0000000000000..f99d3a8624d9c --- /dev/null +++ b/doc/reference/data_structures/mpsc_pbuf.rst @@ -0,0 +1,147 @@ +.. _mpsc_pbuf: + +Multi Producer Single Consumer Packet Buffer +============================================ + +A :dfn:`Multi Producer Single Consumer Packet Buffer (MPSC_PBUF)` is a circular +buffer, whose contents are stored in first-in-first-out order. Variable size +packets are stored in the buffer. Packet buffer works under assumption that there +is a single context that consumes the data. However, it is possible that another +context may interfere to flush the data and never come back (panic case). +Packet is produced in two steps: first requested amount of data is allocated, +producer fills the data and commits it. Consuming a packet is also performed in +two steps: consumer claims the packet, gets pointer to it and length and later +on packet is freed. This approach reduces memory copying. + +A :dfn:`MPSC Packet Buffer` has the following key properties: + +* Allocate, commit scheme used for packet producing. +* Claim, free scheme used for packet consuming. +* Allocator ensures that continue memory of requested length is allocated. +* Following policies can be applied when requested space cannot be allocated: + + * **Overwrite** - oldest entries are dropped until requested amount of memory can + be allocated. For each dropped packet user callback is called. + * **No overwrite** - When requested amount of space cannot be allocated, + allocation fails. +* Dedicated, optimized API for storing short packets. +* Allocation with timeout. + +Internals +--------- + +Each packet in the buffer contains ``MPSC_PBUF`` specific header which is used +for internal management. Header consists of 2 bit flags. In order to optimize +memory usage, header can be added on top of the user header using +:c:macro:`MPSC_PBUF_HDR` and remaining bits in the first word can be application +specific. Header consists of following flags: + +* valid - bit set to one when packet contains valid user packet +* busy - bit set when packet is being consumed (claimed but not free) + +Header state: + ++-------+------+----------------------+ +| valid | busy | description | ++-------+------+----------------------+ +| 0 | 0 | space is free | ++-------+------+----------------------+ +| 1 | 0 | valid packet | ++-------+------+----------------------+ +| 1 | 1 | claimed valid packet | ++-------+------+----------------------+ +| 0 | 1 | internal skip packet | ++-------+------+----------------------+ + +Packet buffer space contains free space, valid user packets and internal skip +packets. Internal skip packets indicates padding, e.g. at the of the buffer. + +Allocation +^^^^^^^^^^ + +Using pairs for read and write indexes, available space is determined. If +space can be allocated, temporary write index is moved and pointer to a space +witing buffer is returned. Packet header is reset. If allocation required +wrapping of the write index, a skip packet is added to the end of buffer. If +space cannot be allocated and overwrite is disabled then ``NULL`` pointer is +returned or context blocks if allocation was with timeout. + +Allocation with overwrite +^^^^^^^^^^^^^^^^^^^^^^^^^ + +If overwrite is enabled, oldest packets are dropped until requested amount of +space can be allocated. When packets are dropped ``busy`` flag is checked in the +header to ensure that currently consumed packet is not overwritten. In that case, +skip packet is added before busy packet and packets following the busy packet +are dropped. When busy packet is being freed, such situation is detected and +packet is converted to skip packet to avoid double processing. + +Usage +----- + +Packet header definition +^^^^^^^^^^^^^^^^^^^^^^^^ + +Packet header details can be found in :zephyr_file:`include/sys/mpsc_packet.h`. +API functions can be found in :zephyr_file:`include/sys/mpsc_pbuf.h`. Headers +are split to avoid include spam when declaring the packet. + +User header structure must start with internal header: + +.. code-block:: c + + #include + + struct foo_header { + MPSC_PBUF_HDR; + uint32_t length: 32 - MPSC_PBUF_HDR_BITS; + }; + +Packet buffer configuration +^^^^^^^^^^^^^^^^^^^^^^^^^^^ + +Configuration structure contains buffer details, configuration flags and +callbacks. Following callbacks are used by the packet buffer: + +* Drop notification - callback called whenever a packet is dropped due to + overwrite. +* Get packet length - callback to determine packet length + +Packet producing +^^^^^^^^^^^^^^^^ + +Standard, two step method: + +.. code-block:: c + + foo_packet *packet = mpsc_pbuf_alloc(buffer, len, K_NO_WAIT); + + fill_data(packet); + + mpsc_pbuf_commit(buffer, packet); + +Performance optimized storing of small packets: + +* 32 bit word packet +* 32 bit word with pointer packet + +Note that since packets are written by value, they should already contain +``valid`` bit set in the header. + +.. code-block:: c + + mpsc_pbuf_put_word(buffer, data); + mpsc_pbuf_put_word_ext(buffer, data, ptr); + +Packet consuming +^^^^^^^^^^^^^^^^ + +Two step method: + +.. code-block:: c + + foo_packet *packet = mpsc_pbuf_claim(buffer); + + process(packet); + + mpsc_pbuf_free(buffer, packet); From f004fec38a5b0bba9a5a92a318e32f39c607eaa9 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Mon, 22 Mar 2021 14:46:11 +0100 Subject: [PATCH 06/22] bluetooth: Add cast to forward declared struct Logging v2 is using _Generic keyword for detecting type of log message arguments. Apparently, it does not support handling of pointers to forward declared structures. Added casting to void *. Signed-off-by: Krzysztof Chruscinski --- subsys/bluetooth/mesh/pb_gatt.c | 4 ++-- subsys/bluetooth/mesh/proxy.c | 6 +++--- subsys/bluetooth/services/ots/ots_l2cap.c | 2 +- 3 files changed, 6 insertions(+), 6 deletions(-) diff --git a/subsys/bluetooth/mesh/pb_gatt.c b/subsys/bluetooth/mesh/pb_gatt.c index 00d01a24639b5..4e36fd7e9fc9d 100644 --- a/subsys/bluetooth/mesh/pb_gatt.c +++ b/subsys/bluetooth/mesh/pb_gatt.c @@ -79,7 +79,7 @@ int bt_mesh_pb_gatt_recv(struct bt_conn *conn, struct net_buf_simple *buf) int bt_mesh_pb_gatt_open(struct bt_conn *conn) { - BT_DBG("conn %p", conn); + BT_DBG("conn %p", (void *)conn); if (link.conn) { return -EBUSY; @@ -95,7 +95,7 @@ int bt_mesh_pb_gatt_open(struct bt_conn *conn) int bt_mesh_pb_gatt_close(struct bt_conn *conn) { - BT_DBG("conn %p", conn); + BT_DBG("conn %p", (void *)conn); if (link.conn != conn) { BT_DBG("Not connected"); diff --git a/subsys/bluetooth/mesh/proxy.c b/subsys/bluetooth/mesh/proxy.c index 4cd5182fc6836..965d0a76edf02 100644 --- a/subsys/bluetooth/mesh/proxy.c +++ b/subsys/bluetooth/mesh/proxy.c @@ -548,7 +548,7 @@ static void proxy_connected(struct bt_conn *conn, uint8_t err) struct bt_mesh_proxy_client *client; int i; - BT_DBG("conn %p err 0x%02x", conn, err); + BT_DBG("conn %p err 0x%02x", (void *)conn, err); conn_count++; @@ -579,7 +579,7 @@ static void proxy_disconnected(struct bt_conn *conn, uint8_t reason) { int i; - BT_DBG("conn %p reason 0x%02x", conn, reason); + BT_DBG("conn %p reason 0x%02x", (void *)conn, reason); conn_count--; @@ -981,7 +981,7 @@ static int proxy_segment_and_send(struct bt_conn *conn, uint8_t type, { uint16_t mtu; - BT_DBG("conn %p type 0x%02x len %u: %s", conn, type, msg->len, + BT_DBG("conn %p type 0x%02x len %u: %s", (void *)conn, type, msg->len, bt_hex(msg->data, msg->len)); /* ATT_MTU - OpCode (1 byte) - Handle (2 bytes) */ diff --git a/subsys/bluetooth/services/ots/ots_l2cap.c b/subsys/bluetooth/services/ots/ots_l2cap.c index f0563573172e2..6d8aedcb2af28 100644 --- a/subsys/bluetooth/services/ots/ots_l2cap.c +++ b/subsys/bluetooth/services/ots/ots_l2cap.c @@ -125,7 +125,7 @@ static int l2cap_accept(struct bt_conn *conn, struct bt_l2cap_chan **chan) { struct bt_gatt_ots_l2cap *l2cap_ctx; - LOG_DBG("Incoming conn %p", conn); + LOG_DBG("Incoming conn %p", (void *)conn); SYS_SLIST_FOR_EACH_CONTAINER(&channels, l2cap_ctx, node) { if (l2cap_ctx->ot_chan.chan.conn) { From 0d2135b743cf13abd5da729cbd4a00e17dad31d0 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Tue, 23 Mar 2021 18:17:19 +0100 Subject: [PATCH 07/22] net: l2: bluetooth: Add cast to forward declared struct Logging v2 is using _Generic keyword for detecting type of log message arguments. Apparently, it does not support handling of pointers to forward declared structures. Added casting to void *. Signed-off-by: Krzysztof Chruscinski --- subsys/net/l2/bluetooth/bluetooth.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/subsys/net/l2/bluetooth/bluetooth.c b/subsys/net/l2/bluetooth/bluetooth.c index dd777d88f0ed6..ae59c5fb677c5 100644 --- a/subsys/net/l2/bluetooth/bluetooth.c +++ b/subsys/net/l2/bluetooth/bluetooth.c @@ -319,7 +319,7 @@ static int ipsp_accept(struct bt_conn *conn, struct bt_l2cap_chan **chan) struct bt_if_conn *if_conn = NULL; int i; - NET_DBG("Incoming conn %p", conn); + NET_DBG("Incoming conn %p", (void *)conn); /* Find unused slot to store the iface */ for (i = 0; i < CONFIG_BT_MAX_CONN; i++) { From 1cfe6e98f7d5f89a6898d12fd9fb966fdc6833d9 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Thu, 28 Jan 2021 09:09:29 +0100 Subject: [PATCH 08/22] logging: Refactor in preparation for logging v2 Refactor and cleanup in preparation for v2. Signed-off-by: Krzysztof Chruscinski --- include/logging/log_core.h | 283 ++++++++++-------- include/logging/log_ctrl.h | 15 +- samples/subsys/logging/logger/src/main.c | 5 +- subsys/logging/log_cmds.c | 4 +- subsys/logging/log_core.c | 48 +-- subsys/logging/log_msg.c | 4 +- .../logging/log_core/src/log_core_test.c | 4 +- 7 files changed, 197 insertions(+), 166 deletions(-) diff --git a/include/logging/log_core.h b/include/logging/log_core.h index c06320409c59b..fa953d5aa86d0 100644 --- a/include/logging/log_core.h +++ b/include/logging/log_core.h @@ -151,7 +151,8 @@ extern "C" { * used. */ -#define Z_LOG_STR(...) "%s: " GET_ARG_N(1, __VA_ARGS__), __func__\ +#define Z_LOG_STR(...) "%s: " GET_ARG_N(1, __VA_ARGS__), \ + (const char *)__func__\ COND_CODE_0(NUM_VA_ARGS_LESS_1(__VA_ARGS__),\ (),\ (, GET_ARGS_LESS_N(1, __VA_ARGS__))\ @@ -162,7 +163,7 @@ extern "C" { /****************** Internal macros for log frontend **************************/ /******************************************************************************/ /**@brief Second stage for Z_LOG_NARGS_POSTFIX */ -#define _LOG_NARGS_POSTFIX_IMPL( \ +#define Z_LOG_NARGS_POSTFIX_IMPL( \ _ignored, \ _0, _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, \ _11, _12, _13, _14, N, ...) N @@ -176,22 +177,38 @@ extern "C" { * @retval Postfix, number of arguments or _LONG when more than 3 arguments. */ #define Z_LOG_NARGS_POSTFIX(...) \ - _LOG_NARGS_POSTFIX_IMPL(__VA_ARGS__, LONG, LONG, LONG, LONG, LONG, \ + Z_LOG_NARGS_POSTFIX_IMPL(__VA_ARGS__, LONG, LONG, LONG, LONG, LONG, \ LONG, LONG, LONG, LONG, LONG, LONG, LONG, 3, 2, 1, 0, ~) #define Z_LOG_INTERNAL_X(N, ...) UTIL_CAT(_LOG_INTERNAL_, N)(__VA_ARGS__) -#define __LOG_INTERNAL(is_user_context, _src_level, ...) \ - do { \ - if (is_user_context) { \ - log_from_user(_src_level, __VA_ARGS__); \ - } else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { \ - log_string_sync(_src_level, __VA_ARGS__); \ - } else { \ - Z_LOG_INTERNAL_X(Z_LOG_NARGS_POSTFIX(__VA_ARGS__), \ - _src_level, __VA_ARGS__);\ - } \ - } while (false) +#define Z_LOG_INTERNAL2(is_user_context, _src_level, ...) do { \ + if (is_user_context) { \ + log_from_user(_src_level, __VA_ARGS__); \ + } else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { \ + log_string_sync(_src_level, __VA_ARGS__); \ + } else { \ + Z_LOG_INTERNAL_X(Z_LOG_NARGS_POSTFIX(__VA_ARGS__), \ + _src_level, __VA_ARGS__); \ + } \ +} while (false) + +#define Z_LOG_INTERNAL(is_user_context, _level, _source, ...) do { \ + uint16_t src_id = \ + IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \ + LOG_DYNAMIC_ID_GET(_source) : LOG_CONST_ID_GET(_source);\ + struct log_msg_ids src_level = { \ + .level = _level, \ + .domain_id = CONFIG_LOG_DOMAIN_ID, \ + .source_id = src_id \ + }; \ + if (BIT(_level) & LOG_FUNCTION_PREFIX_MASK) {\ + Z_LOG_INTERNAL2(is_user_context, src_level, \ + Z_LOG_STR(__VA_ARGS__)); \ + } else { \ + Z_LOG_INTERNAL2(is_user_context, src_level, __VA_ARGS__); \ + } \ +} while (0) #define _LOG_INTERNAL_0(_src_level, _str) \ log_0(_str, _src_level) @@ -228,9 +245,9 @@ extern "C" { ) \ )) -/******************************************************************************/ -/****************** Defiinitions used by minimal logging **********************/ -/******************************************************************************/ +/*****************************************************************************/ +/****************** Defiinitions used by minimal logging *********************/ +/*****************************************************************************/ void z_log_minimal_hexdump_print(int level, const void *data, size_t size); void z_log_minimal_vprintk(const char *fmt, va_list ap); void z_log_minimal_printk(const char *fmt, ...); @@ -256,118 +273,95 @@ static inline char z_log_minimal_level_to_char(int level) return '?'; } } -/******************************************************************************/ -/****************** Macros for standard logging *******************************/ -/******************************************************************************/ -#define __LOG(_level, _id, _filter, ...) \ - do { \ - if (Z_LOG_CONST_LEVEL_CHECK(_level)) { \ - bool is_user_context = k_is_user_context(); \ - \ - if (IS_ENABLED(CONFIG_LOG_MINIMAL)) { \ - Z_LOG_TO_PRINTK(_level, __VA_ARGS__); \ - } else if (LOG_CHECK_CTX_LVL_FILTER(is_user_context, \ - _level, _filter)) { \ - struct log_msg_ids src_level = { \ - .level = _level, \ - .domain_id = CONFIG_LOG_DOMAIN_ID, \ - .source_id = _id \ - }; \ - \ - if ((BIT(_level) & \ - LOG_FUNCTION_PREFIX_MASK) != 0U) { \ - __LOG_INTERNAL(is_user_context, \ - src_level, \ - Z_LOG_STR(__VA_ARGS__));\ - } else { \ - __LOG_INTERNAL(is_user_context, \ - src_level, \ - __VA_ARGS__); \ - } \ - } else { \ - } \ - } \ - if (false) { \ - /* Arguments checker present but never evaluated.*/ \ - /* Placed here to ensure that __VA_ARGS__ are*/ \ - /* evaluated once when log is enabled.*/ \ - log_printf_arg_checker(__VA_ARGS__); \ - } \ - } while (false) - -#define Z_LOG(_level, ...) \ - __LOG(_level, \ - (uint16_t)LOG_CURRENT_MODULE_ID(), \ - LOG_CURRENT_DYNAMIC_DATA_ADDR(), \ - __VA_ARGS__) +/*****************************************************************************/ +/****************** Macros for standard logging ******************************/ +/*****************************************************************************/ +#define Z_LOG2(_level, _source, ...) do { \ + if (!Z_LOG_CONST_LEVEL_CHECK(_level)) { \ + break; \ + } \ + if (IS_ENABLED(CONFIG_LOG_MINIMAL)) { \ + Z_LOG_TO_PRINTK(_level, __VA_ARGS__); \ + break; \ + } \ + \ + bool is_user_context = k_is_user_context(); \ + uint32_t filters = IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \ + ((struct log_source_dynamic_data *)(void *)(_source))->filters : 0;\ + if (!LOG_CHECK_CTX_LVL_FILTER(is_user_context, _level, filters)) { \ + break; \ + } \ + \ + Z_LOG_INTERNAL(is_user_context, _level, _source, __VA_ARGS__);\ + if (false) { \ + /* Arguments checker present but never evaluated.*/ \ + /* Placed here to ensure that __VA_ARGS__ are*/ \ + /* evaluated once when log is enabled.*/ \ + z_log_printf_arg_checker(__VA_ARGS__); \ + } \ +} while (false) -#define Z_LOG_INSTANCE(_level, _inst, ...) \ - __LOG(_level, \ +#define Z_LOG(_level, ...) \ + Z_LOG2(_level, \ IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \ - LOG_DYNAMIC_ID_GET(_inst) : \ - LOG_CONST_ID_GET(_inst), \ - _inst, \ + (void *)__log_current_dynamic_data : \ + (void *)__log_current_const_data, \ __VA_ARGS__) +#define Z_LOG_INSTANCE(_level, _inst, ...) Z_LOG2(_level, _inst, __VA_ARGS__) + + +/*****************************************************************************/ +/****************** Macros for hexdump logging *******************************/ +/*****************************************************************************/ +#define Z_LOG_HEXDUMP2(_level, _source, _data, _len, ...) do { \ + const char *_str = GET_ARG_N(1, __VA_ARGS__); \ + if (!Z_LOG_CONST_LEVEL_CHECK(_level)) { \ + break; \ + } \ + bool is_user_context = k_is_user_context(); \ + uint32_t filters = IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \ + ((struct log_source_dynamic_data *)(void *)(_source))->filters : 0;\ + \ + if (IS_ENABLED(CONFIG_LOG_MINIMAL)) { \ + Z_LOG_TO_PRINTK(_level, "%s", _str); \ + z_log_minimal_hexdump_print(_level, \ + (const char *)_data, _len);\ + break; \ + } \ + if (!LOG_CHECK_CTX_LVL_FILTER(is_user_context, _level, filters)) { \ + break; \ + } \ + uint16_t src_id = \ + IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \ + LOG_DYNAMIC_ID_GET(_source) : LOG_CONST_ID_GET(_source);\ + struct log_msg_ids src_level = { \ + .level = _level, \ + .domain_id = CONFIG_LOG_DOMAIN_ID, \ + .source_id = src_id, \ + }; \ + if (is_user_context) { \ + log_hexdump_from_user(src_level, _str, \ + (const char *)_data, _len); \ + } else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { \ + log_hexdump_sync(src_level, _str, (const char *)_data, _len); \ + } else { \ + log_hexdump(_str, (const char *)_data, _len, src_level); \ + } \ +} while (false) -/******************************************************************************/ -/****************** Macros for hexdump logging ********************************/ -/******************************************************************************/ -#define __LOG_HEXDUMP(_level, _id, _filter, _data, _length, _str) \ - do { \ - if (Z_LOG_CONST_LEVEL_CHECK(_level)) { \ - bool is_user_context = k_is_user_context(); \ - \ - if (IS_ENABLED(CONFIG_LOG_MINIMAL)) { \ - Z_LOG_TO_PRINTK(_level, "%s", _str); \ - z_log_minimal_hexdump_print(_level, \ - (const char *)_data, \ - _length); \ - } else if (LOG_CHECK_CTX_LVL_FILTER(is_user_context, \ - _level, _filter)) { \ - struct log_msg_ids src_level = { \ - .level = _level, \ - .domain_id = CONFIG_LOG_DOMAIN_ID, \ - .source_id = _id, \ - }; \ - \ - if (is_user_context) { \ - log_hexdump_from_user(src_level, _str, \ - (const char *)_data, \ - _length); \ - } else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { \ - log_hexdump_sync(src_level, _str, \ - (const char *)_data, \ - _length); \ - } else { \ - log_hexdump(_str, (const char *)_data, \ - _length, \ - src_level); \ - } \ - } else { \ - } \ - } \ - } while (false) - -#define Z_LOG_HEXDUMP(_level, _data, _length, _str) \ - __LOG_HEXDUMP(_level, \ - (uint16_t)LOG_CURRENT_MODULE_ID(), \ - LOG_CURRENT_DYNAMIC_DATA_ADDR(), \ - _data, _length, _str) +#define Z_LOG_HEXDUMP(_level, _data, _length, ...) \ + Z_LOG_HEXDUMP2(_level, IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \ + (void *)__log_current_dynamic_data : \ + (void *)__log_current_const_data, \ + _data, _length, __VA_ARGS__) #define Z_LOG_HEXDUMP_INSTANCE(_level, _inst, _data, _length, _str) \ - __LOG_HEXDUMP(_level, \ - IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \ - LOG_DYNAMIC_ID_GET(_inst) : \ - LOG_CONST_ID_GET(_inst), \ - _inst, \ - _data, \ - _length, \ - _str) + Z_LOG_HEXDUMP2(_level, _inst, _data, _length, _str) -/******************************************************************************/ -/****************** Filtering macros ******************************************/ -/******************************************************************************/ +/*****************************************************************************/ +/****************** Filtering macros *****************************************/ +/*****************************************************************************/ /** @brief Number of bits used to encode log level. */ #define LOG_LEVEL_BITS 3U @@ -409,9 +403,9 @@ static inline char z_log_minimal_level_to_char(int level) #define LOG_CHECK_CTX_LVL_FILTER(ctx, _level, _filter) \ (ctx || (_level <= LOG_RUNTIME_FILTER(_filter))) #define LOG_RUNTIME_FILTER(_filter) \ - LOG_FILTER_SLOT_GET(&(_filter)->filters, LOG_FILTER_AGGR_SLOT_IDX) + LOG_FILTER_SLOT_GET(&_filter, LOG_FILTER_AGGR_SLOT_IDX) #else -#define LOG_CHECK_CTX_LVL_FILTER(ctx, _level, _filter) (true) +#define LOG_CHECK_CTX_LVL_FILTER(ctx, _level, _filter) ((true) | _filter) #define LOG_RUNTIME_FILTER(_filter) LOG_LEVEL_DBG #endif @@ -430,6 +424,20 @@ enum log_strdup_action { LOG_STRDUP_CHECK_EXEC/**< Duplicate RAM strings, if not dupl. before.*/ }; +#define Z_LOG_PRINTK(...) do { \ + if (IS_ENABLED(CONFIG_LOG_MINIMAL) || !IS_ENABLED(CONFIG_LOG2)) { \ + z_log_minimal_printk(__VA_ARGS__); \ + break; \ + } \ + int _mode; \ + if (0) {\ + z_log_printf_arg_checker(__VA_ARGS__); \ + } \ + Z_LOG_MSG2_CREATE(!IS_ENABLED(CONFIG_USERSPACE), _mode, \ + CONFIG_LOG_DOMAIN_ID, NULL, \ + LOG_LEVEL_INTERNAL_RAW_STRING, NULL, 0, __VA_ARGS__);\ +} while (0) + /** @brief Get name of the log source. * * @param source_id Source ID. @@ -508,7 +516,7 @@ static inline uint32_t log_dynamic_source_id(struct log_source_dynamic_data *dat /** @brief Dummy function to trigger log messages arguments type checking. */ static inline __printf_like(1, 2) -void log_printf_arg_checker(const char *fmt, ...) +void z_log_printf_arg_checker(const char *fmt, ...) { ARG_UNUSED(fmt); } @@ -660,7 +668,20 @@ uint32_t log_get_strdup_longest_string(void); /** @brief Indicate to the log core that one log message has been dropped. */ -void log_dropped(void); +void z_log_dropped(void); + +/** @brief Read and clear current drop indications counter. + * + * @return Dropped count. + */ +uint32_t z_log_dropped_read_and_clear(void); + +/** @brief Check if there are any pending drop notifications. + * + * @retval true Pending unreported drop indications. + * @retval false No pending unreported drop indications. + */ +bool z_log_dropped_pending(void); /** @brief Log a message from user mode context. * @@ -674,6 +695,9 @@ void log_dropped(void); void __printf_like(2, 3) log_from_user(struct log_msg_ids src_level, const char *fmt, ...); +/* Internal function used by log_from_user(). */ +__syscall void z_log_string_from_user(uint32_t src_level_val, const char *str); + /** * @brief Create mask with occurences of a string format specifiers (%s). * @@ -687,9 +711,6 @@ void __printf_like(2, 3) log_from_user(struct log_msg_ids src_level, */ uint32_t z_log_get_s_mask(const char *str, uint32_t nargs); -/* Internal function used by log_from_user(). */ -__syscall void z_log_string_from_user(uint32_t src_level_val, const char *str); - /** @brief Log binary data (displayed as hexdump) from user mode context. * * @note This function is intended to be used internally @@ -760,7 +781,7 @@ static inline log_arg_t z_log_do_strdup(uint32_t msk, uint32_t idx, enum log_strdup_action action) { #ifndef CONFIG_LOG_MINIMAL - char *log_strdup(const char *str); + char *z_log_strdup(const char *str); if (msk & (1 << idx)) { const char *str = (const char *)param; @@ -770,7 +791,7 @@ static inline log_arg_t z_log_do_strdup(uint32_t msk, uint32_t idx, * if already not duplicated. */ if (action == LOG_STRDUP_EXEC || !log_is_strdup(str)) { - param = (log_arg_t)log_strdup(str); + param = (log_arg_t)z_log_strdup(str); } } #else @@ -792,7 +813,7 @@ do { \ _LOG_INTERNAL_0(_src_level, _str); \ } else { \ uint32_t mask = (_strdup_action != LOG_STRDUP_SKIP) ? \ - z_log_get_s_mask(_str, _argnum) \ + z_log_get_s_mask(_str, _argnum) \ : 0; \ \ if (_argnum == 1) { \ diff --git a/include/logging/log_ctrl.h b/include/logging/log_ctrl.h index 0f90583a9a01b..a861f32952a98 100644 --- a/include/logging/log_ctrl.h +++ b/include/logging/log_ctrl.h @@ -106,11 +106,11 @@ uint32_t log_src_cnt_get(uint32_t domain_id); /** @brief Get name of the source (module or instance). * * @param domain_id Domain ID. - * @param src_id Source ID. + * @param source_id Source ID. * * @return Source name or NULL if invalid arguments. */ -const char *log_source_name_get(uint32_t domain_id, uint32_t src_id); +const char *log_source_name_get(uint32_t domain_id, uint32_t source_id); /** @brief Get name of the domain. * @@ -125,29 +125,28 @@ const char *log_domain_name_get(uint32_t domain_id); * * @param backend Backend instance. * @param domain_id ID of the domain. - * @param src_id Source (module or instance) ID. + * @param source_id Source (module or instance) ID. * @param runtime True for runtime filter or false for compiled in. * * @return Severity level. */ uint32_t log_filter_get(struct log_backend const *const backend, - uint32_t domain_id, uint32_t src_id, bool runtime); + uint32_t domain_id, int16_t source_id, bool runtime); /** * @brief Set filter on given source for the provided backend. * * @param backend Backend instance. NULL for all backends. * @param domain_id ID of the domain. - * @param src_id Source (module or instance) ID. + * @param source_id Source (module or instance) ID. * @param level Severity level. * * @return Actual level set which may be limited by compiled level. If filter * was set for all backends then maximal level that was set is returned. */ __syscall uint32_t log_filter_set(struct log_backend const *const backend, - uint32_t domain_id, - uint32_t src_id, - uint32_t level); + uint32_t domain_id, int16_t source_id, + uint32_t level); /** * diff --git a/samples/subsys/logging/logger/src/main.c b/samples/subsys/logging/logger/src/main.c index 433aed27c536c..3bd58eec3adb9 100644 --- a/samples/subsys/logging/logger/src/main.c +++ b/samples/subsys/logging/logger/src/main.c @@ -69,15 +69,16 @@ static uint32_t timestamp_freq(void) * * @return Source ID. */ -static int log_source_id_get(const char *name) +static int16_t log_source_id_get(const char *name) { - for (int i = 0; i < log_src_cnt_get(CONFIG_LOG_DOMAIN_ID); i++) { + for (int16_t i = 0; i < log_src_cnt_get(CONFIG_LOG_DOMAIN_ID); i++) { if (strcmp(log_source_name_get(CONFIG_LOG_DOMAIN_ID, i), name) == 0) { return i; } } + return -1; } diff --git a/subsys/logging/log_cmds.c b/subsys/logging/log_cmds.c index 51bda8175de75..d95e23e39d499 100644 --- a/subsys/logging/log_cmds.c +++ b/subsys/logging/log_cmds.c @@ -95,8 +95,6 @@ static int log_status(const struct shell *shell, uint32_t modules_cnt = log_sources_count(); uint32_t dynamic_lvl; uint32_t compiled_lvl; - uint32_t i; - if (!log_backend_is_active(backend)) { shell_warn(shell, "Logs are halted!"); @@ -107,7 +105,7 @@ static int log_status(const struct shell *shell, shell_fprintf(shell, SHELL_NORMAL, "----------------------------------------------------------\r\n"); - for (i = 0U; i < modules_cnt; i++) { + for (int16_t i = 0U; i < modules_cnt; i++) { dynamic_lvl = log_filter_get(backend, CONFIG_LOG_DOMAIN_ID, i, true); compiled_lvl = log_filter_get(backend, CONFIG_LOG_DOMAIN_ID, diff --git a/subsys/logging/log_core.c b/subsys/logging/log_core.c index 9f53fa33ef0b8..88dbf24e1b6b3 100644 --- a/subsys/logging/log_core.c +++ b/subsys/logging/log_core.c @@ -636,6 +636,7 @@ static bool msg_filter_check(struct log_backend const *backend, if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) { uint32_t backend_level; uint32_t msg_level; + (struct log_source_dynamic_data *) backend_level = log_filter_get(backend, log_msg_domain_id_get(msg), @@ -674,7 +675,7 @@ static void msg_process(struct log_msg *msg, bool bypass) void dropped_notify(void) { - uint32_t dropped = atomic_set(&dropped_cnt, 0); + uint32_t dropped = z_log_dropped_read_and_clear(); for (int i = 0; i < log_backend_count_get(); i++) { struct log_backend const *backend = log_backend_get(i); @@ -702,7 +703,7 @@ bool z_impl_log_process(bool bypass) msg_process(msg, bypass); } - if (!bypass && dropped_cnt) { + if (!bypass && z_log_dropped_pending()) { dropped_notify(); } @@ -730,11 +731,21 @@ uint32_t z_vrfy_log_buffered_cnt(void) #include #endif -void log_dropped(void) +void z_log_dropped(void) { atomic_inc(&dropped_cnt); } +uint32_t z_log_dropped_read_and_clear(void) +{ + return atomic_set(&dropped_cnt, 0); +} + +bool z_log_dropped_pending(void) +{ + return dropped_cnt >= 0; +} + uint32_t log_src_cnt_get(uint32_t domain_id) { return log_sources_count(); @@ -763,16 +774,15 @@ static uint32_t max_filter_get(uint32_t filters) } uint32_t z_impl_log_filter_set(struct log_backend const *const backend, - uint32_t domain_id, - uint32_t src_id, - uint32_t level) + uint32_t domain_id, int16_t source_id, + uint32_t level) { - __ASSERT_NO_MSG(src_id < log_sources_count()); + __ASSERT_NO_MSG(source_id < log_sources_count()); if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) { uint32_t new_aggr_filter; - uint32_t *filters = log_dynamic_filters_get(src_id); + uint32_t *filters = log_dynamic_filters_get(source_id); if (backend == NULL) { struct log_backend const *iter_backend; @@ -783,14 +793,14 @@ uint32_t z_impl_log_filter_set(struct log_backend const *const backend, iter_backend = log_backend_get(i); current = log_filter_set(iter_backend, domain_id, - src_id, level); + source_id, level); max = MAX(current, max); } level = max; } else { uint32_t max = log_filter_get(backend, domain_id, - src_id, false); + source_id, false); level = MIN(level, max); @@ -815,7 +825,7 @@ uint32_t z_impl_log_filter_set(struct log_backend const *const backend, #ifdef CONFIG_USERSPACE uint32_t z_vrfy_log_filter_set(struct log_backend const *const backend, uint32_t domain_id, - uint32_t src_id, + int16_t src_id, uint32_t level) { Z_OOPS(Z_SYSCALL_VERIFY_MSG(backend == 0, @@ -873,20 +883,22 @@ void log_backend_disable(struct log_backend const *const backend) } uint32_t log_filter_get(struct log_backend const *const backend, - uint32_t domain_id, - uint32_t src_id, - bool runtime) + uint32_t domain_id, int16_t source_id, bool runtime) { - __ASSERT_NO_MSG(src_id < log_sources_count()); + __ASSERT_NO_MSG(source_id < log_sources_count()); if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) && runtime) { - uint32_t *filters = log_dynamic_filters_get(src_id); + if (source_id < 0) { + return LOG_LEVEL_DBG; + } + + uint32_t *filters = log_dynamic_filters_get(source_id); return LOG_FILTER_SLOT_GET(filters, log_backend_id_get(backend)); - } else { - return log_compiled_level_get(src_id); } + + return log_compiled_level_get(source_id); } char *log_strdup(const char *str) diff --git a/subsys/logging/log_msg.c b/subsys/logging/log_msg.c index c79e58445f0fb..137fe610d8db8 100644 --- a/subsys/logging/log_msg.c +++ b/subsys/logging/log_msg.c @@ -168,13 +168,13 @@ union log_msg_chunk *log_msg_no_space_handle(void) if (IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW)) { do { more = log_process(true); - log_dropped(); + z_log_dropped(); err = k_mem_slab_alloc(&log_msg_pool, (void **)&msg, K_NO_WAIT); } while ((err != 0) && more); } else { - log_dropped(); + z_log_dropped(); } return msg; diff --git a/tests/subsys/logging/log_core/src/log_core_test.c b/tests/subsys/logging/log_core/src/log_core_test.c index d72bb413c032f..ac66281f51407 100644 --- a/tests/subsys/logging/log_core/src/log_core_test.c +++ b/tests/subsys/logging/log_core/src/log_core_test.c @@ -136,10 +136,10 @@ static uint32_t timestamp_get(void) * * @return Source ID. */ -static int log_source_id_get(const char *name) +static int16_t log_source_id_get(const char *name) { - for (int i = 0; i < log_src_cnt_get(CONFIG_LOG_DOMAIN_ID); i++) { + for (int16_t i = 0; i < log_src_cnt_get(CONFIG_LOG_DOMAIN_ID); i++) { if (strcmp(log_source_name_get(CONFIG_LOG_DOMAIN_ID, i), name) == 0) { return i; From 69663dacc80fbcaaa40c56edd93d5385417fd7e5 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Thu, 19 Nov 2020 17:25:03 +0100 Subject: [PATCH 09/22] logging: Add logging v2 implementation for log_msg Added implementation of log_msg2 which is creating log messages using cbprintf packaging and storing them in circular ring buffer (mpsg_pbuf). Signed-off-by: Krzysztof Chruscinski --- include/linker/common-rom.ld | 7 + include/logging/log_core.h | 2 + include/logging/log_core2.h | 72 ++ include/logging/log_ctrl.h | 9 +- include/logging/log_msg.h | 1 + include/logging/log_msg2.h | 653 ++++++++++++++++++ subsys/logging/CMakeLists.txt | 6 + subsys/logging/Kconfig | 7 +- subsys/logging/Kconfig.misc | 39 +- subsys/logging/Kconfig.mode | 4 + subsys/logging/Kconfig.processing | 18 + subsys/logging/log_core.c | 105 ++- subsys/logging/log_msg2.c | 101 +++ .../subsys/logging/log_msg/src/log_msg_test.c | 4 +- 14 files changed, 1008 insertions(+), 20 deletions(-) create mode 100644 include/logging/log_core2.h create mode 100644 include/logging/log_msg2.h create mode 100644 subsys/logging/log_msg2.c diff --git a/include/linker/common-rom.ld b/include/linker/common-rom.ld index 5b73817cd4ef5..5642e7be66279 100644 --- a/include/linker/common-rom.ld +++ b/include/linker/common-rom.ld @@ -153,6 +153,13 @@ } GROUP_LINK_IN(ROMABLE_REGION) #endif /* CONFIG_PCIE */ + SECTION_DATA_PROLOGUE(log_strings_sections,,) + { + __log_strings_start = .; + KEEP(*(SORT(.log_strings*))); + __log_strings_end = .; + } GROUP_ROM_LINK_IN(RAMABLE_REGION, ROMABLE_REGION) + SECTION_DATA_PROLOGUE(log_const_sections,,) { __log_const_start = .; diff --git a/include/logging/log_core.h b/include/logging/log_core.h index fa953d5aa86d0..533106791fb01 100644 --- a/include/logging/log_core.h +++ b/include/logging/log_core.h @@ -7,6 +7,7 @@ #define ZEPHYR_INCLUDE_LOGGING_LOG_CORE_H_ #include +#include #include #include #include @@ -438,6 +439,7 @@ enum log_strdup_action { LOG_LEVEL_INTERNAL_RAW_STRING, NULL, 0, __VA_ARGS__);\ } while (0) + /** @brief Get name of the log source. * * @param source_id Source ID. diff --git a/include/logging/log_core2.h b/include/logging/log_core2.h new file mode 100644 index 0000000000000..8438814c69c84 --- /dev/null +++ b/include/logging/log_core2.h @@ -0,0 +1,72 @@ +/* + * Copyright (c) 2021 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#ifndef ZEPHYR_INCLUDE_LOGGING_LOG_CORE2_H_ +#define ZEPHYR_INCLUDE_LOGGING_LOG_CORE2_H_ + +#include + +#ifdef __cplusplus +extern "C" { +#endif + +#define Z_TRACING_LOG_TRACE(id) do { \ + Z_TRACING_LOG_HDR_INIT(_msg, id); \ + z_log_msg2_put_trace(_msg); \ +} while (0) + +#define Z_TRACING_LOG_TRACE_PTR(id, ptr) do { \ + Z_TRACING_LOG_HDR_INIT(_msg, id); \ + z_log_msg2_put_trace_ptr(_msg, ptr); \ +} while (0) + +void z_log_msg2_put_trace(struct log_msg2_trace trace); + +void z_log_msg2_put_trace_ptr(struct log_msg2_trace hdr, void *data); + + +/** @brief Initialize module for handling logging message. */ +void z_log_msg2_init(void); + +/** @brief Allocate log message. + * + * @param wlen Length in 32 bit words. + * + * @return allocated space or null if cannot be allocated. + */ +struct log_msg2 *z_log_msg2_alloc(uint32_t wlen); + +/** @brief Commit log message. + * + * @param msg Message. + */ +void z_log_msg2_commit(struct log_msg2 *msg); + +/** @brief Get pending log message. + * + * @param[out] len Message length in bytes is written is @p len is not null. + * + * @param Message or null if no pending messages. + */ +union log_msg2_generic *z_log_msg2_claim(void); + +/** @brief Free message. + * + * @param msg Message. + */ +void z_log_msg2_free(union log_msg2_generic *msg); + +/** @brief Check if there are any message pending. + * + * @retval true if at least one message is pending. + * @retval false if no message is pending. + */ +bool z_log_msg2_pending(void); + +#ifdef __cplusplus +} +#endif + +#endif /* ZEPHYR_INCLUDE_LOGGING_LOG_CORE2_H_ */ diff --git a/include/logging/log_ctrl.h b/include/logging/log_ctrl.h index a861f32952a98..af7e579418530 100644 --- a/include/logging/log_ctrl.h +++ b/include/logging/log_ctrl.h @@ -6,14 +6,14 @@ #ifndef ZEPHYR_INCLUDE_LOGGING_LOG_CTRL_H_ #define ZEPHYR_INCLUDE_LOGGING_LOG_CTRL_H_ -#include #include +#include +#include #ifdef __cplusplus extern "C" { #endif - /** * @brief Logger * @defgroup logger Logger system @@ -29,7 +29,7 @@ extern "C" { * @{ */ -typedef uint32_t (*timestamp_get_t)(void); +typedef log_timestamp_t (*log_timestamp_get_t)(void); /** @brief Function system initialization of the logger. * @@ -63,7 +63,8 @@ void log_thread_set(k_tid_t process_tid); * * @return 0 on success or error. */ -int log_set_timestamp_func(timestamp_get_t timestamp_getter, uint32_t freq); +int log_set_timestamp_func(log_timestamp_get_t timestamp_getter, + uint32_t freq); /** * @brief Switch the logger subsystem to the panic mode. diff --git a/include/logging/log_msg.h b/include/logging/log_msg.h index 892d3f9856192..3daf56f0c79ff 100644 --- a/include/logging/log_msg.h +++ b/include/logging/log_msg.h @@ -9,6 +9,7 @@ #include #include #include +#include #ifdef __cplusplus extern "C" { diff --git a/include/logging/log_msg2.h b/include/logging/log_msg2.h new file mode 100644 index 0000000000000..b5d3cd1cd8f89 --- /dev/null +++ b/include/logging/log_msg2.h @@ -0,0 +1,653 @@ +/* + * Copyright (c) 2021 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#ifndef ZEPHYR_INCLUDE_LOGGING_LOG_MSG2_H_ +#define ZEPHYR_INCLUDE_LOGGING_LOG_MSG2_H_ + +#include +#include +#include +#include +#include +#include + +#ifdef __GNUC__ +#ifndef alloca +#define alloca __builtin_alloca +#endif +#else +#include +#endif + +#ifdef __cplusplus +extern "C" { +#endif + +#define LOG_MSG2_DEBUG 0 +#define LOG_MSG2_DBG(...) IF_ENABLED(LOG_MSG2_DEBUG, (printk(__VA_ARGS__))) + +#if CONFIG_LOG_TIMESTAMP_64BIT +typedef uint64_t log_timestamp_t; +#else +typedef uint32_t log_timestamp_t; +#endif + +/** + * @brief Log message API + * @defgroup log_msg2 Log message v2 API + * @ingroup logger + * @{ + */ + +#define Z_LOG_MSG2_LOG 0 +#define Z_LOG_MSG2_TRACE 1 + +#define LOG_MSG2_GENERIC_HDR \ + MPSC_PBUF_HDR;\ + uint32_t type:1 + +struct log_msg2_desc { + LOG_MSG2_GENERIC_HDR; + uint32_t domain:3; + uint32_t level:3; + uint32_t package_len:10; + uint32_t data_len:12; + uint32_t reserved:1; +}; + +struct log_msg2_trace_hdr { + LOG_MSG2_GENERIC_HDR; + uint32_t evt_id:5; +#if CONFIG_LOG_TRACE_SHORT_TIMESTAMP + uint32_t timestamp:24; +#else + log_timestamp_t timestamp; +#endif +}; + +union log_msg2_source { + const struct log_source_const_data *fixed; + struct log_source_dynamic_data *dynamic; + void *raw; +}; + +struct log_msg2_hdr { + struct log_msg2_desc desc; +/* Attempting to keep best alignment. When address is 64 bit and timestamp 32 + * swap the order to have 16 byte header instead of 24 byte. + */ +#if (INTPTR_MAX > INT32_MAX) && !CONFIG_LOG_TIMESTAMP_64BIT + log_timestamp_t timestamp; + const void *source; +#else + const void *source; + log_timestamp_t timestamp; +#endif +#if defined(__xtensa__) && !defined(CONFIG_LOG_TIMESTAMP_64BIT) + /* xtensa requires that cbprintf package that follows the header is + * aligned to 16 bytes. Adding padding when necessary. + */ + uint32_t padding; +#endif +}; + +struct log_msg2_trace { + struct log_msg2_trace_hdr hdr; +}; + +struct log_msg2_trace_ptr { + struct log_msg2_trace_hdr hdr; + void *ptr; +}; + +struct log_msg2 { + struct log_msg2_hdr hdr; + uint8_t data[]; +}; + +struct log_msg2_generic_hdr { + LOG_MSG2_GENERIC_HDR; +}; + +union log_msg2_generic { + union mpsc_pbuf_generic buf; + struct log_msg2_generic_hdr generic; + struct log_msg2_trace trace; + struct log_msg2_trace_ptr trace_ptr; + struct log_msg2 log; +}; + +enum tracing_log_id { + TRACING_LOG_THREAD_SWITCHED_OUT, + TRACING_LOG_ISR_ENTER, + TRACING_LOG_ISR_EXIT, + TRACING_LOG_ISR_EXIT_TO_SCHEDULER, + TRACING_LOG_IDLE, + + TRACING_LOG_SINGLE_WORD = TRACING_LOG_IDLE, + + /* IDs using additional data */ + TRACING_LOG_THREAD_SWITCHED_IN, + TRACING_LOG_THREAD_PRIO_SET, + TRACING_LOG_THREAD_CREATE, + TRACING_LOG_THREAD_ABORT, + TRACING_LOG_THREAD_SUSPEND, + TRACING_LOG_THREAD_RESUME, + TRACING_LOG_THREAD_READY, + TRACING_LOG_THREAD_PEND, + TRACING_LOG_THREAD_INFO, + TRACING_LOG_THREAD_NAME_SET, + TRACING_LOG_VOID, + TRACING_LOG_END_CALL, + TRACING_LOG_SEMAPHORE_INIT, + TRACING_LOG_SEMAPHORE_TAKE, + TRACING_LOG_SEMAPHORE_GIVE, + TRACING_LOG_MUTEX_INIT, + TRACING_LOG_MUTEX_LOCK, + TRACING_LOG_MUTEX_UNLOCK +}; + +/** @brief Method used for creating a log message. + * + * It is used for testing purposes to validate that expected mode was used. + */ +enum z_log_msg2_mode { + /* Runtime mode is least efficient but supports all cases thus it is + * threated as a fallback method when others cannot be used. + */ + Z_LOG_MSG2_MODE_RUNTIME, + /* Mode creates statically a string package on stack and calls a + * function for creating a message. It takes code size than + * Z_LOG_MSG2_MODE_ZERO_COPY but is a bit slower. + */ + Z_LOG_MSG2_MODE_FROM_STACK, + + /* Mode calculates size of the message and allocates it and writes + * directly to the message space. It is the fastest method but requires + * more code size. + */ + Z_LOG_MSG2_MODE_ZERO_COPY, + + /* Mode used when synchronous logging is enabled. */ + Z_LOG_MSG2_MODE_SYNC +}; + +#define Z_LOG_MSG_DESC_INITIALIZER(_domain_id, _level, _plen, _dlen) \ +{ \ + .type = Z_LOG_MSG2_LOG, \ + .domain = _domain_id, \ + .level = _level, \ + .package_len = _plen, \ + .data_len = _dlen, \ +} + +/* Messages are aligned to alignment required by cbprintf package. */ +#define Z_LOG_MSG2_ALIGNMENT CBPRINTF_PACKAGE_ALIGNMENT + + +#if CONFIG_LOG2_USE_VLA +#define Z_LOG_MSG2_ON_STACK_ALLOC(ptr, len) \ + long long _ll_buf[ceiling_fraction(len, sizeof(long long))]; \ + long double _ld_buf[ceiling_fraction(len, sizeof(long double))]; \ + ptr = (sizeof(long double) == Z_LOG_MSG2_ALIGNMENT) ? \ + (void *)_ld_buf : (void *)_ll_buf; \ + if (IS_ENABLED(CONFIG_LOG_TEST_CLEAR_MESSAGE_SPACE)) { \ + /* During test fill with 0's to simplify message comparison */ \ + memset(ptr, 0, len); \ + } +#else /* Z_LOG_MSG2_USE_VLA */ +/* When VLA cannot be used we need to trick compiler a bit and create multiple + * fixed size arrays and take the smallest one that will fit the message. + * Compiler will remove unused arrays and stack usage will be kept similar + * to vla case, rounded to the size of the used buffer. + */ +#define Z_LOG_MSG2_ON_STACK_ALLOC(ptr, len) \ + long long _ll_buf32[32 / sizeof(long long)]; \ + long long _ll_buf48[48 / sizeof(long long)]; \ + long long _ll_buf64[64 / sizeof(long long)]; \ + long long _ll_buf128[128 / sizeof(long long)]; \ + long long _ll_buf256[256 / sizeof(long long)]; \ + long double _ld_buf32[32 / sizeof(long double)]; \ + long double _ld_buf48[48 / sizeof(long double)]; \ + long double _ld_buf64[64 / sizeof(long double)]; \ + long double _ld_buf128[128 / sizeof(long double)]; \ + long double _ld_buf256[256 / sizeof(long double)]; \ + if (sizeof(long double) == Z_LOG_MSG2_ALIGNMENT) { \ + ptr = (len > 128) ? (void *)_ld_buf256 : \ + ((len > 64) ? (void *)_ld_buf128 : \ + ((len > 48) ? (void *)_ld_buf64 : \ + ((len > 32) ? (void *)_ld_buf48 : (void *)_ld_buf32)));\ + } else { \ + ptr = (len > 128) ? (void *)_ll_buf256 : \ + ((len > 64) ? (void *)_ll_buf128 : \ + ((len > 48) ? (void *)_ll_buf64 : \ + ((len > 32) ? (void *)_ll_buf48 : (void *)_ll_buf32)));\ + } \ + if (IS_ENABLED(CONFIG_LOG_TEST_CLEAR_MESSAGE_SPACE)) { \ + /* During test fill with 0's to simplify message comparison */ \ + memset(ptr, 0, len); \ + } +#endif /* Z_LOG_MSG2_USE_VLA */ + +#define Z_LOG_MSG2_ALIGN_OFFSET \ + sizeof(struct log_msg2_hdr) + +#define Z_LOG_MSG2_LEN(pkg_len, data_len) \ + (sizeof(struct log_msg2_hdr) + pkg_len + (data_len)) + +#define Z_LOG_MSG2_ALIGNED_WLEN(pkg_len, data_len) \ + ceiling_fraction(ROUND_UP(Z_LOG_MSG2_LEN(pkg_len, data_len), \ + Z_LOG_MSG2_ALIGNMENT), \ + sizeof(uint32_t)) + +#define Z_LOG_MSG2_SYNC(_domain_id, _source, _level, _data, _dlen, ...) do { \ + int _plen; \ + CBPRINTF_STATIC_PACKAGE(NULL, 0, _plen, Z_LOG_MSG2_ALIGN_OFFSET, \ + __VA_ARGS__); \ + struct log_msg2 *_msg; \ + Z_LOG_MSG2_ON_STACK_ALLOC(_msg, Z_LOG_MSG2_LEN(_plen, _dlen)); \ + if (_plen) {\ + CBPRINTF_STATIC_PACKAGE(_msg->data, _plen, _plen, \ + Z_LOG_MSG2_ALIGN_OFFSET, __VA_ARGS__); \ + } \ + struct log_msg2_desc _desc = \ + Z_LOG_MSG_DESC_INITIALIZER(_domain_id, _level, \ + _plen, _dlen); \ + z_log_msg2_finalize(_msg, _source, _desc, _data); \ +} while (0) + +#define Z_LOG_MSG2_STACK_CREATE(_domain_id, _source, _level, _data, _dlen, ...)\ +do { \ + int _plen; \ + if (GET_ARG_N(1, __VA_ARGS__) == NULL) { \ + _plen = 0; \ + } else { \ + CBPRINTF_STATIC_PACKAGE(NULL, 0, _plen, \ + Z_LOG_MSG2_ALIGN_OFFSET, __VA_ARGS__); \ + } \ + struct log_msg2 *_msg; \ + Z_LOG_MSG2_ON_STACK_ALLOC(_msg, Z_LOG_MSG2_LEN(_plen, 0)); \ + if (_plen) { \ + CBPRINTF_STATIC_PACKAGE(_msg->data, _plen, \ + _plen, Z_LOG_MSG2_ALIGN_OFFSET, \ + __VA_ARGS__);\ + } \ + struct log_msg2_desc _desc = \ + Z_LOG_MSG_DESC_INITIALIZER(_domain_id, _level, \ + _plen, _dlen); \ + LOG_MSG2_DBG("creating message on stack: package len: %d, data len: %d\n", \ + _plen, (int)(_dlen)); \ + z_log_msg2_static_create((void *)_source, _desc, _msg->data, _data); \ +} while (0) + +#define Z_LOG_MSG2_SIMPLE_CREATE(_domain_id, _source, _level, ...) do { \ + int _plen; \ + CBPRINTF_STATIC_PACKAGE(NULL, 0, _plen, Z_LOG_MSG2_ALIGN_OFFSET, \ + __VA_ARGS__); \ + size_t _msg_wlen = Z_LOG_MSG2_ALIGNED_WLEN(_plen, 0); \ + struct log_msg2 *_msg = z_log_msg2_alloc(_msg_wlen); \ + struct log_msg2_desc _desc = \ + Z_LOG_MSG_DESC_INITIALIZER(_domain_id, _level, _plen, 0); \ + LOG_MSG2_DBG("creating message zero copy: package len: %d, msg: %p\n", \ + _plen, _msg); \ + if (_msg) { \ + CBPRINTF_STATIC_PACKAGE(_msg->data, _plen, _plen, \ + Z_LOG_MSG2_ALIGN_OFFSET, __VA_ARGS__); \ + } \ + z_log_msg2_finalize(_msg, (void *)_source, _desc, NULL); \ +} while (0) + +/* Macro handles case when local variable with log message string is created.It + * replaces origing string literal with that variable. + */ +#define Z_LOG_FMT_ARGS_2(_name, ...) \ + COND_CODE_1(CONFIG_LOG2_FMT_SECTION, \ + (COND_CODE_0(NUM_VA_ARGS_LESS_1(__VA_ARGS__), \ + (_name), (_name, GET_ARGS_LESS_N(1, __VA_ARGS__)))), \ + (__VA_ARGS__)) + +/** @brief Wrapper for log message string with arguments. + * + * Wrapper is replacing first argument with a variable from a dedicated memory + * section if option is enabled. Macro handles the case when there is no + * log message provided. + * + * @param _name Name of the variable with log message string. It is optionally used. + * @param ... Optional log message with arguments (may be empty). + */ +#define Z_LOG_FMT_ARGS(_name, ...) \ + COND_CODE_0(NUM_VA_ARGS_LESS_1(_, ##__VA_ARGS__), \ + (NULL), \ + (Z_LOG_FMT_ARGS_2(_name, ##__VA_ARGS__))) + +/* Macro handles case when there is no string provided, in that case variable + * is not created. + */ +#define Z_LOG_MSG2_STR_VAR_IN_SECTION(_name, ...) \ + COND_CODE_0(NUM_VA_ARGS_LESS_1(_, ##__VA_ARGS__), \ + (/* No args provided, no variable */), \ + (static const char _name[] \ + __attribute__((__section__(".log_strings"))) = \ + GET_ARG_N(1, __VA_ARGS__);)) + +/** @brief Create variable in the dedicated memory section (if enabled). + * + * Variable is initialized with a format string from the log message. + * + * @param _name Variable name. + * @param ... Optional log message with arguments (may be empty). + */ +#define Z_LOG_MSG2_STR_VAR(_name, ...) \ + IF_ENABLED(CONFIG_LOG2_FMT_SECTION, \ + (Z_LOG_MSG2_STR_VAR_IN_SECTION(_name, ##__VA_ARGS__))) + +/** @brief Create log message and write it into the logger buffer. + * + * Macro handles creation of log message which includes storing log message + * description, timestamp, arguments, copying string arguments into message and + * copying user data into the message space. The are 3 modes of message + * creation: + * - at compile time message size is determined, message is allocated and + * content is written directly to the message. It is the fastest but cannot + * be used in user mode. Message size cannot be determined at compile time if + * it contains data or string arguments which are string pointers. + * - at compile time message size is determined, string package is created on + * stack, message is created in function call. String package can only be + * created on stack if it does not contain unexpected pointers to strings. + * - string package is created at runtime. This mode has no limitations but + * it is significantly slower. + * + * @param _try_0cpy If positive then, if possible, message content is written + * directly to message. If 0 then, if possible, string package is created on + * the stack and message is created in the function call. + * + * @param _mode Used for testing. It is set according to message creation mode + * used. + * + * @param _cstr_cnt Number of constant strings present in the string. It is + * used to help detect messages which must be runtime processed, compared to + * message which can be prebuilt at compile time. + * + * @param _domain_id Domain ID. + * + * @param _source Pointer to the constant descriptor of the log message source. + * + * @param _level Log message level. + * + * @param _data Pointer to the data. Can be null. + * + * @param _dlen Number of data bytes. 0 if data is not provided. + * + * @param ... Optional string with arguments (fmt, ...). It may be empty. + */ +#if CONFIG_LOG2_ALWAYS_RUNTIME +#define Z_LOG_MSG2_CREATE2(_try_0cpy, _mode, _cstr_cnt, _domain_id, _source,\ + _level, _data, _dlen, ...) \ +do {\ + Z_LOG_MSG2_STR_VAR(_fmt, ##__VA_ARGS__) \ + z_log_msg2_runtime_create(_domain_id, (void *)_source, \ + _level, (uint8_t *)_data, _dlen,\ + Z_LOG_FMT_ARGS(_fmt, ##__VA_ARGS__));\ + _mode = Z_LOG_MSG2_MODE_RUNTIME; \ +} while (0) +#else /* CONFIG_LOG2_ALWAYS_RUNTIME */ +#define Z_LOG_MSG2_CREATE2(_try_0cpy, _mode, _cstr_cnt, _domain_id, _source,\ + _level, _data, _dlen, ...) \ +do { \ + Z_LOG_MSG2_STR_VAR(_fmt, ##__VA_ARGS__); \ + if (CBPRINTF_MUST_RUNTIME_PACKAGE(_cstr_cnt, __VA_ARGS__)) { \ + LOG_MSG2_DBG("create runtime message\n");\ + z_log_msg2_runtime_create(_domain_id, (void *)_source, \ + _level, (uint8_t *)_data, _dlen,\ + Z_LOG_FMT_ARGS(_fmt, ##__VA_ARGS__));\ + _mode = Z_LOG_MSG2_MODE_RUNTIME; \ + } else if (IS_ENABLED(CONFIG_LOG2_MODE_IMMEDIATE)) {\ + Z_LOG_MSG2_SYNC(_domain_id, _source, _level, \ + _data, _dlen, Z_LOG_FMT_ARGS(_fmt, ##__VA_ARGS__)); \ + _mode = Z_LOG_MSG2_MODE_SYNC; \ + } else if (IS_ENABLED(CONFIG_LOG_SPEED) && _try_0cpy && ((_dlen) == 0)) {\ + LOG_MSG2_DBG("create zero-copy message\n");\ + Z_LOG_MSG2_SIMPLE_CREATE(_domain_id, _source, \ + _level, Z_LOG_FMT_ARGS(_fmt, ##__VA_ARGS__)); \ + _mode = Z_LOG_MSG2_MODE_ZERO_COPY; \ + } else { \ + LOG_MSG2_DBG("create on stack message\n");\ + Z_LOG_MSG2_STACK_CREATE(_domain_id, _source, _level, _data, \ + _dlen, Z_LOG_FMT_ARGS(_fmt, ##__VA_ARGS__)); \ + _mode = Z_LOG_MSG2_MODE_FROM_STACK; \ + } \ + (void)_mode; \ +} while (0) +#endif /* CONFIG_LOG2_ALWAYS_RUNTIME */ + +#define Z_LOG_MSG2_CREATE(_try_0cpy, _mode, _domain_id, _source,\ + _level, _data, _dlen, ...) \ +do { \ + if (BIT(_level) & LOG_FUNCTION_PREFIX_MASK) {\ + Z_LOG_MSG2_CREATE2(_try_0cpy, _mode, 1, _domain_id, _source, \ + _level, _data, _dlen, Z_LOG_STR(__VA_ARGS__));\ + } else { \ + Z_LOG_MSG2_CREATE2(_try_0cpy, _mode, 0, _domain_id, _source, \ + _level, _data, _dlen, __VA_ARGS__); \ + } \ +} while (0) + +#define Z_TRACING_LOG_HDR_INIT(name, id) \ + struct log_msg2_trace name = { \ + .hdr = { \ + .type = Z_LOG_MSG2_TRACE, \ + .valid = 1, \ + .busy = 0, \ + .evt_id = id, \ + } \ + } + +/** @brief Finalize message. + * + * Finalization includes setting source, copying data and timestamp in the + * message followed by committing the message. + * + * @param msg Message. + * + * @param source Address of the source descriptor. + * + * @param desc Message descriptor. + * + * @param data Data. + */ +void z_log_msg2_finalize(struct log_msg2 *msg, const void *source, + const struct log_msg2_desc desc, const void *data); + +/** @brief Create simple message from message details and string package. + * + * @param source Source. + * + * @param desc Message descriptor. + * + * @param package Package. + * + * @oaram data Data. + */ +__syscall void z_log_msg2_static_create(const void *source, + const struct log_msg2_desc desc, + uint8_t *package, const void *data); + +/** @brief Create message at runtime. + * + * Function allows to build any log message based on input data. Processing + * time is significantly higher than statically message creating. + * + * @param domain_id Domain ID. + * + * @param source Source. + * + * @param level Log level. + * + * @param data Data. + * + * @param dlen Data length. + * + * @param fmt String. + * + * @param ap Variable list of string arguments. + */ +__syscall void z_log_msg2_runtime_vcreate(uint8_t domain_id, const void *source, + uint8_t level, const void *data, + size_t dlen, const char *fmt, + va_list ap); + +/** @brief Create message at runtime. + * + * Function allows to build any log message based on input data. Processing + * time is significantly higher than statically message creating. + * + * @param domain_id Domain ID. + * + * @param source Source. + * + * @param level Log level. + * + * @param data Data. + * + * @param dlen Data length. + * + * @param fmt String. + * + * @param ... String arguments. + */ +static inline void z_log_msg2_runtime_create(uint8_t domain_id, + const void *source, + uint8_t level, const void *data, + size_t dlen, const char *fmt, ...) +{ + va_list ap; + + va_start(ap, fmt); + z_log_msg2_runtime_vcreate(domain_id, source, level, + data, dlen, fmt, ap); + va_end(ap); +} + +static inline bool z_log_item_is_msg(union log_msg2_generic *msg) +{ + return msg->generic.type == Z_LOG_MSG2_LOG; +} + +/** @brief Get total length (in 32 bit words) of a log message. + * + * @param desc Log message descriptor. + * + * @return Length. + */ +static inline uint32_t log_msg2_get_total_wlen(const struct log_msg2_desc desc) +{ + return Z_LOG_MSG2_ALIGNED_WLEN(desc.package_len, desc.data_len); +} + +/** @brief Get length of the log item. + * + * @param item Item. + * + * @return Length in 32 bit words. + */ +static inline uint32_t log_msg2_generic_get_wlen(union mpsc_pbuf_generic *item) +{ + union log_msg2_generic *generic_msg = (union log_msg2_generic *)item; + + if (z_log_item_is_msg(generic_msg)) { + struct log_msg2 *msg = (struct log_msg2 *)generic_msg; + + return log_msg2_get_total_wlen(msg->hdr.desc); + } + + /* trace TODO */ + return 0; +} + +/** @brief Get log message domain ID. + * + * @param msg Log message. + * + * @return Domain ID + */ +static inline uint8_t log_msg2_get_domain(struct log_msg2 *msg) +{ + return msg->hdr.desc.domain; +} + +/** @brief Get log message level. + * + * @param msg Log message. + * + * @return Log level. + */ +static inline uint8_t log_msg2_get_level(struct log_msg2 *msg) +{ + return msg->hdr.desc.level; +} + +/** @brief Get message source data. + * + * @param msg Log message. + * + * @return Pointer to the source data. + */ +static inline const void *log_msg2_get_source(struct log_msg2 *msg) +{ + return msg->hdr.source; +} + +/** @brief Get timestamp. + * + * @param msg Log message. + * + * @return Timestamp. + */ +static inline log_timestamp_t log_msg2_get_timestamp(struct log_msg2 *msg) +{ + return msg->hdr.timestamp; +} + +/** @brief Get data buffer. + * + * @param msg log message. + * + * @param len location where data length is written. + * + * @return pointer to the data buffer. + */ +static inline uint8_t *log_msg2_get_data(struct log_msg2 *msg, size_t *len) +{ + *len = msg->hdr.desc.data_len; + + return msg->data + msg->hdr.desc.package_len; +} + +/** @brief Get string package. + * + * @param msg log message. + * + * @param len location where string package length is written. + * + * @return pointer to the package. + */ +static inline uint8_t *log_msg2_get_package(struct log_msg2 *msg, size_t *len) +{ + *len = msg->hdr.desc.package_len; + + return msg->data; +} + +/** + * @} + */ + +#include + +#ifdef __cplusplus +} +#endif + +#endif /* ZEPHYR_INCLUDE_LOGGING_LOG_MSG2_H_ */ diff --git a/subsys/logging/CMakeLists.txt b/subsys/logging/CMakeLists.txt index 5b40230f9dd42..6a1103f4b46ce 100644 --- a/subsys/logging/CMakeLists.txt +++ b/subsys/logging/CMakeLists.txt @@ -9,6 +9,12 @@ if(NOT CONFIG_LOG_MINIMAL) log_output.c ) + zephyr_sources_ifdef( + CONFIG_LOG2 + log_msg2.c + ) + + zephyr_sources_ifdef( CONFIG_LOG_BACKEND_UART log_backend_uart.c diff --git a/subsys/logging/Kconfig b/subsys/logging/Kconfig index e1ec88968444e..7f63205d7fe48 100644 --- a/subsys/logging/Kconfig +++ b/subsys/logging/Kconfig @@ -14,9 +14,7 @@ rsource "Kconfig.mode" rsource "Kconfig.filtering" -if !LOG_MINIMAL - -if !LOG_FRONTEND +if !LOG_FRONTEND && !LOG_MINIMAL rsource "Kconfig.formatting" @@ -24,9 +22,8 @@ rsource "Kconfig.processing" rsource "Kconfig.backends" -endif # !LOG_FRONTEND +endif # !LOG_FRONTEND && !LOG_MINIMAL rsource "Kconfig.misc" -endif # LOG_MINIMAL endif # LOG diff --git a/subsys/logging/Kconfig.misc b/subsys/logging/Kconfig.misc index 49814942f6a14..4c97e6d6f164c 100644 --- a/subsys/logging/Kconfig.misc +++ b/subsys/logging/Kconfig.misc @@ -5,6 +5,7 @@ menu "Misc" config LOG_DOMAIN_ID int "Domain ID" + depends on !LOG_MINIMAL default 0 range 0 7 help @@ -13,7 +14,43 @@ config LOG_DOMAIN_ID config LOG_CMDS bool "Enable shell commands" depends on SHELL - depends on !LOG_FRONTEND + depends on !LOG_FRONTEND && !LOG_MINIMAL default y if SHELL +config LOG_TEST_CLEAR_MESSAGE_SPACE + bool "Clear message after allocation" + default y + depends on ZTEST + depends on LOG2 + help + Used in testing to simplify message comparision if message contains + paddings. + +config LOG2_USE_VLA + bool "Using variable length arrays" + default y if !MISRA_SANE + help + Using VLA slightly decreases stack usage in some cases it may not be + supported. Note that VLA are used for arrays which size is resolved at + compile time so at runtime arrays have fixed size. + +config LOG2_ALWAYS_RUNTIME + bool "Always use runtime message creation (v2)" + default y if NO_OPTIMIZATIONS + help + If enabled, runtime method is always used for message creation. Static + creation relies on compiler being able to optimize and remove code + based on information known at compile time. It is recommended to + enable this option when optimization is disabled because some compilers + (seen on arm_cortex_m and x86) were using unrealistic amount of stack + for dead code. Option applies to v1 as well because distinction + between versions is done by the compiler. + +config LOG2_FMT_SECTION + bool "Keep log strings in dedicated section" + help + When enabled, logs are kept in dedicated memory section. It allows + removing strings from final binary and should be used for dictionary + logging. + endmenu diff --git a/subsys/logging/Kconfig.mode b/subsys/logging/Kconfig.mode index afbdcfabdc83e..454fe2dc1bdb5 100644 --- a/subsys/logging/Kconfig.mode +++ b/subsys/logging/Kconfig.mode @@ -12,6 +12,10 @@ config LOG_MODE_DEFERRED least impact on the application. Time consuming processing is deferred to the known context. +config LOG2 + bool "Deferred logging v2" + select MPSC_PBUF + config LOG_MODE_IMMEDIATE bool "Synchronous" help diff --git a/subsys/logging/Kconfig.processing b/subsys/logging/Kconfig.processing index 162e096aa252f..117fb29e7bede 100644 --- a/subsys/logging/Kconfig.processing +++ b/subsys/logging/Kconfig.processing @@ -138,6 +138,24 @@ config LOG_STRDUP_POOL_PROFILING endif # LOG_MODE_DEFERRED +if LOG2 + +config LOG_TRACE_SHORT_TIMESTAMP + bool "Use 24 bit timestamp for tracing" + default y + help + When enabled, shorter timestamp is used and trace message is + compressed. + +config LOG_TIMESTAMP_64BIT + bool "Use 64 bit timestamp" + +config LOG_SPEED + bool "Prefer performance over size" + help + If enabled, logging may take more code size to get faster logging. +endif # LOG2 + endif # !LOG_MINIMAL endmenu diff --git a/subsys/logging/log_core.c b/subsys/logging/log_core.c index 88dbf24e1b6b3..90839dbb8052f 100644 --- a/subsys/logging/log_core.c +++ b/subsys/logging/log_core.c @@ -9,6 +9,8 @@ #include #include #include +#include +#include #include #include #include @@ -47,6 +49,10 @@ LOG_MODULE_REGISTER(log); #define CONFIG_LOG_STRDUP_BUF_COUNT 0 #endif +#ifndef CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS +#define CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS 0 +#endif + struct log_strdup_buf { atomic_t refcount; char buf[CONFIG_LOG_STRDUP_MAX_STRING + 1]; /* for termination */ @@ -75,8 +81,25 @@ static uint32_t log_strdup_longest; static struct k_timer log_process_thread_timer; static uint32_t dummy_timestamp(void); -static timestamp_get_t timestamp_func = dummy_timestamp; +log_timestamp_get_t log_timestamp_func = dummy_timestamp; + +struct mpsc_pbuf_buffer log_buffer; +static uint32_t __aligned(Z_LOG_MSG2_ALIGNMENT) + buf32[CONFIG_LOG_BUFFER_SIZE / sizeof(int)]; + +static void notify_drop(struct mpsc_pbuf_buffer *buffer, + union mpsc_pbuf_generic *item) +{ + /* empty for now */ +} +static const struct mpsc_pbuf_buffer_config mpsc_config = { + .buf = (uint32_t *)buf32, + .size = ARRAY_SIZE(buf32), + .notify_drop = notify_drop, + .get_wlen = log_msg2_generic_get_wlen, + .flags = 0 +}; bool log_is_strdup(const void *buf); @@ -396,7 +419,7 @@ void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap, } else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) && (!IS_ENABLED(CONFIG_LOG_FRONTEND))) { struct log_backend const *backend; - uint32_t timestamp = timestamp_func(); + uint32_t timestamp = log_timestamp_func(); for (int i = 0; i < log_backend_count_get(); i++) { backend = log_backend_get(i); @@ -461,7 +484,7 @@ void log_hexdump_sync(struct log_msg_ids src_level, const char *metadata, src_level); } else { struct log_backend const *backend; - uint32_t timestamp = timestamp_func(); + uint32_t timestamp = log_timestamp_func(); for (int i = 0; i < log_backend_count_get(); i++) { backend = log_backend_get(i); @@ -479,7 +502,7 @@ static uint32_t k_cycle_get_32_wrapper(void) { /* * The k_cycle_get_32() is a define which cannot be referenced - * by timestamp_func. Instead, this wrapper is used. + * by log_timestamp_func. Instead, this wrapper is used. */ return k_cycle_get_32(); } @@ -499,10 +522,10 @@ void log_core_init(void) /* Set default timestamp. */ if (sys_clock_hw_cycles_per_sec() > 1000000) { - timestamp_func = k_uptime_get_32; + log_timestamp_func = k_uptime_get_32; freq = 1000U; } else { - timestamp_func = k_cycle_get_32_wrapper; + log_timestamp_func = k_cycle_get_32_wrapper; freq = sys_clock_hw_cycles_per_sec(); } @@ -580,13 +603,13 @@ void log_thread_set(k_tid_t process_tid) } } -int log_set_timestamp_func(timestamp_get_t timestamp_getter, uint32_t freq) +int log_set_timestamp_func(log_timestamp_get_t timestamp_getter, uint32_t freq) { if (timestamp_getter == NULL) { return -EINVAL; } - timestamp_func = timestamp_getter; + log_timestamp_func = timestamp_getter; log_output_timestamp_freq_set(freq); return 0; @@ -1189,6 +1212,72 @@ void log_hexdump_from_user(struct log_msg_ids src_level, const char *metadata, } #endif /* !defined(CONFIG_USERSPACE) */ +void z_log_msg2_init(void) +{ + mpsc_pbuf_init(&log_buffer, &mpsc_config); +} + +static uint32_t log_diff_timestamp(void) +{ + extern log_timestamp_get_t log_timestamp_func; + + return log_timestamp_func(); +} + +void z_log_msg2_put_trace(struct log_msg2_trace trace) +{ + union log_msg2_generic generic = { + .trace = trace + }; + + trace.hdr.timestamp = IS_ENABLED(CONFIG_LOG_TRACE_SHORT_TIMESTAMP) ? + log_diff_timestamp() : log_timestamp_func(); + mpsc_pbuf_put_word(&log_buffer, generic.buf); +} + +void z_log_msg2_put_trace_ptr(struct log_msg2_trace trace, void *data) +{ + union log_msg2_generic generic = { + .trace = trace + }; + + trace.hdr.timestamp = IS_ENABLED(CONFIG_LOG_TRACE_SHORT_TIMESTAMP) ? + log_diff_timestamp() : log_timestamp_func(); + mpsc_pbuf_put_word_ext(&log_buffer, generic.buf, data); +} + +struct log_msg2 *z_log_msg2_alloc(uint32_t wlen) +{ + return (struct log_msg2 *)mpsc_pbuf_alloc(&log_buffer, wlen, + K_MSEC(CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS)); +} + +void z_log_msg2_commit(struct log_msg2 *msg) +{ + msg->hdr.timestamp = log_timestamp_func(); + mpsc_pbuf_commit(&log_buffer, (union mpsc_pbuf_generic *)msg); + + if (IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED)) { + z_log_msg_post_finalize(); + } +} + +union log_msg2_generic *z_log_msg2_claim(void) +{ + return (union log_msg2_generic *)mpsc_pbuf_claim(&log_buffer); +} + +void z_log_msg2_free(union log_msg2_generic *msg) +{ + mpsc_pbuf_free(&log_buffer, (union mpsc_pbuf_generic *)msg); +} + + +bool z_log_msg2_pending(void) +{ + return mpsc_pbuf_is_pending(&log_buffer); +} + static void log_process_thread_timer_expiry_fn(struct k_timer *timer) { k_sem_give(&log_process_thread_sem); diff --git a/subsys/logging/log_msg2.c b/subsys/logging/log_msg2.c new file mode 100644 index 0000000000000..ad80d98393353 --- /dev/null +++ b/subsys/logging/log_msg2.c @@ -0,0 +1,101 @@ +/* + * Copyright (c) 2020 Nordic Semiconductor + * + * SPDX-License-Identifier: Apache-2.0 + */ +#include +#include +#include +#include +#include + +void z_log_msg2_finalize(struct log_msg2 *msg, const void *source, + const struct log_msg2_desc desc, const void *data) +{ + if (!msg) { + z_log_dropped(); + + return; + } + + if (data) { + uint8_t *d = msg->data + desc.package_len; + + memcpy(d, data, desc.data_len); + } + + msg->hdr.desc = desc; + msg->hdr.source = source; + z_log_msg2_commit(msg); +} + +void z_impl_z_log_msg2_static_create(const void *source, + const struct log_msg2_desc desc, + uint8_t *package, const void *data) +{ + uint32_t msg_wlen = log_msg2_get_total_wlen(desc); + struct log_msg2 *msg = z_log_msg2_alloc(msg_wlen); + + if (msg) { + memcpy(msg->data, package, desc.package_len); + } + + z_log_msg2_finalize(msg, source, desc, data); +} + +#ifdef CONFIG_USERSPACE +static inline void z_vrfy_z_log_msg2_static_create(const void *source, + const struct log_msg2_desc desc, + uint8_t *package, const void *data) +{ + return z_impl_z_log_msg2_static_create(source, desc, package, data); +} +#include +#endif + +void z_impl_z_log_msg2_runtime_vcreate(uint8_t domain_id, const void *source, + uint8_t level, const void *data, size_t dlen, + const char *fmt, va_list ap) +{ + int plen; + va_list ap2; + + if (fmt) { + va_copy(ap2, ap); + plen = cbvprintf_package(NULL, Z_LOG_MSG2_ALIGN_OFFSET, + fmt, ap2); + __ASSERT_NO_MSG(plen >= 0); + } else { + plen = 0; + } + + size_t msg_wlen = Z_LOG_MSG2_ALIGNED_WLEN(plen, dlen); + struct log_msg2 *msg; + struct log_msg2_desc desc = + Z_LOG_MSG_DESC_INITIALIZER(domain_id, level, plen, dlen); + + if (IS_ENABLED(CONFIG_LOG2_MODE_IMMEDIATE)) { + msg = alloca(msg_wlen * sizeof(int)); + } else { + msg = z_log_msg2_alloc(msg_wlen); + } + + if (msg && fmt) { + plen = cbvprintf_package(msg->data, plen, fmt, ap); + __ASSERT_NO_MSG(plen >= 0); + } + + z_log_msg2_finalize(msg, source, desc, data); +} + +#ifdef CONFIG_USERSPACE +static inline void z_vrfy_z_log_msg2_runtime_vcreate(uint8_t domain_id, + const void *source, + uint8_t level, const void *data, size_t dlen, + const char *fmt, va_list ap) +{ + return z_impl_z_log_msg2_runtime_vcreate(domain_id, source, level, data, + dlen, fmt, ap); +} +#include +#endif diff --git a/tests/subsys/logging/log_msg/src/log_msg_test.c b/tests/subsys/logging/log_msg/src/log_msg_test.c index fe98a84fbda21..8971dbc1b305e 100644 --- a/tests/subsys/logging/log_msg/src/log_msg_test.c +++ b/tests/subsys/logging/log_msg/src/log_msg_test.c @@ -458,7 +458,6 @@ void test_log_hexdump_data_put_chunks(void) log_msg_put(msg); } - /*test case main entry*/ void test_main(void) { @@ -468,6 +467,7 @@ void test_main(void) ztest_unit_test(test_log_hexdump_data_get_single_chunk), ztest_unit_test(test_log_hexdump_data_get_two_chunks), ztest_unit_test(test_log_hexdump_data_get_multiple_chunks), - ztest_unit_test(test_log_hexdump_data_put_chunks)); + ztest_unit_test(test_log_hexdump_data_put_chunks) + ); ztest_run_test_suite(test_log_message); } From 07e0548c285cd0bf8d25ce689225b1b7ca400d69 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Fri, 4 Dec 2020 09:53:58 +0100 Subject: [PATCH 10/22] logging: log_output: Extend to support log_msg2 parsing Added parsing of log_msg2. Signed-off-by: Krzysztof Chruscinski --- include/logging/log_output.h | 12 +++++ subsys/logging/log_output.c | 98 +++++++++++++++++++++++++++++++++--- 2 files changed, 104 insertions(+), 6 deletions(-) diff --git a/include/logging/log_output.h b/include/logging/log_output.h index 2df6bb979cfbd..474fc18ec2769 100644 --- a/include/logging/log_output.h +++ b/include/logging/log_output.h @@ -109,6 +109,18 @@ void log_output_msg_process(const struct log_output *output, struct log_msg *msg, uint32_t flags); +/** @brief Process log messages v2 to readable strings. + * + * Function is using provided context with the buffer and output function to + * process formatted string and output the data. + * + * @param log_output Pointer to the log output instance. + * @param msg Log message. + * @param flags Optional flags. + */ +void log_output_msg2_process(const struct log_output *log_output, + struct log_msg2 *msg, uint32_t flags); + /** @brief Process log string * * Function is formatting provided string adding optional prefixes and diff --git a/subsys/logging/log_output.c b/subsys/logging/log_output.c index 56f9be3c34391..3a0dfa6f335e6 100644 --- a/subsys/logging/log_output.c +++ b/subsys/logging/log_output.c @@ -117,6 +117,16 @@ static int out_func(int c, void *ctx) return 0; } +static int cr_out_func(int c, void *ctx) +{ + out_func(c, ctx); + if (c == '\n') { + out_func((int)'\r', ctx); + } + + return 0; +} + static int print_formatted(const struct log_output *output, const char *fmt, ...) { @@ -239,7 +249,8 @@ static void color_postfix(const struct log_output *output, static int ids_print(const struct log_output *output, bool level_on, - bool func_on, uint32_t domain_id, uint32_t source_id, uint32_t level) + bool func_on, uint32_t domain_id, int16_t source_id, + uint32_t level) { int total = 0; @@ -247,11 +258,13 @@ static int ids_print(const struct log_output *output, bool level_on, total += print_formatted(output, "<%s> ", severity[level]); } - total += print_formatted(output, + if (source_id >= 0) { + total += print_formatted(output, (func_on && ((1 << level) & LOG_FUNCTION_PREFIX_MASK)) ? "%s." : "%s: ", log_source_name_get(domain_id, source_id)); + } return total; } @@ -427,6 +440,23 @@ static void hexdump_print(struct log_msg *msg, } while (true); } +static void log_msg2_hexdump(const struct log_output *output, + uint8_t *data, uint32_t len, + int prefix_offset, uint32_t flags) +{ + size_t length; + + do { + length = MIN(len, HEXDUMP_BYTES_IN_LINE); + + hexdump_line_print(output, data, length, + prefix_offset, flags); + data += length; + len -= length; + } while (len); +} + + static void raw_string_print(struct log_msg *msg, const struct log_output *output) { @@ -457,7 +487,7 @@ static void raw_string_print(struct log_msg *msg, static uint32_t prefix_print(const struct log_output *output, uint32_t flags, bool func_on, uint32_t timestamp, uint8_t level, - uint8_t domain_id, uint16_t source_id) + uint8_t domain_id, int16_t source_id) { uint32_t length = 0U; @@ -499,6 +529,7 @@ static uint32_t prefix_print(const struct log_output *output, length += ids_print(output, level_on, func_on, domain_id, source_id, level); + return length; } @@ -518,7 +549,7 @@ void log_output_msg_process(const struct log_output *output, uint32_t timestamp = log_msg_timestamp_get(msg); uint8_t level = (uint8_t)log_msg_level_get(msg); uint8_t domain_id = (uint8_t)log_msg_domain_id_get(msg); - uint16_t source_id = (uint16_t)log_msg_source_id_get(msg); + int16_t source_id = (int16_t)log_msg_source_id_get(msg); bool raw_string = (level == LOG_LEVEL_INTERNAL_RAW_STRING); int prefix_offset; @@ -547,6 +578,61 @@ void log_output_msg_process(const struct log_output *output, log_output_flush(output); } +void log_output_msg2_process(const struct log_output *output, + struct log_msg2 *msg, uint32_t flags) +{ + log_timestamp_t timestamp = log_msg2_get_timestamp(msg); + uint8_t level = log_msg2_get_level(msg); + bool raw_string = (level == LOG_LEVEL_INTERNAL_RAW_STRING); + uint32_t prefix_offset; + + if (IS_ENABLED(CONFIG_LOG_MIPI_SYST_ENABLE) && + flags & LOG_OUTPUT_FLAG_FORMAT_SYST) { + __ASSERT_NO_MSG(0); + /* todo not supported + * log_output_msg_syst_process(output, msg, flags); + */ + return; + } + + if (!raw_string) { + void *source = (void *)log_msg2_get_source(msg); + uint8_t domain_id = log_msg2_get_domain(msg); + int16_t source_id = source ? + (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? + log_dynamic_source_id(source) : + log_const_source_id(source)) : + -1; + + prefix_offset = prefix_print(output, flags, 0, timestamp, + level, domain_id, source_id); + } else { + prefix_offset = 0; + } + + size_t len; + uint8_t *data = log_msg2_get_package(msg, &len); + + if (len) { + int err = cbpprintf(raw_string ? cr_out_func : out_func, + (void *)output, data); + + (void)err; + __ASSERT_NO_MSG(err >= 0); + } + + data = log_msg2_get_data(msg, &len); + if (len) { + log_msg2_hexdump(output, data, len, prefix_offset, flags); + } + + if (!raw_string) { + postfix_print(output, flags, level); + } + + log_output_flush(output); +} + static bool ends_with_newline(const char *fmt) { char c = '\0'; @@ -566,7 +652,7 @@ void log_output_string(const struct log_output *output, int length; uint8_t level = (uint8_t)src_level.level; uint8_t domain_id = (uint8_t)src_level.domain_id; - uint16_t source_id = (uint16_t)src_level.source_id; + int16_t source_id = (int16_t)src_level.source_id; bool raw_string = (level == LOG_LEVEL_INTERNAL_RAW_STRING); if (IS_ENABLED(CONFIG_LOG_MIPI_SYST_ENABLE) && @@ -605,7 +691,7 @@ void log_output_hexdump(const struct log_output *output, uint32_t prefix_offset; uint8_t level = (uint8_t)src_level.level; uint8_t domain_id = (uint8_t)src_level.domain_id; - uint16_t source_id = (uint16_t)src_level.source_id; + int16_t source_id = (int16_t)src_level.source_id; if (IS_ENABLED(CONFIG_LOG_MIPI_SYST_ENABLE) && flags & LOG_OUTPUT_FLAG_FORMAT_SYST) { From f381ca831c79eda4ece3a48ee61c1751f5076e47 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Tue, 22 Dec 2020 19:55:11 +0100 Subject: [PATCH 11/22] logging: Adapt logger to support both versions Adapted to be able to switch between v1 and v2. Signed-off-by: Krzysztof Chruscinski --- include/logging/log.h | 18 +- include/logging/log_backend.h | 14 ++ include/logging/log_backend_std.h | 15 ++ include/logging/log_core.h | 131 ++++++++--- include/sys/printk.h | 13 ++ lib/os/printk.c | 12 +- .../logger/src/ext_log_system_adapter.c | 18 +- subsys/logging/Kconfig.backends | 7 + subsys/logging/Kconfig.mode | 19 +- subsys/logging/log_core.c | 204 +++++++++++++----- 10 files changed, 341 insertions(+), 110 deletions(-) diff --git a/include/logging/log.h b/include/logging/log.h index ee1a3ef24bb60..4992308c0b7c8 100644 --- a/include/logging/log.h +++ b/include/logging/log.h @@ -252,9 +252,12 @@ extern "C" { * @param fmt Formatted string to output. * @param ap Variable parameters. */ -void log_printk(const char *fmt, va_list ap); +void z_log_printk(const char *fmt, va_list ap); +static inline void log_printk(const char *fmt, va_list ap) +{ + z_log_printk(fmt, ap); +} -#ifndef CONFIG_LOG_MINIMAL /** @brief Copy transient string to a buffer from internal, logger pool. * * Function should be used when transient string is intended to be logged. @@ -272,14 +275,15 @@ void log_printk(const char *fmt, va_list ap); * a buffer from the pool (see CONFIG_LOG_STRDUP_MAX_STRING). In * some configurations, the original string pointer is returned. */ -char *log_strdup(const char *str); -#else - +char *z_log_strdup(const char *str); static inline char *log_strdup(const char *str) { - return (char *)str; + if (IS_ENABLED(CONFIG_LOG_MINIMAL) || IS_ENABLED(CONFIG_LOG2)) { + return (char *)str; + } + + return z_log_strdup(str); } -#endif /* CONFIG_LOG_MINIMAL */ #ifdef __cplusplus } diff --git a/include/logging/log_backend.h b/include/logging/log_backend.h index 5c6b4ca30aa3d..ed79015424d84 100644 --- a/include/logging/log_backend.h +++ b/include/logging/log_backend.h @@ -7,6 +7,7 @@ #define ZEPHYR_INCLUDE_LOGGING_LOG_BACKEND_H_ #include +#include #include #include #include @@ -29,6 +30,9 @@ struct log_backend; * @brief Logger backend API. */ struct log_backend_api { + void (*process)(const struct log_backend *const backend, + union log_msg2_generic *msg); + void (*put)(const struct log_backend *const backend, struct log_msg *msg); void (*put_sync_string)(const struct log_backend *const backend, @@ -102,6 +106,16 @@ static inline void log_backend_put(const struct log_backend *const backend, backend->api->put(backend, msg); } +static inline void log_backend_msg2_process( + const struct log_backend *const backend, + union log_msg2_generic *msg) +{ + __ASSERT_NO_MSG(backend != NULL); + __ASSERT_NO_MSG(msg != NULL); + backend->api->process(backend, msg); +} + + /** * @brief Synchronously process log message. * diff --git a/include/logging/log_backend_std.h b/include/logging/log_backend_std.h index d681f68f17d7f..6709a35a59ce4 100644 --- a/include/logging/log_backend_std.h +++ b/include/logging/log_backend_std.h @@ -21,6 +21,21 @@ extern "C" { * @{ */ +static inline uint32_t log_backend_std_get_flags(void) +{ + uint32_t flags = (LOG_OUTPUT_FLAG_LEVEL | LOG_OUTPUT_FLAG_TIMESTAMP); + + if (IS_ENABLED(CONFIG_LOG_BACKEND_SHOW_COLOR)) { + flags |= LOG_OUTPUT_FLAG_COLORS; + } + + if (IS_ENABLED(CONFIG_LOG_BACKEND_FORMAT_TIMESTAMP)) { + flags |= LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP; + } + + return flags; +} + /** @brief Put log message to a standard logger backend. * * @param output Log output instance. diff --git a/include/logging/log_core.h b/include/logging/log_core.h index 533106791fb01..10fa16c402898 100644 --- a/include/logging/log_core.h +++ b/include/logging/log_core.h @@ -141,6 +141,7 @@ extern "C" { (0)\ ) + /** * @brief Macro for optional injection of function name as first argument of * formatted string. COND_CODE_0() macro is used to handle no arguments @@ -151,14 +152,22 @@ extern "C" { * argument. In order to handle string with no arguments _LOG_Z_EVAL is * used. */ - -#define Z_LOG_STR(...) "%s: " GET_ARG_N(1, __VA_ARGS__), \ +#define Z_LOG_STR2(...) "%s: " GET_ARG_N(1, __VA_ARGS__), \ (const char *)__func__\ COND_CODE_0(NUM_VA_ARGS_LESS_1(__VA_ARGS__),\ (),\ (, GET_ARGS_LESS_N(1, __VA_ARGS__))\ ) +/** + * @brief Handle optional injection of function name as the first argument. + * + * Additionally, macro is handling the empty message case. + */ +#define Z_LOG_STR(...) \ + COND_CODE_0(NUM_VA_ARGS_LESS_1(_, ##__VA_ARGS__), \ + ("%s", (const char *)__func__), \ + (Z_LOG_STR2(__VA_ARGS__))) /******************************************************************************/ /****************** Internal macros for log frontend **************************/ @@ -259,6 +268,12 @@ void z_log_minimal_printk(const char *fmt, ...); ##__VA_ARGS__); \ } while (false) +#define Z_LOG_TO_VPRINTK(_level, fmt, valist) do { \ + z_log_minimal_printk("%c: ", z_log_minimal_level_to_char(_level)); \ + z_log_minimal_vprintk(fmt, valist); \ + z_log_minimal_printk("\n"); \ +} while (false) + static inline char z_log_minimal_level_to_char(int level) { switch (level) { @@ -274,6 +289,9 @@ static inline char z_log_minimal_level_to_char(int level) return '?'; } } + +#define Z_LOG_INST(_inst) COND_CODE_1(CONFIG_LOG, (_inst), NULL) + /*****************************************************************************/ /****************** Macros for standard logging ******************************/ /*****************************************************************************/ @@ -292,8 +310,14 @@ static inline char z_log_minimal_level_to_char(int level) if (!LOG_CHECK_CTX_LVL_FILTER(is_user_context, _level, filters)) { \ break; \ } \ - \ - Z_LOG_INTERNAL(is_user_context, _level, _source, __VA_ARGS__);\ + if (IS_ENABLED(CONFIG_LOG2)) { \ + int _mode; \ + Z_LOG_MSG2_CREATE(!IS_ENABLED(CONFIG_USERSPACE), _mode, \ + CONFIG_LOG_DOMAIN_ID, _source, _level, NULL,\ + 0, __VA_ARGS__); \ + } else { \ + Z_LOG_INTERNAL(is_user_context, _level, _source, __VA_ARGS__);\ + } \ if (false) { \ /* Arguments checker present but never evaluated.*/ \ /* Placed here to ensure that __VA_ARGS__ are*/ \ @@ -309,7 +333,8 @@ static inline char z_log_minimal_level_to_char(int level) (void *)__log_current_const_data, \ __VA_ARGS__) -#define Z_LOG_INSTANCE(_level, _inst, ...) Z_LOG2(_level, _inst, __VA_ARGS__) +#define Z_LOG_INSTANCE(_level, _inst, ...) \ + Z_LOG2(_level, Z_LOG_INST(_inst), __VA_ARGS__) /*****************************************************************************/ @@ -333,8 +358,19 @@ static inline char z_log_minimal_level_to_char(int level) if (!LOG_CHECK_CTX_LVL_FILTER(is_user_context, _level, filters)) { \ break; \ } \ + if (IS_ENABLED(CONFIG_LOG2)) { \ + int mode; \ + Z_LOG_MSG2_CREATE(!IS_ENABLED(CONFIG_USERSPACE), mode, \ + CONFIG_LOG_DOMAIN_ID, _source, _level, \ + _data, _len, \ + COND_CODE_0(NUM_VA_ARGS_LESS_1(_, ##__VA_ARGS__), \ + (), \ + (COND_CODE_0(NUM_VA_ARGS_LESS_1(__VA_ARGS__), \ + ("%s", __VA_ARGS__), (__VA_ARGS__)))));\ + break; \ + } \ uint16_t src_id = \ - IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \ + IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \ LOG_DYNAMIC_ID_GET(_source) : LOG_CONST_ID_GET(_source);\ struct log_msg_ids src_level = { \ .level = _level, \ @@ -358,7 +394,7 @@ static inline char z_log_minimal_level_to_char(int level) _data, _length, __VA_ARGS__) #define Z_LOG_HEXDUMP_INSTANCE(_level, _inst, _data, _length, _str) \ - Z_LOG_HEXDUMP2(_level, _inst, _data, _length, _str) + Z_LOG_HEXDUMP2(_level, Z_LOG_INST(_inst), _data, _length, _str) /*****************************************************************************/ /****************** Filtering macros *****************************************/ @@ -619,6 +655,21 @@ void log_hexdump_sync(struct log_msg_ids src_level, const char *metadata, void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap, enum log_strdup_action strdup_action); +/** + * @brief Writes a generic log message to the logging v2. + * + * @note This function is intended to be used when porting other log systems. + * + * @param level Log level.. + * @param fmt String to format. + * @param ap Poiner to arguments list. + */ +static inline void log2_generic(uint8_t level, const char *fmt, va_list ap) +{ + z_log_msg2_runtime_vcreate(CONFIG_LOG_DOMAIN_ID, NULL, level, + NULL, 0, fmt, ap); +} + /** * @brief Returns number of arguments visible from format string. * @@ -738,33 +789,45 @@ __syscall void z_log_hexdump_from_user(uint32_t src_level_val, /********* Speed optimized for up to three arguments number. ***************/ /******************************************************************************/ #define Z_LOG_VA(_level, _str, _valist, _argnum, _strdup_action)\ - __LOG_VA(_level, \ - (uint16_t)LOG_CURRENT_MODULE_ID(), \ - LOG_CURRENT_DYNAMIC_DATA_ADDR(), \ - _str, _valist, _argnum, _strdup_action) - -#define __LOG_VA(_level, _id, _filter, _str, _valist, _argnum, _strdup_action) \ - do { \ - if (Z_LOG_CONST_LEVEL_CHECK(_level)) { \ - bool is_user_context = k_is_user_context(); \ - \ - if (IS_ENABLED(CONFIG_LOG_MINIMAL)) { \ - z_log_minimal_printk(_str, _valist); \ - } else if (LOG_CHECK_CTX_LVL_FILTER(is_user_context, \ - _level, _filter)) { \ - struct log_msg_ids src_level = { \ - .level = _level, \ - .domain_id = CONFIG_LOG_DOMAIN_ID, \ - .source_id = _id \ - }; \ - __LOG_INTERNAL_VA(is_user_context, \ - src_level, \ - _str, _valist, _argnum, \ - _strdup_action); \ - } else { \ - } \ - } \ - } while (false) + __LOG_VA(_level, \ + IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \ + (void *)__log_current_dynamic_data : \ + (void *)__log_current_const_data, \ + _str, _valist, _argnum, _strdup_action) + +#define __LOG_VA(_level, _source, _str, _valist, _argnum, _strdup_action) do { \ + if (!Z_LOG_CONST_LEVEL_CHECK(_level)) { \ + break; \ + } \ + if (IS_ENABLED(CONFIG_LOG_MINIMAL)) { \ + Z_LOG_TO_VPRINTK(_level, _str, _valist); \ + break; \ + } \ + \ + bool is_user_context = k_is_user_context(); \ + uint32_t filters = IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \ + ((struct log_source_dynamic_data *)(void *)(_source))->filters : 0;\ + if (!LOG_CHECK_CTX_LVL_FILTER(is_user_context, _level, filters)) { \ + break; \ + } \ + if (IS_ENABLED(CONFIG_LOG2)) { \ + z_log_msg2_runtime_vcreate(CONFIG_LOG_DOMAIN_ID, _source, \ + _level, NULL, 0, _str, _valist); \ + break; \ + } \ + uint16_t _id = \ + IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING) ? \ + LOG_DYNAMIC_ID_GET(_source) : LOG_CONST_ID_GET(_source);\ + struct log_msg_ids src_level = { \ + .level = _level, \ + .domain_id = CONFIG_LOG_DOMAIN_ID, \ + .source_id = _id \ + }; \ + __LOG_INTERNAL_VA(is_user_context, \ + src_level, \ + _str, _valist, _argnum, \ + _strdup_action); \ +} while (false) /** * @brief Inline function to perform strdup, used in __LOG_INTERNAL_VA macro diff --git a/include/sys/printk.h b/include/sys/printk.h index c36a653e228b0..5393337ada296 100644 --- a/include/sys/printk.h +++ b/include/sys/printk.h @@ -45,8 +45,21 @@ extern "C" { * @return N/A */ #ifdef CONFIG_PRINTK + +#if defined(CONFIG_LOG_PRINTK) && defined(CONFIG_LOG2) +#include +#define printk(...) Z_LOG_PRINTK(__VA_ARGS__) +static inline __printf_like(1, 0) void vprintk(const char *fmt, va_list ap) +{ + z_log_msg2_runtime_vcreate(CONFIG_LOG_DOMAIN_ID, NULL, + LOG_LEVEL_INTERNAL_RAW_STRING, NULL, 0, + fmt, ap); +} +#else extern __printf_like(1, 2) void printk(const char *fmt, ...); extern __printf_like(1, 0) void vprintk(const char *fmt, va_list ap); +#endif /* defined(CONFIG_LOG_PRINTK) && defined(CONFIG_LOG) */ + #else static inline __printf_like(1, 2) void printk(const char *fmt, ...) { diff --git a/lib/os/printk.c b/lib/os/printk.c index 36523f20edc09..af14c497f3645 100644 --- a/lib/os/printk.c +++ b/lib/os/printk.c @@ -22,7 +22,8 @@ #include #include -#ifdef CONFIG_PRINTK_SYNC +#if defined(CONFIG_PRINTK_SYNC) && \ + !(defined(CONFIG_LOG_PRINTK) && defined(CONFIG_LOG2)) static struct k_spinlock lock; #endif @@ -76,8 +77,8 @@ void *__printk_get_hook(void) } #endif /* CONFIG_PRINTK */ - -#ifdef CONFIG_PRINTK +#if defined(CONFIG_PRINTK) && \ + !(defined(CONFIG_LOG_PRINTK) && defined(CONFIG_LOG2)) #ifdef CONFIG_USERSPACE struct buf_out_context { int count; @@ -204,6 +205,7 @@ static inline void z_vrfy_k_str_out(char *c, size_t n) * * @return N/A */ + void printk(const char *fmt, ...) { va_list ap; @@ -217,7 +219,9 @@ void printk(const char *fmt, ...) } va_end(ap); } -#endif /* CONFIG_PRINTK */ +#endif /* defined(CONFIG_PRINTK) && \ + * !(defined(CONFIG_LOG_PRINTK) && defined(CONFIG_LOG2)) + */ struct str_context { char *str; diff --git a/samples/subsys/logging/logger/src/ext_log_system_adapter.c b/samples/subsys/logging/logger/src/ext_log_system_adapter.c index 6f863b6c881cb..50ccf2439c906 100644 --- a/samples/subsys/logging/logger/src/ext_log_system_adapter.c +++ b/samples/subsys/logging/logger/src/ext_log_system_adapter.c @@ -24,16 +24,22 @@ static const uint8_t log_level_lut[] = { static void log_handler(enum ext_log_level level, const char *fmt, ...) { - struct log_msg_ids src_level = { - .level = log_level_lut[level], - .domain_id = CONFIG_LOG_DOMAIN_ID, - .source_id = LOG_CURRENT_MODULE_ID() - }; va_list ap; va_start(ap, fmt); - log_generic(src_level, fmt, ap, LOG_STRDUP_CHECK_EXEC); + if (IS_ENABLED(CONFIG_LOG2)) { + log2_generic(log_level_lut[level], fmt, ap); + } else { + struct log_msg_ids src_level = { + .level = log_level_lut[level], + .domain_id = CONFIG_LOG_DOMAIN_ID, + .source_id = LOG_CURRENT_MODULE_ID() + }; + + log_generic(src_level, fmt, ap, LOG_STRDUP_CHECK_EXEC); + } + va_end(ap); } diff --git a/subsys/logging/Kconfig.backends b/subsys/logging/Kconfig.backends index 4cb84d0619b82..27f0f70190831 100644 --- a/subsys/logging/Kconfig.backends +++ b/subsys/logging/Kconfig.backends @@ -20,6 +20,7 @@ config LOG_BACKEND_UART_SYST_ENABLE config LOG_BACKEND_SWO bool "Enable Serial Wire Output (SWO) backend" depends on HAS_SWO + depends on !LOG2 help When enabled, backend will use SWO for logging. @@ -51,6 +52,7 @@ endif # LOG_BACKEND_SWO config LOG_BACKEND_RTT bool "Enable Segger J-Link RTT backend" depends on USE_SEGGER_RTT + depends on !LOG2 default y if !SHELL_BACKEND_RTT help When enabled, backend will use RTT for logging. This backend works on a per @@ -152,6 +154,7 @@ config LOG_BACKEND_SPINEL bool "Enable OpenThread dedicated Spinel protocol backend" depends on (OPENTHREAD_COPROCESSOR_SPINEL_ON_UART_DEV_NAME!=UART_CONSOLE_ON_DEV_NAME || !LOG_BACKEND_UART) depends on NET_L2_OPENTHREAD + depends on !LOG2 help When enabled, backend will use OpenThread dedicated SPINEL protocol for logging. This protocol is byte oriented and wrapps given messages into serial frames. @@ -171,12 +174,14 @@ endif # LOG_BACKEND_SPINEL config LOG_BACKEND_NATIVE_POSIX bool "Enable native backend" depends on ARCH_POSIX + depends on !LOG2 help Enable backend in native_posix config LOG_BACKEND_XTENSA_SIM bool "Enable xtensa simulator backend" depends on SOC_XTENSA_SAMPLE_CONTROLLER || SOC_FAMILY_INTEL_ADSP + depends on !LOG2 help Enable backend in xtensa simulator @@ -192,6 +197,7 @@ config LOG_BACKEND_XTENSA_OUTPUT_BUFFER_SIZE # rsyslog message to be malformed. config LOG_BACKEND_NET bool "Enable networking backend" + depends on !LOG2 depends on NETWORKING && NET_UDP && !LOG_IMMEDIATE select NET_CONTEXT_NET_PKT_POOL help @@ -256,6 +262,7 @@ endif # LOG_BACKEND_NET config LOG_BACKEND_ADSP bool "Enable Intel ADSP buffer backend" depends on SOC_FAMILY_INTEL_ADSP + depends on !LOG2 help Enable backend for the host trace protocol of the Intel ADSP family of audio processors diff --git a/subsys/logging/Kconfig.mode b/subsys/logging/Kconfig.mode index 454fe2dc1bdb5..eee352c3694cf 100644 --- a/subsys/logging/Kconfig.mode +++ b/subsys/logging/Kconfig.mode @@ -12,9 +12,22 @@ config LOG_MODE_DEFERRED least impact on the application. Time consuming processing is deferred to the known context. -config LOG2 +config LOG2_MODE_DEFERRED bool "Deferred logging v2" select MPSC_PBUF + select LOG2 + +config LOG2_MODE_IMMEDIATE + bool "Synchronous v2" + select LOG2 + select MPSC_PBUF + help + When enabled log is processed in the context of the call. It impacts + performance of the system since time consuming operations are + performed in the context of the log entry (e.g. high priority + interrupt).Logger backends must support exclusive access to work + flawlessly in that mode because one log operation can be interrupted + by another one in the higher priority context. config LOG_MODE_IMMEDIATE bool "Synchronous" @@ -48,9 +61,13 @@ config LOG_FRONTEND endchoice +config LOG2 + bool + config LOG_IMMEDIATE bool default y if LOG_MODE_IMMEDIATE + default y if LOG2_MODE_IMMEDIATE config LOG_MINIMAL bool diff --git a/subsys/logging/log_core.c b/subsys/logging/log_core.c index 90839dbb8052f..52057eada8de1 100644 --- a/subsys/logging/log_core.c +++ b/subsys/logging/log_core.c @@ -9,9 +9,11 @@ #include #include #include +#include #include #include #include +#include #include #include #include @@ -53,11 +55,20 @@ LOG_MODULE_REGISTER(log); #define CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS 0 #endif +#ifndef CONFIG_LOG_BUFFER_SIZE +#define CONFIG_LOG_BUFFER_SIZE 4 +#endif + struct log_strdup_buf { atomic_t refcount; char buf[CONFIG_LOG_STRDUP_MAX_STRING + 1]; /* for termination */ } __aligned(sizeof(uintptr_t)); +union log_msgs { + struct log_msg *msg; + union log_msg2_generic *msg2; +}; + #define LOG_STRDUP_POOL_BUFFER_SIZE \ (sizeof(struct log_strdup_buf) * CONFIG_LOG_STRDUP_BUF_COUNT) @@ -80,30 +91,29 @@ static uint32_t log_strdup_max; static uint32_t log_strdup_longest; static struct k_timer log_process_thread_timer; -static uint32_t dummy_timestamp(void); -log_timestamp_get_t log_timestamp_func = dummy_timestamp; +static log_timestamp_t dummy_timestamp(void); +static log_timestamp_get_t timestamp_func = dummy_timestamp; struct mpsc_pbuf_buffer log_buffer; static uint32_t __aligned(Z_LOG_MSG2_ALIGNMENT) buf32[CONFIG_LOG_BUFFER_SIZE / sizeof(int)]; static void notify_drop(struct mpsc_pbuf_buffer *buffer, - union mpsc_pbuf_generic *item) -{ - /* empty for now */ -} + union mpsc_pbuf_generic *item); static const struct mpsc_pbuf_buffer_config mpsc_config = { .buf = (uint32_t *)buf32, .size = ARRAY_SIZE(buf32), .notify_drop = notify_drop, .get_wlen = log_msg2_generic_get_wlen, - .flags = 0 + .flags = IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW) ? + MPSC_PBUF_MODE_OVERWRITE : 0 }; bool log_is_strdup(const void *buf); +static void msg_process(union log_msgs msg, bool bypass); -static uint32_t dummy_timestamp(void) +static log_timestamp_t dummy_timestamp(void) { return 0; } @@ -349,7 +359,7 @@ void log_hexdump(const char *str, const void *data, uint32_t length, } } -void log_printk(const char *fmt, va_list ap) +void z_log_printk(const char *fmt, va_list ap) { if (IS_ENABLED(CONFIG_LOG_PRINTK)) { union { @@ -419,7 +429,7 @@ void log_generic(struct log_msg_ids src_level, const char *fmt, va_list ap, } else if (IS_ENABLED(CONFIG_LOG_IMMEDIATE) && (!IS_ENABLED(CONFIG_LOG_FRONTEND))) { struct log_backend const *backend; - uint32_t timestamp = log_timestamp_func(); + uint32_t timestamp = timestamp_func(); for (int i = 0; i < log_backend_count_get(); i++) { backend = log_backend_get(i); @@ -484,7 +494,7 @@ void log_hexdump_sync(struct log_msg_ids src_level, const char *metadata, src_level); } else { struct log_backend const *backend; - uint32_t timestamp = log_timestamp_func(); + log_timestamp_t timestamp = timestamp_func(); for (int i = 0; i < log_backend_count_get(); i++) { backend = log_backend_get(i); @@ -498,39 +508,50 @@ void log_hexdump_sync(struct log_msg_ids src_level, const char *metadata, } } -static uint32_t k_cycle_get_32_wrapper(void) +static log_timestamp_t default_get_timestamp(void) { - /* - * The k_cycle_get_32() is a define which cannot be referenced - * by log_timestamp_func. Instead, this wrapper is used. - */ - return k_cycle_get_32(); + return IS_ENABLED(CONFIG_LOG_TIMESTAMP_64BIT) ? + sys_clock_tick_get() : k_cycle_get_32(); +} + +static log_timestamp_t default_lf_get_timestamp(void) +{ + return IS_ENABLED(CONFIG_LOG_TIMESTAMP_64BIT) ? + k_uptime_get() : k_uptime_get_32(); } void log_core_init(void) { uint32_t freq; - if (!IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { - log_msg_pool_init(); - log_list_init(&list); - - k_mem_slab_init(&log_strdup_pool, log_strdup_pool_buf, - sizeof(struct log_strdup_buf), - CONFIG_LOG_STRDUP_BUF_COUNT); - } - /* Set default timestamp. */ if (sys_clock_hw_cycles_per_sec() > 1000000) { - log_timestamp_func = k_uptime_get_32; + timestamp_func = default_lf_get_timestamp; freq = 1000U; } else { - log_timestamp_func = k_cycle_get_32_wrapper; + timestamp_func = default_get_timestamp; freq = sys_clock_hw_cycles_per_sec(); } log_output_timestamp_freq_set(freq); + if (IS_ENABLED(CONFIG_LOG2)) { + log_set_timestamp_func(default_get_timestamp, + IS_ENABLED(CONFIG_LOG_TIMESTAMP_64BIT) ? + CONFIG_SYS_CLOCK_TICKS_PER_SEC : + sys_clock_hw_cycles_per_sec()); + if (IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED)) { + z_log_msg2_init(); + } + } else if (IS_ENABLED(CONFIG_LOG_MODE_DEFERRED)) { + log_msg_pool_init(); + log_list_init(&list); + + k_mem_slab_init(&log_strdup_pool, log_strdup_pool_buf, + sizeof(struct log_strdup_buf), + CONFIG_LOG_STRDUP_BUF_COUNT); + } + /* * Initialize aggregated runtime filter levels (no backends are * attached yet, so leave backend slots in each dynamic filter set @@ -609,7 +630,7 @@ int log_set_timestamp_func(log_timestamp_get_t timestamp_getter, uint32_t freq) return -EINVAL; } - log_timestamp_func = timestamp_getter; + timestamp_func = timestamp_getter; log_output_timestamp_freq_set(freq); return 0; @@ -654,46 +675,72 @@ void z_vrfy_log_panic(void) #endif static bool msg_filter_check(struct log_backend const *backend, - struct log_msg *msg) + union log_msgs msg) { - if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) { + if (IS_ENABLED(CONFIG_LOG2) && !z_log_item_is_msg(msg.msg2)) { + return true; + } else if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) { uint32_t backend_level; - uint32_t msg_level; + uint8_t level; + uint8_t domain_id; + int16_t source_id; + + if (IS_ENABLED(CONFIG_LOG2)) { + struct log_msg2 *msg2 = &msg.msg2->log; + struct log_source_dynamic_data *source = (struct log_source_dynamic_data *) + log_msg2_get_source(msg2); - backend_level = log_filter_get(backend, - log_msg_domain_id_get(msg), - log_msg_source_id_get(msg), - true /*enum RUNTIME, COMPILETIME*/); - msg_level = log_msg_level_get(msg); + level = log_msg2_get_level(msg2); + domain_id = log_msg2_get_domain(msg2); + source_id = source ? log_dynamic_source_id(source) : -1; + } else { + level = log_msg_level_get(msg.msg); + domain_id = log_msg_domain_id_get(msg.msg); + source_id = log_msg_source_id_get(msg.msg); + } - return (msg_level <= backend_level); + backend_level = log_filter_get(backend, domain_id, + source_id, true); + + return (level <= backend_level); } else { return true; } } -static void msg_process(struct log_msg *msg, bool bypass) +static void msg_process(union log_msgs msg, bool bypass) { struct log_backend const *backend; if (!bypass) { - if (IS_ENABLED(CONFIG_LOG_DETECT_MISSED_STRDUP) && + if (!IS_ENABLED(CONFIG_LOG2) && + IS_ENABLED(CONFIG_LOG_DETECT_MISSED_STRDUP) && !panic_mode) { - detect_missed_strdup(msg); + detect_missed_strdup(msg.msg); } for (int i = 0; i < log_backend_count_get(); i++) { backend = log_backend_get(i); - if (log_backend_is_active(backend) && msg_filter_check(backend, msg)) { - log_backend_put(backend, msg); + if (IS_ENABLED(CONFIG_LOG2)) { + log_backend_msg2_process(backend, + msg.msg2); + } else { + log_backend_put(backend, msg.msg); + } } } } - log_msg_put(msg); + if (!IS_ENABLED(CONFIG_LOG2_MODE_IMMEDIATE)) { + if (IS_ENABLED(CONFIG_LOG2)) { + z_log_msg2_free(msg.msg2); + } else { + log_msg_put(msg.msg); + } + } } void dropped_notify(void) @@ -709,19 +756,43 @@ void dropped_notify(void) } } +union log_msgs get_msg(void) +{ + union log_msgs msg; + + if (IS_ENABLED(CONFIG_LOG2)) { + msg.msg2 = z_log_msg2_claim(); + + return msg; + } + + int key = irq_lock(); + + msg.msg = log_list_head_get(&list); + irq_unlock(key); + + return msg; +} + +static bool next_pending(void) +{ + if (IS_ENABLED(CONFIG_LOG2)) { + return z_log_msg2_pending(); + } + + return (log_list_head_peek(&list) != NULL); +} + bool z_impl_log_process(bool bypass) { - struct log_msg *msg; + union log_msgs msg; if (!backend_attached && !bypass) { return false; } - unsigned int key = irq_lock(); - msg = log_list_head_get(&list); - irq_unlock(key); - - if (msg != NULL) { + msg = get_msg(); + if (msg.msg) { atomic_dec(&buffered_cnt); msg_process(msg, bypass); } @@ -730,7 +801,7 @@ bool z_impl_log_process(bool bypass) dropped_notify(); } - return (log_list_head_peek(&list) != NULL); + return next_pending(); } #ifdef CONFIG_USERSPACE @@ -766,7 +837,13 @@ uint32_t z_log_dropped_read_and_clear(void) bool z_log_dropped_pending(void) { - return dropped_cnt >= 0; + return dropped_cnt > 0; +} + +static void notify_drop(struct mpsc_pbuf_buffer *buffer, + union mpsc_pbuf_generic *item) +{ + z_log_dropped(); } uint32_t log_src_cnt_get(uint32_t domain_id) @@ -924,7 +1001,7 @@ uint32_t log_filter_get(struct log_backend const *const backend, return log_compiled_level_get(source_id); } -char *log_strdup(const char *str) +char *z_log_strdup(const char *str) { struct log_strdup_buf *dup; int err; @@ -1219,9 +1296,9 @@ void z_log_msg2_init(void) static uint32_t log_diff_timestamp(void) { - extern log_timestamp_get_t log_timestamp_func; + extern log_timestamp_get_t timestamp_func; - return log_timestamp_func(); + return timestamp_func(); } void z_log_msg2_put_trace(struct log_msg2_trace trace) @@ -1231,7 +1308,7 @@ void z_log_msg2_put_trace(struct log_msg2_trace trace) }; trace.hdr.timestamp = IS_ENABLED(CONFIG_LOG_TRACE_SHORT_TIMESTAMP) ? - log_diff_timestamp() : log_timestamp_func(); + log_diff_timestamp() : timestamp_func(); mpsc_pbuf_put_word(&log_buffer, generic.buf); } @@ -1242,7 +1319,7 @@ void z_log_msg2_put_trace_ptr(struct log_msg2_trace trace, void *data) }; trace.hdr.timestamp = IS_ENABLED(CONFIG_LOG_TRACE_SHORT_TIMESTAMP) ? - log_diff_timestamp() : log_timestamp_func(); + log_diff_timestamp() : timestamp_func(); mpsc_pbuf_put_word_ext(&log_buffer, generic.buf, data); } @@ -1254,7 +1331,18 @@ struct log_msg2 *z_log_msg2_alloc(uint32_t wlen) void z_log_msg2_commit(struct log_msg2 *msg) { - msg->hdr.timestamp = log_timestamp_func(); + msg->hdr.timestamp = timestamp_func(); + + if (IS_ENABLED(CONFIG_LOG2_MODE_IMMEDIATE)) { + union log_msgs msgs = { + .msg2 = (union log_msg2_generic *)msg + }; + + msg_process(msgs, false); + + return; + } + mpsc_pbuf_commit(&log_buffer, (union mpsc_pbuf_generic *)msg); if (IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED)) { From 65266bd6d80bd7b2467a7ee7f1f4e29a9f923950 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Mon, 21 Dec 2020 15:32:08 +0100 Subject: [PATCH 12/22] tests: logging: Add test for log_msg2 Added suite for log_msg2 macros. Signed-off-by: Krzysztof Chruscinski --- tests/subsys/logging/log_msg2/CMakeLists.txt | 8 + tests/subsys/logging/log_msg2/prj.conf | 14 + tests/subsys/logging/log_msg2/src/main.c | 588 +++++++++++++++++++ tests/subsys/logging/log_msg2/testcase.yaml | 59 ++ 4 files changed, 669 insertions(+) create mode 100644 tests/subsys/logging/log_msg2/CMakeLists.txt create mode 100644 tests/subsys/logging/log_msg2/prj.conf create mode 100644 tests/subsys/logging/log_msg2/src/main.c create mode 100644 tests/subsys/logging/log_msg2/testcase.yaml diff --git a/tests/subsys/logging/log_msg2/CMakeLists.txt b/tests/subsys/logging/log_msg2/CMakeLists.txt new file mode 100644 index 0000000000000..622a8263e84e5 --- /dev/null +++ b/tests/subsys/logging/log_msg2/CMakeLists.txt @@ -0,0 +1,8 @@ +# SPDX-License-Identifier: Apache-2.0 + +cmake_minimum_required(VERSION 3.13.1) +find_package(Zephyr REQUIRED HINTS $ENV{ZEPHYR_BASE}) +project(log_msg2) + +FILE(GLOB app_sources src/*.c) +target_sources(app PRIVATE ${app_sources}) diff --git a/tests/subsys/logging/log_msg2/prj.conf b/tests/subsys/logging/log_msg2/prj.conf new file mode 100644 index 0000000000000..434184f477665 --- /dev/null +++ b/tests/subsys/logging/log_msg2/prj.conf @@ -0,0 +1,14 @@ +CONFIG_MAIN_THREAD_PRIORITY=5 +CONFIG_ZTEST=y +CONFIG_TEST_LOGGING_DEFAULTS=n +CONFIG_LOG=y +CONFIG_LOG2_MODE_DEFERRED=y +CONFIG_LOG_PRINTK=n +CONFIG_LOG_SPEED=y +CONFIG_LOG_BUFFER_SIZE=1024 +CONFIG_CBPRINTF_FP_SUPPORT=y +CONFIG_CBPRINTF_LIBC_SUBSTS=y +CONFIG_ZTEST_STACKSIZE=4096 +CONFIG_LOG_PROCESS_THREAD=n + +CONFIG_MPSC_CLEAR_ALLOCATED=y diff --git a/tests/subsys/logging/log_msg2/src/main.c b/tests/subsys/logging/log_msg2/src/main.c new file mode 100644 index 0000000000000..8028666c11272 --- /dev/null +++ b/tests/subsys/logging/log_msg2/src/main.c @@ -0,0 +1,588 @@ +/* + * Copyright (c) 2018 Nordic Semiconductor + * + * SPDX-License-Identifier: Apache-2.0 + */ + +/** + * @file + * @brief Test log message + */ + +#include +#include +#include +#include + +#include +#include +#include +#include +#include + +#if defined(__sparc__) || defined(CONFIG_ARCH_POSIX) +/* On some platforms all strings are considered RW, that impacts size of the + * package. + */ +#define TEST_LOG_MSG2_RW_STRINGS 1 +#else +#define TEST_LOG_MSG2_RW_STRINGS 0 +#endif + +#if CONFIG_NO_OPTIMIZATIONS && CONFIG_ARM +#define EXP_MODE(name) Z_LOG_MSG2_MODE_RUNTIME +#else +#define EXP_MODE(name) Z_LOG_MSG2_MODE_##name +#endif + +#define TEST_TIMESTAMP_INIT_VALUE \ + COND_CODE_1(CONFIG_LOG_TIMESTAMP_64BIT, (0x1234123412), (0x11223344)) + +static log_timestamp_t timestamp; + +log_timestamp_t get_timestamp(void) +{ + return timestamp; +} + +static void test_init(void) +{ + timestamp = TEST_TIMESTAMP_INIT_VALUE; + z_log_msg2_init(); + log_set_timestamp_func(get_timestamp, 0); +} + +void print_msg(struct log_msg2 *msg) +{ + printk("-----------------------printing message--------------------\n"); + printk("message %p\n", msg); + printk("package len: %d, data len: %d\n", + msg->hdr.desc.package_len, + msg->hdr.desc.data_len); + for (int i = 0; i < msg->hdr.desc.package_len; i++) { + printk("%02x ", msg->data[i]); + } + printk("\n"); + printk("source: %p\n", msg->hdr.source); + printk("timestamp: %d\n", (int)msg->hdr.timestamp); + printk("-------------------end of printing message-----------------\n"); +} + +struct test_buf { + char *buf; + int idx; +}; + +int out(int c, void *ctx) +{ + struct test_buf *t = ctx; + + t->buf[t->idx++] = c; + + return c; +} + +static void basic_validate(struct log_msg2 *msg, + const struct log_source_const_data *source, + uint8_t domain, uint8_t level, log_timestamp_t t, + const void *data, size_t data_len, char *str) +{ + int rv; + uint8_t *d; + size_t len = 0; + char buf[256]; + struct test_buf tbuf = { .buf = buf, .idx = 0 }; + + zassert_equal(log_msg2_get_source(msg), (void *)source, NULL); + zassert_equal(log_msg2_get_domain(msg), domain, NULL); + zassert_equal(log_msg2_get_level(msg), level, NULL); + zassert_equal(log_msg2_get_timestamp(msg), t, NULL); + + d = log_msg2_get_data(msg, &len); + zassert_equal(len, data_len, NULL); + if (len) { + rv = memcmp(d, data, data_len); + zassert_equal(rv, 0, NULL); + } + + d = log_msg2_get_package(msg, &len); + if (str) { + rv = cbpprintf(out, &tbuf, d); + buf[rv] = '\0'; + zassert_true(rv > 0, NULL); + + rv = strncmp(buf, str, sizeof(buf)); + zassert_equal(rv, 0, "expected:\n%s,\ngot:\n%s", str, buf); + } +} + +union log_msg2_generic *msg_copy_and_free(union log_msg2_generic *msg, + uint8_t *buf, size_t buf_len) +{ + size_t len = sizeof(int) * + log_msg2_generic_get_wlen((union mpsc_pbuf_generic *)msg); + + zassert_true(len < buf_len, NULL); + + memcpy(buf, msg, len); + + z_log_msg2_free(msg); + + return (union log_msg2_generic *)buf; +} + +void validate_base_message_set(const struct log_source_const_data *source, + uint8_t domain, uint8_t level, + log_timestamp_t t, const void *data, + size_t data_len, char *str) +{ + uint8_t __aligned(Z_LOG_MSG2_ALIGNMENT) buf0[256]; + uint8_t __aligned(Z_LOG_MSG2_ALIGNMENT) buf1[256]; + uint8_t __aligned(Z_LOG_MSG2_ALIGNMENT) buf2[256]; + size_t len0, len1, len2; + union log_msg2_generic *msg0, *msg1, *msg2; + + msg0 = z_log_msg2_claim(); + zassert_true(msg0, "Unexpected null message"); + len0 = log_msg2_generic_get_wlen((union mpsc_pbuf_generic *)msg0); + msg0 = msg_copy_and_free(msg0, buf0, sizeof(buf0)); + + msg1 = z_log_msg2_claim(); + zassert_true(msg1, "Unexpected null message"); + len1 = log_msg2_generic_get_wlen((union mpsc_pbuf_generic *)msg1); + msg1 = msg_copy_and_free(msg1, buf1, sizeof(buf1)); + + msg2 = z_log_msg2_claim(); + zassert_true(msg2, "Unexpected null message"); + len2 = log_msg2_generic_get_wlen((union mpsc_pbuf_generic *)msg2); + msg2 = msg_copy_and_free(msg2, buf2, sizeof(buf2)); + + print_msg(&msg0->log); + print_msg(&msg1->log); + print_msg(&msg2->log); + + /* Messages created with static packaging should have same output. + * Runtime created message (msg2) may have strings copied in and thus + * different length. + */ + zassert_equal(len0, len1, NULL); + + int rv = memcmp(msg0, msg1, sizeof(int) * len0); + + zassert_equal(rv, 0, "Unxecpted memcmp result: %d", rv); + + /* msg1 is not validated because it should be the same as msg0. */ + basic_validate(&msg0->log, source, domain, level, + t, data, data_len, str); + basic_validate(&msg2->log, source, domain, level, + t, data, data_len, str); +} + +void test_log_msg2_0_args_msg(void) +{ +#undef TEST_MSG +#define TEST_MSG "0 args" + static const uint8_t domain = 3; + static const uint8_t level = 2; + const void *source = (const void *)123; + int mode; + + test_init(); + printk("Test string:%s\n", TEST_MSG); + + Z_LOG_MSG2_CREATE2(1, mode, 0, domain, source, level, + NULL, 0, TEST_MSG); + zassert_equal(mode, EXP_MODE(ZERO_COPY), NULL); + + Z_LOG_MSG2_CREATE2(0, mode, 0, domain, source, level, + NULL, 0, TEST_MSG); + zassert_equal(mode, EXP_MODE(FROM_STACK), NULL); + + z_log_msg2_runtime_create(domain, source, + level, NULL, 0, TEST_MSG); + + validate_base_message_set(source, domain, level, + TEST_TIMESTAMP_INIT_VALUE, + NULL, 0, TEST_MSG); +} + +void test_log_msg2_various_args(void) +{ +#undef TEST_MSG +#define TEST_MSG "%d %d %lld %p %lld %p" + static const uint8_t domain = 3; + static const uint8_t level = 2; + const void *source = (const void *)123; + int mode; + uint8_t u = 0x45; + signed char s8 = -5; + long long lld = 0x12341234563412; + char str[256]; + static const int iarray[] = {1, 2, 3, 4}; + + test_init(); + printk("Test string:%s\n", TEST_MSG); + + Z_LOG_MSG2_CREATE2(1, mode, 0, domain, source, level, NULL, 0, + TEST_MSG, s8, u, lld, (void *)str, lld, (void *)iarray); + zassert_equal(mode, EXP_MODE(ZERO_COPY), NULL); + + Z_LOG_MSG2_CREATE2(0, mode, 0, domain, source, level, NULL, 0, + TEST_MSG, s8, u, lld, (void *)str, lld, (void *)iarray); + zassert_equal(mode, EXP_MODE(FROM_STACK), NULL); + + z_log_msg2_runtime_create(domain, (void *)source, level, NULL, + 0, TEST_MSG, s8, u, lld, str, lld, iarray); + snprintfcb(str, sizeof(str), TEST_MSG, s8, u, lld, str, lld, iarray); + + validate_base_message_set(source, domain, level, + TEST_TIMESTAMP_INIT_VALUE, + NULL, 0, str); +} + +void test_log_msg2_only_data(void) +{ + static const uint8_t domain = 3; + static const uint8_t level = 2; + const void *source = (const void *)123; + int mode; + static const uint8_t array[] = {1, 2, 3, 4}; + + test_init(); + + Z_LOG_MSG2_CREATE2(1, mode, 0, domain, source, level, array, + sizeof(array)); + zassert_equal(mode, EXP_MODE(FROM_STACK), NULL); + + Z_LOG_MSG2_CREATE2(0, mode, 0, domain, source, level, array, + sizeof(array)); + zassert_equal(mode, EXP_MODE(FROM_STACK), NULL); + + z_log_msg2_runtime_create(domain, (void *)source, level, array, + sizeof(array), NULL); + + validate_base_message_set(source, domain, level, + TEST_TIMESTAMP_INIT_VALUE, + array, sizeof(array), NULL); +} + +void test_log_msg2_string_and_data(void) +{ +#undef TEST_MSG +#define TEST_MSG "test" + + static const uint8_t domain = 3; + static const uint8_t level = 2; + const void *source = (const void *)123; + int mode; + static const uint8_t array[] = {1, 2, 3, 4}; + + test_init(); + + Z_LOG_MSG2_CREATE2(1, mode, 0, domain, source, level, array, + sizeof(array), TEST_MSG); + zassert_equal(mode, EXP_MODE(FROM_STACK), NULL); + + Z_LOG_MSG2_CREATE2(0, mode, 0, domain, source, level, array, + sizeof(array), TEST_MSG); + zassert_equal(mode, EXP_MODE(FROM_STACK), NULL); + + z_log_msg2_runtime_create(domain, (void *)source, level, array, + sizeof(array), TEST_MSG); + + validate_base_message_set(source, domain, level, + TEST_TIMESTAMP_INIT_VALUE, + array, sizeof(array), TEST_MSG); +} + +void test_log_msg2_fp(void) +{ + if (!(IS_ENABLED(CONFIG_CBPRINTF_FP_SUPPORT) && IS_ENABLED(CONFIG_FPU))) { + return; + } + +#undef TEST_MSG +#define TEST_MSG "%d %lld %f %p %f %p" + + static const uint8_t domain = 3; + static const uint8_t level = 2; + const void *source = (const void *)123; + int mode; + long long lli; + float f = 1.234; + double d = 11.3434; + char str[256]; + int i = -100; + + test_init(); + + Z_LOG_MSG2_CREATE2(1, mode, 0, domain, source, level, NULL, 0, + TEST_MSG, i, lli, f, str, d, source); + zassert_equal(mode, EXP_MODE(ZERO_COPY), NULL); + + Z_LOG_MSG2_CREATE2(0, mode, 0, domain, source, level, NULL, 0, + TEST_MSG, i, lli, f, str, d, source); + zassert_equal(mode, EXP_MODE(FROM_STACK), NULL); + + z_log_msg2_runtime_create(domain, (void *)source, level, NULL, 0, + TEST_MSG, i, lli, f, str, d, source); + snprintfcb(str, sizeof(str), TEST_MSG, i, lli, f, str, d, source); + + validate_base_message_set(source, domain, level, + TEST_TIMESTAMP_INIT_VALUE, + NULL, 0, str); +} + +static void get_msg_validate_length(uint32_t exp_len) +{ + uint32_t len; + union log_msg2_generic *msg; + + msg = z_log_msg2_claim(); + len = log_msg2_generic_get_wlen((union mpsc_pbuf_generic *)msg); + + zassert_equal(len, exp_len, "Unexpected message length %d (exp:%d)", + len, exp_len); + + z_log_msg2_free(msg); +} + +void test_mode_size_plain_string(void) +{ + static const uint8_t domain = 3; + static const uint8_t level = 2; + const void *source = (const void *)123; + uint32_t exp_len; + int mode; + + Z_LOG_MSG2_CREATE2(1, mode, 0, domain, source, level, NULL, 0, + "test str"); + zassert_equal(mode, EXP_MODE(ZERO_COPY), + "Unexpected creation mode"); + + Z_LOG_MSG2_CREATE2(0, mode, 0, domain, source, level, NULL, 0, + "test str"); + zassert_equal(mode, EXP_MODE(FROM_STACK), + "Unexpected creation mode"); + + /* Calculate expected message length. Message consists of: + * - header + * - package of plain string header + string pointer + * + * Message size is rounded up to the required alignment. + */ + exp_len = sizeof(struct log_msg2_hdr) + + /* package */2 * sizeof(const char *); + if (mode == Z_LOG_MSG2_MODE_RUNTIME && TEST_LOG_MSG2_RW_STRINGS) { + exp_len += 2 + strlen("test str"); + } + + exp_len = ROUND_UP(exp_len, Z_LOG_MSG2_ALIGNMENT) / sizeof(int); + get_msg_validate_length(exp_len); + get_msg_validate_length(exp_len); +} + +void test_mode_size_data_only(void) +{ + static const uint8_t domain = 3; + static const uint8_t level = 2; + const void *source = (const void *)123; + uint32_t exp_len; + int mode; + /* If data is present then message is created from stack, even though + * _from_stack is 0. + */ + uint8_t data[] = {1, 2, 3}; + + Z_LOG_MSG2_CREATE2(1, mode, 0, domain, source, level, + data, sizeof(data)); + zassert_equal(mode, EXP_MODE(FROM_STACK), + "Unexpected creation mode"); + + /* Calculate expected message length. Message consists of: + * - header + * - data + * + * Message size is rounded up to the required alignment. + */ + exp_len = sizeof(struct log_msg2_hdr) + sizeof(data); + exp_len = ROUND_UP(exp_len, Z_LOG_MSG2_ALIGNMENT) / sizeof(int); + get_msg_validate_length(exp_len); +} + +void test_mode_size_plain_str_data(void) +{ + static const uint8_t domain = 3; + static const uint8_t level = 2; + const void *source = (const void *)123; + uint32_t exp_len; + int mode; + /* If data is present then message is created from stack, even though + * _from_stack is 0. + */ + uint8_t data[] = {1, 2, 3}; + + Z_LOG_MSG2_CREATE2(1, mode, 0, domain, source, level, + data, sizeof(data), "test"); + zassert_equal(mode, EXP_MODE(FROM_STACK), + "Unexpected creation mode"); + + /* Calculate expected message length. Message consists of: + * - header + * - data + * + * Message size is rounded up to the required alignment. + */ + exp_len = sizeof(struct log_msg2_hdr) + sizeof(data) + + /* package */2 * sizeof(char *); + if (mode == Z_LOG_MSG2_MODE_RUNTIME && TEST_LOG_MSG2_RW_STRINGS) { + exp_len += 2 + strlen("test str"); + } + exp_len = ROUND_UP(exp_len, Z_LOG_MSG2_ALIGNMENT) / sizeof(int); + get_msg_validate_length(exp_len); +} + +void test_mode_size_str_with_strings(void) +{ + static const uint8_t domain = 3; + static const uint8_t level = 2; + const void *source = (const void *)123; + uint32_t exp_len; + int mode; + static const char *prefix = "prefix"; + + Z_LOG_MSG2_CREATE2(1, mode, + 1 /* accept one string pointer*/, + domain, source, level, + NULL, 0, "test %s", prefix); + zassert_equal(mode, EXP_MODE(ZERO_COPY), + "Unexpected creation mode"); + Z_LOG_MSG2_CREATE2(0, mode, + 1 /* accept one string pointer*/, + domain, source, level, + NULL, 0, "test %s", prefix); + zassert_equal(mode, EXP_MODE(FROM_STACK), + "Unexpected creation mode"); + + /* Calculate expected message length. Message consists of: + * - header + * - package: header + fmt pointer + pointer + * + * Message size is rounded up to the required alignment. + */ + exp_len = sizeof(struct log_msg2_hdr) + + /* package */3 * sizeof(const char *); + exp_len = ROUND_UP(exp_len, Z_LOG_MSG2_ALIGNMENT) / sizeof(int); + + get_msg_validate_length(exp_len); + get_msg_validate_length(exp_len); +} + +void test_mode_size_str_with_2strings(void) +{ +#undef TEST_STR +#define TEST_STR "%s test %s" + + static const uint8_t domain = 3; + static const uint8_t level = 2; + const void *source = (const void *)123; + uint32_t exp_len; + int mode; + static const char *prefix = "prefix"; + + Z_LOG_MSG2_CREATE2(1, mode, + 1 /* accept one string pointer*/, + domain, source, level, + NULL, 0, TEST_STR, prefix, "sufix"); + zassert_equal(mode, EXP_MODE(RUNTIME), + "Unexpected creation mode"); + Z_LOG_MSG2_CREATE2(0, mode, + 1 /* accept one string pointer*/, + domain, source, level, + NULL, 0, TEST_STR, prefix, "sufix"); + zassert_equal(mode, EXP_MODE(RUNTIME), + "Unexpected creation mode"); + + /* Calculate expected message length. Message consists of: + * - header + * - package: header + fmt pointer + 2 pointers (on some platforms + * strings are included in the package) + * + * Message size is rounded up to the required alignment. + */ + exp_len = sizeof(struct log_msg2_hdr) + + /* package */4 * sizeof(const char *); + if (TEST_LOG_MSG2_RW_STRINGS) { + exp_len += strlen("sufix") + 2 /* null + header */ + + strlen(prefix) + 2 /* null + header */+ + strlen(TEST_STR) + 2 /* null + header */; + } + + exp_len = ROUND_UP(exp_len, Z_LOG_MSG2_ALIGNMENT) / sizeof(int); + + get_msg_validate_length(exp_len); + get_msg_validate_length(exp_len); +} + +static log_timestamp_t timestamp_get_inc(void) +{ + return timestamp++; +} + +void test_saturate(void) +{ + if (IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW)) { + return; + } + + uint32_t exp_len = + ROUND_UP(sizeof(struct log_msg2_hdr) + 2 * sizeof(void *), + Z_LOG_MSG2_ALIGNMENT); + uint32_t exp_capacity = (CONFIG_LOG_BUFFER_SIZE - 1) / exp_len; + int mode; + union log_msg2_generic *msg; + + test_init(); + timestamp = 0; + log_set_timestamp_func(timestamp_get_inc, 0); + + for (int i = 0; i < exp_capacity; i++) { + Z_LOG_MSG2_CREATE2(1, mode, 0, 0, (void *)1, 2, NULL, 0, "test"); + } + + zassert_equal(z_log_dropped_read_and_clear(), 0, "No dropped messages."); + + /* Message should not fit in and be dropped. */ + Z_LOG_MSG2_CREATE2(1, mode, 0, 0, (void *)1, 2, NULL, 0, "test"); + Z_LOG_MSG2_CREATE2(0, mode, 0, 0, (void *)1, 2, NULL, 0, "test"); + z_log_msg2_runtime_create(0, (void *)1, 2, NULL, 0, "test"); + + zassert_equal(z_log_dropped_read_and_clear(), 3, "No dropped messages."); + + for (int i = 0; i < exp_capacity; i++) { + msg = z_log_msg2_claim(); + zassert_equal(log_msg2_get_timestamp(&msg->log), i, + "Unexpected timestamp used for message id"); + } + + msg = z_log_msg2_claim(); + zassert_equal(msg, NULL, "Expected no pending messages"); +} + +/*test case main entry*/ +void test_main(void) +{ + ztest_test_suite(test_log_msg2, + ztest_unit_test(test_log_msg2_0_args_msg), + ztest_unit_test(test_log_msg2_various_args), + ztest_unit_test(test_log_msg2_only_data), + ztest_unit_test(test_log_msg2_string_and_data), + ztest_unit_test(test_log_msg2_fp), + ztest_unit_test(test_mode_size_plain_string), + ztest_unit_test(test_mode_size_data_only), + ztest_unit_test(test_mode_size_plain_str_data), + ztest_unit_test(test_mode_size_str_with_2strings), + ztest_unit_test(test_saturate) + ); + ztest_run_test_suite(test_log_msg2); +} diff --git a/tests/subsys/logging/log_msg2/testcase.yaml b/tests/subsys/logging/log_msg2/testcase.yaml new file mode 100644 index 0000000000000..742d2deb9648b --- /dev/null +++ b/tests/subsys/logging/log_msg2/testcase.yaml @@ -0,0 +1,59 @@ +tests: + logging.log_msg2: + tags: log_msg2 logging + integration_platforms: + - native_posix + platform_allow: > + qemu_arc_em qemu_arc_hs qemu_cortex_a53 qemu_cortex_m0 qemu_cortex_m3 + qemu_cortex_r5 qemu_leon3 qemu_nios2 qemu_riscv32 qemu_riscv64 qemu_x86 + qemu_x86_64 qemu_xtensa native_posix_64 + extra_configs: + - CONFIG_CBPRINTF_COMPLETE=y + + logging.log_msg2_no_overflow: + tags: log_msg2 logging + integration_platforms: + - native_posix + platform_allow: > + qemu_arc_em qemu_arc_hs qemu_cortex_a53 qemu_cortex_m0 qemu_cortex_m3 + qemu_cortex_r5 qemu_leon3 qemu_nios2 qemu_riscv32 qemu_riscv64 qemu_x86 + qemu_x86_64 qemu_xtensa native_posix native_posix_64 + extra_configs: + - CONFIG_LOG_MODE_OVERFLOW=n + + logging.log_msg2_64b_timestamp: + tags: log_msg2 logging + integration_platforms: + - native_posix + platform_allow: > + qemu_arc_em qemu_arc_hs qemu_cortex_a53 qemu_cortex_m0 qemu_cortex_m3 + qemu_cortex_r5 qemu_leon3 qemu_nios2 qemu_riscv32 qemu_riscv64 qemu_x86 + qemu_x86_64 qemu_xtensa native_posix_64 + extra_configs: + - CONFIG_CBPRINTF_COMPLETE=y + - CONFIG_LOG_TIMESTAMP_64BIT=y + + logging.log_msg2_fp: + tags: log_msg2 logging + integration_platforms: + - native_posix + platform_allow: > + qemu_arc_em qemu_arc_hs qemu_cortex_a53 qemu_cortex_m3 qemu_cortex_r5 + qemu_leon3 qemu_nios2 qemu_riscv32 qemu_riscv64 qemu_x86_64 qemu_xtensa + native_posix_64 + extra_configs: + - CONFIG_CBPRINTF_COMPLETE=y + - CONFIG_CBPRINTF_FP_SUPPORT=y + + logging.log_msg2_fp_64b_timestamp: + tags: log_msg2 logging + integration_platforms: + - native_posix + platform_allow: > + qemu_arc_em qemu_arc_hs qemu_cortex_a53 qemu_cortex_m3 qemu_cortex_r5 + qemu_leon3 qemu_nios2 qemu_riscv32 qemu_riscv64 qemu_x86_64 qemu_xtensa + native_posix_64 + extra_configs: + - CONFIG_CBPRINTF_COMPLETE=y + - CONFIG_CBPRINTF_FP_SUPPORT=y + - CONFIG_LOG_TIMESTAMP_64BIT=y From f3949735aa3ab9f95f2f5e01eeaa0d3b26e331df Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Thu, 4 Feb 2021 13:50:16 +0100 Subject: [PATCH 13/22] logging: Add LOG_PRINTK macro for printing via logging Added macro which allows to print formatted string using logging infrastructure. Signed-off-by: Krzysztof Chruscinski --- include/logging/log.h | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/include/logging/log.h b/include/logging/log.h index 4992308c0b7c8..31c22e1a8a69d 100644 --- a/include/logging/log.h +++ b/include/logging/log.h @@ -70,6 +70,17 @@ extern "C" { */ #define LOG_DBG(...) Z_LOG(LOG_LEVEL_DBG, __VA_ARGS__) +/** + * @brief Unconditionally print raw log message. + * + * The result is same as if printk was used but it goes through logging + * infrastructure thus utilizes logging mode, e.g. deferred mode. + * + * @param ... A string optionally containing printk valid conversion specifier, + * followed by as many values as specifiers. + */ +#define LOG_PRINTK(...) Z_LOG_PRINTK(__VA_ARGS__) + /** * @brief Writes an ERROR level message associated with the instance to the log. * From 1e495efb9a8bf00933bf2132ab6d86a6b21dd2c3 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Mon, 29 Mar 2021 13:17:02 +0200 Subject: [PATCH 14/22] tests: logging: Add benchmark test Added test which benchmarks deferred logging v1 and v2. Signed-off-by: Krzysztof Chruscinski --- .../logging/log_benchmark/CMakeLists.txt | 8 + tests/subsys/logging/log_benchmark/prj.conf | 18 ++ tests/subsys/logging/log_benchmark/src/main.c | 260 ++++++++++++++++++ .../logging/log_benchmark/src/test_helpers.c | 61 ++++ .../logging/log_benchmark/src/test_helpers.h | 17 ++ .../logging/log_benchmark/testcase.yaml | 50 ++++ 6 files changed, 414 insertions(+) create mode 100644 tests/subsys/logging/log_benchmark/CMakeLists.txt create mode 100644 tests/subsys/logging/log_benchmark/prj.conf create mode 100644 tests/subsys/logging/log_benchmark/src/main.c create mode 100644 tests/subsys/logging/log_benchmark/src/test_helpers.c create mode 100644 tests/subsys/logging/log_benchmark/src/test_helpers.h create mode 100644 tests/subsys/logging/log_benchmark/testcase.yaml diff --git a/tests/subsys/logging/log_benchmark/CMakeLists.txt b/tests/subsys/logging/log_benchmark/CMakeLists.txt new file mode 100644 index 0000000000000..52e8600940e07 --- /dev/null +++ b/tests/subsys/logging/log_benchmark/CMakeLists.txt @@ -0,0 +1,8 @@ +# SPDX-License-Identifier: Apache-2.0 + +cmake_minimum_required(VERSION 3.13.1) +find_package(Zephyr REQUIRED HINTS $ENV{ZEPHYR_BASE}) +project(log_benchmark) + +FILE(GLOB app_sources src/*.c) +target_sources(app PRIVATE ${app_sources}) diff --git a/tests/subsys/logging/log_benchmark/prj.conf b/tests/subsys/logging/log_benchmark/prj.conf new file mode 100644 index 0000000000000..96b3fe5143b69 --- /dev/null +++ b/tests/subsys/logging/log_benchmark/prj.conf @@ -0,0 +1,18 @@ +CONFIG_MAIN_THREAD_PRIORITY=5 +CONFIG_ZTEST=y +CONFIG_TEST_LOGGING_DEFAULTS=n +CONFIG_LOG=y +CONFIG_LOG_PRINTK=n +CONFIG_LOG_BACKEND_UART=n +CONFIG_LOG_BUFFER_SIZE=2048 +CONFIG_LOG_STRDUP_BUF_COUNT=1 +CONFIG_LOG_STRDUP_MAX_STRING=8 +CONFIG_KERNEL_LOG_LEVEL_OFF=y +CONFIG_SOC_LOG_LEVEL_OFF=y +CONFIG_ARCH_LOG_LEVEL_OFF=y +CONFIG_LOG_FUNC_NAME_PREFIX_DBG=n +CONFIG_LOG_PROCESS_THREAD=n +CONFIG_ASSERT=n +CONFIG_LOG_STRDUP_POOL_PROFILING=y +CONFIG_LOG_TEST_CLEAR_MESSAGE_SPACE=n +CONFIG_APPLICATION_DEFINED_SYSCALL=y diff --git a/tests/subsys/logging/log_benchmark/src/main.c b/tests/subsys/logging/log_benchmark/src/main.c new file mode 100644 index 0000000000000..6d7988c247bad --- /dev/null +++ b/tests/subsys/logging/log_benchmark/src/main.c @@ -0,0 +1,260 @@ +/* + * Copyright (c) 2021 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ + +/** + * @file + * @brief Test log benchmark + * + */ + + +#include +#include +#include +#include +#include +#include +#include +#include "test_helpers.h" + +#define LOG_MODULE_NAME test +LOG_MODULE_REGISTER(LOG_MODULE_NAME); + +#if LOG_BENCHMARK_DETAILED_PRINT +#define DBG_PRINT(...) PRINT(__VA_ARGS__) +#else +#define DBG_PRINT(...) +#endif + +typedef void (*custom_put_callback_t)(struct log_backend const *const backend, + struct log_msg *msg, size_t counter); + +struct backend_cb { + size_t counter; + bool panic; + bool keep_msgs; + bool check_id; + uint32_t exp_id[100]; + bool check_timestamp; + uint32_t exp_timestamps[100]; + bool check_args; + uint32_t exp_nargs[100]; + bool check_strdup; + bool exp_strdup[100]; + custom_put_callback_t callback; + uint32_t total_drops; +}; + +static void put(struct log_backend const *const backend, + struct log_msg *msg) +{ + log_msg_get(msg); + log_msg_put(msg); +} + +static void process(struct log_backend const *const backend, + union log_msg2_generic *msg) +{ +} + +static void panic(struct log_backend const *const backend) +{ + struct backend_cb *cb = (struct backend_cb *)backend->cb->ctx; + + cb->panic = true; +} + +static void dropped(struct log_backend const *const backend, uint32_t cnt) +{ + struct backend_cb *cb = (struct backend_cb *)backend->cb->ctx; + + cb->total_drops += cnt; +} + +const struct log_backend_api log_backend_test_api = { + .put = IS_ENABLED(CONFIG_LOG_MODE_DEFERRED) ? put : NULL, + .process = IS_ENABLED(CONFIG_LOG2) ? process : NULL, + .panic = panic, + .dropped = dropped, +}; + +LOG_BACKEND_DEFINE(backend, log_backend_test_api, false); +struct backend_cb backend_ctrl_blk; + +#define TEST_FORMAT_SPEC(i, _) " %d" +#define TEST_VALUE(i, _), i + +/** @brief Count log messages until first drop. + * + * Report number of messages that fit in the buffer. + * + * @param nargs Number of int arguments in the log message. + */ +#define TEST_LOG_CAPACITY(nargs, inc_cnt, _print) do { \ + int _cnt = 0; \ + test_helpers_log_setup(); \ + while (!test_helpers_log_dropped_pending()) { \ + LOG_ERR("test" UTIL_LISTIFY(nargs, TEST_FORMAT_SPEC) \ + UTIL_LISTIFY(nargs, TEST_VALUE)); \ + _cnt++; \ + } \ + _cnt--; \ + inc_cnt += _cnt; \ + if (_print) { \ + DBG_PRINT("%d log message with %d arguments fit in %d space.\n", \ + _cnt, nargs, CONFIG_LOG_BUFFER_SIZE); \ + } \ +} while (0) + +/** Test how many messages fits in the logging buffer in deferred mode. Test + * serves as the comparison between logging versions. + */ +void test_log_capacity(void) +{ + int total_cnt = 0; + + TEST_LOG_CAPACITY(0, total_cnt, 1); + TEST_LOG_CAPACITY(1, total_cnt, 1); + TEST_LOG_CAPACITY(2, total_cnt, 1); + TEST_LOG_CAPACITY(3, total_cnt, 1); + TEST_LOG_CAPACITY(4, total_cnt, 1); + TEST_LOG_CAPACITY(5, total_cnt, 1); + TEST_LOG_CAPACITY(6, total_cnt, 1); + TEST_LOG_CAPACITY(7, total_cnt, 1); + TEST_LOG_CAPACITY(8, total_cnt, 1); + + PRINT("In total %d message were stored.\n", total_cnt); +} + +#define TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(nargs, inc_time, inc_msg) do { \ + int _msg_cnt = 0; \ + TEST_LOG_CAPACITY(nargs, _msg_cnt, 0); \ + test_helpers_log_setup(); \ + uint32_t cyc = test_helpers_cycle_get(); \ + for (int i = 0; i < _msg_cnt; i++) { \ + LOG_ERR("test" UTIL_LISTIFY(nargs, TEST_FORMAT_SPEC) \ + UTIL_LISTIFY(nargs, TEST_VALUE)); \ + } \ + cyc = test_helpers_cycle_get() - cyc; \ + inc_time += cyc; \ + inc_msg += _msg_cnt; \ + DBG_PRINT("%d arguments message logged in %u cycles (%u us). " \ + "%d message logged in %u cycles.\n", \ + nargs, cyc / _msg_cnt, k_cyc_to_us_ceil32(cyc) / _msg_cnt, \ + _msg_cnt, cyc); \ +} while (0) + +void test_log_message_store_time_no_overwrite(void) +{ + uint32_t total_cyc = 0; + uint32_t total_msg = 0; + + TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(0, total_cyc, total_msg); + TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(1, total_cyc, total_msg); + TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(2, total_cyc, total_msg); + TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(3, total_cyc, total_msg); + TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(4, total_cyc, total_msg); + TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(5, total_cyc, total_msg); + TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(6, total_cyc, total_msg); + TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(7, total_cyc, total_msg); + TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(8, total_cyc, total_msg); + + uint32_t total_us = k_cyc_to_us_ceil32(total_cyc); + + PRINT("%sAvarage logging a message: %u cycles (%u us)\n", + k_is_user_context() ? "USERSPACE: " : "", + total_cyc / total_msg, total_us / total_msg); +} + +#define TEST_LOG_MESSAGE_STORE_OVERFLOW(nargs, _msg_cnt, inc_time, inc_msg) do { \ + int _dummy = 0; \ + /* Saturate buffer. */ \ + TEST_LOG_CAPACITY(nargs, _dummy, 0); \ + uint32_t cyc = test_helpers_cycle_get(); \ + for (int i = 0; i < _msg_cnt; i++) { \ + LOG_ERR("test" UTIL_LISTIFY(nargs, TEST_FORMAT_SPEC) \ + UTIL_LISTIFY(nargs, TEST_VALUE)); \ + } \ + cyc = test_helpers_cycle_get() - cyc; \ + inc_time += cyc; \ + inc_msg += _msg_cnt; \ + DBG_PRINT("%d arguments message logged in %u cycles (%u us). " \ + "%d message logged in %u cycles.\n", \ + nargs, cyc / _msg_cnt, k_cyc_to_us_ceil32(cyc) / _msg_cnt, \ + _msg_cnt, cyc); \ +} while (0) + +void test_log_message_store_time_overwrite(void) +{ + uint32_t total_cyc = 0; + uint32_t total_msg = 0; + + TEST_LOG_MESSAGE_STORE_OVERFLOW(0, 50, total_cyc, total_msg); + TEST_LOG_MESSAGE_STORE_OVERFLOW(1, 50, total_cyc, total_msg); + TEST_LOG_MESSAGE_STORE_OVERFLOW(2, 50, total_cyc, total_msg); + TEST_LOG_MESSAGE_STORE_OVERFLOW(3, 50, total_cyc, total_msg); + TEST_LOG_MESSAGE_STORE_OVERFLOW(4, 50, total_cyc, total_msg); + TEST_LOG_MESSAGE_STORE_OVERFLOW(5, 50, total_cyc, total_msg); + TEST_LOG_MESSAGE_STORE_OVERFLOW(6, 50, total_cyc, total_msg); + TEST_LOG_MESSAGE_STORE_OVERFLOW(7, 50, total_cyc, total_msg); + TEST_LOG_MESSAGE_STORE_OVERFLOW(8, 50, total_cyc, total_msg); + + uint32_t total_us = k_cyc_to_us_ceil32(total_cyc); + + PRINT("Avarage overwrite logging a message: %u cycles (%u us)\n", + total_cyc / total_msg, total_us / total_msg); +} + +void test_log_message_store_time_no_overwrite_from_user(void) +{ + if (!IS_ENABLED(CONFIG_USERSPACE)) { + printk("no userspace\n"); + return; + } + + test_log_message_store_time_no_overwrite(); +} + +void test_log_message_with_string(void) +{ + test_helpers_log_setup(); + char strbuf[] = "test string"; + uint32_t cyc = test_helpers_cycle_get(); + int repeat = 8; + + for (int i = 0; i < repeat; i++) { + LOG_ERR("test with string to duplicate: %s", log_strdup(strbuf)); + } + + cyc = test_helpers_cycle_get() - cyc; + uint32_t us = k_cyc_to_us_ceil32(cyc); + + PRINT("%slogging with transient string %u cycles (%u us).", + k_is_user_context() ? "USERSPACE: " : "", + cyc / repeat, us / repeat); +} + +/*test case main entry*/ +void test_main(void) +{ + PRINT("LOGGING MODE:%s\n", IS_ENABLED(CONFIG_LOG_MODE_DEFERRED) ? "DEFERREDv1" : + (IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED) ? "DEFERREDv2" : + (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? "IMMEDIATEv1" : + "IMMEDIATEv2"))); + PRINT("\tOVERWRITE: %d\n", IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW)); + PRINT("\tBUFFER_SIZE: %d\n", CONFIG_LOG_BUFFER_SIZE); + if (IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED)) { + PRINT("\tSPEED: %d", IS_ENABLED(CONFIG_LOG_SPEED)); + } + ztest_test_suite(test_log_benchmark, + ztest_unit_test(test_log_capacity), + ztest_unit_test(test_log_message_store_time_no_overwrite), + ztest_unit_test(test_log_message_store_time_overwrite), + ztest_user_unit_test(test_log_message_store_time_no_overwrite_from_user), + ztest_user_unit_test(test_log_message_with_string) + ); + ztest_run_test_suite(test_log_benchmark); +} diff --git a/tests/subsys/logging/log_benchmark/src/test_helpers.c b/tests/subsys/logging/log_benchmark/src/test_helpers.c new file mode 100644 index 0000000000000..7834d76c0daca --- /dev/null +++ b/tests/subsys/logging/log_benchmark/src/test_helpers.c @@ -0,0 +1,61 @@ +/* + * Copyright (c) 2021 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#include "test_helpers.h" +#include +#include + + +static log_timestamp_t stamp; + +static log_timestamp_t timestamp_get(void) +{ + return stamp++; +} + +void z_impl_test_helpers_log_setup(void) +{ + stamp = 0; + log_core_init(); + log_init(); + z_log_dropped_read_and_clear(); + + log_set_timestamp_func(timestamp_get, 0); + +} + +#ifdef CONFIG_USERSPACE +static inline void z_vrfy_test_helpers_log_setup(void) +{ + return z_impl_test_helpers_log_setup(); +} +#include +#endif + +int z_impl_test_helpers_cycle_get(void) +{ + return arch_k_cycle_get_32(); +} + +#ifdef CONFIG_USERSPACE +static inline int z_vrfy_test_helpers_cycle_get(void) +{ + return z_impl_test_helpers_cycle_get(); +} +#include +#endif + +bool z_impl_test_helpers_log_dropped_pending(void) +{ + return z_log_dropped_pending(); +} + +#ifdef CONFIG_USERSPACE +static inline bool z_vrfy_test_helpers_log_dropped_pending(void) +{ + return z_impl_test_helpers_log_dropped_pending(); +} +#include +#endif diff --git a/tests/subsys/logging/log_benchmark/src/test_helpers.h b/tests/subsys/logging/log_benchmark/src/test_helpers.h new file mode 100644 index 0000000000000..3dac96584809b --- /dev/null +++ b/tests/subsys/logging/log_benchmark/src/test_helpers.h @@ -0,0 +1,17 @@ +/* + * Copyright (c) 2021 Nordic Semiconductor ASA + * + * SPDX-License-Identifier: Apache-2.0 + */ +#ifndef SRC_TEST_HELPERS_H__ +#define SRC_TEST_HELPERS_H__ + +#include + +__syscall void test_helpers_log_setup(void); +__syscall int test_helpers_cycle_get(void); +__syscall bool test_helpers_log_dropped_pending(void); + +#include + +#endif /* SRC_TEST_HELPERS_H__ */ diff --git a/tests/subsys/logging/log_benchmark/testcase.yaml b/tests/subsys/logging/log_benchmark/testcase.yaml new file mode 100644 index 0000000000000..edd4f7075bc39 --- /dev/null +++ b/tests/subsys/logging/log_benchmark/testcase.yaml @@ -0,0 +1,50 @@ +tests: + logging.log_benchmark_v1: + integration_platforms: + - native_posix + tags: logging + extra_configs: + - CONFIG_CBPRINTF_COMPLETE=y + - CONFIG_LOG_STRDUP_BUF_COUNT=8 + - CONFIG_LOG_STRDUP_MAX_STRING=32 + - CONFIG_LOG_MODE_DEFERRED=y + + logging.log_benchmark_user_v1: + integration_platforms: + - native_posix + tags: logging + platform_allow: qemu_x86 + extra_configs: + - CONFIG_CBPRINTF_COMPLETE=y + - CONFIG_LOG_STRDUP_BUF_COUNT=8 + - CONFIG_LOG_STRDUP_MAX_STRING=32 + - CONFIG_LOG_MODE_DEFERRED=y + - CONFIG_TEST_USERSPACE=y + + logging.log_benchmark_v2: + integration_platforms: + - native_posix + tags: logging + extra_configs: + - CONFIG_CBPRINTF_COMPLETE=y + - CONFIG_LOG2_MODE_DEFERRED=y + + logging.log_benchmark_v2_speed: + integration_platforms: + - native_posix + tags: logging + extra_configs: + - CONFIG_CBPRINTF_COMPLETE=y + - CONFIG_LOG2_MODE_DEFERRED=y + - CONFIG_LOG_SPEED=y + + logging.log_benchmark_user_v2: + integration_platforms: + - native_posix + tags: logging + platform_allow: qemu_x86 + extra_configs: + - CONFIG_CBPRINTF_COMPLETE=y + - CONFIG_CBPRINTF_COMPLETE=y + - CONFIG_LOG2_MODE_DEFERRED=y + - CONFIG_TEST_USERSPACE=y From faef9035517497dcab9929af8072156c95fa3298 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Thu, 1 Apr 2021 14:42:25 +0200 Subject: [PATCH 15/22] doc: logging: Add documentation for logging v2 Extended and refactored logging documentation. Added details about logging v2 and comparison with v1. Signed-off-by: Krzysztof Chruscinski --- doc/reference/logging/index.rst | 487 ++++++++++++++++++++++---------- 1 file changed, 343 insertions(+), 144 deletions(-) diff --git a/doc/reference/logging/index.rst b/doc/reference/logging/index.rst index 87628156a95b0..35abb2585f494 100644 --- a/doc/reference/logging/index.rst +++ b/doc/reference/logging/index.rst @@ -7,13 +7,13 @@ Logging :local: :depth: 2 -The logger API provides a common interface to process messages issued by +The logging API provides a common interface to process messages issued by developers. Messages are passed through a frontend and are then processed by active backends. Custom frontend and backends can be used if needed. Default configuration uses built-in frontend and UART backend. -Summary of logger features: +Summary of the logging features: - Deferred logging reduces the time needed to log a message by shifting time consuming operations to a known context instead of processing and sending @@ -26,13 +26,32 @@ Summary of logger features: - Timestamping with user provided function. - Dedicated API for dumping data. - Dedicated API for handling transient strings. -- Panic support - in panic mode logger switches to blocking, synchronous +- Panic support - in panic mode logging switches to blocking, synchronous processing. -- Printk support - printk message can be redirected to the logger. +- Printk support - printk message can be redirected to the logging. - Design ready for multi-domain/multi-processor system. -Logger API is highly configurable at compile time as well as at run time. Using -Kconfig options (see :ref:`logger_kconfig`) logs can be gradually removed from +Logging v2 introduces following changes: + +- Option to use 64 bit timestamp +- Support for logging floating point variables +- Support for logging variables extending size of a machine word (64 bit values + on 32 bit architectures) +- Remove the need for special treatment of ``%s`` format specifier +- Extend API for dumping data to accept formatted string +- Improve memory utilization. More log messages fit in the logging buffer in + deferred mode. +- Log message is no longer fragmented. It is self-contained block of memory which + simplifies out of domain handling (e.g. offline processing) +- Improved performance when logging from user space +- Improved performance when logging to full buffer and message are dropped. +- Slightly degrade performance in normal circumstances due to the fact that + allocation from ring buffer is more complex than from memslab. +- No change in logging API +- Logging backend API exteded with function for processing v2 messages. + +Logging API is highly configurable at compile time as well as at run time. Using +Kconfig options (see :ref:`logging_kconfig`) logs can be gradually removed from compilation to reduce image size and execution time when logs are not needed. During compilation logs can be filtered out on module basis and severity level. @@ -41,7 +60,7 @@ time filtering is independent for each backend and each source of log messages. Source of log messages can be a module or specific instance of the module. There are four severity levels available in the system: error, warning, info -and debug. For each severity level the logger API (:zephyr_file:`include/logging/log.h`) +and debug. For each severity level the logging API (:zephyr_file:`include/logging/log.h`) has set of dedicated macros. Logger API also has macros for logging data. For each level following set of macros are available: @@ -65,39 +84,45 @@ system, where maximal means lowest severity (e.g. if maximal level in the system is set to info, it means that errors, warnings and info levels are present but debug messages are excluded). -Each module which is using the logger must specify its unique name and -register itself to the logger. If module consists of more than one file, +Each module which is using the logging must specify its unique name and +register itself to the logging. If module consists of more than one file, registration is performed in one file but each file must define a module name. Logger's default frontend is designed to be thread safe and minimizes time needed to log the message. Time consuming operations like string formatting or access to the -transport are not performed by default when logger API is called. When logger +transport are not performed by default when logging API is called. When logging API is called a message is created and added to the list. Dedicated, -configurable pool of log messages is used. There are 2 types of messages: +configurable buffer for pool of log messages is used. There are 2 types of messages: standard and hexdump. Each message contain source ID (module or instance ID and domain ID which might be used for multiprocessor systems), timestamp and -severity level. Standard message contains pointer to the string and 32 bit -arguments. Hexdump message contains copied data. +severity level. Standard message contains pointer to the string and arguments. +Hexdump message contains copied data and string. -.. _logger_kconfig: +.. _logging_kconfig: Global Kconfig Options ********************** These options can be found in the following path :zephyr_file:`subsys/logging/Kconfig`. -:option:`CONFIG_LOG`: Global switch, turns on/off the logger. +:option:`CONFIG_LOG`: Global switch, turns on/off the logging. -:option:`CONFIG_LOG_RUNTIME_FILTERING`: Enables runtime reconfiguration of the -logger. +Mode of operations: -:option:`CONFIG_LOG_MODE_OVERFLOW`: When logger cannot allocate new message -oldest one are discarded. +:option:`CONFIG_LOG_MODE_DEFERRED`: Deferred mode. -:option:`CONFIG_LOG_BLOCK_IN_THREAD`: If enabled and new log message cannot -be allocated thread context will block for up to -:option:`CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS` or until log message is -allocated. +:option:`CONFIG_LOG2_MODE_DEFERRED`: Deferred mode v2. + +:option:`CONFIG_LOG_MODE_IMMEDIATE`: Immediate (synchronous) mode. + +:option:`CONFIG_LOG2_MODE_IMMEDIATE`: Immediate (synchronous) mode v2. + +:option:`CONFIG_LOG_MODE_MINIMAL`: Minimal footprint mode. + +Filtering options: + +:option:`CONFIG_LOG_RUNTIME_FILTERING`: Enables runtime reconfiguration of the +filtering. :option:`CONFIG_LOG_DEFAULT_LEVEL`: Default level, sets the logging level used by modules that are not setting their own logging level. @@ -108,38 +133,33 @@ it is not set or set lower than the override value. :option:`CONFIG_LOG_MAX_LEVEL`: Maximal (lowest severity) level which is compiled in. -:option:`CONFIG_LOG_FUNC_NAME_PREFIX_ERR`: Prepend standard ERROR log messages -with function name. Hexdump messages are not prepended. - -:option:`CONFIG_LOG_FUNC_NAME_PREFIX_WRN`: Prepend standard WARNING log messages -with function name. Hexdump messages are not prepended. +Processing options: -:option:`CONFIG_LOG_FUNC_NAME_PREFIX_INF`: Prepend standard INFO log messages -with function name. Hexdump messages are not prepended. +:option:`CONFIG_LOG_MODE_OVERFLOW`: When new message cannot be allocated, +oldest one are discarded. -:option:`CONFIG_LOG_FUNC_NAME_PREFIX_DBG`: Prepend standard DEBUG log messages -with function name. Hexdump messages are not prepended. +:option:`CONFIG_LOG_BLOCK_IN_THREAD`: If enabled and new log message cannot +be allocated thread context will block for up to +:option:`CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS` or until log message is +allocated. -:option:`CONFIG_LOG_PRINTK`: Redirect printk calls to the logger. +:option:`CONFIG_LOG_PRINTK`: Redirect printk calls to the logging. :option:`CONFIG_LOG_PRINTK_MAX_STRING_LENGTH`: Maximal string length that can be processed by printk. Longer strings are trimmed. -:option:`CONFIG_LOG_IMMEDIATE`: Messages are processed in the context -of the log macro call. Note that it can lead to errors when logger is used in -the interrupt context. - :option:`CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD`: When number of buffered log messages reaches the threshold dedicated thread (see :c:func:`log_thread_set`) is waken up. If :option:`CONFIG_LOG_PROCESS_THREAD` is enabled then this threshold is used by the internal thread. -:option:`CONFIG_LOG_PROCESS_THREAD`: When enabled, logger is creating own thread +:option:`CONFIG_LOG_PROCESS_THREAD`: When enabled, logging thread is created which handles log processing. -:option:`CONFIG_LOG_BUFFER_SIZE`: Number of bytes dedicated for the logger -message pool. Single message capable of storing standard log with up to 3 -arguments or hexdump message with 12 bytes of data take 32 bytes. +:option:`CONFIG_LOG_BUFFER_SIZE`: Number of bytes dedicated for the message pool. +Single message capable of storing standard log with up to 3 arguments or hexdump +message with 12 bytes of data take 32 bytes. In v2 it indicates buffer size +dedicated for circular packet buffer. :option:`CONFIG_LOG_DETECT_MISSED_STRDUP`: Enable detection of missed transient strings handling. @@ -154,7 +174,21 @@ log_strdup(). :option:`CONFIG_LOG_FRONTEND`: Redirect logs to a custom frontend. -:option:`CONFIG_LOG_BACKEND_UART`: Enabled build-in UART backend. +:option:`CONFIG_LOG_TIMESTAMP_64BIT`: 64 bit timestamp. + +Formatting options: + +:option:`CONFIG_LOG_FUNC_NAME_PREFIX_ERR`: Prepend standard ERROR log messages +with function name. Hexdump messages are not prepended. + +:option:`CONFIG_LOG_FUNC_NAME_PREFIX_WRN`: Prepend standard WARNING log messages +with function name. Hexdump messages are not prepended. + +:option:`CONFIG_LOG_FUNC_NAME_PREFIX_INF`: Prepend standard INFO log messages +with function name. Hexdump messages are not prepended. + +:option:`CONFIG_LOG_FUNC_NAME_PREFIX_DBG`: Prepend standard DEBUG log messages +with function name. Hexdump messages are not prepended. :option:`CONFIG_LOG_BACKEND_SHOW_COLOR`: Enables coloring of errors (red) and warnings (yellow). @@ -162,6 +196,10 @@ and warnings (yellow). :option:`CONFIG_LOG_BACKEND_FORMAT_TIMESTAMP`: If enabled timestamp is formatted to *hh:mm:ss:mmm,uuu*. Otherwise is printed in raw format. +Backend options: + +:option:`CONFIG_LOG_BACKEND_UART`: Enabled build-in UART backend. + .. _log_usage: Usage @@ -170,12 +208,11 @@ Usage Logging in a module =================== -In order to use logger in the module, a unique name of a module must be -specified and module must be registered with the logger core using -:c:macro:`LOG_MODULE_REGISTER`. Optionally, a compile time log level for the -module can be specified as the second parameter. Default log level -(:option:`CONFIG_LOG_DEFAULT_LEVEL`) is used if custom log level is not -provided. +In order to use logging in the module, a unique name of a module must be +specified and module must be registered using :c:macro:`LOG_MODULE_REGISTER`. +Optionally, a compile time log level for the module can be specified as the +second parameter. Default log level (:option:`CONFIG_LOG_DEFAULT_LEVEL`) is used +if custom log level is not provided. .. code-block:: c @@ -195,9 +232,9 @@ is used if custom log level is not provided. /* In all files comprising the module but one */ LOG_MODULE_DECLARE(foo, CONFIG_FOO_LOG_LEVEL); -In order to use logger API in a function implemented in a header file +In order to use logging API in a function implemented in a header file :c:macro:`LOG_MODULE_DECLARE` macro must be used in the function body -before logger API is called. Optionally, a compile time log level for the module +before logging API is called. Optionally, a compile time log level for the module can be specified as the second parameter. Default log level (:option:`CONFIG_LOG_DEFAULT_LEVEL`) is used if custom log level is not provided. @@ -235,7 +272,7 @@ level. In that case logging can be enabled for particular instance. In order to use instance level filtering following steps must be performed: -- a pointer to specific logger structure is declared in instance structure. +- a pointer to specific logging structure is declared in instance structure. :c:macro:`LOG_INSTANCE_PTR_DECLARE` is used for that. .. code-block:: c @@ -247,7 +284,7 @@ In order to use instance level filtering following steps must be performed: uint32_t id; } -- module must provide macro for instantiation. In that macro, logger instance +- module must provide macro for instantiation. In that macro, logging instance is registered and log instance pointer is initialized in the object structure. .. code-block:: c @@ -258,7 +295,7 @@ In order to use instance level filtering following steps must be performed: LOG_INSTANCE_PTR_INIT(log, foo, _name) \ } -Note that when logger is disabled logger instance and pointer to that instance +Note that when logging is disabled logging instance and pointer to that instance are not created. In order to use the instance logging API in a source file, a compile-time log @@ -285,17 +322,17 @@ level must be set using :c:macro:`LOG_LEVEL_SET`. LOG_INST_INF(f->log, "Initialized."); } -Controlling the logger -====================== +Controlling the logging +======================= -Logger can be controlled using API defined in +Logging can be controlled using API defined in :zephyr_file:`include/logging/log_ctrl.h`. Logger must be initialized before it can be used. Optionally, user can provide function which returns timestamp value. If not provided, :c:macro:`k_cycle_get_32` is used for timestamping. :c:func:`log_process` function is used to trigger processing of one log message (if pending). Function returns true if there is more messages pending. -Following snippet shows how logger can be processed in simple forever loop. +Following snippet shows how logging can be processed in simple forever loop. .. code-block:: c @@ -312,33 +349,24 @@ Following snippet shows how logger can be processed in simple forever loop. } } -Logger controlling API contains also functions for run time reconfiguration of -the logger. If run time filtering is enabled the :c:func:`log_filter_set` can -be used to change maximal severity level for given module. Module is identified -by source ID and domain ID. Source ID can be retrieved if source name is known -by iterating through all registered sources. - -If logger is processed from a thread then it is possible to enable a feature +If logs are processed from a thread then it is possible to enable a feature which will wake up processing thread when certain amount of log messages are buffered (see :option:`CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD`). It is also -possible to enable internal logger thread (see -:option:`CONFIG_LOG_PROCESS_THREAD`). In that case logger thread is initialized -and log messages are processed implicitly. +possible to enable internal logging thread (see :option:`CONFIG_LOG_PROCESS_THREAD`). +In that case, logging thread is initialized and log messages are processed implicitly. -.. _logger_panic: +.. _logging_panic: -Logger panic -************ +Logging panic +************* In case of error condition system usually can no longer rely on scheduler or interrupts. In that situation deferred log message processing is not an option. Logger controlling API provides a function for entering into panic mode (:c:func:`log_panic`) which should be called in such situation. -When :c:func:`log_panic` is called, logger sends _panic_ notification to -all active backends. It is backend responsibility to react. Backend should -switch to blocking, synchronous mode (stop using interrupts) or disable itself. -Once all backends are notified, logger flushes all buffered messages. Since +When :c:func:`log_panic` is called, _panic_ notification is sent to all active +backends. Once all backends are notified, all buffered messages are flushed. Since that moment all logs are processed in a blocking way. .. _log_architecture: @@ -346,7 +374,7 @@ that moment all logs are processed in a blocking way. Architecture ************ -Logger consists of 3 main parts: +Logging consists of 3 main parts: - Frontend - Core @@ -358,32 +386,106 @@ instance of a module. Default Frontend ================ -Default frontend is engaged when logger API is called in a source of logging (e.g. +Default frontend is engaged when logging API is called in a source of logging (e.g. :c:macro:`LOG_INF`) and is responsible for filtering a message (compile and run -time), allocating buffer for the message, creating the message and putting that -message into the list of pending messages. Since logger API can be called in an -interrupt, frontend is optimized to log the message as fast as possible. Each -log message consists of one or more fixed size chunks. Message head chunk +time), allocating buffer for the message, creating the message and committing that +message. Since logging API can be called in an interrupt, frontend is optimized +to log the message as fast as possible. + +Log message v1 +-------------- + +Each log message consists of one or more fixed size chunks allocated from the +pool of fixed size buffers (:ref:`memory_slabs_v2`). Message head chunk contains log entry details like: source ID, timestamp, severity level and the data (string pointer and arguments or raw data). Message contains also a reference counter which indicates how many users still uses this message. It is used to return message to the pool once last user indicates that it can be freed. If more than 3 arguments or 12 bytes of raw data is used in the log then -log message is formed from multiple chunks which are linked together. - -It may happen that frontend cannot allocate message. It happens if system is +log message is formed from multiple chunks which are linked together. When +message body is filled it is put into the list. +When log processing is triggered, a message is removed from the list of pending +messages. If runtime filtering is disabled, the message is passed to all +active backends, otherwise the message is passed to only those backends that +have requested messages from that particular source (based on the source ID in +the message), and severity level. Once all backends are iterated, the message +is considered processed, but the message may still be in use by a backend. +Because message is allocated from a pool, it is not mandatory to sequentially +free messages. Processing by the backends is asynchronous and memory is freed +when last user indicates that message can be freed. It also means that improper +backend implementation may lead to pool drought. + +Log message v2 +-------------- + +Log message v2 contains message descriptor (source, domain and level), timestamp, +formatted string details (see :ref:`cbprintf_packaging`) and optional data. +Log messages v2 are stored in a continuous block of memory (contrary to v1). +Memory is allocated from a circular packet buffer (:ref:`mpsc_pbuf`). It has +few consequences: + + * Each message is self-contained, continuous block of memory thus it is suited + for copying the message (e.g. for offline processing). + * Memory is better utilized because fixed size chunks are not used. + * Messages must be sequentially freed. Backend processing is synchronous. Backend + can make a copy for deferred processing. + +Log message has following format: + ++------------------+----------------------------------------------------+ +| Message Header | 2 bits: MPSC packet buffer header | +| +----------------------------------------------------+ +| | 1 bit: Trace/Log message flag | +| +----------------------------------------------------+ +| | 3 bits: Domain ID | +| +----------------------------------------------------+ +| | 3 bits: Level | +| +----------------------------------------------------+ +| | 10 bits: Cbprintf Package Length | +| +----------------------------------------------------+ +| | 12 bits: Data length | +| +----------------------------------------------------+ +| | 1 bit: Reserved | +| +----------------------------------------------------+ +| | pointer: Pointer to the source descriptor [#l0]_ | +| +----------------------------------------------------+ +| | 32 or 64 bits: Timestamp [#l0]_ | +| +----------------------------------------------------+ +| | Optional padding [#l1]_ | ++------------------+----------------------------------------------------+ +| Cbprintf | Header | +| +----------------------------------------------------+ +| | package | Arguments | +| | (optional) +----------------------------------------------------+ +| | Appended strings | ++------------------+----------------------------------------------------+ +| Hexdump data (optional) | ++------------------+----------------------------------------------------+ +| Alignment padding (optional) | ++------------------+----------------------------------------------------+ + +.. rubric:: Footnotes + +.. [#l0] Depending on the platform and the timestamp size fields may be swapped. +.. [#l1] It may be required for cbprintf package alignment + +Log message allocation +---------------------- + +It may happen that frontend cannot allocate a message. It happens if system is generating more log messages than it can process in certain time frame. There are two strategies to handle that case: -- Overflow - oldest pending messages are freed, before backends process them, - until new message can be allocated. -- No overflow - new log is dropped if message cannot be allocated. +- No overflow - new log is dropped if space for a message cannot be allocated. +- Overflow - oldest pending messages are freed, until new message can be + allocated. Enabled by :option:`CONFIG_LOG_MODE_OVERFLOW`. Note that it degrades + performance thus it is recommended to adjust buffer size and amount of enabled + logs to limit dropping. + +.. _logging_runtime_filtering: -Second option is simpler however in many case less welcomed. On the other hand, -handling overflows degrades performance of the logger since allocating a -message requires freeing other messages which degrades logger performance. It -is thus recommended to avoid such cases by increasing logger buffer or -filtering out logs. +Run-time filtering +------------------ If run-time filtering is enabled, then for each source of logging a filter structure in RAM is declared. Such filter is using 32 bits divided into ten 3 @@ -391,8 +493,9 @@ bit slots. Except *slot 0*, each slot stores current filter for one backend in the system. *Slot 0* (bits 0-2) is used to aggregate maximal filter setting for given source of logging. Aggregate slot determines if log message is created for given entry since it indicates if there is at least one backend expecting -that log entry. Backend slots are examined when message is process by the -logger core to determine if message is accepted by given backend. +that log entry. Backend slots are examined when message is processed by the core +to determine if message is accepted by the given backend. Contrary to compile +time filtering, binary footprint is increased because logs are compiled in. In the example below backend 1 is set to receive errors (*slot 1*) and backend 2 up to info level (*slot 2*). Slots 3-9 are not used. Aggregated filter @@ -410,32 +513,24 @@ Custom Frontend Custom frontend is enabled using :option:`CONFIG_LOG_FRONTEND`. Logs are redirected to functions declared in :zephyr_file:`include/logging/log_frontend.h`. -This may be required in very time-sensitive cases, but this hurts -logger functionality. All features from default frontend, core and all backends -are not used. +This may be required in very time-sensitive cases, but most of the logging +features cannot be used then, which includes default frontend, core and all +backends features. -Core -==== - -When log processing is triggered, a message is removed from the list of pending -messages. If runtime filtering is disabled, the message is passed to all -active backends, otherwise the message is passed to only those backends that -have requested messages from that particular source (based on the source ID in -the message), and severity level. Once all backends are iterated, the message -is considered processed by the logger, but the message may still be in use by a -backend. - -.. _logger_strings: +.. _logging_strings: Logging strings =============== -Logger stores the address of a log message string argument passed to it. Because -a string variable argument could be transient, allocated on the stack, or -modifiable, logger provides a mechanism and a dedicated buffer pool to hold -copies of strings. The buffer size and count is configurable -(see :option:`CONFIG_LOG_STRDUP_MAX_STRING` and -:option:`CONFIG_LOG_STRDUP_BUF_COUNT`). +Logging v1 +---------- + +Since log message contains only the value of the argument, when ``%s`` is used +only the address of a string is stored. Because a string variable argument could +be transient, allocated on the stack, or modifiable, logger provides a mechanism +and a dedicated buffer pool to hold copies of strings. The buffer size and count +is configurable (see :option:`CONFIG_LOG_STRDUP_MAX_STRING` and +:option:`CONFIG_LOG_STRDUP_BUF_COUNT`). If a string argument is transient, the user must call :c:func:`log_strdup` to duplicate the passed string into a buffer from the pool. See the examples below. @@ -456,16 +551,41 @@ address is not in read only memory section or does not belong to memory pool dedicated to string duplicates. It indictes that :c:func:`log_strdup` is missing in a call to log a message, such as ``LOG_INF``. -Logger backends -=============== +Logging v2 +---------- -Logger supports up to 9 concurrent backends. Logger backend interface consists -of two functions: +String arguments are handled by :ref:`cbprintf_packaging` thus no special action +is required. -- :c:func:`log_backend_put` - backend gets log message. -- :c:func:`log_backend_panic` - on that call backend is notified that it must - switch to panic (synchronous) mode. If backend cannot support synchronous, - interrupt-less operation (e.g. network) it should stop any processing. +Logging backends +================ + +Logging backends are registered using :c:macro:`LOG_BACKEND_DEFINE`. The macro +creates an instance in the dedicated memory section. Backends can be dynamically +enabled (:c:func:`log_backend_enable`) and disabled. When +:ref:`logging_runtime_filtering` is enabled, :c:func:`log_filter_set` can be used +to dynamically change filtering of a module logs for given backend. Module is +identified by source ID and domain ID. Source ID can be retrieved if source name +is known by iterating through all registered sources. + +Logging supports up to 9 concurrent backends. Log message is passed to the +each backend in processing phase. Additionally, backend is notfied when logging +enter panic mode with :c:func:`log_backend_panic`. On that call backend should +switch to synchronous, interrupt-less operation or shut down itself if that is +not supported. Occasionally, logging may inform backend about number of dropped +messages with :c:func:`log_backend_dropped`. Message processing API is version +specific. + +Logging v1 +---------- + +Logging backend interface contains following functions for processing: + +- :c:func:`log_backend_put` - backend gets log message in deferred mode. +- :c:func:`log_backend_put_sync_string` - backend gets log message with formatted + string message in the immediate mode. +- :c:func:`log_backend_put_sync_hexdump` - backend gets log message with hexdump + message in the immediate mode. The log message contains a reference counter tracking how many backends are processing the message. On receiving a message backend must claim it by calling @@ -473,20 +593,12 @@ processing the message. On receiving a message backend must claim it by calling Once message is processed, backend puts back the message (:c:func:`log_msg_put`) decrementing a reference counter. On last :c:func:`log_msg_put`, when reference counter reaches 0, message is returned -to the pool. It is up to the backend how message is processed. If backend -intends to format message into the string, helper function for that are -available in :zephyr_file:`include/logging/log_output.h`. - -Example message formatted using :c:func:`log_output_msg_process`. - -.. code-block:: console - - [00:00:00.000,274] sample_instance.inst1: logging message +to the pool. It is up to the backend how message is processed. .. note:: The message pool can be starved if a backend does not call - :c:func:`log_msg_put` when it is done processing a message. The logger + :c:func:`log_msg_put` when it is done processing a message. The logging core has no means to force messages back to the pool if they're still marked as in use (with a non-zero reference counter). @@ -504,22 +616,109 @@ Example message formatted using :c:func:`log_output_msg_process`. log_msg_put(msg); } -Logger backends are registered to the logger using -:c:macro:`LOG_BACKEND_DEFINE` macro. The macro creates an instance in the -dedicated memory section. Backends can be dynamically enabled -(:c:func:`log_backend_enable`) and disabled. +Logging v2 +---------- + +:c:func:`log_backend_msg2_process` is used for processing message. It is common for +standard and hexdump messages because log message v2 hold string with arguments +and data. It is also common for deferred and immediate logging. + +Message formatting +------------------ + +Logging provides set of function that can be used by the backend to format a +message. Helper functions are available in :zephyr_file:`include/logging/log_output.h`. + +Example message formatted using :c:func:`log_output_msg_process` or +:c:func:`log_output_msg2_process`. + +.. code-block:: console + + [00:00:00.000,274] sample_instance.inst1: logging message + +Limitations and recommendations +******************************* + +Logging v1 +========== -Limitations -*********** +The are following limitations: -The Logger architecture has the following limitations: +* Strings as arguments (*%s*) require special treatment (see + :ref:`logging_strings`). +* Logging double and float variables is not possible because arguments are + word size. +* Variables larger than word size cannot be logged. +* Number of arguments in the string is limited to 15. -- Strings as arguments (*%s*) require special treatment (see - :ref:`logger_strings`). -- Logging double floating point variables is not possible because arguments are - 32 bit values. -- Number of arguments in the string is limited to 9. +Logging v2 +========== + +Solves major limitations of v1. However, in order to get most of the logging +capabilities following recommendations shall be followed: + +* Enable :option:`CONFIG_LOG_SPEED` to slightly speed up deferred logging at the + cost of slight increase in memory footprint. +* Compiler with C11 ``_Generic`` keyword support is recommended. Logging + performance is significantly degraded without it. See :ref:`cbprintf_packaging`. +* When ``_Generic`` is supported, during compilation it is determined which + packaging method shall be used: static or runtime. It is done by searching for + any string pointers in the argument list. If string pointer is used with + format specifier other than string, e.g. ``%p``, it is recommended to cast it + to ``void *``. + +.. code-block:: c + LOG_WRN("%s", str); + LOG_WRN("%p", (void *)str); + +Benchmark +********* + +Benchmark numbers from :zephyr_file:`tests/subsys/logging/log_benchmark` performed +on ``qemu_x86``. It is a rough comparison to give general overview. Overall, +logging v2 improves in most a the areas with the biggest improvement in logging +from userspace. It is at the cost of larger memory footprint for a log message. + ++--------------------------------------------+----------------+------------------+----------------+ +| Feature | v1 | v2 | Summary | ++============================================+================+==================+================+ +| Kernel logging | 7us | 7us [#f0]_/11us | No significant | +| | | | change | ++--------------------------------------------+----------------+------------------+----------------+ +| User logging | 86us | 13us | **Strongly | +| | | | improved** | ++--------------------------------------------+----------------+------------------+----------------+ +| kernel logging with overwrite | 23us | 10us [#f0]_/15us | **Improved** | ++--------------------------------------------+----------------+------------------+----------------+ +| Logging transient string | 16us | 42us | **Degraded** | ++--------------------------------------------+----------------+------------------+----------------+ +| Logging transient string from user | 111us | 50us | **Improved** | ++--------------------------------------------+----------------+------------------+----------------+ +| Memory utilization [#f1]_ | 416 | 518 | Slightly | +| | | | improved | ++--------------------------------------------+----------------+------------------+----------------+ +| Memory footprint (test) [#f2]_ | 3.2k | 2k | **Improved** | ++--------------------------------------------+----------------+------------------+----------------+ +| Memory footprint (application) [#f3]_ | 6.2k | 3.5k | **Improved** | ++--------------------------------------------+----------------+------------------+----------------+ +| Message footprint [#f4]_ | 15 bytes | 47 [#f0]_/32 | **Degraded** | +| | | bytes | | ++--------------------------------------------+----------------+------------------+----------------+ + +.. rubric:: Benchmark details + +.. [#f0] :option:`CONFIG_LOG_SPEED` enabled. + +.. [#f1] Number of log messages with various number of arguments that fits in 2048 + bytes dedicated for logging. + +.. [#f2] Logging subsystem memory footprint in :zephyr_file:`tests/subsys/logging/log_benchmark` + where filtering and formatting features are not used. + +.. [#f3] Logging subsystem memory footprint in :zephyr_file:`samples/subsys/logging/logger`. + +.. [#f4] Avarage size of a log message (excluding string) with 2 arguments on ``Cortex M3`` API Reference ************* From 0a8b760bba8a1caf3e8065627a2bc982b526f23a Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Tue, 22 Dec 2020 19:56:54 +0100 Subject: [PATCH 16/22] logging: backend_uart: Adapt to support v2 api Adapted to handle processing of v2 log messages. Signed-off-by: Krzysztof Chruscinski --- subsys/logging/log_backend_uart.c | 15 ++++++++++++--- 1 file changed, 12 insertions(+), 3 deletions(-) diff --git a/subsys/logging/log_backend_uart.c b/subsys/logging/log_backend_uart.c index 7190ce305384c..0f14595107139 100644 --- a/subsys/logging/log_backend_uart.c +++ b/subsys/logging/log_backend_uart.c @@ -39,6 +39,14 @@ static void put(const struct log_backend *const backend, log_backend_std_put(&log_output_uart, flag, msg); } +static void process(const struct log_backend *const backend, + union log_msg2_generic *msg) +{ + uint32_t flags = log_backend_std_get_flags(); + + log_output_msg2_process(&log_output_uart, &msg->log, flags); +} + static void log_backend_uart_init(struct log_backend const *const backend) { uart_dev = device_get_binding(CONFIG_UART_CONSOLE_ON_DEV_NAME); @@ -80,10 +88,11 @@ static void sync_hexdump(const struct log_backend *const backend, } const struct log_backend_api log_backend_uart_api = { - .put = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? NULL : put, - .put_sync_string = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? + .process = IS_ENABLED(CONFIG_LOG2) ? process : NULL, + .put = IS_ENABLED(CONFIG_LOG_MODE_DEFERRED) ? put : NULL, + .put_sync_string = IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? sync_string : NULL, - .put_sync_hexdump = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? + .put_sync_hexdump = IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? sync_hexdump : NULL, .panic = panic, .init = log_backend_uart_init, From f660c7271a973db89bc2a273ab0ff16d71635747 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Tue, 26 Jan 2021 14:30:51 +0100 Subject: [PATCH 17/22] logging: Add v2 support to native_posix backend Add support for logging v2 to native_posix backend. Signed-off-by: Krzysztof Chruscinski --- subsys/logging/Kconfig.backends | 1 - subsys/logging/log_backend_native_posix.c | 16 +++++++++++++--- 2 files changed, 13 insertions(+), 4 deletions(-) diff --git a/subsys/logging/Kconfig.backends b/subsys/logging/Kconfig.backends index 27f0f70190831..412cf935d8cc9 100644 --- a/subsys/logging/Kconfig.backends +++ b/subsys/logging/Kconfig.backends @@ -174,7 +174,6 @@ endif # LOG_BACKEND_SPINEL config LOG_BACKEND_NATIVE_POSIX bool "Enable native backend" depends on ARCH_POSIX - depends on !LOG2 help Enable backend in native_posix diff --git a/subsys/logging/log_backend_native_posix.c b/subsys/logging/log_backend_native_posix.c index a6d3f56e1177b..18afcadf148b8 100644 --- a/subsys/logging/log_backend_native_posix.c +++ b/subsys/logging/log_backend_native_posix.c @@ -8,6 +8,7 @@ #include #include #include +#include #include #include #include @@ -134,11 +135,20 @@ static void sync_hexdump(const struct log_backend *const backend, irq_unlock(key); } +static void process(const struct log_backend *const backend, + union log_msg2_generic *msg) +{ + uint32_t flags = log_backend_std_get_flags(); + + log_output_msg2_process(&log_output_posix, &msg->log, flags); +} + const struct log_backend_api log_backend_native_posix_api = { - .put = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? NULL : put, - .put_sync_string = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? + .process = IS_ENABLED(CONFIG_LOG2) ? process : NULL, + .put = IS_ENABLED(CONFIG_LOG_MODE_DEFERRED) ? put : NULL, + .put_sync_string = IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? sync_string : NULL, - .put_sync_hexdump = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? + .put_sync_hexdump = IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? sync_hexdump : NULL, .panic = panic, .dropped = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? NULL : dropped, From 70ab8feb8f2c63006298806892f175bef603a6ed Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Wed, 27 Jan 2021 12:56:07 +0100 Subject: [PATCH 18/22] logging: Add v2 support to RTT backend Add support for logging v2 to RTT backend. Signed-off-by: Krzysztof Chruscinski --- subsys/logging/Kconfig.backends | 1 - subsys/logging/log_backend_rtt.c | 15 ++++++++++++--- 2 files changed, 12 insertions(+), 4 deletions(-) diff --git a/subsys/logging/Kconfig.backends b/subsys/logging/Kconfig.backends index 412cf935d8cc9..9a97b00d9eba5 100644 --- a/subsys/logging/Kconfig.backends +++ b/subsys/logging/Kconfig.backends @@ -52,7 +52,6 @@ endif # LOG_BACKEND_SWO config LOG_BACKEND_RTT bool "Enable Segger J-Link RTT backend" depends on USE_SEGGER_RTT - depends on !LOG2 default y if !SHELL_BACKEND_RTT help When enabled, backend will use RTT for logging. This backend works on a per diff --git a/subsys/logging/log_backend_rtt.c b/subsys/logging/log_backend_rtt.c index 7bbbb10455867..3b27b85ae2865 100644 --- a/subsys/logging/log_backend_rtt.c +++ b/subsys/logging/log_backend_rtt.c @@ -295,11 +295,20 @@ static void sync_hexdump(const struct log_backend *const backend, timestamp, metadata, data, length); } +static void process(const struct log_backend *const backend, + union log_msg2_generic *msg) +{ + uint32_t flags = log_backend_std_get_flags(); + + log_output_msg2_process(&log_output_rtt, &msg->log, flags); +} + const struct log_backend_api log_backend_rtt_api = { - .put = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? NULL : put, - .put_sync_string = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? + .process = IS_ENABLED(CONFIG_LOG2) ? process : NULL, + .put = IS_ENABLED(CONFIG_LOG_MODE_DEFERRED) ? put : NULL, + .put_sync_string = IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? sync_string : NULL, - .put_sync_hexdump = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? + .put_sync_hexdump = IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? sync_hexdump : NULL, .panic = panic, .init = log_backend_rtt_init, From 3d00a139ee15cef5fff274fb46344da851d3a644 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Thu, 28 Jan 2021 09:54:16 +0100 Subject: [PATCH 19/22] logging: Adapt ADSP backend to v2 Added support for v2 backend interface to ADSP. Signed-off-by: Krzysztof Chruscinski --- subsys/logging/Kconfig.backends | 1 - subsys/logging/log_backend_adsp.c | 20 +++++++++++++------- 2 files changed, 13 insertions(+), 8 deletions(-) diff --git a/subsys/logging/Kconfig.backends b/subsys/logging/Kconfig.backends index 9a97b00d9eba5..646029c6c0737 100644 --- a/subsys/logging/Kconfig.backends +++ b/subsys/logging/Kconfig.backends @@ -260,7 +260,6 @@ endif # LOG_BACKEND_NET config LOG_BACKEND_ADSP bool "Enable Intel ADSP buffer backend" depends on SOC_FAMILY_INTEL_ADSP - depends on !LOG2 help Enable backend for the host trace protocol of the Intel ADSP family of audio processors diff --git a/subsys/logging/log_backend_adsp.c b/subsys/logging/log_backend_adsp.c index acadd5afa290f..91a57334a34f6 100644 --- a/subsys/logging/log_backend_adsp.c +++ b/subsys/logging/log_backend_adsp.c @@ -70,14 +70,20 @@ static inline void put_sync_hexdump(const struct log_backend *const backend, metadata, data, length, format_flags()); } +static void process(const struct log_backend *const backend, + union log_msg2_generic *msg) +{ + log_output_msg2_process(&log_output_adsp, &msg->log, format_flags()); +} + const struct log_backend_api log_backend_adsp_api = { -#ifdef CONFIG_LOG_IMMEDIATE - .put_sync_string = put_sync_string, - .put_sync_hexdump = put_sync_hexdump, -#else - .put = put, - .dropped = dropped, -#endif + .process = IS_ENABLED(CONFIG_LOG2) ? process : NULL, + .put_sync_string = IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? + put_sync_string : NULL, + .put_sync_hexdump = IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? + put_sync_hexdump : NULL, + .put = IS_ENABLED(CONFIG_LOG_MODE_DEFERRED) ? put : NULL, + .dropped = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? NULL : dropped, .panic = panic, }; From b3bcad5101d724eab3346001b48d83e8dab5caaa Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Fri, 29 Jan 2021 16:34:48 +0100 Subject: [PATCH 20/22] shell: Add support for logging v2 Extended shell to support logging v2. Signed-off-by: Krzysztof Chruscinski --- include/shell/shell_log_backend.h | 43 +++++--- subsys/shell/shell_log_backend.c | 169 +++++++++++++++++++++++++++--- 2 files changed, 184 insertions(+), 28 deletions(-) diff --git a/include/shell/shell_log_backend.h b/include/shell/shell_log_backend.h index cd255c0525e10..b1f87f933b7a0 100644 --- a/include/shell/shell_log_backend.h +++ b/include/shell/shell_log_backend.h @@ -10,6 +10,7 @@ #include #include #include +#include #include #ifdef __cplusplus extern "C" { @@ -38,6 +39,8 @@ struct shell_log_backend { const struct log_output *log_output; struct shell_log_backend_control_block *control_block; uint32_t timeout; + const struct mpsc_pbuf_buffer_config *mpsc_buffer_config; + struct mpsc_pbuf_buffer *mpsc_buffer; }; /** @brief Shell log backend message structure. */ @@ -65,19 +68,33 @@ int z_shell_log_backend_output_func(uint8_t *data, size_t length, void *ctx); * @param _name Shell name. */ #ifdef CONFIG_SHELL_LOG_BACKEND -#define Z_SHELL_LOG_BACKEND_DEFINE(_name, _buf, _size, _queue_size, _timeout) \ - LOG_BACKEND_DEFINE(_name##_backend, log_backend_shell_api, false); \ - K_MSGQ_DEFINE(_name##_msgq, sizeof(struct shell_log_backend_msg), \ - _queue_size, sizeof(void *)); \ - LOG_OUTPUT_DEFINE(_name##_log_output, z_shell_log_backend_output_func, \ - _buf, _size); \ - static struct shell_log_backend_control_block _name##_control_block; \ - static const struct shell_log_backend _name##_log_backend = { \ - .backend = &_name##_backend, \ - .msgq = &_name##_msgq, \ - .log_output = &_name##_log_output, \ - .control_block = &_name##_control_block, \ - .timeout = _timeout \ +#define Z_SHELL_LOG_BACKEND_DEFINE(_name, _buf, _size, _queue_size, _timeout) \ + LOG_BACKEND_DEFINE(_name##_backend, log_backend_shell_api, false); \ + K_MSGQ_DEFINE(_name##_msgq, sizeof(struct shell_log_backend_msg), \ + _queue_size, sizeof(void *)); \ + LOG_OUTPUT_DEFINE(_name##_log_output, z_shell_log_backend_output_func,\ + _buf, _size); \ + static struct shell_log_backend_control_block _name##_control_block; \ + static uint32_t _name##_buf[128]; \ + const struct mpsc_pbuf_buffer_config _name##_mpsc_buffer_config = { \ + .buf = _name##_buf, \ + .size = ARRAY_SIZE(_name##_buf), \ + .notify_drop = NULL, \ + .get_wlen = log_msg2_generic_get_wlen, \ + .flags = MPSC_PBUF_MODE_OVERWRITE, \ + }; \ + struct mpsc_pbuf_buffer _name##_mpsc_buffer; \ + static const struct shell_log_backend _name##_log_backend = { \ + .backend = &_name##_backend, \ + .msgq = IS_ENABLED(CONFIG_LOG_MODE_DEFERRED) ? \ + &_name##_msgq : NULL, \ + .log_output = &_name##_log_output, \ + .control_block = &_name##_control_block, \ + .timeout = _timeout, \ + .mpsc_buffer_config = IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED) ? \ + &_name##_mpsc_buffer_config : NULL, \ + .mpsc_buffer = IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED) ? \ + &_name##_mpsc_buffer : NULL, \ } #define Z_SHELL_LOG_BACKEND_PTR(_name) (&_name##_log_backend) diff --git a/subsys/shell/shell_log_backend.c b/subsys/shell/shell_log_backend.c index 185134dbb5a64..613e00285cf0f 100644 --- a/subsys/shell/shell_log_backend.c +++ b/subsys/shell/shell_log_backend.c @@ -9,6 +9,8 @@ #include "shell_ops.h" #include +static bool process_msg2_from_buffer(const struct shell *shell); + int z_shell_log_backend_output_func(uint8_t *data, size_t length, void *ctx) { z_shell_print_stream(ctx, data, length); @@ -29,6 +31,11 @@ void z_shell_log_backend_enable(const struct shell_log_backend *backend, err = shell->iface->api->enable(shell->iface, true); } + if (IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED)) { + mpsc_pbuf_init(backend->mpsc_buffer, + backend->mpsc_buffer_config); + } + if (err == 0) { log_backend_enable(backend->backend, ctx, init_log_level); log_output_ctx_set(backend->log_output, ctx); @@ -141,16 +148,11 @@ static void msg_process(const struct log_output *log_output, bool z_shell_log_backend_process(const struct shell_log_backend *backend) { - uint32_t dropped; const struct shell *shell = (const struct shell *)backend->backend->cb->ctx; + uint32_t dropped; bool colors = IS_ENABLED(CONFIG_SHELL_VT100_COLORS) && shell->ctx->internal.flags.use_colors; - struct log_msg *msg = msg_from_fifo(backend); - - if (!msg) { - return false; - } dropped = atomic_set(&backend->control_block->dropped_cnt, 0); if (dropped) { @@ -168,6 +170,15 @@ bool z_shell_log_backend_process(const struct shell_log_backend *backend) } } + if (IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED)) { + return process_msg2_from_buffer(shell); + } + + struct log_msg *msg = msg_from_fifo(backend); + + if (!msg) { + return false; + } msg_process(shell->log_backend->log_output, msg, colors); return true; @@ -234,7 +245,8 @@ static void put_sync_string(const struct log_backend *const backend, static void put_sync_hexdump(const struct log_backend *const backend, struct log_msg_ids src_level, uint32_t timestamp, - const char *metadata, const uint8_t *data, uint32_t length) + const char *metadata, const uint8_t *data, + uint32_t length) { const struct shell *shell = (const struct shell *)backend->cb->ctx; uint32_t key; @@ -250,8 +262,8 @@ static void put_sync_hexdump(const struct log_backend *const backend, if (!z_flag_cmd_ctx_get(shell)) { z_shell_cmd_line_erase(shell); } - log_output_hexdump(shell->log_backend->log_output, src_level, timestamp, - metadata, data, length, flags); + log_output_hexdump(shell->log_backend->log_output, src_level, + timestamp, metadata, data, length, flags); if (!z_flag_cmd_ctx_get(shell)) { z_shell_print_prompt_and_cmd(shell); } @@ -271,7 +283,7 @@ static void panic(const struct log_backend *const backend) if (err == 0) { shell->log_backend->control_block->state = - SHELL_LOG_BACKEND_PANIC; + SHELL_LOG_BACKEND_PANIC; /* Move to the start of next line. */ z_shell_multiline_data_calc(&shell->ctx->vt100_ctx.cons, @@ -281,8 +293,15 @@ static void panic(const struct log_backend *const backend) z_shell_op_cursor_horiz_move(shell, -shell->ctx->vt100_ctx.cons.cur_x); - while (z_shell_log_backend_process(shell->log_backend)) { - /* empty */ + if (IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED)) { + while (process_msg2_from_buffer(shell)) { + /* empty */ + } + } else if (IS_ENABLED(CONFIG_LOG_MODE_DEFERRED)) { + while (z_shell_log_backend_process( + shell->log_backend)) { + /* empty */ + } } } else { z_shell_log_backend_disable(shell->log_backend); @@ -298,11 +317,131 @@ static void dropped(const struct log_backend *const backend, uint32_t cnt) atomic_add(&log_backend->control_block->dropped_cnt, cnt); } +static void copy_to_pbuffer(struct mpsc_pbuf_buffer *mpsc_buffer, + union log_msg2_generic *msg, uint32_t timeout) +{ + size_t wlen; + union mpsc_pbuf_generic *dst; + + wlen = log_msg2_generic_get_wlen((union mpsc_pbuf_generic *)msg); + dst = mpsc_pbuf_alloc(mpsc_buffer, wlen, K_MSEC(timeout)); + if (!dst) { + /* No space to store the log */ + return; + } + + /* First word contains intenal mpsc packet flags and when copying + * those flags must be omitted. + */ + uint8_t *dst_data = (uint8_t *)dst + sizeof(struct mpsc_pbuf_hdr); + uint8_t *src_data = (uint8_t *)msg + sizeof(struct mpsc_pbuf_hdr); + size_t hdr_wlen = ceiling_fraction(sizeof(struct mpsc_pbuf_hdr), + sizeof(uint32_t)); + + dst->hdr.data = msg->buf.hdr.data; + memcpy(dst_data, src_data, (wlen - hdr_wlen) * sizeof(uint32_t)); + + mpsc_pbuf_commit(mpsc_buffer, dst); +} + +static void process_log_msg2(const struct shell *shell, + const struct log_output *log_output, + union log_msg2_generic *msg, + bool locked, bool colors) +{ + unsigned int key; + uint32_t flags = LOG_OUTPUT_FLAG_LEVEL | + LOG_OUTPUT_FLAG_TIMESTAMP | + LOG_OUTPUT_FLAG_FORMAT_TIMESTAMP; + + if (colors) { + flags |= LOG_OUTPUT_FLAG_COLORS; + } + + if (locked) { + key = irq_lock(); + if (!z_flag_cmd_ctx_get(shell)) { + z_shell_cmd_line_erase(shell); + } + } + + log_output_msg2_process(log_output, &msg->log, flags); + + if (locked) { + if (!z_flag_cmd_ctx_get(shell)) { + z_shell_print_prompt_and_cmd(shell); + } + irq_unlock(key); + } +} + +static bool process_msg2_from_buffer(const struct shell *shell) +{ + const struct shell_log_backend *log_backend = shell->log_backend; + struct mpsc_pbuf_buffer *mpsc_buffer = log_backend->mpsc_buffer; + const struct log_output *log_output = log_backend->log_output; + union log_msg2_generic *msg; + bool colors = IS_ENABLED(CONFIG_SHELL_VT100_COLORS) && + shell->ctx->internal.flags.use_colors; + + msg = (union log_msg2_generic *)mpsc_pbuf_claim(mpsc_buffer); + if (!msg) { + return false; + } + + process_log_msg2(shell, log_output, msg, false, colors); + + mpsc_pbuf_free(mpsc_buffer, &msg->buf); + + return true; +} + +static void log2_process(const struct log_backend *const backend, + union log_msg2_generic *msg) +{ + const struct shell *shell = (const struct shell *)backend->cb->ctx; + const struct shell_log_backend *log_backend = shell->log_backend; + struct mpsc_pbuf_buffer *mpsc_buffer = log_backend->mpsc_buffer; + const struct log_output *log_output = log_backend->log_output; + bool colors = IS_ENABLED(CONFIG_SHELL_VT100_COLORS) && + shell->ctx->internal.flags.use_colors; + struct k_poll_signal *signal; + + switch (shell->log_backend->control_block->state) { + case SHELL_LOG_BACKEND_ENABLED: + if (IS_ENABLED(CONFIG_LOG_IMMEDIATE)) { + process_log_msg2(shell, log_output, msg, true, colors); + } else { + copy_to_pbuffer(mpsc_buffer, msg, + log_backend->timeout); + + if (IS_ENABLED(CONFIG_MULTITHREADING)) { + signal = + &shell->ctx->signals[SHELL_SIGNAL_LOG_MSG]; + k_poll_signal_raise(signal, 0); + } + } + + break; + case SHELL_LOG_BACKEND_PANIC: + z_shell_cmd_line_erase(shell); + process_log_msg2(shell, log_output, msg, true, colors); + + break; + + case SHELL_LOG_BACKEND_DISABLED: + __fallthrough; + default: + break; + } +} + const struct log_backend_api log_backend_shell_api = { - .put = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? NULL : put, - .put_sync_string = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? + .process = IS_ENABLED(CONFIG_LOG2) ? log2_process : NULL, + .put = IS_ENABLED(CONFIG_LOG_MODE_DEFERRED) ? put : NULL, + .put_sync_string = IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? put_sync_string : NULL, - .put_sync_hexdump = IS_ENABLED(CONFIG_LOG_IMMEDIATE) ? + .put_sync_hexdump = IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? put_sync_hexdump : NULL, .dropped = dropped, .panic = panic, From c074e84d86f3f8bd34109fe349b78ba8facb89a5 Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Tue, 23 Mar 2021 19:00:47 +0100 Subject: [PATCH 21/22] manifest: Temporary point to sof repo with MAX workaround Point to commit which contains temporary fix for sof redefining MAX macro. Signed-off-by: Krzysztof Chruscinski --- west.yml | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/west.yml b/west.yml index 35c8a10f8d4e2..bf306cb7f1582 100644 --- a/west.yml +++ b/west.yml @@ -115,7 +115,8 @@ manifest: revision: 38c79a447e4a47d413b4e8d34448316a5cece77c path: modules/debug/segger - name: sof - revision: b5b772dd611879ee6309da38759def79fc7f33f1 + url: https://github.com/nordic-krch/sof + revision: 2f8ef204454d278f0c189e8c7cc70e84f745561a path: modules/audio/sof - name: tinycbor path: modules/lib/tinycbor From 020624342dae69ee1cb4686aebfcde0263a2ebaf Mon Sep 17 00:00:00 2001 From: Krzysztof Chruscinski Date: Tue, 13 Apr 2021 08:22:01 +0200 Subject: [PATCH 22/22] net: lib: openthread: logging: Refactor logging function Refactor logging function to avoid multiple macro calls. Signed-off-by: Krzysztof Chruscinski --- subsys/net/lib/openthread/platform/logging.c | 46 +++++++++++--------- 1 file changed, 25 insertions(+), 21 deletions(-) diff --git a/subsys/net/lib/openthread/platform/logging.c b/subsys/net/lib/openthread/platform/logging.c index cd47ba8e7968f..b7d904872e209 100644 --- a/subsys/net/lib/openthread/platform/logging.c +++ b/subsys/net/lib/openthread/platform/logging.c @@ -18,6 +18,25 @@ LOG_MODULE_REGISTER(LOG_MODULE_NAME); #include "platform-zephyr.h" +/* Convert OT log level to zephyr log level. */ +static inline int log_translate(otLogLevel aLogLevel) +{ + switch (aLogLevel) { + case OT_LOG_LEVEL_CRIT: + return LOG_LEVEL_ERR; + case OT_LOG_LEVEL_WARN: + return LOG_LEVEL_WRN; + case OT_LOG_LEVEL_NOTE: + case OT_LOG_LEVEL_INFO: + return LOG_LEVEL_INF; + case OT_LOG_LEVEL_DEBG: + return LOG_LEVEL_DBG; + default: + break; + } + + return -1; +} void otPlatLog(otLogLevel aLogLevel, otLogRegion aLogRegion, const char *aFormat, ...) @@ -47,6 +66,11 @@ void otPlatLog(otLogLevel aLogLevel, otLogRegion aLogRegion, #endif va_list param_list; + int level = log_translate(aLogLevel); + + if (level < 0) { + return; + } va_start(param_list, aFormat); @@ -55,26 +79,6 @@ void otPlatLog(otLogLevel aLogLevel, otLogRegion aLogRegion, * been duplicated. So, to save time, in Z_LOG_VA macro calls * we will use LOG_STRDUP_EXEC option. */ - switch (aLogLevel) { - case OT_LOG_LEVEL_CRIT: - Z_LOG_VA(LOG_LEVEL_ERR, aFormat, param_list, args_num, - LOG_STRDUP_EXEC); - break; - case OT_LOG_LEVEL_WARN: - Z_LOG_VA(LOG_LEVEL_WRN, aFormat, param_list, args_num, - LOG_STRDUP_EXEC); - break; - case OT_LOG_LEVEL_NOTE: - case OT_LOG_LEVEL_INFO: - Z_LOG_VA(LOG_LEVEL_INF, aFormat, param_list, args_num, - LOG_STRDUP_EXEC); - break; - case OT_LOG_LEVEL_DEBG: - Z_LOG_VA(LOG_LEVEL_DBG, aFormat, param_list, args_num, - LOG_STRDUP_EXEC); - break; - default: - break; - } + Z_LOG_VA(level, aFormat, param_list, args_num, LOG_STRDUP_EXEC); va_end(param_list); }