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