Skip to content

Commit 1e495ef

Browse files
nordic-krchnordic-krch
committed
tests: logging: Add benchmark test
Added test which benchmarks deferred logging v1 and v2. Signed-off-by: Krzysztof Chruscinski <[email protected]>
1 parent f394973 commit 1e495ef

File tree

6 files changed

+414
-0
lines changed

6 files changed

+414
-0
lines changed

‎tests/subsys/logging/log_benchmark/CMakeLists.txt‎

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,8 @@
1+
# SPDX-License-Identifier: Apache-2.0
2+
3+
cmake_minimum_required(VERSION 3.13.1)
4+
find_package(Zephyr REQUIRED HINTS $ENV{ZEPHYR_BASE})
5+
project(log_benchmark)
6+
7+
FILE(GLOB app_sources src/*.c)
8+
target_sources(app PRIVATE ${app_sources})

‎tests/subsys/logging/log_benchmark/prj.conf‎

Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,18 @@
1+
CONFIG_MAIN_THREAD_PRIORITY=5
2+
CONFIG_ZTEST=y
3+
CONFIG_TEST_LOGGING_DEFAULTS=n
4+
CONFIG_LOG=y
5+
CONFIG_LOG_PRINTK=n
6+
CONFIG_LOG_BACKEND_UART=n
7+
CONFIG_LOG_BUFFER_SIZE=2048
8+
CONFIG_LOG_STRDUP_BUF_COUNT=1
9+
CONFIG_LOG_STRDUP_MAX_STRING=8
10+
CONFIG_KERNEL_LOG_LEVEL_OFF=y
11+
CONFIG_SOC_LOG_LEVEL_OFF=y
12+
CONFIG_ARCH_LOG_LEVEL_OFF=y
13+
CONFIG_LOG_FUNC_NAME_PREFIX_DBG=n
14+
CONFIG_LOG_PROCESS_THREAD=n
15+
CONFIG_ASSERT=n
16+
CONFIG_LOG_STRDUP_POOL_PROFILING=y
17+
CONFIG_LOG_TEST_CLEAR_MESSAGE_SPACE=n
18+
CONFIG_APPLICATION_DEFINED_SYSCALL=y

‎tests/subsys/logging/log_benchmark/src/main.c‎

Lines changed: 260 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,260 @@
1+
/*
2+
* Copyright (c) 2021 Nordic Semiconductor ASA
3+
*
4+
* SPDX-License-Identifier: Apache-2.0
5+
*/
6+
7+
/**
8+
* @file
9+
* @brief Test log benchmark
10+
*
11+
*/
12+
13+
14+
#include <tc_util.h>
15+
#include <stdbool.h>
16+
#include <zephyr.h>
17+
#include <ztest.h>
18+
#include <logging/log_backend.h>
19+
#include <logging/log_ctrl.h>
20+
#include <logging/log.h>
21+
#include "test_helpers.h"
22+
23+
#define LOG_MODULE_NAME test
24+
LOG_MODULE_REGISTER(LOG_MODULE_NAME);
25+
26+
#if LOG_BENCHMARK_DETAILED_PRINT
27+
#define DBG_PRINT(...) PRINT(__VA_ARGS__)
28+
#else
29+
#define DBG_PRINT(...)
30+
#endif
31+
32+
typedef void (*custom_put_callback_t)(struct log_backend const *const backend,
33+
struct log_msg *msg, size_t counter);
34+
35+
struct backend_cb {
36+
size_t counter;
37+
bool panic;
38+
bool keep_msgs;
39+
bool check_id;
40+
uint32_t exp_id[100];
41+
bool check_timestamp;
42+
uint32_t exp_timestamps[100];
43+
bool check_args;
44+
uint32_t exp_nargs[100];
45+
bool check_strdup;
46+
bool exp_strdup[100];
47+
custom_put_callback_t callback;
48+
uint32_t total_drops;
49+
};
50+
51+
static void put(struct log_backend const *const backend,
52+
struct log_msg *msg)
53+
{
54+
log_msg_get(msg);
55+
log_msg_put(msg);
56+
}
57+
58+
static void process(struct log_backend const *const backend,
59+
union log_msg2_generic *msg)
60+
{
61+
}
62+
63+
static void panic(struct log_backend const *const backend)
64+
{
65+
struct backend_cb *cb = (struct backend_cb *)backend->cb->ctx;
66+
67+
cb->panic = true;
68+
}
69+
70+
static void dropped(struct log_backend const *const backend, uint32_t cnt)
71+
{
72+
struct backend_cb *cb = (struct backend_cb *)backend->cb->ctx;
73+
74+
cb->total_drops += cnt;
75+
}
76+
77+
const struct log_backend_api log_backend_test_api = {
78+
.put = IS_ENABLED(CONFIG_LOG_MODE_DEFERRED) ? put : NULL,
79+
.process = IS_ENABLED(CONFIG_LOG2) ? process : NULL,
80+
.panic = panic,
81+
.dropped = dropped,
82+
};
83+
84+
LOG_BACKEND_DEFINE(backend, log_backend_test_api, false);
85+
struct backend_cb backend_ctrl_blk;
86+
87+
#define TEST_FORMAT_SPEC(i, _) " %d"
88+
#define TEST_VALUE(i, _), i
89+
90+
/** @brief Count log messages until first drop.
91+
*
92+
* Report number of messages that fit in the buffer.
93+
*
94+
* @param nargs Number of int arguments in the log message.
95+
*/
96+
#define TEST_LOG_CAPACITY(nargs, inc_cnt, _print) do { \
97+
int _cnt = 0; \
98+
test_helpers_log_setup(); \
99+
while (!test_helpers_log_dropped_pending()) { \
100+
LOG_ERR("test" UTIL_LISTIFY(nargs, TEST_FORMAT_SPEC) \
101+
UTIL_LISTIFY(nargs, TEST_VALUE)); \
102+
_cnt++; \
103+
} \
104+
_cnt--; \
105+
inc_cnt += _cnt; \
106+
if (_print) { \
107+
DBG_PRINT("%d log message with %d arguments fit in %d space.\n", \
108+
_cnt, nargs, CONFIG_LOG_BUFFER_SIZE); \
109+
} \
110+
} while (0)
111+
112+
/** Test how many messages fits in the logging buffer in deferred mode. Test
113+
* serves as the comparison between logging versions.
114+
*/
115+
void test_log_capacity(void)
116+
{
117+
int total_cnt = 0;
118+
119+
TEST_LOG_CAPACITY(0, total_cnt, 1);
120+
TEST_LOG_CAPACITY(1, total_cnt, 1);
121+
TEST_LOG_CAPACITY(2, total_cnt, 1);
122+
TEST_LOG_CAPACITY(3, total_cnt, 1);
123+
TEST_LOG_CAPACITY(4, total_cnt, 1);
124+
TEST_LOG_CAPACITY(5, total_cnt, 1);
125+
TEST_LOG_CAPACITY(6, total_cnt, 1);
126+
TEST_LOG_CAPACITY(7, total_cnt, 1);
127+
TEST_LOG_CAPACITY(8, total_cnt, 1);
128+
129+
PRINT("In total %d message were stored.\n", total_cnt);
130+
}
131+
132+
#define TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(nargs, inc_time, inc_msg) do { \
133+
int _msg_cnt = 0; \
134+
TEST_LOG_CAPACITY(nargs, _msg_cnt, 0); \
135+
test_helpers_log_setup(); \
136+
uint32_t cyc = test_helpers_cycle_get(); \
137+
for (int i = 0; i < _msg_cnt; i++) { \
138+
LOG_ERR("test" UTIL_LISTIFY(nargs, TEST_FORMAT_SPEC) \
139+
UTIL_LISTIFY(nargs, TEST_VALUE)); \
140+
} \
141+
cyc = test_helpers_cycle_get() - cyc; \
142+
inc_time += cyc; \
143+
inc_msg += _msg_cnt; \
144+
DBG_PRINT("%d arguments message logged in %u cycles (%u us). " \
145+
"%d message logged in %u cycles.\n", \
146+
nargs, cyc / _msg_cnt, k_cyc_to_us_ceil32(cyc) / _msg_cnt, \
147+
_msg_cnt, cyc); \
148+
} while (0)
149+
150+
void test_log_message_store_time_no_overwrite(void)
151+
{
152+
uint32_t total_cyc = 0;
153+
uint32_t total_msg = 0;
154+
155+
TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(0, total_cyc, total_msg);
156+
TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(1, total_cyc, total_msg);
157+
TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(2, total_cyc, total_msg);
158+
TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(3, total_cyc, total_msg);
159+
TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(4, total_cyc, total_msg);
160+
TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(5, total_cyc, total_msg);
161+
TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(6, total_cyc, total_msg);
162+
TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(7, total_cyc, total_msg);
163+
TEST_LOG_MESSAGE_STORE_NO_OVERFLOW(8, total_cyc, total_msg);
164+
165+
uint32_t total_us = k_cyc_to_us_ceil32(total_cyc);
166+
167+
PRINT("%sAvarage logging a message: %u cycles (%u us)\n",
168+
k_is_user_context() ? "USERSPACE: " : "",
169+
total_cyc / total_msg, total_us / total_msg);
170+
}
171+
172+
#define TEST_LOG_MESSAGE_STORE_OVERFLOW(nargs, _msg_cnt, inc_time, inc_msg) do { \
173+
int _dummy = 0; \
174+
/* Saturate buffer. */ \
175+
TEST_LOG_CAPACITY(nargs, _dummy, 0); \
176+
uint32_t cyc = test_helpers_cycle_get(); \
177+
for (int i = 0; i < _msg_cnt; i++) { \
178+
LOG_ERR("test" UTIL_LISTIFY(nargs, TEST_FORMAT_SPEC) \
179+
UTIL_LISTIFY(nargs, TEST_VALUE)); \
180+
} \
181+
cyc = test_helpers_cycle_get() - cyc; \
182+
inc_time += cyc; \
183+
inc_msg += _msg_cnt; \
184+
DBG_PRINT("%d arguments message logged in %u cycles (%u us). " \
185+
"%d message logged in %u cycles.\n", \
186+
nargs, cyc / _msg_cnt, k_cyc_to_us_ceil32(cyc) / _msg_cnt, \
187+
_msg_cnt, cyc); \
188+
} while (0)
189+
190+
void test_log_message_store_time_overwrite(void)
191+
{
192+
uint32_t total_cyc = 0;
193+
uint32_t total_msg = 0;
194+
195+
TEST_LOG_MESSAGE_STORE_OVERFLOW(0, 50, total_cyc, total_msg);
196+
TEST_LOG_MESSAGE_STORE_OVERFLOW(1, 50, total_cyc, total_msg);
197+
TEST_LOG_MESSAGE_STORE_OVERFLOW(2, 50, total_cyc, total_msg);
198+
TEST_LOG_MESSAGE_STORE_OVERFLOW(3, 50, total_cyc, total_msg);
199+
TEST_LOG_MESSAGE_STORE_OVERFLOW(4, 50, total_cyc, total_msg);
200+
TEST_LOG_MESSAGE_STORE_OVERFLOW(5, 50, total_cyc, total_msg);
201+
TEST_LOG_MESSAGE_STORE_OVERFLOW(6, 50, total_cyc, total_msg);
202+
TEST_LOG_MESSAGE_STORE_OVERFLOW(7, 50, total_cyc, total_msg);
203+
TEST_LOG_MESSAGE_STORE_OVERFLOW(8, 50, total_cyc, total_msg);
204+
205+
uint32_t total_us = k_cyc_to_us_ceil32(total_cyc);
206+
207+
PRINT("Avarage overwrite logging a message: %u cycles (%u us)\n",
208+
total_cyc / total_msg, total_us / total_msg);
209+
}
210+
211+
void test_log_message_store_time_no_overwrite_from_user(void)
212+
{
213+
if (!IS_ENABLED(CONFIG_USERSPACE)) {
214+
printk("no userspace\n");
215+
return;
216+
}
217+
218+
test_log_message_store_time_no_overwrite();
219+
}
220+
221+
void test_log_message_with_string(void)
222+
{
223+
test_helpers_log_setup();
224+
char strbuf[] = "test string";
225+
uint32_t cyc = test_helpers_cycle_get();
226+
int repeat = 8;
227+
228+
for (int i = 0; i < repeat; i++) {
229+
LOG_ERR("test with string to duplicate: %s", log_strdup(strbuf));
230+
}
231+
232+
cyc = test_helpers_cycle_get() - cyc;
233+
uint32_t us = k_cyc_to_us_ceil32(cyc);
234+
235+
PRINT("%slogging with transient string %u cycles (%u us).",
236+
k_is_user_context() ? "USERSPACE: " : "",
237+
cyc / repeat, us / repeat);
238+
}
239+
240+
/*test case main entry*/
241+
void test_main(void)
242+
{
243+
PRINT("LOGGING MODE:%s\n", IS_ENABLED(CONFIG_LOG_MODE_DEFERRED) ? "DEFERREDv1" :
244+
(IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED) ? "DEFERREDv2" :
245+
(IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE) ? "IMMEDIATEv1" :
246+
"IMMEDIATEv2")));
247+
PRINT("\tOVERWRITE: %d\n", IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW));
248+
PRINT("\tBUFFER_SIZE: %d\n", CONFIG_LOG_BUFFER_SIZE);
249+
if (IS_ENABLED(CONFIG_LOG2_MODE_DEFERRED)) {
250+
PRINT("\tSPEED: %d", IS_ENABLED(CONFIG_LOG_SPEED));
251+
}
252+
ztest_test_suite(test_log_benchmark,
253+
ztest_unit_test(test_log_capacity),
254+
ztest_unit_test(test_log_message_store_time_no_overwrite),
255+
ztest_unit_test(test_log_message_store_time_overwrite),
256+
ztest_user_unit_test(test_log_message_store_time_no_overwrite_from_user),
257+
ztest_user_unit_test(test_log_message_with_string)
258+
);
259+
ztest_run_test_suite(test_log_benchmark);
260+
}

