1 /*
2 * Copyright (c) 2018 Nordic Semiconductor ASA
3 *
4 * SPDX-License-Identifier: Apache-2.0
5 */
6
7 #include <zephyr/kernel.h>
8 #include <string.h>
9 #include <zephyr/sys/printk.h>
10 #include "sample_instance.h"
11 #include "sample_module.h"
12 #include "ext_log_system.h"
13 #include "ext_log_system_adapter.h"
14 #include <zephyr/logging/log_ctrl.h>
15 #include <zephyr/app_memory/app_memdomain.h>
16
17 #include <zephyr/logging/log.h>
18 LOG_MODULE_REGISTER(main);
19
20 #ifdef CONFIG_USERSPACE
21 K_APPMEM_PARTITION_DEFINE(app_part);
22 static struct k_mem_domain app_domain;
23 static struct k_mem_partition *app_parts[] = {
24 #ifdef Z_LIBC_PARTITION_EXISTS
25 /* C library globals, stack canary storage, etc */
26 &z_libc_partition,
27 #endif
28 &app_part
29 };
30 #endif /* CONFIG_USERSPACE */
31
32 /* size of stack area used by each thread */
33 #define STACKSIZE (1024)
34
35 extern void sample_module_func(void);
36
37 #define INST1_NAME STRINGIFY(SAMPLE_INSTANCE_NAME.inst1)
38 SAMPLE_INSTANCE_DEFINE(app_part, inst1);
39
40 #define INST2_NAME STRINGIFY(SAMPLE_INSTANCE_NAME.inst2)
41 SAMPLE_INSTANCE_DEFINE(app_part, inst2);
42
timestamp_get(void)43 static uint32_t timestamp_get(void)
44 {
45 return k_cycle_get_32();
46 }
47
timestamp_freq(void)48 static uint32_t timestamp_freq(void)
49 {
50 return sys_clock_hw_cycles_per_sec();
51 }
52
53 /**
54 * @brief Function demonstrates module level filtering.
55 *
56 * Sample module API is called then logging for this module is disabled and
57 * function is called again. It is expected that only logs generated by the
58 * first call will be processed by the output.
59 */
module_logging_showcase(void)60 static void module_logging_showcase(void)
61 {
62 printk("Module logging showcase.\n");
63
64 sample_module_func();
65 inline_func();
66
67 if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
68 printk("Disabling logging in the %s module\n",
69 sample_module_name_get());
70
71 log_filter_set(NULL, 0,
72 log_source_id_get(sample_module_name_get()),
73 LOG_LEVEL_NONE);
74
75 sample_module_func();
76
77 printk("Function called again but with logging disabled.\n");
78
79 } else {
80 printk("%s option disabled.\n",
81 STRINGIFY(CONFIG_LOG_RUNTIME_FILTERING));
82 }
83 }
84
85 /**
86 * @brief Function demonstrates instance level filtering.
87 *
88 * Sample multi-instance module API on two instances is called then logging
89 * level for one instance is reduced and function is called again on two
90 * instances. It is expected that one instance will generate less logs.
91 */
instance_logging_showcase(void)92 static void instance_logging_showcase(void)
93 {
94 printk("Instance level logging showcase.\n");
95
96 sample_instance_inline_call(&inst1);
97 sample_instance_call(&inst1);
98 sample_instance_inline_call(&inst2);
99 sample_instance_call(&inst2);
100
101 if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
102 printk("Changing filter to warning on %s instance.\n",
103 INST1_NAME);
104
105 log_filter_set(NULL, 0,
106 log_source_id_get(INST1_NAME), LOG_LEVEL_WRN);
107
108 sample_instance_inline_call(&inst1);
109 sample_instance_call(&inst1);
110 sample_instance_inline_call(&inst2);
111 sample_instance_call(&inst2);
112
113 printk("Disabling logging on both instances.\n");
114
115 log_filter_set(NULL, 0,
116 log_source_id_get(INST1_NAME),
117 LOG_LEVEL_NONE);
118
119 log_filter_set(NULL, 0,
120 log_source_id_get(INST2_NAME),
121 LOG_LEVEL_NONE);
122
123 sample_instance_inline_call(&inst1);
124 sample_instance_call(&inst1);
125 sample_instance_inline_call(&inst2);
126 sample_instance_call(&inst2);
127
128 printk("Function call on both instances with logging disabled.\n");
129 }
130 }
131
132 /**
133 * @brief Function demonstrates supported severity logging level.
134 */
severity_levels_showcase(void)135 static void severity_levels_showcase(void)
136 {
137 printk("Severity levels showcase.\n");
138
139 LOG_ERR("Error message example.");
140 LOG_WRN("Warning message example.");
141 LOG_INF("Info message example.");
142 LOG_DBG("Debug message example.");
143 }
144
145 /**
146 * @brief Function demonstrates how transient strings can be logged.
147 */
log_transient_string_showcase(void)148 static void log_transient_string_showcase(void)
149 {
150 char transient_str[] = "transient_string";
151
152 printk("String logging showcase.\n");
153
154 LOG_INF("Logging transient string:%s", transient_str);
155
156 /* Overwrite transient string to show that the logger has a copy. */
157 transient_str[0] = '\0';
158 }
159
wait_on_log_flushed(void)160 static void wait_on_log_flushed(void)
161 {
162 while (log_buffered_cnt()) {
163 k_sleep(K_MSEC(5));
164 }
165 }
166
167 /**
168 * @brief Function demonstrates how fast data can be logged.
169 *
170 * Messages are logged and counted in a loop for 2 ticks (same clock source as
171 * the one used for logging timestamp). Based on that and known clock frequency,
172 * logging bandwidth is calculated.
173 */
performance_showcase(void)174 static void performance_showcase(void)
175 {
176 /* Arbitrary limit when LOG_MODE_IMMEDIATE is enabled. */
177 #define LOG_IMMEDIATE_TEST_MESSAGES_LIMIT 50
178 #define MSG_SIZE (sizeof(struct log_msg) + 2 * sizeof(void *) + sizeof(int))
179
180 volatile uint32_t current_timestamp;
181 volatile uint32_t start_timestamp;
182 uint32_t limit = COND_CODE_1(CONFIG_LOG_MODE_IMMEDIATE,
183 (LOG_IMMEDIATE_TEST_MESSAGES_LIMIT),
184 (CONFIG_LOG_BUFFER_SIZE / MSG_SIZE));
185 uint32_t per_sec;
186 uint32_t cnt = 0U;
187 uint32_t window = 2U;
188
189 printk("Logging performance showcase.\n");
190 wait_on_log_flushed();
191
192 do {
193 cnt = 0;
194 start_timestamp = timestamp_get();
195
196 while (start_timestamp == timestamp_get()) {
197 Z_SPIN_DELAY(100);
198 }
199
200 start_timestamp = timestamp_get();
201
202 do {
203 LOG_INF("performance test - log message %d", cnt);
204 cnt++;
205 current_timestamp = timestamp_get();
206 Z_SPIN_DELAY(100);
207 } while (current_timestamp < (start_timestamp + window));
208
209 wait_on_log_flushed();
210
211 /* If limit exceeded then some messages might be dropped which
212 * degraded performance. Decrease window size.
213 * If less than half of limit is reached then it means that
214 * window can be increased to improve precision.
215 */
216 if (cnt >= limit) {
217 if (window >= 2) {
218 window /= 2;
219 } else {
220 break;
221 }
222 } else if (cnt < (limit / 2)) {
223 window *= 2;
224 } else {
225 break;
226 }
227 } while (1);
228
229 per_sec = (cnt * timestamp_freq()) / window;
230 printk("Estimated logging capabilities: %d messages/second\n", per_sec);
231 }
232
external_log_system_showcase(void)233 static void external_log_system_showcase(void)
234 {
235 printk("Logs from external logging system showcase.\n");
236
237 ext_log_system_log_adapt();
238
239 ext_log_system_foo();
240 }
241
log_demo_thread(void * p1,void * p2,void * p3)242 static void log_demo_thread(void *p1, void *p2, void *p3)
243 {
244 bool usermode = k_is_user_context();
245
246 (void)log_set_tag("demo_tag");
247
248 k_sleep(K_MSEC(100));
249
250 printk("\n\t---=< RUNNING LOGGER DEMO FROM %s THREAD >=---\n\n",
251 (usermode) ? "USER" : "KERNEL");
252
253 module_logging_showcase();
254
255 instance_logging_showcase();
256
257 /* Re-enabling filters before processing.
258 * Note: Same filters are used to for gathering logs and processing.
259 */
260 log_filter_set(NULL, Z_LOG_LOCAL_DOMAIN_ID,
261 log_source_id_get(sample_module_name_get()),
262 CONFIG_LOG_DEFAULT_LEVEL);
263
264 log_filter_set(NULL, Z_LOG_LOCAL_DOMAIN_ID,
265 log_source_id_get(INST1_NAME),
266 CONFIG_LOG_DEFAULT_LEVEL);
267
268 log_filter_set(NULL, Z_LOG_LOCAL_DOMAIN_ID,
269 log_source_id_get(INST2_NAME),
270 CONFIG_LOG_DEFAULT_LEVEL);
271
272 wait_on_log_flushed();
273
274 log_transient_string_showcase();
275
276 severity_levels_showcase();
277
278 wait_on_log_flushed();
279
280 if (!usermode) {
281 /*
282 * Logger performance in user mode cannot be demonstrated
283 * as precise timing API is accessible only from the kernel.
284 */
285 performance_showcase();
286 wait_on_log_flushed();
287
288 }
289
290 external_log_system_showcase();
291 wait_on_log_flushed();
292 }
293
log_demo_supervisor(void * p1,void * p2,void * p3)294 static void log_demo_supervisor(void *p1, void *p2, void *p3)
295 {
296 /* Timestamp function could be set only from kernel thread. */
297 (void)log_set_timestamp_func(timestamp_get, timestamp_freq());
298
299 log_demo_thread(p1, p2, p3);
300
301 #ifdef CONFIG_USERSPACE
302 int ret = k_mem_domain_init(&app_domain, ARRAY_SIZE(app_parts), app_parts);
303
304 __ASSERT(ret == 0, "k_mem_domain_init() failed %d\n", ret);
305 ARG_UNUSED(ret);
306
307 k_mem_domain_add_thread(&app_domain, k_current_get());
308 k_thread_user_mode_enter(log_demo_thread, p1, p2, p3);
309 #endif
310 }
311
312 K_THREAD_DEFINE(log_demo_thread_id, STACKSIZE, log_demo_supervisor,
313 NULL, NULL, NULL,
314 K_LOWEST_APPLICATION_THREAD_PRIO, 0, 1);
315
