Skip to content
Permalink
Browse files

logging: Add string duplicates pool profiling

Added option profiling instrumentation which can help determine
string duplicates pool configuration. Added shell command to
read current peak utilization of the pool.

Signed-off-by: Krzysztof Chruscinski <krzysztof.chruscinski@nordicsemi.no>
  • Loading branch information...
nordic-krch authored and carlescufi committed May 22, 2019
1 parent e72e457 commit 04a5cee5565049ed398494dd2ca79bdba3853b8e
Showing with 92 additions and 0 deletions.
  1. +15 −0 include/logging/log_core.h
  2. +6 −0 subsys/logging/Kconfig
  3. +41 −0 subsys/logging/log_cmds.c
  4. +30 −0 subsys/logging/log_core.c
@@ -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);
@@ -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
@@ -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
);

@@ -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);
}
}
}

0 comments on commit 04a5cee

Please sign in to comment.
You can’t perform that action at this time.