diff --git a/include/logging/log_core.h b/include/logging/log_core.h index ebc35c09165..669e2f6d733 100644 --- a/include/logging/log_core.h +++ b/include/logging/log_core.h @@ -543,6 +543,21 @@ bool log_is_strdup(void *buf); */ void log_free(void *buf); +/** + * @brief Get maximal number of simultaneously allocated buffers for string + * duplicates. + * + * Value can be used to determine pool size. + */ +u32_t log_get_strdup_pool_utilization(void); + +/** + * @brief Get length of the longest string duplicated. + * + * Value can be used to determine buffer size in the string duplicates pool. + */ +u32_t log_get_strdup_longest_string(void); + /** @brief Indicate to the log core that one log message has been dropped. */ void log_dropped(void); diff --git a/subsys/logging/Kconfig b/subsys/logging/Kconfig index 3cdc8465f0c..d178f364141 100644 --- a/subsys/logging/Kconfig +++ b/subsys/logging/Kconfig @@ -192,6 +192,12 @@ config LOG_STRDUP_BUF_COUNT Each entry takes CONFIG_LOG_STRDUP_MAX_STRING bytes of memory plus some additional fixed overhead. +config LOG_STRDUP_POOL_PROFILING + bool "Enable profiling of pool used for log_strdup()" + help + When enabled, maximal utilization of the pool is tracked. It can + be read out using shell command. + endif # !LOG_IMMEDIATE config LOG_DOMAIN_ID diff --git a/subsys/logging/log_cmds.c b/subsys/logging/log_cmds.c index 87148064743..4f5ccc5894f 100644 --- a/subsys/logging/log_cmds.c +++ b/subsys/logging/log_cmds.c @@ -363,6 +363,44 @@ static int cmd_log_backends_list(const struct shell *shell, return 0; } +static int cmd_log_strdup_utilization(const struct shell *shell, + size_t argc, char **argv) +{ + + /* Defines needed when string duplication is disabled (LOG_IMMEDIATE is + * on). In that case, this function is not compiled in. + */ + #ifndef CONFIG_LOG_STRDUP_BUF_COUNT + #define CONFIG_LOG_STRDUP_BUF_COUNT 0 + #endif + + #ifndef CONFIG_LOG_STRDUP_MAX_STRING + #define CONFIG_LOG_STRDUP_MAX_STRING 0 + #endif + + u32_t buf_cnt = log_get_strdup_pool_utilization(); + u32_t buf_size = log_get_strdup_longest_string(); + u32_t percent = CONFIG_LOG_STRDUP_BUF_COUNT ? + 100 * buf_cnt / CONFIG_LOG_STRDUP_BUF_COUNT : 0; + + shell_print(shell, + "Maximal utilization of the buffer pool: %d / %d (%d %%).", + buf_cnt, CONFIG_LOG_STRDUP_BUF_COUNT, percent); + if (buf_cnt == CONFIG_LOG_STRDUP_BUF_COUNT) { + shell_warn(shell, "Buffer count too small."); + } + + shell_print(shell, + "Longest duplicated string: %d, buffer capacity: %d.", + buf_size, CONFIG_LOG_STRDUP_MAX_STRING); + if (buf_size > CONFIG_LOG_STRDUP_MAX_STRING) { + shell_warn(shell, "Buffer size too small."); + + } + + return 0; +} + SHELL_STATIC_SUBCMD_SET_CREATE(sub_log_backend, SHELL_CMD_ARG(disable, &dsub_module_name, @@ -413,6 +451,9 @@ SHELL_STATIC_SUBCMD_SET_CREATE(sub_log_stat, SHELL_CMD_ARG(list_backends, NULL, "Lists logger backends.", cmd_log_backends_list, 1, 0), SHELL_CMD(status, NULL, "Logger status", cmd_log_self_status), + SHELL_COND_CMD_ARG(CONFIG_LOG_STRDUP_POOL_PROFILING, strdup_utilization, + NULL, "Get utilization of string duplicates pool", + cmd_log_strdup_utilization, 1, 0), SHELL_SUBCMD_SET_END ); diff --git a/subsys/logging/log_core.c b/subsys/logging/log_core.c index ba89473207c..238be65b9db 100644 --- a/subsys/logging/log_core.c +++ b/subsys/logging/log_core.c @@ -58,6 +58,9 @@ static bool backend_attached; static atomic_t buffered_cnt; static atomic_t dropped_cnt; static k_tid_t proc_tid; +static u32_t log_strdup_in_use; +static u32_t log_strdup_max; +static u32_t log_strdup_longest; static u32_t dummy_timestamp(void); static timestamp_get_t timestamp_func = dummy_timestamp; @@ -644,6 +647,18 @@ char *log_strdup(const char *str) return (char *)log_strdup_fail_msg; } + if (IS_ENABLED(CONFIG_LOG_STRDUP_POOL_PROFILING)) { + size_t slen = strlen(str); + struct k_spinlock lock; + k_spinlock_key_t key; + + key = k_spin_lock(&lock); + log_strdup_in_use++; + log_strdup_max = MAX(log_strdup_in_use, log_strdup_max); + log_strdup_longest = MAX(slen, log_strdup_longest); + k_spin_unlock(&lock, key); + } + /* Set 'allocated' flag. */ (void)atomic_set(&dup->refcount, 1); @@ -654,6 +669,18 @@ char *log_strdup(const char *str) return dup->buf; } +u32_t log_get_strdup_pool_utilization(void) +{ + return IS_ENABLED(CONFIG_LOG_STRDUP_POOL_PROFILING) ? + log_strdup_max : 0; +} + +u32_t log_get_strdup_longest_string(void) +{ + return IS_ENABLED(CONFIG_LOG_STRDUP_POOL_PROFILING) ? + log_strdup_longest : 0; +} + bool log_is_strdup(void *buf) { struct log_strdup_buf *pool_first, *pool_last; @@ -673,6 +700,9 @@ void log_free(void *str) if (atomic_dec(&dup->refcount) == 1) { k_mem_slab_free(&log_strdup_pool, (void **)&dup); + if (IS_ENABLED(CONFIG_LOG_STRDUP_POOL_PROFILING)) { + atomic_dec((atomic_t *)&log_strdup_in_use); + } } }