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>

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

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

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

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