1 /*
2 * Copyright (c) 2022 Nordic Semiconductor ASA
3 *
4 * SPDX-License-Identifier: Apache-2.0
5 */
6
7 #include <zephyr/ztest.h>
8 #include <zephyr/sys/util.h>
9 #include <string.h>
10 #include <zephyr/ztress.h>
11 #include <zephyr/random/random.h>
12 #include <zephyr/logging/log.h>
13 #include <zephyr/logging/log_ctrl.h>
14 #include <zephyr/logging/log_backend.h>
15
16 #define MODULE_NAME test
17
18 LOG_MODULE_REGISTER(MODULE_NAME);
19
20 static uint32_t test_source_id;
21
22 #define CNT_BITS 28
23
24 struct mock_log_backend {
25 uint32_t last_id[16];
26 uint32_t cnt[16];
27 uint32_t dropped;
28 uint32_t missing;
29 };
30
31 static struct mock_log_backend mock_backend;
32 static uint32_t log_process_delay = 10;
33
handle_msg(uint32_t arg0)34 static void handle_msg(uint32_t arg0)
35 {
36 uint32_t ctx_id = arg0 >> CNT_BITS;
37 uint32_t id = arg0 & BIT_MASK(CNT_BITS);
38 int off = id - mock_backend.last_id[ctx_id] - 1;
39
40 mock_backend.cnt[ctx_id]++;
41
42 k_busy_wait(log_process_delay);
43
44 if (off > 0) {
45 mock_backend.missing += off;
46 }
47
48 mock_backend.last_id[ctx_id] = id;
49 }
50
process(const struct log_backend * const backend,union log_msg_generic * msg)51 static void process(const struct log_backend *const backend,
52 union log_msg_generic *msg)
53 {
54 size_t len;
55 uint8_t *package = log_msg_get_package(&msg->log, &len);
56
57 package += 2 * sizeof(void *);
58
59 handle_msg(*(uint32_t *)package);
60 }
61
mock_init(struct log_backend const * const backend)62 static void mock_init(struct log_backend const *const backend)
63 {
64
65 }
66
panic(struct log_backend const * const backend)67 static void panic(struct log_backend const *const backend)
68 {
69 zassert_true(false);
70 }
71
dropped(const struct log_backend * const backend,uint32_t cnt)72 static void dropped(const struct log_backend *const backend, uint32_t cnt)
73 {
74
75 mock_backend.dropped += cnt;
76 }
77
78 static const struct log_backend_api log_backend_api = {
79 .process = process,
80 .panic = panic,
81 .init = mock_init,
82 .dropped = IS_ENABLED(CONFIG_LOG_MODE_DEFERRED) ? dropped : NULL,
83 };
84
85 LOG_BACKEND_DEFINE(test, log_backend_api, true, NULL);
86
validate(int ctx_cnt)87 static void validate(int ctx_cnt)
88 {
89 uint64_t in_cnt = 0;
90 uint64_t out_cnt = 0;
91
92 for (int i = 0; i < ctx_cnt; i++) {
93 /* First exectution skips (-1) but there is one final round of logging
94 * when ztress execution is completed (+1).
95 */
96 in_cnt += ztress_exec_count(i) - 1 + 1;
97 out_cnt += mock_backend.cnt[i];
98 }
99
100 out_cnt += mock_backend.dropped;
101
102 zassert_equal(mock_backend.dropped, mock_backend.missing,
103 "dropped:%u missing:%u",
104 mock_backend.dropped, mock_backend.missing);
105 zassert_equal(in_cnt, out_cnt);
106 }
107
context_handler(void * user_data,uint32_t cnt,bool last,int prio)108 static bool context_handler(void *user_data, uint32_t cnt, bool last, int prio)
109 {
110 /* Skip first execution to start from id = 1. That simplifies handling in
111 * the backend and validation of message.
112 */
113 if (cnt == 0) {
114 return true;
115 }
116
117 uint32_t i = cnt | (prio << CNT_BITS);
118
119 switch (sys_rand8_get() % 4) {
120 case 0:
121 LOG_INF("%u", i);
122 break;
123 case 1:
124 LOG_INF("%u %u %u %u", i, 1, 2, 3);
125 break;
126 case 2:
127 {
128 char test_str[] = "test string";
129 LOG_INF("%u %s %s", i, "test", test_str);
130 break;
131 }
132 default:
133 LOG_INF("%u %d", i, 100);
134 break;
135 }
136
137 return true;
138 }
139
get_test_timeout(void)140 static int get_test_timeout(void)
141 {
142 if (IS_ENABLED(CONFIG_BOARD_QEMU_CORTEX_A9)) {
143 /* Emulation for that target is extremely slow. */
144 return 500;
145 }
146
147 if (IS_ENABLED(CONFIG_BOARD_QEMU_X86)) {
148 /* Emulation for that target is very fast. */
149 return 10000;
150 }
151
152 if (IS_ENABLED(CONFIG_BOARD_QEMU_X86_64)) {
153 /* Emulation for that target is very fast. */
154 return 10000;
155 }
156
157 return 5000;
158 }
159
test_stress(uint32_t delay)160 static void test_stress(uint32_t delay)
161 {
162 uint32_t preempt = 2000;
163 uint32_t ctx_cnt = 3;
164
165 memset(&mock_backend, 0, sizeof(mock_backend));
166 log_process_delay = delay;
167 ztress_set_timeout(K_MSEC(get_test_timeout()));
168 ZTRESS_EXECUTE(
169 ZTRESS_TIMER(context_handler, NULL, 0, Z_TIMEOUT_TICKS(30)),
170 ZTRESS_THREAD(context_handler, NULL, 0, preempt, Z_TIMEOUT_TICKS(30)),
171 ZTRESS_THREAD(context_handler, NULL, 0, preempt, Z_TIMEOUT_TICKS(30)));
172
173 while (log_data_pending()) {
174 k_msleep(200);
175 }
176
177 /* Log last messages, they should not be dropped as all messages are processed earlier. */
178 for (int i = 0; i < ctx_cnt; i++) {
179 uint32_t data = (i << CNT_BITS) | ztress_exec_count(i);
180
181 LOG_INF("%u", data);
182 }
183
184 while (log_data_pending()) {
185 k_msleep(100);
186 }
187
188 k_msleep(10);
189
190 validate(ctx_cnt);
191 }
192
ZTEST(log_stress,test_stress_fast_processing)193 ZTEST(log_stress, test_stress_fast_processing)
194 {
195 test_stress(10);
196 }
197
ZTEST(log_stress,test_stress_slow_processing)198 ZTEST(log_stress, test_stress_slow_processing)
199 {
200 test_stress(100);
201 }
202
setup(void)203 static void *setup(void)
204 {
205 test_source_id = log_source_id_get(STRINGIFY(MODULE_NAME));
206
207 return NULL;
208 }
209
before(void * data)210 static void before(void *data)
211 {
212 ARG_UNUSED(data);
213
214 ztest_simple_1cpu_before(data);
215 }
216
after(void * data)217 static void after(void *data)
218 {
219 ARG_UNUSED(data);
220
221 ztest_simple_1cpu_after(data);
222 }
223
teardown(void * data)224 static void teardown(void *data)
225 {
226 ARG_UNUSED(data);
227
228 log_backend_disable(&test);
229 }
230
231 ZTEST_SUITE(log_stress, NULL, setup, before, after, teardown);
232
