trace: Adaptive rate-limiting of repetitive messages

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

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

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

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

src/include/sof/trace/trace.h

@@ -136,21 +136,20 @@ void trace_flush(void);
 void trace_on(void);
 void trace_off(void);
 void trace_init(struct sof *sof);
-void trace_log(bool send_atomic, const void *log_entry,
-	       const struct tr_ctx *ctx, uint32_t lvl, uint32_t id_1,
-	       uint32_t id_2, int arg_count, ...);
+void trace_log_filtered(bool send_atomic, const void *log_entry, const struct tr_ctx *ctx,
+			uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...);
+void trace_log_unfiltered(bool send_atomic, const void *log_entry, const struct tr_ctx *ctx,
+			  uint32_t lvl, uint32_t id_1, uint32_t id_2, int arg_count, ...);
 struct sof_ipc_trace_filter_elem *trace_filter_fill(struct sof_ipc_trace_filter_elem *elem,
 						    struct sof_ipc_trace_filter_elem *end,
 						    struct trace_filter *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
 
@@ -191,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(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)
@@ -273,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__)

src/trace/Kconfig

@@ -31,4 +31,60 @@ 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.
+
+config TRACE_BURST_COUNT
+	int "Allowed amount of rapidly repeated messages, that will not be suppressed by the filter"
+	depends on TRACE_FILTERING_ADAPTIVE
+	default 4
+	help
+		Amount of messages that will pass through the filter even if sent in rapid succession.
+		Allowed message burst size before filter suppresses the message.
+
 endmenu