diff --git a/src/arch/xtensa/configs/baytrail_defconfig b/src/arch/xtensa/configs/baytrail_defconfig index 3068f1ccc..294426bbe 100644 --- a/src/arch/xtensa/configs/baytrail_defconfig +++ b/src/arch/xtensa/configs/baytrail_defconfig @@ -12,3 +12,4 @@ CONFIG_COMP_TDFB=n CONFIG_OPTIMIZE_FOR_SIZE=y CONFIG_HAVE_AGENT=n CONFIG_DEBUG_MEMORY_USAGE_SCAN=n +CONFIG_TRACE_FILTERING_ADAPTIVE=n diff --git a/src/arch/xtensa/configs/baytrail_gcc_defconfig b/src/arch/xtensa/configs/baytrail_gcc_defconfig index 3ffaf3811..e48ac786c 100644 --- a/src/arch/xtensa/configs/baytrail_gcc_defconfig +++ b/src/arch/xtensa/configs/baytrail_gcc_defconfig @@ -11,3 +11,4 @@ CONFIG_COMP_ASRC=n CONFIG_COMP_TDFB=n CONFIG_HAVE_AGENT=n CONFIG_DEBUG_MEMORY_USAGE_SCAN=n +CONFIG_TRACE_FILTERING_ADAPTIVE=n diff --git a/src/arch/xtensa/configs/cherrytrail_defconfig b/src/arch/xtensa/configs/cherrytrail_defconfig index 355278634..1692f7fcb 100644 --- a/src/arch/xtensa/configs/cherrytrail_defconfig +++ b/src/arch/xtensa/configs/cherrytrail_defconfig @@ -13,3 +13,4 @@ CONFIG_COMP_TONE=n CONFIG_OPTIMIZE_FOR_SIZE=y CONFIG_HAVE_AGENT=n CONFIG_DEBUG_MEMORY_USAGE_SCAN=n +CONFIG_TRACE_FILTERING_ADAPTIVE=n diff --git a/src/arch/xtensa/configs/cherrytrail_gcc_defconfig b/src/arch/xtensa/configs/cherrytrail_gcc_defconfig index 43b203bfa..490ded181 100644 --- a/src/arch/xtensa/configs/cherrytrail_gcc_defconfig +++ b/src/arch/xtensa/configs/cherrytrail_gcc_defconfig @@ -11,3 +11,4 @@ CONFIG_COMP_ASRC=n CONFIG_COMP_TDFB=n CONFIG_HAVE_AGENT=n CONFIG_DEBUG_MEMORY_USAGE_SCAN=n +CONFIG_TRACE_FILTERING_ADAPTIVE=n diff --git a/src/include/sof/trace/trace.h b/src/include/sof/trace/trace.h index c8ff27e2a..b5f410fa3 100644 --- a/src/include/sof/trace/trace.h +++ b/src/include/sof/trace/trace.h @@ -146,12 +146,10 @@ struct sof_ipc_trace_filter_elem *trace_filter_fill(struct sof_ipc_trace_filter_ int trace_filter_update(const struct trace_filter *elem); #define _trace_event_with_ids(lvl, class, ctx, id_1, id_2, format, ...) \ - _log_message(false, lvl, class, ctx, id_1, id_2, \ - format, ##__VA_ARGS__) + _log_message(trace_log_filtered, false, lvl, class, ctx, id_1, id_2, format, ##__VA_ARGS__) -#define _trace_event_atomic_with_ids(lvl, class, ctx, id_1, id_2, format, ...) \ - _log_message(true, lvl, class, ctx, id_1, \ - id_2, format, ##__VA_ARGS__) +#define _trace_event_atomic_with_ids(lvl, class, ctx, id_1, id_2, format, ...) \ + _log_message(trace_log_filtered, true, lvl, class, ctx, id_1, id_2, format, ##__VA_ARGS__) #ifndef CONFIG_LIBRARY @@ -192,37 +190,33 @@ _thrown_from_macro_BASE_LOG_in_trace_h #define STATIC_ASSERT_ARG_SIZE(...) \ META_MAP(1, trace_check_size_uint32, __VA_ARGS__) -#define _log_message(atomic, lvl, comp_class, ctx, id_1, id_2, \ - format, ...) \ -do { \ - _DECLARE_LOG_ENTRY(lvl, format, comp_class, \ - META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__)); \ - STATIC_ASSERT_ARG_SIZE(__VA_ARGS__); \ - STATIC_ASSERT(_TRACE_EVENT_MAX_ARGUMENT_COUNT >= \ - META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), \ - BASE_LOG_ASSERT_FAIL_MSG \ - ); \ - trace_log_filtered(atomic, &log_entry, ctx, lvl, id_1, id_2, \ - META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), \ - ##__VA_ARGS__); \ +#define _log_message(log_func, atomic, lvl, comp_class, ctx, id_1, id_2, format, ...) \ +do { \ + _DECLARE_LOG_ENTRY(lvl, format, comp_class, \ + META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__)); \ + STATIC_ASSERT_ARG_SIZE(__VA_ARGS__); \ + STATIC_ASSERT(_TRACE_EVENT_MAX_ARGUMENT_COUNT >= \ + META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), \ + BASE_LOG_ASSERT_FAIL_MSG \ + ); \ + log_func(atomic, &log_entry, ctx, lvl, id_1, id_2, \ + META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), ##__VA_ARGS__); \ } while (0) #else /* CONFIG_LIBRARY */ extern int test_bench_trace; char *get_trace_class(uint32_t trace_class); -#define _log_message(atomic, level, comp_class, ctx, id_1, id_2, \ - format, ...) \ -do { \ - (void)ctx; \ - (void)id_1; \ - (void)id_2; \ - if (test_bench_trace) { \ - char *msg = "%s " format; \ - fprintf(stderr, msg, get_trace_class(comp_class), \ - ##__VA_ARGS__); \ - fprintf(stderr, "\n"); \ - } \ +#define _log_message(log_func, atomic, level, comp_class, ctx, id_1, id_2, format, ...) \ +do { \ + (void)ctx; \ + (void)id_1; \ + (void)id_2; \ + if (test_bench_trace) { \ + char *msg = "%s " format; \ + fprintf(stderr, msg, get_trace_class(comp_class), ##__VA_ARGS__); \ + fprintf(stderr, "\n"); \ + } \ } while (0) #define trace_point(x) do {} while (0) @@ -274,8 +268,8 @@ static inline int trace_filter_update(const struct trace_filter *filter) /* error tracing */ #if CONFIG_TRACEE -#define _trace_error_with_ids(class, ctx, id_1, id_2, format, ...) \ - _log_message(true, LOG_LEVEL_CRITICAL, class, ctx, id_1, \ +#define _trace_error_with_ids(class, ctx, id_1, id_2, format, ...) \ + _log_message(trace_log_filtered, true, LOG_LEVEL_CRITICAL, class, ctx, id_1, \ id_2, format, ##__VA_ARGS__) #define trace_error_with_ids(class, ctx, id_1, id_2, format, ...) \ _trace_error_with_ids(class, ctx, id_1, id_2, format, ##__VA_ARGS__) diff --git a/src/trace/Kconfig b/src/trace/Kconfig index fdcd70878..f6b2adf12 100644 --- a/src/trace/Kconfig +++ b/src/trace/Kconfig @@ -31,4 +31,52 @@ config TRACEM help Sending all traces by mailbox additionally. +config TRACE_FILTERING + bool "Trace filtering" + depends on TRACE + default y + help + Filtering of trace messages based on their verbosity level and frequency. + +config TRACE_FILTERING_VERBOSITY + bool "Filter by verbosity" + depends on TRACE_FILTERING + default y + help + Filtering by log verbosity level, where maximum verbosity allowed is specified for each + context and may be adjusted in runtime. + +config TRACE_FILTERING_ADAPTIVE + bool "Adaptive rate limiting" + depends on TRACE_FILTERING + default y + help + Adaptive filtering of trace messages, tracking up to CONFIG_TRACE_RECENT_ENTRIES_COUNT, + suppressing all repeated messages for up to CONFIG_TRACE_RECENT_TIME_THRESHOLD cycles. + +config TRACE_RECENT_ENTRIES_COUNT + int "Amount of entries considered recent" + depends on TRACE_FILTERING_ADAPTIVE + default 5 + help + Recent entries are used to determine whether currently processed message was sent in the + past. Size of that filtering window affects effectiveness and performance. More recent + entries allow to better filter repetitive messeges out, but also slightly decrease + performance due to increased number of comparisions necessary. + +config TRACE_RECENT_TIME_THRESHOLD + int "Period of time considered recent (microseconds)" + depends on TRACE_FILTERING_ADAPTIVE + default 1500 + range 1 TRACE_RECENT_MAX_TIME + help + Period of time during which entries are tracked and will be suppressed if reported again. + +config TRACE_RECENT_MAX_TIME + int "Maximum period of time that message can be suppressed (microseconds)" + depends on TRACE_FILTERING_ADAPTIVE + default 5000000 + help + Maximum amount of time message can be suppressed for, due to repeated suppression. + endmenu diff --git a/src/trace/trace.c b/src/trace/trace.c index d8df3fb96..e7c92e9d1 100644 --- a/src/trace/trace.c +++ b/src/trace/trace.c @@ -26,10 +26,29 @@ #include #include +extern struct tr_ctx dt_tr; + +#if CONFIG_TRACE_FILTERING_ADAPTIVE +struct recent_log_entry { + uint32_t entry_id; + uint64_t message_ts; + uint64_t first_suppression_ts; + uint32_t suppress_count; +}; + +struct recent_trace_context { + struct recent_log_entry recent_entries[CONFIG_TRACE_RECENT_ENTRIES_COUNT]; +}; +#endif /* CONFIG_TRACE_FILTERING_ADAPTIVE */ + struct trace { uintptr_t pos ; /* trace position */ uint32_t enable; spinlock_t lock; /* locking mechanism */ + +#if CONFIG_TRACE_FILTERING_ADAPTIVE + struct recent_trace_context trace_core_context[CONFIG_CORE_COUNT]; +#endif }; /* calculates total message size, both header and payload in bytes */ @@ -96,19 +115,111 @@ static inline void mtrace_event(const char *data, uint32_t length) platform_shared_commit(trace, sizeof(*trace)); } +#if CONFIG_TRACE_FILTERING_VERBOSITY /** - * \brief Runtime trace filtering + * \brief Runtime trace filtering based on verbosity level * \param lvl log level (LOG_LEVEL_ ERROR, INFO, DEBUG ...) * \param uuid uuid address * \return false when trace is filtered out, otherwise true */ -static inline bool trace_filter_pass(uint32_t lvl, - const struct tr_ctx *ctx) +static inline bool trace_filter_verbosity(uint32_t lvl, const struct tr_ctx *ctx) { STATIC_ASSERT(LOG_LEVEL_CRITICAL < LOG_LEVEL_VERBOSE, LOG_LEVEL_CRITICAL_MUST_HAVE_LOWEST_VALUE); return lvl <= ctx->level; } +#endif /* CONFIG_TRACE_FILTERING_VERBOSITY */ + +#if CONFIG_TRACE_FILTERING_ADAPTIVE +static void emit_recent_entry(struct recent_log_entry *entry) +{ + _log_message(trace_log_unfiltered, false, LOG_LEVEL_INFO, _TRACE_INV_CLASS, &dt_tr, + _TRACE_INV_ID, _TRACE_INV_ID, "Suppressed %u similar messages: %pQ", + entry->suppress_count, entry->entry_id); + + memset(entry, 0, sizeof(*entry)); +} + +static void emit_recent_entries(uint64_t current_ts) +{ + struct trace *trace = trace_get(); + struct recent_log_entry *recent_entries = + trace->trace_core_context[cpu_get_id()].recent_entries; + int i; + + /* Check if any tracked entries were dormant long enough to unsuppress them */ + for (i = 0; i < CONFIG_TRACE_RECENT_ENTRIES_COUNT; i++) { + if (recent_entries[i].entry_id) { + if (current_ts - recent_entries[i].message_ts > + CONFIG_TRACE_RECENT_TIME_THRESHOLD) { + if (recent_entries[i].suppress_count) + emit_recent_entry(&recent_entries[i]); + } + } + } + + platform_shared_commit(trace, sizeof(*trace)); +} + +/** + * \brief Runtime trace flood suppression + * \param log_level log verbosity level + * \param entry ID of log entry + * \param message_ts message timestamp + * \return false when trace is filtered out, true otherwise + */ +static bool trace_filter_flood(uint32_t log_level, uint32_t entry, uint64_t message_ts) +{ + struct trace *trace = trace_get(); + struct recent_log_entry *recent_entries = + trace->trace_core_context[cpu_get_id()].recent_entries; + struct recent_log_entry *oldest_entry = recent_entries; + int i; + + /* don't attempt to suppress debug messages using this method, it would be uneffective */ + if (log_level >= LOG_LEVEL_DEBUG) + return true; + + /* check if same log entry was sent recently */ + for (i = 0; i < CONFIG_TRACE_RECENT_ENTRIES_COUNT; i++) { + /* in the meantime identify the oldest or an empty entry, for reuse later */ + if (oldest_entry->first_suppression_ts > recent_entries[i].first_suppression_ts) + oldest_entry = &recent_entries[i]; + + if (recent_entries[i].entry_id == entry) { + if (message_ts - recent_entries[i].first_suppression_ts < + CONFIG_TRACE_RECENT_MAX_TIME && + message_ts - recent_entries[i].message_ts < + CONFIG_TRACE_RECENT_TIME_THRESHOLD) { + recent_entries[i].suppress_count++; + /* refresh suppression timer */ + recent_entries[i].message_ts = message_ts; + + platform_shared_commit(trace, sizeof(*trace)); + return false; + } + + if (recent_entries[i].suppress_count) + emit_recent_entry(&recent_entries[i]); + else + memset(&recent_entries[i], 0, sizeof(recent_entries[i])); + platform_shared_commit(trace, sizeof(*trace)); + return true; + } + } + + /* Make room for tracking new entry, by emitting the oldest one in the filter */ + if (oldest_entry->entry_id && oldest_entry->suppress_count) + emit_recent_entry(oldest_entry); + + oldest_entry->entry_id = entry; + oldest_entry->message_ts = message_ts; + oldest_entry->first_suppression_ts = message_ts; + + platform_shared_commit(trace, sizeof(*trace)); + return true; +} +#endif /* CONFIG_TRACE_FILTERING_ADAPTIVE */ static void vatrace_log(bool send_atomic, uint32_t log_entry, const struct tr_ctx *ctx, uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, va_list vargs) @@ -170,12 +281,29 @@ void trace_log_filtered(bool send_atomic, const void *log_entry, const struct tr { struct trace *trace = trace_get(); va_list vl; +#if CONFIG_TRACE_FILTERING_ADAPTIVE + uint64_t current_ts; +#endif /* CONFIG_TRACE_FILTERING_ADAPTIVE */ - if (!trace->enable || !trace_filter_pass(lvl, ctx)) { + if (!trace->enable) { platform_shared_commit(trace, sizeof(*trace)); return; } +#if CONFIG_TRACE_FILTERING_VERBOSITY + if (!trace_filter_verbosity(lvl, ctx)) + return; +#endif /* CONFIG_TRACE_FILTERING_VERBOSITY */ + +#if CONFIG_TRACE_FILTERING_ADAPTIVE + current_ts = platform_timer_get(timer_get()); + + emit_recent_entries(current_ts); + + if (!trace_filter_flood(lvl, (uint32_t)log_entry, current_ts)) + return; +#endif /* CONFIG_TRACE_FILTERING_ADAPTIVE */ + va_start(vl, arg_count); vatrace_log(send_atomic, (uint32_t)log_entry, ctx, lvl, id_1, id_2, arg_count, vl); va_end(vl);