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
put(struct log_backend const * const backend,struct log_msg * msg)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
process(struct log_backend const * const backend,union log_msg2_generic * msg)58 static void process(struct log_backend const *const backend,
59 union log_msg2_generic *msg)
60 {
61 }
62
panic(struct log_backend const * const backend)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
dropped(struct log_backend const * const backend,uint32_t cnt)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 */
test_log_capacity(void)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
test_log_message_store_time_no_overwrite(void)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
test_log_message_store_time_overwrite(void)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
test_log_message_store_time_no_overwrite_from_user(void)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
test_log_message_with_string(void)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*/
test_main(void)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 }
261