‎tests/subsys/logging/log_benchmark/src/test_helpers.c‎

Lines changed: 61 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,61 @@
1+
/*
2+
* Copyright (c) 2021 Nordic Semiconductor ASA
3+
*
4+
* SPDX-License-Identifier: Apache-2.0
5+
*/
6+
#include "test_helpers.h"
7+
#include <logging/log_core.h>
8+
#include <logging/log_ctrl.h>
9+
10+
11+
static log_timestamp_t stamp;
12+
13+
static log_timestamp_t timestamp_get(void)
14+
{
15+
return stamp++;
16+
}
17+
18+
void z_impl_test_helpers_log_setup(void)
19+
{
20+
stamp = 0;
21+
log_core_init();
22+
log_init();
23+
z_log_dropped_read_and_clear();
24+
25+
log_set_timestamp_func(timestamp_get, 0);
26+
27+
}
28+
29+
#ifdef CONFIG_USERSPACE
30+
static inline void z_vrfy_test_helpers_log_setup(void)
31+
{
32+
return z_impl_test_helpers_log_setup();
33+
}
34+
#include <syscalls/test_helpers_log_setup_mrsh.c>
35+
#endif
36+
37+
int z_impl_test_helpers_cycle_get(void)
38+
{
39+
return arch_k_cycle_get_32();
40+
}
41+
42+
#ifdef CONFIG_USERSPACE
43+
static inline int z_vrfy_test_helpers_cycle_get(void)
44+
{
45+
return z_impl_test_helpers_cycle_get();
46+
}
47+
#include <syscalls/test_helpers_cycle_get_mrsh.c>
48+
#endif
49+
50+
bool z_impl_test_helpers_log_dropped_pending(void)
51+
{
52+
return z_log_dropped_pending();
53+
}
54+
55+
#ifdef CONFIG_USERSPACE
56+
static inline bool z_vrfy_test_helpers_log_dropped_pending(void)
57+
{
58+
return z_impl_test_helpers_log_dropped_pending();
59+
}
60+
#include <syscalls/test_helpers_log_dropped_pending_mrsh.c>
61+
#endif

‎tests/subsys/logging/log_benchmark/src/test_helpers.h‎

Lines changed: 17 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,17 @@
1+
/*
2+
* Copyright (c) 2021 Nordic Semiconductor ASA
3+
*
4+
* SPDX-License-Identifier: Apache-2.0
5+
*/
6+
#ifndef SRC_TEST_HELPERS_H__
7+
#define SRC_TEST_HELPERS_H__
8+
9+
#include <zephyr.h>
10+
11+
__syscall void test_helpers_log_setup(void);
12+
__syscall int test_helpers_cycle_get(void);
13+
__syscall bool test_helpers_log_dropped_pending(void);
14+
15+
#include <syscalls/test_helpers.h>
16+
17+
#endif /* SRC_TEST_HELPERS_H__ */

0 commit comments

Comments
 (0)