Branch data Line data Source code
1 : : /*
2 : : * Copyright (c) 2018 Nordic Semiconductor ASA
3 : : *
4 : : * SPDX-License-Identifier: Apache-2.0
5 : : */
6 : : #include <time.h>
7 : : #include <zephyr/logging/log.h>
8 : : #include <zephyr/logging/log_backend.h>
9 : : #include <zephyr/logging/log_ctrl.h>
10 : : #include <zephyr/logging/log_output.h>
11 : : #include <zephyr/logging/log_internal.h>
12 : : #include <zephyr/sys/mpsc_pbuf.h>
13 : : #include <zephyr/logging/log_link.h>
14 : : #include <zephyr/sys/printk.h>
15 : : #include <zephyr/sys_clock.h>
16 : : #include <zephyr/sys/clock.h>
17 : : #include <zephyr/init.h>
18 : : #include <zephyr/sys/__assert.h>
19 : : #include <zephyr/sys/atomic.h>
20 : : #include <zephyr/sys/iterable_sections.h>
21 : : #include <ctype.h>
22 : : #include <zephyr/logging/log_frontend.h>
23 : : #include <zephyr/internal/syscall_handler.h>
24 : : #include <zephyr/logging/log_output_dict.h>
25 : : #include <zephyr/logging/log_output_custom.h>
26 : : #include <zephyr/linker/utils.h>
27 : :
28 : : #if CONFIG_USERSPACE && CONFIG_LOG_ALWAYS_RUNTIME
29 : : #include <zephyr/app_memory/app_memdomain.h>
30 : : K_APPMEM_PARTITION_DEFINE(k_log_partition);
31 : : #endif
32 : :
33 : : LOG_MODULE_REGISTER(log);
34 : :
35 : : #ifndef CONFIG_LOG_PROCESS_THREAD_SLEEP_MS
36 : : #define CONFIG_LOG_PROCESS_THREAD_SLEEP_MS 0
37 : : #endif
38 : :
39 : : #ifndef CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD
40 : : #define CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD 0
41 : : #endif
42 : :
43 : : #ifndef CONFIG_LOG_PROCESS_THREAD_STACK_SIZE
44 : : #define CONFIG_LOG_PROCESS_THREAD_STACK_SIZE 1
45 : : #endif
46 : :
47 : : #ifndef CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS
48 : : #define CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS 0
49 : : #endif
50 : :
51 : : #ifndef CONFIG_LOG_PROCESSING_LATENCY_US
52 : : #define CONFIG_LOG_PROCESSING_LATENCY_US 0
53 : : #endif
54 : :
55 : : #ifndef CONFIG_LOG_BUFFER_SIZE
56 : : #define CONFIG_LOG_BUFFER_SIZE 4
57 : : #endif
58 : :
59 : : #ifdef CONFIG_LOG_PROCESS_THREAD_CUSTOM_PRIORITY
60 : : #define LOG_PROCESS_THREAD_PRIORITY CONFIG_LOG_PROCESS_THREAD_PRIORITY
61 : : #else
62 : : #define LOG_PROCESS_THREAD_PRIORITY K_LOWEST_APPLICATION_THREAD_PRIO
63 : : #endif
64 : :
65 : : #ifndef CONFIG_LOG_TAG_MAX_LEN
66 : : #define CONFIG_LOG_TAG_MAX_LEN 0
67 : : #endif
68 : :
69 : : #ifndef CONFIG_LOG_FAILURE_REPORT_PERIOD
70 : : #define CONFIG_LOG_FAILURE_REPORT_PERIOD 0
71 : : #endif
72 : :
73 : : #ifndef CONFIG_LOG_ALWAYS_RUNTIME
74 : : BUILD_ASSERT(!IS_ENABLED(CONFIG_NO_OPTIMIZATIONS),
75 : : "CONFIG_LOG_ALWAYS_RUNTIME must be enabled when "
76 : : "CONFIG_NO_OPTIMIZATIONS is set");
77 : : BUILD_ASSERT(!IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE),
78 : : "CONFIG_LOG_ALWAYS_RUNTIME must be enabled when "
79 : : "CONFIG_LOG_MODE_IMMEDIATE is set");
80 : : #endif
81 : :
82 : : static const log_format_func_t format_table[] = {
83 : : [LOG_OUTPUT_TEXT] = IS_ENABLED(CONFIG_LOG_OUTPUT) ?
84 : : log_output_msg_process : NULL,
85 : : [LOG_OUTPUT_SYST] = IS_ENABLED(CONFIG_LOG_MIPI_SYST_ENABLE) ?
86 : : log_output_msg_syst_process : NULL,
87 : : [LOG_OUTPUT_DICT] = IS_ENABLED(CONFIG_LOG_DICTIONARY_SUPPORT) ?
88 : : log_dict_output_msg_process : NULL,
89 : : [LOG_OUTPUT_CUSTOM] = IS_ENABLED(CONFIG_LOG_CUSTOM_FORMAT_SUPPORT) ?
90 : : log_custom_output_msg_process : NULL,
91 : : };
92 : :
93 : 177 : log_format_func_t log_format_func_t_get(uint32_t log_type)
94 : : {
95 : 177 : return format_table[log_type];
96 : : }
97 : :
98 : 0 : size_t log_format_table_size(void)
99 : : {
100 : 0 : return ARRAY_SIZE(format_table);
101 : : }
102 : :
103 : : K_SEM_DEFINE(log_process_thread_sem, 0, 1);
104 : :
105 : : static atomic_t initialized;
106 : : static bool panic_mode;
107 : : static bool backend_attached;
108 : : static atomic_t buffered_cnt;
109 : : static atomic_t dropped_cnt;
110 : : static k_tid_t proc_tid;
111 : : static struct k_timer log_process_thread_timer;
112 : :
113 : : static log_timestamp_t dummy_timestamp(void);
114 : : static log_timestamp_get_t timestamp_func = dummy_timestamp;
115 : : static uint32_t timestamp_freq;
116 : : static log_timestamp_t proc_latency;
117 : : static log_timestamp_t prev_timestamp;
118 : : static atomic_t unordered_cnt;
119 : : static uint64_t last_failure_report;
120 : : static struct k_spinlock process_lock;
121 : :
122 : : static STRUCT_SECTION_ITERABLE(log_msg_ptr, log_msg_ptr);
123 : : static STRUCT_SECTION_ITERABLE_ALTERNATE(log_mpsc_pbuf, mpsc_pbuf_buffer, log_buffer);
124 : : static struct mpsc_pbuf_buffer *curr_log_buffer;
125 : :
126 : : #ifdef CONFIG_MPSC_PBUF
127 : : static uint32_t __aligned(Z_LOG_MSG_ALIGNMENT)
128 : : buf32[CONFIG_LOG_BUFFER_SIZE / sizeof(int)];
129 : :
130 : : static void z_log_notify_drop(const struct mpsc_pbuf_buffer *buffer,
131 : : const union mpsc_pbuf_generic *item);
132 : :
133 : : static const struct mpsc_pbuf_buffer_config mpsc_config = {
134 : : .buf = (uint32_t *)buf32,
135 : : .size = ARRAY_SIZE(buf32),
136 : : .notify_drop = z_log_notify_drop,
137 : : .get_wlen = log_msg_generic_get_wlen,
138 : : .flags = (IS_ENABLED(CONFIG_LOG_MODE_OVERFLOW) ?
139 : : MPSC_PBUF_MODE_OVERWRITE : 0) |
140 : : (IS_ENABLED(CONFIG_LOG_MEM_UTILIZATION) ?
141 : : MPSC_PBUF_MAX_UTILIZATION : 0)
142 : : };
143 : : #endif
144 : :
145 : : /* Check that default tag can fit in tag buffer. */
146 : : COND_CODE_0(CONFIG_LOG_TAG_MAX_LEN, (),
147 : : (BUILD_ASSERT(sizeof(CONFIG_LOG_TAG_DEFAULT) <= CONFIG_LOG_TAG_MAX_LEN + 1,
148 : : "Default string longer than tag capacity")));
149 : :
150 : : static char tag[CONFIG_LOG_TAG_MAX_LEN + 1] =
151 : : COND_CODE_0(CONFIG_LOG_TAG_MAX_LEN, ({}), (CONFIG_LOG_TAG_DEFAULT));
152 : :
153 : : static void msg_process(union log_msg_generic *msg);
154 : :
155 : 0 : static log_timestamp_t dummy_timestamp(void)
156 : : {
157 : 0 : return 0;
158 : : }
159 : :
160 : 0 : log_timestamp_t z_log_timestamp(void)
161 : : {
162 : 0 : return timestamp_func();
163 : : }
164 : :
165 : : static void z_log_msg_post_finalize(void)
166 : : {
167 : : atomic_val_t cnt = atomic_inc(&buffered_cnt);
168 : :
169 : : if (panic_mode) {
170 : : k_spinlock_key_t key = k_spin_lock(&process_lock);
171 : : (void)log_process();
172 : :
173 : : k_spin_unlock(&process_lock, key);
174 : : } else if (proc_tid != NULL) {
175 : : /*
176 : : * If CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD == 1,
177 : : * timer is never needed. We release the processing
178 : : * thread after every message is posted.
179 : : */
180 : : if (CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD == 1) {
181 : : if (cnt == 0) {
182 : : k_sem_give(&log_process_thread_sem);
183 : : }
184 : : } else {
185 : : if (cnt == 0) {
186 : : k_timer_start(&log_process_thread_timer,
187 : : K_MSEC(CONFIG_LOG_PROCESS_THREAD_SLEEP_MS),
188 : : K_NO_WAIT);
189 : : } else if (CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD &&
190 : : (cnt + 1) == CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD) {
191 : : k_timer_stop(&log_process_thread_timer);
192 : : k_sem_give(&log_process_thread_sem);
193 : : } else {
194 : : /* No action needed. Message processing will be triggered by the
195 : : * timeout or when number of upcoming messages exceeds the
196 : : * threshold.
197 : : */
198 : : }
199 : : }
200 : : }
201 : : }
202 : :
203 : 0 : const struct log_backend *log_format_set_all_active_backends(size_t log_type)
204 : : {
205 : 0 : const struct log_backend *failed_backend = NULL;
206 : :
207 [ # # # # ]: 0 : STRUCT_SECTION_FOREACH(log_backend, backend) {
208 [ # # ]: 0 : if (log_backend_is_active(backend)) {
209 : 0 : int retCode = log_backend_format_set(backend, log_type);
210 : :
211 [ # # ]: 0 : if (retCode != 0) {
212 : 0 : failed_backend = backend;
213 : : }
214 : : }
215 : : }
216 : 0 : return failed_backend;
217 : : }
218 : :
219 : 177 : void z_log_vprintk(const char *fmt, va_list ap)
220 : : {
221 : 177 : if (!IS_ENABLED(CONFIG_LOG_PRINTK)) {
222 : : return;
223 : : }
224 : :
225 : 177 : z_log_msg_runtime_vcreate(Z_LOG_LOCAL_DOMAIN_ID, NULL,
226 : : LOG_LEVEL_INTERNAL_RAW_STRING, NULL, 0,
227 : : Z_LOG_MSG_CBPRINTF_FLAGS(0),
228 : : fmt, ap);
229 : : }
230 : :
231 : : #ifndef CONFIG_LOG_TIMESTAMP_USE_REALTIME
232 : 177 : static log_timestamp_t default_get_timestamp(void)
233 : : {
234 : 177 : return IS_ENABLED(CONFIG_LOG_TIMESTAMP_64BIT) ?
235 : 177 : sys_clock_tick_get() : k_cycle_get_32();
236 : : }
237 : :
238 : : static log_timestamp_t default_lf_get_timestamp(void)
239 : : {
240 : : return IS_ENABLED(CONFIG_LOG_TIMESTAMP_64BIT) ?
241 : : k_uptime_get() : k_uptime_get_32();
242 : : }
243 : : #else
244 : : static log_timestamp_t default_rt_get_timestamp(void)
245 : : {
246 : : struct timespec tspec;
247 : :
248 : : sys_clock_gettime(SYS_CLOCK_REALTIME, &tspec);
249 : :
250 : : return ((uint64_t)tspec.tv_sec * MSEC_PER_SEC) + (tspec.tv_nsec / NSEC_PER_MSEC);
251 : : }
252 : : #endif /* CONFIG_LOG_TIMESTAMP_USE_REALTIME */
253 : :
254 : 1 : void log_core_init(void)
255 : : {
256 : 1 : panic_mode = false;
257 : 1 : dropped_cnt = 0;
258 : 1 : buffered_cnt = 0;
259 : :
260 : 1 : if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
261 : : log_frontend_init();
262 : :
263 : : if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
264 : : for (uint16_t s = 0; s < log_src_cnt_get(0); s++) {
265 : : log_frontend_filter_set(s, CONFIG_LOG_MAX_LEVEL);
266 : : }
267 : : }
268 : :
269 : : if (IS_ENABLED(CONFIG_LOG_FRONTEND_ONLY)) {
270 : : return;
271 : : }
272 : : }
273 : :
274 : : /* Set default timestamp. */
275 : : #ifdef CONFIG_LOG_TIMESTAMP_USE_REALTIME
276 : : log_set_timestamp_func(default_rt_get_timestamp, 1000U);
277 : : #else
278 : 1 : if (sys_clock_hw_cycles_per_sec() > 1000000) {
279 : : log_set_timestamp_func(default_lf_get_timestamp, 1000U);
280 : : } else {
281 : 1 : uint32_t freq = IS_ENABLED(CONFIG_LOG_TIMESTAMP_64BIT) ?
282 : : CONFIG_SYS_CLOCK_TICKS_PER_SEC : sys_clock_hw_cycles_per_sec();
283 : 1 : log_set_timestamp_func(default_get_timestamp, freq);
284 : : }
285 : : #endif /* CONFIG_LOG_TIMESTAMP_USE_REALTIME */
286 : :
287 : 1 : if (IS_ENABLED(CONFIG_LOG_MODE_DEFERRED)) {
288 : : z_log_msg_init();
289 : : }
290 : :
291 : 1 : if (IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
292 : : z_log_runtime_filters_init();
293 : : }
294 : :
295 [ - + + + ]: 2 : STRUCT_SECTION_FOREACH(log_backend, backend) {
296 : 1 : uint32_t id;
297 : : /* As first slot in filtering mask is reserved, backend ID has offset.*/
298 : 1 : id = LOG_FILTER_FIRST_BACKEND_SLOT_IDX;
299 : 1 : id += backend - log_backend_get(0);
300 : 1 : log_backend_id_set(backend, id);
301 : : }
302 : : }
303 : :
304 : 0 : static uint32_t activate_foreach_backend(uint32_t mask)
305 : : {
306 : 0 : uint32_t mask_cpy = mask;
307 : :
308 [ # # ]: 0 : while (mask_cpy) {
309 : 0 : uint32_t i = __builtin_ctz(mask_cpy);
310 : 0 : const struct log_backend *backend = log_backend_get(i);
311 : :
312 : 0 : mask_cpy &= ~BIT(i);
313 [ # # # # ]: 0 : if (backend->autostart && (log_backend_is_ready(backend) == 0)) {
314 : 0 : uint32_t level = CONFIG_LOG_MAX_LEVEL;
315 : :
316 : : #if defined(CONFIG_LOG_RUNTIME_FILTERING) && defined(CONFIG_LOG_RUNTIME_DEFAULT_LEVEL)
317 : : level = CONFIG_LOG_RUNTIME_DEFAULT_LEVEL;
318 : : #endif
319 : 0 : mask &= ~BIT(i);
320 : 0 : log_backend_enable(backend, backend->cb->ctx, level);
321 : : }
322 : : }
323 : :
324 : 0 : return mask;
325 : : }
326 : :
327 : 2 : static uint32_t z_log_init(bool blocking, bool can_sleep)
328 : : {
329 : 2 : uint32_t mask = 0;
330 : :
331 : 2 : if (IS_ENABLED(CONFIG_LOG_FRONTEND_ONLY)) {
332 : : return 0;
333 : : }
334 : :
335 [ - + ]: 2 : __ASSERT_NO_MSG(log_backend_count_get() < LOG_FILTERS_MAX_BACKENDS);
336 : :
337 [ + + ]: 2 : if (atomic_inc(&initialized) != 0) {
338 : : return 0;
339 : : }
340 : :
341 : : if (IS_ENABLED(CONFIG_LOG_MULTIDOMAIN)) {
342 : : z_log_links_initiate();
343 : : }
344 : :
345 : : int backend_index = 0;
346 : :
347 [ - + + + ]: 2 : STRUCT_SECTION_FOREACH(log_backend, backend) {
348 : : /* Activate autostart backends */
349 [ - + ]: 1 : if (backend->autostart) {
350 : 1 : uint32_t level = CONFIG_LOG_MAX_LEVEL;
351 : :
352 : : #if defined(CONFIG_LOG_RUNTIME_FILTERING) && defined(CONFIG_LOG_RUNTIME_DEFAULT_LEVEL)
353 : : level = CONFIG_LOG_RUNTIME_DEFAULT_LEVEL;
354 : : #endif
355 : 1 : log_backend_init(backend);
356 : :
357 : : /* If backend has activation function then backend is
358 : : * not ready until activated.
359 : : */
360 [ + - ]: 1 : if (log_backend_is_ready(backend) == 0) {
361 : 1 : log_backend_enable(backend, backend->cb->ctx, level);
362 : : } else {
363 : 0 : mask |= BIT(backend_index);
364 : : }
365 : : }
366 : :
367 : 1 : ++backend_index;
368 : : }
369 : :
370 : : /* If blocking init, wait until all backends are activated. */
371 [ - + ]: 1 : if (blocking) {
372 [ # # ]: 0 : while (mask) {
373 : 0 : mask = activate_foreach_backend(mask);
374 [ # # ]: 0 : if (IS_ENABLED(CONFIG_MULTITHREADING) && can_sleep) {
375 : 0 : k_msleep(10);
376 : : }
377 : : }
378 : : }
379 : :
380 : : return mask;
381 : : }
382 : :
383 : 0 : void log_init(void)
384 : : {
385 : 0 : (void)z_log_init(true, true);
386 : 0 : }
387 : :
388 : 0 : void log_thread_trigger(void)
389 : : {
390 : 0 : if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
391 : 0 : return;
392 : : }
393 : :
394 : : k_timer_stop(&log_process_thread_timer);
395 : : k_sem_give(&log_process_thread_sem);
396 : : }
397 : :
398 : 0 : static void thread_set(k_tid_t process_tid)
399 : : {
400 : 0 : proc_tid = process_tid;
401 : :
402 : 0 : if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
403 : 0 : return;
404 : : }
405 : :
406 : : if (CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD &&
407 : : process_tid &&
408 : : buffered_cnt >= CONFIG_LOG_PROCESS_TRIGGER_THRESHOLD) {
409 : : k_sem_give(&log_process_thread_sem);
410 : : }
411 : : }
412 : :
413 : 0 : void log_thread_set(k_tid_t process_tid)
414 : : {
415 : 0 : if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
416 : : __ASSERT_NO_MSG(0);
417 : : } else {
418 : 0 : thread_set(process_tid);
419 : : }
420 : 0 : }
421 : :
422 : 1 : int log_set_timestamp_func(log_timestamp_get_t timestamp_getter, uint32_t freq)
423 : : {
424 [ + - ]: 1 : if (timestamp_getter == NULL) {
425 : : return -EINVAL;
426 : : }
427 : :
428 : 1 : timestamp_func = timestamp_getter;
429 : 1 : timestamp_freq = freq;
430 : 1 : if (CONFIG_LOG_PROCESSING_LATENCY_US) {
431 : : proc_latency = (freq * CONFIG_LOG_PROCESSING_LATENCY_US) / 1000000;
432 : : }
433 : :
434 : 1 : if (IS_ENABLED(CONFIG_LOG_OUTPUT)) {
435 : 1 : log_output_timestamp_freq_set(freq);
436 : : }
437 : :
438 : 1 : return 0;
439 : : }
440 : :
441 : 1 : void z_impl_log_panic(void)
442 : : {
443 [ + - ]: 1 : if (panic_mode) {
444 : : return;
445 : : }
446 : :
447 : : /* If panic happened early logger might not be initialized.
448 : : * Forcing initialization of the logger and auto-starting backends.
449 : : */
450 : 1 : (void)z_log_init(true, false);
451 : :
452 : 1 : if (IS_ENABLED(CONFIG_LOG_FRONTEND)) {
453 : : log_frontend_panic();
454 : : if (IS_ENABLED(CONFIG_LOG_FRONTEND_ONLY)) {
455 : : goto out;
456 : : }
457 : : }
458 : :
459 [ - + + + ]: 2 : STRUCT_SECTION_FOREACH(log_backend, backend) {
460 [ + - ]: 1 : if (log_backend_is_active(backend)) {
461 : 1 : log_backend_panic(backend);
462 : : }
463 : : }
464 : :
465 : 1 : if (!IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
466 : : /* Flush */
467 : : while (log_process() == true) {
468 : : }
469 : : }
470 : :
471 : 1 : out:
472 : 1 : panic_mode = true;
473 : : }
474 : :
475 : : #ifdef CONFIG_USERSPACE
476 : : void z_vrfy_log_panic(void)
477 : : {
478 : : z_impl_log_panic();
479 : : }
480 : : #include <zephyr/syscalls/log_panic_mrsh.c>
481 : : #endif
482 : :
483 : 177 : static bool msg_filter_check(struct log_backend const *backend,
484 : : union log_msg_generic *msg)
485 : : {
486 : 177 : if (!z_log_item_is_msg(msg)) {
487 : : return true;
488 : : }
489 : :
490 : 177 : if (!IS_ENABLED(CONFIG_LOG_RUNTIME_FILTERING)) {
491 : 177 : return true;
492 : : }
493 : :
494 : : uint32_t backend_level;
495 : : uint8_t level;
496 : : uint8_t domain_id;
497 : : int16_t source_id;
498 : :
499 : : level = log_msg_get_level(&msg->log);
500 : : domain_id = log_msg_get_domain(&msg->log);
501 : : source_id = log_msg_get_source_id(&msg->log);
502 : :
503 : : /* Accept all non-logging messages. */
504 : : if (level == LOG_LEVEL_NONE) {
505 : : return true;
506 : : }
507 : : if (source_id >= 0) {
508 : : backend_level = log_filter_get(backend, domain_id, source_id, true);
509 : :
510 : : return (level <= backend_level);
511 : : } else {
512 : : return true;
513 : : }
514 : : }
515 : :
516 : 177 : static void msg_process(union log_msg_generic *msg)
517 : : {
518 [ - + + + ]: 354 : STRUCT_SECTION_FOREACH(log_backend, backend) {
519 [ + - ]: 177 : if (log_backend_is_active(backend) &&
520 [ + - ]: 177 : msg_filter_check(backend, msg)) {
521 : 177 : log_backend_msg_process(backend, msg);
522 : : }
523 : : }
524 : 177 : }
525 : :
526 : 0 : void dropped_notify(void)
527 : : {
528 : 0 : uint32_t dropped = z_log_dropped_read_and_clear();
529 : :
530 [ # # # # ]: 0 : STRUCT_SECTION_FOREACH(log_backend, backend) {
531 [ # # ]: 0 : if (log_backend_is_active(backend)) {
532 : 0 : log_backend_dropped(backend, dropped);
533 : : }
534 : : }
535 : 0 : }
536 : :
537 : 0 : void unordered_notify(void)
538 : : {
539 : 0 : uint32_t unordered = atomic_set(&unordered_cnt, 0);
540 : :
541 : 0 : LOG_WRN("%d unordered messages since last report", unordered);
542 : 0 : }
543 : :
544 : 1 : void z_log_notify_backend_enabled(void)
545 : : {
546 : : /* Wakeup logger thread after attaching first backend. It might be
547 : : * blocked with log messages pending.
548 : : */
549 : 1 : if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD) && !backend_attached) {
550 : : k_sem_give(&log_process_thread_sem);
551 : : }
552 : :
553 : 1 : backend_attached = true;
554 : 1 : }
555 : :
556 : : static inline bool z_log_unordered_pending(void)
557 : : {
558 : : return IS_ENABLED(CONFIG_LOG_MULTIDOMAIN) && unordered_cnt;
559 : : }
560 : :
561 : 0 : bool z_impl_log_process(void)
562 : : {
563 : 0 : if (!IS_ENABLED(CONFIG_LOG_MODE_DEFERRED)) {
564 : 0 : return false;
565 : : }
566 : :
567 : : k_timeout_t backoff = K_NO_WAIT;
568 : : union log_msg_generic *msg;
569 : :
570 : : if (!backend_attached) {
571 : : return false;
572 : : }
573 : :
574 : : msg = z_log_msg_claim(&backoff);
575 : :
576 : : if (msg) {
577 : : msg_process(msg);
578 : : z_log_msg_free(msg);
579 : : atomic_dec(&buffered_cnt);
580 : : } else if (CONFIG_LOG_PROCESSING_LATENCY_US > 0 && !K_TIMEOUT_EQ(backoff, K_NO_WAIT)) {
581 : : /* If backoff is requested, it means that there are pending
582 : : * messages but they are too new and processing shall back off
583 : : * to allow arrival of newer messages from remote domains.
584 : : */
585 : : k_timer_start(&log_process_thread_timer, backoff, K_NO_WAIT);
586 : :
587 : : return false;
588 : : }
589 : :
590 : : if (IS_ENABLED(CONFIG_LOG_MODE_DEFERRED)) {
591 : : bool dropped_pend = z_log_dropped_pending();
592 : : bool unordered_pend = z_log_unordered_pending();
593 : :
594 : : if ((dropped_pend || unordered_pend) &&
595 : : (k_uptime_get() - last_failure_report) > CONFIG_LOG_FAILURE_REPORT_PERIOD) {
596 : : if (dropped_pend) {
597 : : dropped_notify();
598 : : }
599 : :
600 : : if (unordered_pend) {
601 : : unordered_notify();
602 : : }
603 : : }
604 : :
605 : : last_failure_report += CONFIG_LOG_FAILURE_REPORT_PERIOD;
606 : : }
607 : :
608 : : return z_log_msg_pending();
609 : : }
610 : :
611 : : #ifdef CONFIG_USERSPACE
612 : : bool z_vrfy_log_process(void)
613 : : {
614 : : return z_impl_log_process();
615 : : }
616 : : #include <zephyr/syscalls/log_process_mrsh.c>
617 : : #endif
618 : :
619 : 0 : uint32_t z_impl_log_buffered_cnt(void)
620 : : {
621 : 0 : return buffered_cnt;
622 : : }
623 : :
624 : : #ifdef CONFIG_USERSPACE
625 : : uint32_t z_vrfy_log_buffered_cnt(void)
626 : : {
627 : : return z_impl_log_buffered_cnt();
628 : : }
629 : : #include <zephyr/syscalls/log_buffered_cnt_mrsh.c>
630 : : #endif
631 : :
632 : 0 : void z_log_dropped(bool buffered)
633 : : {
634 : 0 : atomic_inc(&dropped_cnt);
635 [ # # ]: 0 : if (buffered) {
636 : 0 : atomic_dec(&buffered_cnt);
637 : : }
638 : :
639 : 0 : if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
640 : : k_timer_stop(&log_process_thread_timer);
641 : : k_sem_give(&log_process_thread_sem);
642 : : }
643 : 0 : }
644 : :
645 : 0 : uint32_t z_log_dropped_read_and_clear(void)
646 : : {
647 : 0 : return atomic_set(&dropped_cnt, 0);
648 : : }
649 : :
650 : 0 : bool z_log_dropped_pending(void)
651 : : {
652 : 0 : return dropped_cnt > 0;
653 : : }
654 : :
655 : 0 : void z_log_msg_init(void)
656 : : {
657 : : #ifdef CONFIG_MPSC_PBUF
658 : : mpsc_pbuf_init(&log_buffer, &mpsc_config);
659 : : curr_log_buffer = &log_buffer;
660 : : #endif
661 : 0 : }
662 : :
663 : 0 : static struct log_msg *msg_alloc(struct mpsc_pbuf_buffer *buffer, uint32_t wlen)
664 : : {
665 : 0 : if (!IS_ENABLED(CONFIG_LOG_MODE_DEFERRED)) {
666 : 0 : return NULL;
667 : : }
668 : :
669 : : return (struct log_msg *)mpsc_pbuf_alloc(
670 : : buffer, wlen,
671 : : (CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS == -1)
672 : : ? K_FOREVER
673 : : : K_MSEC(CONFIG_LOG_BLOCK_IN_THREAD_TIMEOUT_MS));
674 : : }
675 : :
676 : 0 : struct log_msg *z_log_msg_alloc(uint32_t wlen)
677 : : {
678 : 0 : return msg_alloc(&log_buffer, wlen);
679 : : }
680 : :
681 : 177 : static void msg_commit(struct mpsc_pbuf_buffer *buffer, struct log_msg *msg)
682 : : {
683 : 177 : union log_msg_generic *m = (union log_msg_generic *)msg;
684 : :
685 : 177 : if (IS_ENABLED(CONFIG_LOG_MODE_IMMEDIATE)) {
686 : 177 : k_spinlock_key_t key;
687 : :
688 : 177 : if (IS_ENABLED(CONFIG_LOG_IMMEDIATE_CLEAN_OUTPUT)) {
689 : : key = k_spin_lock(&process_lock);
690 : : }
691 : :
692 : 177 : msg_process(m);
693 : :
694 : 177 : if (IS_ENABLED(CONFIG_LOG_IMMEDIATE_CLEAN_OUTPUT)) {
695 : : k_spin_unlock(&process_lock, key);
696 : : }
697 : :
698 : 177 : return;
699 : : }
700 : :
701 : : #ifdef CONFIG_MPSC_PBUF
702 : : mpsc_pbuf_commit(buffer, &m->buf);
703 : : #endif
704 : : z_log_msg_post_finalize();
705 : : }
706 : :
707 : 177 : void z_log_msg_commit(struct log_msg *msg)
708 : : {
709 : 177 : msg->hdr.timestamp = timestamp_func();
710 : 177 : msg_commit(&log_buffer, msg);
711 : 177 : }
712 : :
713 : 0 : union log_msg_generic *z_log_msg_local_claim(void)
714 : : {
715 : : #ifdef CONFIG_MPSC_PBUF
716 : : return (union log_msg_generic *)mpsc_pbuf_claim(&log_buffer);
717 : : #else
718 : 0 : return NULL;
719 : : #endif
720 : :
721 : : }
722 : :
723 : : /* If there are buffers dedicated for each link, claim the oldest message (lowest timestamp). */
724 : 0 : union log_msg_generic *z_log_msg_claim_oldest(k_timeout_t *backoff)
725 : : {
726 : 0 : union log_msg_generic *msg = NULL;
727 : 0 : struct log_msg_ptr *chosen = NULL;
728 : 0 : log_timestamp_t t_min = sizeof(log_timestamp_t) > sizeof(uint32_t) ?
729 : : UINT64_MAX : UINT32_MAX;
730 : 0 : int i = 0;
731 : :
732 : : /* Else iterate on all available buffers and get the oldest message. */
733 [ # # # # ]: 0 : STRUCT_SECTION_FOREACH(log_msg_ptr, msg_ptr) {
734 : 0 : struct log_mpsc_pbuf *buf;
735 : :
736 : 0 : STRUCT_SECTION_GET(log_mpsc_pbuf, i, &buf);
737 : :
738 : : #ifdef CONFIG_MPSC_PBUF
739 : : if (msg_ptr->msg == NULL) {
740 : : msg_ptr->msg = (union log_msg_generic *)mpsc_pbuf_claim(&buf->buf);
741 : : }
742 : : #endif
743 : :
744 [ # # ]: 0 : if (msg_ptr->msg) {
745 : 0 : log_timestamp_t t = log_msg_get_timestamp(&msg_ptr->msg->log);
746 : :
747 [ # # ]: 0 : if (t < t_min) {
748 : 0 : t_min = t;
749 : 0 : msg = msg_ptr->msg;
750 : 0 : chosen = msg_ptr;
751 : 0 : curr_log_buffer = &buf->buf;
752 : : }
753 : : }
754 : 0 : i++;
755 : : }
756 : :
757 [ # # ]: 0 : if (msg) {
758 : 0 : if (CONFIG_LOG_PROCESSING_LATENCY_US > 0) {
759 : : int32_t diff = t_min - (timestamp_func() - proc_latency);
760 : :
761 : : if (diff > 0) {
762 : : /* Entry is too new. Back off for sometime to allow new
763 : : * remote messages to arrive which may have been captured
764 : : * earlier (but on other platform). Calculate for how
765 : : * long processing shall back off.
766 : : */
767 : : if (timestamp_freq == sys_clock_hw_cycles_per_sec()) {
768 : : *backoff = K_CYC(diff);
769 : : } else {
770 : : *backoff = K_CYC((diff * sys_clock_hw_cycles_per_sec()) /
771 : : timestamp_freq);
772 : : }
773 : :
774 : : return NULL;
775 : : }
776 : : }
777 : :
778 : 0 : (*chosen).msg = NULL;
779 : : }
780 : :
781 [ # # ]: 0 : if (t_min < prev_timestamp) {
782 : 0 : atomic_inc(&unordered_cnt);
783 : : }
784 : :
785 : 0 : prev_timestamp = t_min;
786 : :
787 : 0 : return msg;
788 : : }
789 : :
790 : 0 : union log_msg_generic *z_log_msg_claim(k_timeout_t *backoff)
791 : : {
792 : 0 : size_t len;
793 : :
794 : 0 : STRUCT_SECTION_COUNT(log_mpsc_pbuf, &len);
795 : :
796 : : /* Use only one buffer if others are not registered. */
797 : 0 : if (IS_ENABLED(CONFIG_LOG_MULTIDOMAIN) && len > 1) {
798 : : return z_log_msg_claim_oldest(backoff);
799 : : }
800 : :
801 : 0 : return z_log_msg_local_claim();
802 : : }
803 : :
804 : : static void msg_free(struct mpsc_pbuf_buffer *buffer, const union log_msg_generic *msg)
805 : : {
806 : : #ifdef CONFIG_MPSC_PBUF
807 : : mpsc_pbuf_free(buffer, &msg->buf);
808 : : #endif
809 : : }
810 : :
811 : 0 : void z_log_msg_free(union log_msg_generic *msg)
812 : : {
813 : 0 : msg_free(curr_log_buffer, msg);
814 : 0 : }
815 : :
816 : 0 : static bool msg_pending(struct mpsc_pbuf_buffer *buffer)
817 : : {
818 : : #ifdef CONFIG_MPSC_PBUF
819 : : return mpsc_pbuf_is_pending(buffer);
820 : : #else
821 : 0 : return false;
822 : : #endif
823 : : }
824 : :
825 : 0 : bool z_log_msg_pending(void)
826 : : {
827 : 0 : size_t len;
828 : 0 : int i = 0;
829 : :
830 : 0 : STRUCT_SECTION_COUNT(log_mpsc_pbuf, &len);
831 : :
832 : 0 : if (!IS_ENABLED(CONFIG_LOG_MULTIDOMAIN) || (len == 1)) {
833 : 0 : return msg_pending(&log_buffer);
834 : : }
835 : :
836 : : STRUCT_SECTION_FOREACH(log_msg_ptr, msg_ptr) {
837 : : struct log_mpsc_pbuf *buf;
838 : :
839 : : if (msg_ptr->msg) {
840 : : return true;
841 : : }
842 : :
843 : : STRUCT_SECTION_GET(log_mpsc_pbuf, i, &buf);
844 : :
845 : : if (msg_pending(&buf->buf)) {
846 : : return true;
847 : : }
848 : :
849 : : i++;
850 : : }
851 : :
852 : : return false;
853 : : }
854 : :
855 : 0 : void z_log_msg_enqueue(const struct log_link *link, const void *data, size_t len)
856 : : {
857 : 0 : struct log_msg *log_msg = (struct log_msg *)data;
858 : 0 : size_t wlen = DIV_ROUND_UP(ROUND_UP(len, Z_LOG_MSG_ALIGNMENT), sizeof(int));
859 [ # # ]: 0 : struct mpsc_pbuf_buffer *mpsc_pbuffer = link->mpsc_pbuf ? link->mpsc_pbuf : &log_buffer;
860 : 0 : struct log_msg *local_msg = msg_alloc(mpsc_pbuffer, wlen);
861 : :
862 [ # # ]: 0 : if (!local_msg) {
863 : 0 : z_log_dropped(false);
864 : 0 : return;
865 : : }
866 : :
867 : 0 : log_msg->hdr.desc.valid = 0;
868 : 0 : log_msg->hdr.desc.busy = 0;
869 : 0 : log_msg->hdr.desc.domain += link->ctrl_blk->domain_offset;
870 : 0 : memcpy((void *)local_msg, data, len);
871 : 0 : msg_commit(mpsc_pbuffer, local_msg);
872 : : }
873 : :
874 : 0 : const char *z_log_get_tag(void)
875 : : {
876 : 0 : return CONFIG_LOG_TAG_MAX_LEN > 0 ? tag : NULL;
877 : : }
878 : :
879 : 0 : int log_set_tag(const char *str)
880 : : {
881 : : #if CONFIG_LOG_TAG_MAX_LEN > 0
882 : : if (str == NULL) {
883 : : return -EINVAL;
884 : : }
885 : :
886 : : size_t len = strlen(str);
887 : : size_t cpy_len = MIN(len, CONFIG_LOG_TAG_MAX_LEN);
888 : :
889 : : memcpy(tag, str, cpy_len);
890 : : tag[cpy_len] = '\0';
891 : :
892 : : if (cpy_len < len) {
893 : : tag[cpy_len - 1] = '~';
894 : : return -ENOMEM;
895 : : }
896 : :
897 : : return 0;
898 : : #else
899 : 0 : return -ENOTSUP;
900 : : #endif
901 : : }
902 : :
903 : 0 : int log_mem_get_usage(uint32_t *buf_size, uint32_t *usage)
904 : : {
905 [ # # ]: 0 : __ASSERT_NO_MSG(buf_size != NULL);
906 [ # # ]: 0 : __ASSERT_NO_MSG(usage != NULL);
907 : :
908 : 0 : if (!IS_ENABLED(CONFIG_LOG_MODE_DEFERRED)) {
909 : 0 : return -EINVAL;
910 : : }
911 : :
912 : : mpsc_pbuf_get_utilization(&log_buffer, buf_size, usage);
913 : :
914 : : return 0;
915 : : }
916 : :
917 : 0 : int log_mem_get_max_usage(uint32_t *max)
918 : : {
919 [ # # ]: 0 : __ASSERT_NO_MSG(max != NULL);
920 : :
921 : 0 : if (!IS_ENABLED(CONFIG_LOG_MODE_DEFERRED)) {
922 : 0 : return -EINVAL;
923 : : }
924 : :
925 : : return mpsc_pbuf_get_max_utilization(&log_buffer, max);
926 : : }
927 : :
928 : : static void log_backend_notify_all(enum log_backend_evt event,
929 : : union log_backend_evt_arg *arg)
930 : : {
931 : : STRUCT_SECTION_FOREACH(log_backend, backend) {
932 : : log_backend_notify(backend, event, arg);
933 : : }
934 : : }
935 : :
936 : : static void log_process_thread_timer_expiry_fn(struct k_timer *timer)
937 : : {
938 : : k_sem_give(&log_process_thread_sem);
939 : : }
940 : :
941 : : static void log_process_thread_func(void *dummy1, void *dummy2, void *dummy3)
942 : : {
943 : : __ASSERT_NO_MSG(log_backend_count_get() > 0);
944 : : uint32_t links_active_mask = 0xFFFFFFFF;
945 : : uint8_t domain_offset = 0;
946 : : uint32_t activate_mask = z_log_init(false, false);
947 : : /* If some backends are not activated yet set periodical thread wake up
948 : : * to poll backends for readiness. Period is set arbitrary.
949 : : * If all backends are ready periodic wake up is not needed.
950 : : */
951 : : k_timeout_t timeout = (activate_mask != 0) ? K_MSEC(50) : K_FOREVER;
952 : : bool processed_any = false;
953 : : thread_set(k_current_get());
954 : :
955 : : /* Logging thread is periodically waken up until all backends that
956 : : * should be autostarted are ready.
957 : : */
958 : : while (true) {
959 : : if (activate_mask) {
960 : : activate_mask = activate_foreach_backend(activate_mask);
961 : : if (!activate_mask) {
962 : : /* Periodic wake up no longer needed since all
963 : : * backends are ready.
964 : : */
965 : : timeout = K_FOREVER;
966 : : }
967 : : }
968 : :
969 : : /* Keep trying to activate links until all links are active. */
970 : : if (IS_ENABLED(CONFIG_LOG_MULTIDOMAIN) && links_active_mask) {
971 : : links_active_mask =
972 : : z_log_links_activate(links_active_mask, &domain_offset);
973 : : }
974 : :
975 : :
976 : : if (log_process() == false) {
977 : : if (processed_any) {
978 : : processed_any = false;
979 : : log_backend_notify_all(LOG_BACKEND_EVT_PROCESS_THREAD_DONE, NULL);
980 : : }
981 : : (void)k_sem_take(&log_process_thread_sem, timeout);
982 : : } else {
983 : : processed_any = true;
984 : : }
985 : : }
986 : : }
987 : :
988 : : K_KERNEL_STACK_DEFINE(logging_stack, CONFIG_LOG_PROCESS_THREAD_STACK_SIZE);
989 : : struct k_thread logging_thread;
990 : :
991 : 1 : static int enable_logger(void)
992 : : {
993 : 1 : if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
994 : : k_timer_init(&log_process_thread_timer,
995 : : log_process_thread_timer_expiry_fn, NULL);
996 : : /* start logging thread */
997 : : k_thread_create(&logging_thread, logging_stack,
998 : : K_KERNEL_STACK_SIZEOF(logging_stack),
999 : : log_process_thread_func, NULL, NULL, NULL,
1000 : : LOG_PROCESS_THREAD_PRIORITY, 0,
1001 : : COND_CODE_1(CONFIG_LOG_PROCESS_THREAD,
1002 : : K_MSEC(CONFIG_LOG_PROCESS_THREAD_STARTUP_DELAY_MS),
1003 : : K_NO_WAIT));
1004 : : k_thread_name_set(&logging_thread, "logging");
1005 : : } else {
1006 : 1 : (void)z_log_init(false, false);
1007 : : }
1008 : :
1009 : 1 : return 0;
1010 : : }
1011 : :
1012 : : #ifdef CONFIG_LOG_MODE_DEFERRED
1013 : : void log_flush(void)
1014 : : {
1015 : : if (IS_ENABLED(CONFIG_LOG_PROCESS_THREAD)) {
1016 : : while (atomic_get(&buffered_cnt)) {
1017 : : log_thread_trigger();
1018 : : k_sleep(K_USEC(CONFIG_LOG_FLUSH_SLEEP_US));
1019 : : }
1020 : : } else {
1021 : : while (LOG_PROCESS()) {
1022 : : }
1023 : : }
1024 : : }
1025 : : #endif
1026 : :
1027 : : SYS_INIT(enable_logger, POST_KERNEL, CONFIG_LOG_CORE_INIT_PRIORITY);
|
