diff --git a/include/logging/log.h b/include/logging/log.h index ee1a3ef24bb..4992308c0b7 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 5c6b4ca30aa..ed79015424d 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 d681f68f17d..6709a35a59c 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 533106791fb..10fa16c4028 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) + __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, _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) +#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 c36a653e228..5393337ada2 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 36523f20edc..af14c497f36 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 6f863b6c881..50ccf2439c9 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 4cb84d0619b..27f0f701908 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 454fe2dc1bd..eee352c3694 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 90839dbb805..52057eada8d 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,20 +508,42 @@ 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)) { + /* Set default timestamp. */ + if (sys_clock_hw_cycles_per_sec() > 1000000) { + timestamp_func = default_lf_get_timestamp; + freq = 1000U; + } else { + 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); @@ -520,17 +552,6 @@ void log_core_init(void) CONFIG_LOG_STRDUP_BUF_COUNT); } - /* Set default timestamp. */ - if (sys_clock_hw_cycles_per_sec() > 1000000) { - log_timestamp_func = k_uptime_get_32; - freq = 1000U; - } else { - log_timestamp_func = k_cycle_get_32_wrapper; - freq = sys_clock_hw_cycles_per_sec(); - } - - log_output_timestamp_freq_set(freq); - /* * 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)) {