tests: logging: Add benchmark test

Added test which benchmarks deferred logging v1 and v2.

Signed-off-by: Krzysztof Chruscinski <[email protected]>

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

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

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 <tc_util.h>
+#include <stdbool.h>
+#include <zephyr.h>
+#include <ztest.h>
+#include <logging/log_backend.h>
+#include <logging/log_ctrl.h>
+#include <logging/log.h>
+#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);
+}

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 <logging/log_core.h>
+#include <logging/log_ctrl.h>
+
+
+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 <syscalls/test_helpers_log_setup_mrsh.c>
+#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 <syscalls/test_helpers_cycle_get_mrsh.c>
+#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 <syscalls/test_helpers_log_dropped_pending_mrsh.c>
+#endif

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 <zephyr.h>
+
+__syscall void test_helpers_log_setup(void);
+__syscall int test_helpers_cycle_get(void);
+__syscall bool test_helpers_log_dropped_pending(void);
+
+#include <syscalls/test_helpers.h>
+
+#endif /* SRC_TEST_HELPERS_H__ */