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