diff --git a/tests/subsys/logging/log_benchmark/CMakeLists.txt b/tests/subsys/logging/log_benchmark/CMakeLists.txt new file mode 100644 index 00000000000..52e8600940e --- /dev/null +++ b/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}) diff --git a/tests/subsys/logging/log_benchmark/prj.conf b/tests/subsys/logging/log_benchmark/prj.conf new file mode 100644 index 00000000000..96b3fe5143b --- /dev/null +++ b/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 diff --git a/tests/subsys/logging/log_benchmark/src/main.c b/tests/subsys/logging/log_benchmark/src/main.c new file mode 100644 index 00000000000..6d7988c247b --- /dev/null +++ b/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 +#include +#include +#include +#include +#include +#include +#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); +} diff --git a/tests/subsys/logging/log_benchmark/src/test_helpers.c b/tests/subsys/logging/log_benchmark/src/test_helpers.c new file mode 100644 index 00000000000..7834d76c0da --- /dev/null +++ b/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 +#include + + +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 +#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 +#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 +#endif diff --git a/tests/subsys/logging/log_benchmark/src/test_helpers.h b/tests/subsys/logging/log_benchmark/src/test_helpers.h new file mode 100644 index 00000000000..3dac9658480 --- /dev/null +++ b/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 + +__syscall void test_helpers_log_setup(void); +__syscall int test_helpers_cycle_get(void); +__syscall bool test_helpers_log_dropped_pending(void); + +#include + +#endif /* SRC_TEST_HELPERS_H__ */ diff --git a/tests/subsys/logging/log_benchmark/testcase.yaml b/tests/subsys/logging/log_benchmark/testcase.yaml new file mode 100644 index 00000000000..edd4f7075bc --- /dev/null +++ b/tests/subsys/logging/log_benchmark/testcase.yaml @@ -0,0 +1,50 @@ +tests: + logging.log_benchmark_v1: + integration_platforms: + - native_posix + tags: logging + extra_configs: + - CONFIG_CBPRINTF_COMPLETE=y + - CONFIG_LOG_STRDUP_BUF_COUNT=8 + - CONFIG_LOG_STRDUP_MAX_STRING=32 + - CONFIG_LOG_MODE_DEFERRED=y + + logging.log_benchmark_user_v1: + integration_platforms: + - native_posix + tags: logging + platform_allow: qemu_x86 + extra_configs: + - CONFIG_CBPRINTF_COMPLETE=y + - CONFIG_LOG_STRDUP_BUF_COUNT=8 + - CONFIG_LOG_STRDUP_MAX_STRING=32 + - CONFIG_LOG_MODE_DEFERRED=y + - CONFIG_TEST_USERSPACE=y + + logging.log_benchmark_v2: + integration_platforms: + - native_posix + tags: logging + extra_configs: + - CONFIG_CBPRINTF_COMPLETE=y + - CONFIG_LOG2_MODE_DEFERRED=y + + logging.log_benchmark_v2_speed: + integration_platforms: + - native_posix + tags: logging + extra_configs: + - CONFIG_CBPRINTF_COMPLETE=y + - CONFIG_LOG2_MODE_DEFERRED=y + - CONFIG_LOG_SPEED=y + + logging.log_benchmark_user_v2: + integration_platforms: + - native_posix + tags: logging + platform_allow: qemu_x86 + extra_configs: + - CONFIG_CBPRINTF_COMPLETE=y + - CONFIG_CBPRINTF_COMPLETE=y + - CONFIG_LOG2_MODE_DEFERRED=y + - CONFIG_TEST_USERSPACE=y