From 9af90ce211203741d6b377d3aed7b837e2734306 Mon Sep 17 00:00:00 2001 From: ArturX Kloniecki Date: Mon, 5 Nov 2018 15:02:39 +0100 Subject: [PATCH 1/4] debugability: Add components ids to trace_event macros 2 arbitrary IDs may now be passed to specialized versions of trace_event macro: trace_event_with_ids. Also optimized runtime stack usage of _trace_event functions. Signed-off-by: ArturX Kloniecki --- src/host/trace.c | 84 +++++---- src/include/sof/preproc-private.h | 2 +- src/include/sof/preproc.h | 23 +-- src/include/sof/trace.h | 298 +++++++++++++++++------------- src/include/uapi/logging.h | 21 ++- src/lib/trace.c | 234 +++++++++++++---------- 6 files changed, 369 insertions(+), 293 deletions(-) diff --git a/src/host/trace.c b/src/host/trace.c index 5c2c79386183..16704b4f009d 100644 --- a/src/host/trace.c +++ b/src/host/trace.c @@ -49,7 +49,7 @@ int num_trace_classes; int setup_trace_table(void) { char buffer[2048]; - char *trace = "sof/trace.h"; + char *trace = "uapi/logging.h"; char *trace_filename = malloc(strlen(SOF_INC) + strlen(trace) + 2); char *token; int ret, i = 0; @@ -143,47 +143,55 @@ static char *get_trace_class(uint32_t trace_class) return "value"; } -#define META_SEQ_STEP_param_procD(i, _) META_CONCAT(param, i) %d +#define META_SEQ_STEP_param_procU(i, _) META_CONCAT(param, i) %u -#define HOST_TRACE_EVENT_NTH(postfix, vararg_count)\ - META_FUNC_WITH_VARARGS(_trace_event, postfix, void,\ - META_CONCAT(, uint32_t event),\ - vararg_count, META_SEQ_STEP_param_uint32_t) +#define HOST_TRACE_EVENT_NTH_PARAMS(id_count, param_count) \ + uintptr_t event \ + META_SEQ_FROM_0_TO(id_count , META_SEQ_STEP_id_uint32_t) \ + META_SEQ_FROM_0_TO(param_count, META_SEQ_STEP_param_uint32_t) + +#define HOST_TRACE_EVENT_NTH(postfix, param_count) \ + META_FUNC_WITH_VARARGS( \ + _trace_event, META_CONCAT(postfix, param_count), \ + void, HOST_TRACE_EVENT_NTH_PARAMS(2, param_count) \ + ) /* print trace event */ -#define HOST_TRACE_EVENT_NTH_IMPL(arg_count)\ -HOST_TRACE_EVENT_NTH(, arg_count)\ -{\ - char a, b, c;\ - \ - if (test_bench_trace > 0) {\ - /* look up subsystem from trace class table */\ +#define HOST_TRACE_EVENT_NTH_IMPL(arg_count) \ +HOST_TRACE_EVENT_NTH(, arg_count) \ +{ \ + char a, b, c; \ + \ + if (test_bench_trace > 0) { \ + /* look up subsystem from trace class table */ \ char *trace_class = strdup(get_trace_class(event >> 24));\ - \ - a = event & 0xff;\ - b = (event >> 8) & 0xff;\ - c = (event >> 16) & 0xff;\ - \ - /* print trace event stderr*/\ - if (!strcmp(trace_class, "value"))\ - fprintf(stderr,\ - "Trace value %d, "META_QUOTE(\ - META_SEQ_FROM_0_TO(\ - arg_count, META_SEQ_STEP_param_procD\ - ))"\n"\ - , event META_SEQ_FROM_0_TO(arg_count, META_SEQ_STEP_param));\ - else\ - fprintf(stderr,\ - "Trace %s %c%c%c\n"\ - , trace_class, c, b, a);\ - if (trace_class)\ - free(trace_class);\ - }\ -}\ -HOST_TRACE_EVENT_NTH(_mbox_atomic, arg_count)\ -{\ - META_CONCAT(_trace_event, arg_count)\ - (event META_SEQ_FROM_0_TO(arg_count,META_SEQ_STEP_param));\ + \ + a = event & 0xff; \ + b = (event >> 8) & 0xff; \ + c = (event >> 16) & 0xff; \ + \ + /* print trace event stderr*/ \ + if (!strcmp(trace_class, "value")) \ + fprintf(stderr, \ + "Trace value %lu, "META_QUOTE( \ + META_SEQ_FROM_0_TO(arg_count, \ + META_SEQ_STEP_param_procU \ + ))"\n" \ + , event META_SEQ_FROM_0_TO(arg_count, \ + META_SEQ_STEP_param)); \ + else \ + fprintf(stderr, \ + "Trace %s %c%c%c\n" \ + , trace_class, c, b, a); \ + if (trace_class) \ + free(trace_class); \ + } \ +} \ +HOST_TRACE_EVENT_NTH(_mbox_atomic, arg_count) \ +{ \ + META_CONCAT(_trace_event, arg_count) \ + (event META_SEQ_FROM_0_TO(2, META_SEQ_STEP_id) \ + META_SEQ_FROM_0_TO(arg_count, META_SEQ_STEP_param)); \ } /* Implementation of diff --git a/src/include/sof/preproc-private.h b/src/include/sof/preproc-private.h index eae699cab6c8..9bb9469e5871 100644 --- a/src/include/sof/preproc-private.h +++ b/src/include/sof/preproc-private.h @@ -65,7 +65,7 @@ * META_COUNT_VARAGS_BEFORE_COMPILE(A,B,C,D) evaluates to 4 */ #define _META_PP_NARG_BEFORE_COMPILE_(...) \ - _META_PP_ARG_N(__VA_ARGS__) + META_DEC(_META_PP_ARG_N(__VA_ARGS__)) #define _META_PP_ARG_N(\ _1, _2, _3, _4, _5, _6, _7, _8, _9, _10, \ _11, _12, _13, _14, _15, _16, _17, _18, _19, _20, \ diff --git a/src/include/sof/preproc.h b/src/include/sof/preproc.h index 8e6180e12494..1714a4852221 100644 --- a/src/include/sof/preproc.h +++ b/src/include/sof/preproc.h @@ -46,12 +46,7 @@ * META_COUNT_VARAGS_BEFORE_COMPILE(A,B,C,D) evaluates to 4 */ #define META_COUNT_VARAGS_BEFORE_COMPILE(...)\ - META_IF_ELSE(META_HAS_ARGS(__VA_ARGS__)) (\ - _META_PP_NARG_BEFORE_COMPILE_(__VA_ARGS__, _META_PP_RSEQ_N())\ - )\ - (\ - 0\ - ) + _META_PP_NARG_BEFORE_COMPILE_(_, ##__VA_ARGS__, _META_PP_RSEQ_N()) /* treat x as string while forcing x expansion beforehand */ #define META_QUOTE(x) _META_QUOTE(x) @@ -167,19 +162,17 @@ #define META_SEQ_STEP_param_int32_t( i, _) , int32_t META_CONCAT(param, i) #define META_SEQ_STEP_param_int64_t( i, _) , int64_t META_CONCAT(param, i) +#define META_SEQ_STEP_id(i, _) , META_CONCAT(id_, i) +#define META_SEQ_STEP_id_uint32_t(i, _) , uint32_t META_CONCAT(id_, i) + /* generates function signature * for instance with: * prefix=foo ; postfix=__bar ; return_t=void - * fixed_args=(int x, int y) - * vararg_count=3 - * vararg_gen_step= - * #define META_SEQ_STEP_param_float(i, _) , float META_CONCAT(param, i) + * args=(int x, int y) * will produce: - * void foo_bar(int x, int y , float param0 , float param1 , float param2) + * void foo_bar(int x, int y) */ -#define META_FUNC_WITH_VARARGS(prefix, postfix, return_t,\ - fixed_args, vararg_count, vararg_gen_step)\ - return_t META_CONCAT_SEQ(prefix, postfix, vararg_count)\ - (fixed_args META_SEQ_FROM_0_TO(vararg_count, vararg_gen_step)) +#define META_FUNC_WITH_VARARGS(prefix, postfix, return_t, args)\ + return_t META_CONCAT(prefix, postfix) (args) #endif // __INCLUDE_MACRO_METAPROGRAMMING__ diff --git a/src/include/sof/trace.h b/src/include/sof/trace.h index 520ed2dbe75b..1e1d52377817 100644 --- a/src/include/sof/trace.h +++ b/src/include/sof/trace.h @@ -114,62 +114,88 @@ #define TRACEE 1 #define TRACEM 0 /* send all trace messages to mbox and local trace buffer */ -#define _TRACE_EVENT_NTH(postfix, vararg_count)\ - META_FUNC_WITH_VARARGS(_trace_event, postfix, void,\ - META_CONCAT(, uint32_t log_entry),\ - vararg_count, META_SEQ_STEP_param_uint32_t) - -#define _TRACE_EVENT_NTH_DECLARE_GROUP(arg_count)\ - _TRACE_EVENT_NTH(, arg_count);\ - _TRACE_EVENT_NTH(_mbox, arg_count);\ - _TRACE_EVENT_NTH(_atomic, arg_count);\ - _TRACE_EVENT_NTH(_mbox_atomic, arg_count); +#define _TRACE_EVENT_NTH_PARAMS(id_count, param_count) \ + uintptr_t log_entry \ + META_SEQ_FROM_0_TO(id_count , META_SEQ_STEP_id_uint32_t) \ + META_SEQ_FROM_0_TO(param_count, META_SEQ_STEP_param_uint32_t) + +#define _TRACE_EVENT_NTH(postfix, param_count) \ + META_FUNC_WITH_VARARGS( \ + _trace_event, META_CONCAT(postfix, param_count),\ + void, _TRACE_EVENT_NTH_PARAMS(2, param_count) \ + ) + +#define _TRACE_EVENT_NTH_DECLARE_GROUP(arg_count) \ + _TRACE_EVENT_NTH( , arg_count); \ + _TRACE_EVENT_NTH(_mbox , arg_count); \ + _TRACE_EVENT_NTH(_atomic , arg_count); \ + _TRACE_EVENT_NTH(_mbox_atomic , arg_count); /* Declaration of - * void _trace_event0 (uint32_t log_entry); - * void _trace_event_mbox0 (uint32_t log_entry); - * void _trace_event_atomic0 (uint32_t log_entry); - * void _trace_event_mbox_atomic0(uint32_t log_entry); + * void _trace_event0 (uint32_t log_entry, uint32_t ids...); + * void _trace_event_mbox0 (uint32_t log_entry, uint32_t ids...); + * void _trace_event_atomic0 (uint32_t log_entry, uint32_t ids...); + * void _trace_event_mbox_atomic0(uint32_t log_entry, uint32_t ids...); */ _TRACE_EVENT_NTH_DECLARE_GROUP(0) /* Declaration of - * void _trace_event1 (uint32_t log_entry, uint32_t params...); - * void _trace_event_mbox1 (uint32_t log_entry, uint32_t params...); - * void _trace_event_atomic1 (uint32_t log_entry, uint32_t params...); - * void _trace_event_mbox_atomic1(uint32_t log_entry, uint32_t params...); + * void _trace_event1 (uint32_t log_entry, uint32_t ids..., + * uint32_t params...); + * void _trace_event_mbox1 (uint32_t log_entry, uint32_t ids..., + * uint32_t params...); + * void _trace_event_atomic1 (uint32_t log_entry, uint32_t ids..., + * uint32_t params...); + * void _trace_event_mbox_atomic1(uint32_t log_entry, uint32_t ids..., + * uint32_t params...); */ _TRACE_EVENT_NTH_DECLARE_GROUP(1) /* Declaration of - * void _trace_event2 (uint32_t log_entry, uint32_t params...); - * void _trace_event_mbox2 (uint32_t log_entry, uint32_t params...); - * void _trace_event_atomic2 (uint32_t log_entry, uint32_t params...); - * void _trace_event_mbox_atomic2(uint32_t log_entry, uint32_t params...); + * void _trace_event2 (uint32_t log_entry, uint32_t ids..., + * uint32_t params...); + * void _trace_event_mbox2 (uint32_t log_entry, uint32_t ids..., + * uint32_t params...); + * void _trace_event_atomic2 (uint32_t log_entry, uint32_t ids..., + * uint32_t params...); + * void _trace_event_mbox_atomic2(uint32_t log_entry, uint32_t ids..., + * uint32_t params...); */ _TRACE_EVENT_NTH_DECLARE_GROUP(2) /* Declaration of - * void _trace_event3 (uint32_t log_entry, uint32_t params...); - * void _trace_event_mbox3 (uint32_t log_entry, uint32_t params...); - * void _trace_event_atomic3 (uint32_t log_entry, uint32_t params...); - * void _trace_event_mbox_atomic3(uint32_t log_entry, uint32_t params...); + * void _trace_event3 (uint32_t log_entry, uint32_t ids..., + * uint32_t params...); + * void _trace_event_mbox3 (uint32_t log_entry, uint32_t ids..., + * uint32_t params...); + * void _trace_event_atomic3 (uint32_t log_entry, uint32_t ids..., + * uint32_t params...); + * void _trace_event_mbox_atomic3(uint32_t log_entry, uint32_t ids..., + * uint32_t params...); */ _TRACE_EVENT_NTH_DECLARE_GROUP(3) /* Declaration of - * void _trace_event4 (uint32_t log_entry, uint32_t params...); - * void _trace_event_mbox4 (uint32_t log_entry, uint32_t params...); - * void _trace_event_atomic4 (uint32_t log_entry, uint32_t params...); - * void _trace_event_mbox_atomic4(uint32_t log_entry, uint32_t params...); + * void _trace_event4 (uint32_t log_entry, uint32_t ids..., + * uint32_t params...); + * void _trace_event_mbox4 (uint32_t log_entry, uint32_t ids..., + * uint32_t params...); + * void _trace_event_atomic4 (uint32_t log_entry, uint32_t ids..., + * uint32_t params...); + * void _trace_event_mbox_atomic4(uint32_t log_entry, uint32_t ids..., + * uint32_t params...); */ _TRACE_EVENT_NTH_DECLARE_GROUP(4) /* Declaration of - * void _trace_event5 (uint32_t log_entry, uint32_t params...); - * void _trace_event_mbox5 (uint32_t log_entry, uint32_t params...); - * void _trace_event_atomic5 (uint32_t log_entry, uint32_t params...); - * void _trace_event_mbox_atomic5(uint32_t log_entry, uint32_t params...); + * void _trace_event5 (uint32_t log_entry, uint32_t ids..., + * uint32_t params...); + * void _trace_event_mbox5 (uint32_t log_entry, uint32_t ids..., + * uint32_t params...); + * void _trace_event_atomic5 (uint32_t log_entry, uint32_t ids..., + * uint32_t params...); + * void _trace_event_mbox_atomic5(uint32_t log_entry, uint32_t ids..., + * uint32_t params...); */ _TRACE_EVENT_NTH_DECLARE_GROUP(5) @@ -180,38 +206,50 @@ void trace_off(void); void trace_init(struct sof *sof); #if TRACE - /* - * trace_event macro definition - * - * trace_event() macro is used for logging events that occur at runtime. - * It comes in 2 main flavours, atomic and non-atomic. Depending of definitions - * above, it might also propagate log messages to mbox if desired. - * - * First argument is always class of event being logged, as defined above. - * Second argument is string literal in printf format, followed by up to 3 - * parameters (uint32_t), that are used to expand into string fromat when - * parsing log data. - * - * All compile-time accessible data (verbosity, class, source file name, line - * index and string literal) are linked into .static_log_entries section - * of binary and then extracted by rimage, so they do not contribute to loadable - * image size. This way more elaborate log messages are possible and encouraged, - * for better debugging experience, without worrying about runtime performance. - */ +* trace_event macro definition +* +* trace_event() macro is used for logging events that occur at runtime. +* It comes in 2 main flavours, atomic and non-atomic. Depending of definitions +* above, it might also propagate log messages to mbox if desired. +* +* First argument is always class of event being logged, as defined in +* uapi/logging.h. +* Second argument is string literal in printf format, followed by up to 4 +* parameters (uint32_t), that are used to expand into string fromat when +* parsing log data. +* +* All compile-time accessible data (verbosity, class, source file name, line +* index and string literal) are linked into .static_log_entries section +* of binary and then extracted by rimage, so they do not contribute to loadable +* image size. This way more elaborate log messages are possible and encouraged, +* for better debugging experience, without worrying about runtime performance. +*/ +#define trace_event(class, format, ...) \ + _trace_event_with_ids(class, -1, -1, 0, format, ##__VA_ARGS__) +#define trace_event_atomic(class, format, ...) \ + _trace_event_atomic_with_ids(class, -1, -1, 0, format, ##__VA_ARGS__) + +#define trace_event_with_ids(class, id_0, id_1, format, ...) \ + _trace_event_with_ids(class, id_0, id_1, 1, format, ##__VA_ARGS__) +#define trace_event_atomic_with_ids(class, id_0, id_1, format, ...) \ + _trace_event_atomic_with_ids(class, id_0, id_1, 1, format, \ + ##__VA_ARGS__) + #if TRACEM /* send all trace to mbox and local trace buffer */ -#define trace_event(__c, __e, ...) \ - _log_message(_mbox,, LOG_LEVEL_VERBOSE, __c, __e, ##__VA_ARGS__) -#define trace_event_atomic(__c, __e, ...) \ - _log_message(_mbox, _atomic, LOG_LEVEL_VERBOSE, __c, __e, ##__VA_ARGS__) +#define __mbox _mbox #else /* send trace events only to the local trace buffer */ -#define trace_event(__c, __e, ...) \ - _log_message(,, LOG_LEVEL_VERBOSE, __c, __e, ##__VA_ARGS__) -#define trace_event_atomic(__c, __e, ...) \ - _log_message(, _atomic, LOG_LEVEL_VERBOSE, __c, __e, ##__VA_ARGS__) +#define __mbox #endif +#define _trace_event_with_ids(class, id_0, id_1, has_ids, format, ...) \ + _log_message(__mbox,, LOG_LEVEL_VERBOSE, class, id_0, id_1, \ + has_ids, format, ##__VA_ARGS__) +#define _trace_event_atomic_with_ids(class, id_0, id_1, has_ids, format, ...)\ + _log_message(__mbox, _atomic, LOG_LEVEL_VERBOSE, class, id_0, id_1, \ + has_ids, format, ##__VA_ARGS__) + #define trace_value(x) trace_event(0, "value %u", x) #define trace_value_atomic(x) trace_event_atomic(0, "value %u", x) @@ -219,14 +257,18 @@ void trace_init(struct sof *sof); /* verbose tracing */ #if TRACEV -#define tracev_event(__c, __e, ...) trace_event(__c, __e, ##__VA_ARGS__) +#define tracev_event(...) trace_event(__VA_ARGS__) +#define tracev_event_with_ids(...) trace_event_with_ids(__VA_ARGS__) +#define tracev_event_atomic(...) trace_event_atomic(__VA_ARGS__) +#define tracev_event_atomic_with_ids(...) trace_event_with_ids(__VA_ARGS__) + #define tracev_value(x) trace_value(x) -#define tracev_event_atomic(__c, __e, ...) \ - trace_event_atomic(__c, __e, ##__VA_ARGS__) #define tracev_value_atomic(x) trace_value_atomic(x) #else -#define tracev_event(__c, __e, ...) -#define tracev_event_atomic(__c, __e, ...) +#define tracev_event(...) +#define tracev_event_with_ids(...) +#define tracev_event_atomic(...) +#define tracev_event_atomic_with_ids(...) #define tracev_value(x) #define tracev_value_atomic(x) @@ -234,88 +276,86 @@ void trace_init(struct sof *sof); /* error tracing */ #if TRACEE -#define trace_error(__c, __e, ...) _log_message(_mbox, _atomic, \ - LOG_LEVEL_CRITICAL, __c, __e, ##__VA_ARGS__) -#define trace_error_atomic(__c, __e, ...) \ - trace_error(__c, __e, ##__VA_ARGS__) +#define _trace_error_with_ids(class, id_0, id_1, has_ids, format, ...) \ + _log_message(_mbox, _atomic, LOG_LEVEL_CRITICAL, class, id_0, \ + id_1, has_ids, format, ##__VA_ARGS__) +#define trace_error(class, format, ...) \ + _trace_error_with_ids(class, -1, -1, 0, format, ##__VA_ARGS__) +#define trace_error_with_ids(class, id_0, id_1, format, ...) \ + _trace_error_with_ids(class, id_0, id_1, 1, format, ##__VA_ARGS__) +#define trace_error_atomic(...) trace_error(__VA_ARGS__) +#define trace_error_atomic_with_ids(...) trace_error_with_ids(__VA_ARGS__) /* write back error value to mbox */ -#define trace_error_value(x) \ - trace_error(0, "value %u", x) -#define trace_error_value_atomic(x) \ - trace_error_atomic(0, "value %u", x) +#define trace_error_value(x) trace_error(0, "value %u", x) +#define trace_error_value_atomic(...) trace_error_value(__VA_ARGS__) #else -#define trace_error(__c, __e, ...) -#define trace_error_atomic(__c, __e, ...) +#define trace_error(...) +#define trace_error_atomic(...) #define trace_error_value(x) #define trace_error_value_atomic(x) #endif -typedef void(*log_func)(); - -/* - * Log entry declaration - * - * Each log_entry defines anonymous type, with all compile-time data - * associated with it, to save on transmission. It is then placed by the linker - * in .static_log_entries section of ELF. - */ -#define _DECLARE_LOG_ENTRY(lvl, format, comp_id, params)\ - __attribute__((section(".static_log." #lvl))) \ - static const struct { \ - uint32_t level; \ - uint32_t component_id; \ - uint32_t params_num; \ - uint32_t line_idx; \ - uint32_t file_name_len; \ - const char file_name[sizeof(__FILE__)]; \ - uint32_t text_len; \ - const char text[sizeof(format)]; \ - } log_entry = { \ - lvl, \ - comp_id, \ - params, \ - __LINE__, \ - sizeof(__FILE__), \ - __FILE__, \ - sizeof(format), \ - format \ +#define _DECLARE_LOG_ENTRY(lvl, format, comp_class, params, ids)\ + __attribute__((section(".static_log." #lvl))) \ + static const struct { \ + uint32_t level; \ + uint32_t component_class; \ + uint32_t has_ids; \ + uint32_t params_num; \ + uint32_t line_idx; \ + uint32_t file_name_len; \ + uint32_t text_len; \ + const char file_name[sizeof(__FILE__)]; \ + const char text[sizeof(format)]; \ + } log_entry = { \ + lvl, \ + comp_class, \ + ids, \ + params, \ + __LINE__, \ + sizeof(__FILE__), \ + sizeof(format), \ + __FILE__, \ + format \ } #define BASE_LOG_ASSERT_FAIL_MSG \ unsupported_amount_of_params_in_trace_event\ _thrown_from_macro_BASE_LOG_in_trace_h -#define BASE_LOG(function_name, entry, ...)\ -{\ - STATIC_ASSERT(\ - _TRACE_EVENT_MAX_ARGUMENT_COUNT >=\ - META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__),\ - BASE_LOG_ASSERT_FAIL_MSG\ - );\ - log_func log_function = (log_func)&\ - META_CONCAT(function_name,\ - META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__));\ - log_function(entry, ##__VA_ARGS__);\ +#define BASE_LOG(function_name, id_0, id_1, entry, ...) \ +{ \ + STATIC_ASSERT( \ + _TRACE_EVENT_MAX_ARGUMENT_COUNT >= \ + META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__), \ + BASE_LOG_ASSERT_FAIL_MSG \ + ); \ + META_CONCAT(function_name, \ + META_COUNT_VARAGS_BEFORE_COMPILE(__VA_ARGS__)) \ + ((uintptr_t)entry, id_0, id_1, ##__VA_ARGS__); \ } -#define __log_message(func_name, lvl, comp_id, format, ...) \ +#define __log_message(func_name, lvl, comp_class, id_0, id_1, has_ids, \ + format, ...) \ { \ - _DECLARE_LOG_ENTRY(lvl, format, comp_id, PP_NARG(__VA_ARGS__)); \ - BASE_LOG(func_name, &log_entry, ##__VA_ARGS__) \ + _DECLARE_LOG_ENTRY(lvl, format, comp_class, \ + PP_NARG(__VA_ARGS__), has_ids); \ + BASE_LOG(func_name, id_0, id_1, &log_entry, ##__VA_ARGS__) \ } -#define _log_message(mbox, atomic, level, comp_id, format, ...) \ - __log_message(_trace_event##mbox##atomic, level, \ - comp_id, format, ##__VA_ARGS__) - +#define _log_message(mbox, atomic, level, comp_class, id_0, id_1, \ + has_ids, format, ...) \ + __log_message(META_CONCAT_SEQ(_trace_event, mbox, atomic), \ + level, comp_class, id_0, id_1, has_ids, format, \ + ##__VA_ARGS__) #else -#define trace_event(__c, __e, ...) -#define trace_event_atomic(__c, __e, ...) +#define trace_event(...) +#define trace_event_atomic(...) -#define trace_error(__c, __e, ...) -#define trace_error_atomic(__c, __e, ...) +#define trace_error_with_ids(...) +#define trace_error_atomic_with_ids(...) #define trace_error_value(x) #define trace_error_value_atomic(x) @@ -325,8 +365,10 @@ _thrown_from_macro_BASE_LOG_in_trace_h #define trace_point(x) -#define tracev_event(__c, __e, ...) -#define tracev_event_atomic(__c, __e, ...) +#define tracev_event(...) +#define tracev_event_with_ids(...) +#define tracev_event_atomic(...) +#define tracev_event_atomic_with_ids(...) #define tracev_value(x) #define tracev_value_atomic(x) diff --git a/src/include/uapi/logging.h b/src/include/uapi/logging.h index b97309c29034..b070a7f1c14a 100644 --- a/src/include/uapi/logging.h +++ b/src/include/uapi/logging.h @@ -98,18 +98,21 @@ struct log_buffer_status { uint32_t core_id; /* ID of core that logged to other half */ }; +#define TRACE_ID_LENGTH 12 + /* - * Log entry header. - * - * The header is followed by an array of arguments (uint32_t[]). - * Number of arguments is specified by the params_num field of log_entry, - * and is 0-based value (entry_len=0 means there is 1 argument). - */ +* Log entry header. +* +* The header is followed by an array of arguments (uint32_t[]). +* Number of arguments is specified by the params_num field of log_entry +*/ struct log_entry_header { - uint32_t rsvd : 24; /* Unused */ - uint32_t core_id : 8; /* Reporting core's id */ + uint32_t id_0 : TRACE_ID_LENGTH; /* e.g. Pipeline ID */ + uint32_t id_1 : TRACE_ID_LENGTH; /* e.g. Component ID */ + uint32_t core_id : 8; /* Reporting core's id */ - uint64_t timestamp; /* Timestamp (in dsp ticks) */ + uint64_t timestamp; /* Timestamp (in dsp ticks) */ + uintptr_t log_entry_address; /* Address of log entry in ELF */ } __attribute__((__packed__)); #endif //#ifndef __INCLUDE_LOGGING__ diff --git a/src/lib/trace.c b/src/lib/trace.c index 85fa381c93ae..3dcbe46f2028 100644 --- a/src/lib/trace.c +++ b/src/lib/trace.c @@ -48,18 +48,30 @@ struct trace { static struct trace *trace; -/* calculates total message size, both header and payload */ -#define MESSAGE_SIZE(args_num) \ - ((sizeof(struct log_entry_header) + (1 + args_num) * sizeof(uint32_t)) \ - / sizeof(uint32_t)) +/* calculates total message size, both header and payload in bytes */ +#define MESSAGE_SIZE(args_num) \ + (sizeof(struct log_entry_header) + args_num * sizeof(uint32_t)) -static void put_header(volatile uint32_t *dst, uint64_t timestamp) +/* calculated total message size in dwords */ +#define MESSAGE_SIZE_DWORDS(args_num) \ + (MESSAGE_SIZE(args_num) / sizeof(uint32_t)) + +/* calculates offset to param_idx of payload */ +#define PAYLOAD_OFFSET(param_idx) \ + (MESSAGE_SIZE_DWORDS(0) + param_idx) + +#define TRACE_ID_MASK ((1 << TRACE_ID_LENGTH) - 1) + +static void put_header(volatile uint32_t *dst, uint32_t id_0, uint32_t id_1, + uintptr_t entry, uint64_t timestamp) { struct log_entry_header header; - header.rsvd = 0; + header.id_0 = id_0 & TRACE_ID_MASK; + header.id_1 = id_1 & TRACE_ID_MASK; header.core_id = cpu_get_id(); header.timestamp = timestamp; + header.log_entry_address = entry; int i = 0; @@ -76,132 +88,150 @@ static void put_header(volatile uint32_t *dst, uint64_t timestamp) * META_CONCAT(param, i); * #define BAR(array, arg_count) META_SEQ_FROM_0_TO(arg_count, FOO(array)) */ -#define _TRACE_EVENT_NTH_IMPL_DT_STEP(i, _)\ - dt[payload_offset + 1 + i] = META_CONCAT(param, i); -#define _TRACE_EVENT_NTH_IMPL_T_STEP(i, _)\ - t[payload_offset + 1 + i] = META_CONCAT(param, i); -#define _TRACE_EVENT_NTH_IMPL_DT(arg_count)\ +#define _TRACE_EVENT_NTH_IMPL_DT_STEP(i, _) \ + dt[PAYLOAD_OFFSET(i)] = META_CONCAT(param, i); +#define _TRACE_EVENT_NTH_IMPL_T_STEP(i, _) \ + t[PAYLOAD_OFFSET(i)] = META_CONCAT(param, i); +#define _TRACE_EVENT_NTH_IMPL_DT(arg_count) \ META_SEQ_FROM_0_TO(arg_count, _TRACE_EVENT_NTH_IMPL_DT_STEP) -#define _TRACE_EVENT_NTH_IMPL_T(arg_count)\ +#define _TRACE_EVENT_NTH_IMPL_T(arg_count) \ META_SEQ_FROM_0_TO(arg_count, _TRACE_EVENT_NTH_IMPL_T_STEP) /* _trace_event function with poor people's version of constexpr if */ -#define _TRACE_EVENT_NTH_IMPL(is_mbox, is_atomic, arg_count)\ -_TRACE_EVENT_NTH(META_CONCAT(\ -/*if is_mbox , append _mbox to function name*/\ -META_IF_ELSE(is_mbox)(_mbox)(),\ -/*if is_atomic, append _atomic to function name*/\ -META_IF_ELSE(is_atomic)(_atomic)()\ -), arg_count)\ -{\ - const uint32_t msg_size_dwords = MESSAGE_SIZE(arg_count);\ - const uint32_t payload_offset = sizeof(struct log_entry_header)\ - / sizeof(uint32_t);\ - uint32_t dt[MESSAGE_SIZE(arg_count)];\ - META_IF_ELSE(is_mbox)\ - (\ - volatile uint32_t *t;\ - META_IF_ELSE(is_atomic)()(unsigned long flags;)\ - )()\ -\ - if (!trace->enable)\ - return;\ -\ - META_IF_ELSE(is_mbox)\ - (\ - uint64_t time = platform_timer_get(platform_timer);\ - put_header(dt, time);\ - )\ - (\ - put_header(dt, platform_timer_get(platform_timer));\ - )\ -\ - dt[payload_offset] = log_entry;\ - _TRACE_EVENT_NTH_IMPL_DT(arg_count)\ - META_IF_ELSE(is_atomic)\ - (dtrace_event_atomic)\ - (dtrace_event)\ - ((const char *)dt, sizeof(uint32_t) * msg_size_dwords);\ - META_IF_ELSE(is_mbox)\ - (\ - META_IF_ELSE(is_atomic)()(\ - /* send event by mail box too. */\ - spin_lock_irq(&trace->lock, flags);\ - )\ - /* write timestamp and event to trace buffer */\ - t = (volatile uint32_t *)(MAILBOX_TRACE_BASE + trace->pos);\ - trace->pos += sizeof(uint32_t) * msg_size_dwords;\ -\ - if (trace->pos > MAILBOX_TRACE_SIZE\ - - sizeof(uint32_t) * msg_size_dwords)\ - trace->pos = 0;\ -\ - META_IF_ELSE(is_atomic)()(spin_unlock_irq(&trace->lock, flags);)\ -\ - put_header(t, time);\ - t[payload_offset] = log_entry;\ - _TRACE_EVENT_NTH_IMPL_T(arg_count)\ -\ - /* writeback trace data */\ - dcache_writeback_region\ - ((void *)t, sizeof(uint32_t) * msg_size_dwords);\ - )()\ +#define _TRACE_EVENT_NTH_IMPL(is_mbox, is_atomic, arg_count) \ +_TRACE_EVENT_NTH(META_CONCAT( \ +/*if is_mbox , append _mbox to function name*/ \ +META_IF_ELSE(is_mbox)(_mbox)(), \ +/*if is_atomic, append _atomic to function name*/ \ +META_IF_ELSE(is_atomic)(_atomic)() \ +), arg_count) \ +{ \ + uint32_t dt[MESSAGE_SIZE_DWORDS(arg_count)]; \ + META_IF_ELSE(is_mbox) \ + ( \ + volatile uint32_t *t; \ + META_IF_ELSE(is_atomic)()(unsigned long flags;) \ + )() \ + \ + if (!trace->enable) \ + return; \ + \ + META_IF_ELSE(is_mbox) \ + ( \ + uint64_t time = platform_timer_get(platform_timer); \ + put_header(dt, id_0, id_1, log_entry, time); \ + ) \ + ( \ + put_header(dt, id_0, id_1, log_entry, \ + platform_timer_get(platform_timer)); \ + ) \ + \ + _TRACE_EVENT_NTH_IMPL_DT(arg_count) \ + META_IF_ELSE(is_atomic) \ + (dtrace_event_atomic) \ + (dtrace_event) \ + ((const char *)dt, MESSAGE_SIZE(arg_count)); \ + META_IF_ELSE(is_mbox) \ + ( \ + META_IF_ELSE(is_atomic)()( \ + /* send event by mail box too. */ \ + spin_lock_irq(&trace->lock, flags); \ + ) \ + /* write timestamp and event to trace buffer */ \ + t = (volatile uint32_t *)(MAILBOX_TRACE_BASE + \ + trace->pos); \ + trace->pos += MESSAGE_SIZE(arg_count); \ + \ + if (trace->pos > MAILBOX_TRACE_SIZE \ + - MESSAGE_SIZE(arg_count)) \ + trace->pos = 0; \ + \ + META_IF_ELSE(is_atomic)()(spin_unlock_irq(&trace->lock, \ + flags);) \ + \ + put_header(t, id_0, id_1, log_entry, time); \ + _TRACE_EVENT_NTH_IMPL_T(arg_count) \ + \ + /* writeback trace data */ \ + dcache_writeback_region \ + ((void *)t, MESSAGE_SIZE(arg_count)); \ + )() \ } -#define _TRACE_EVENT_NTH_IMPL_GROUP(arg_count)\ - /* send trace events only to the local trace buffer */\ - _TRACE_EVENT_NTH_IMPL(0, 0, arg_count)\ - _TRACE_EVENT_NTH_IMPL(0, 1, arg_count)\ - /* send trace events to the local trace buffer and the mailbox */\ - _TRACE_EVENT_NTH_IMPL(1, 0, arg_count)\ +#define _TRACE_EVENT_NTH_IMPL_GROUP(arg_count) \ + /* send trace events only to the local trace buffer */ \ + _TRACE_EVENT_NTH_IMPL(0, 0, arg_count) \ + _TRACE_EVENT_NTH_IMPL(0, 1, arg_count) \ + /* send trace events to the local trace buffer and mailbox */ \ + _TRACE_EVENT_NTH_IMPL(1, 0, arg_count) \ _TRACE_EVENT_NTH_IMPL(1, 1, arg_count) /* Implementation of - * void _trace_event1( uint32_t log_entry) {...} - * void _trace_event_mbox1( uint32_t log_entry) {...} - * void _trace_event_atomic1( uint32_t log_entry) {...} - * void _trace_event_mbox_atomic1(uint32_t log_entry) {...} + * void _trace_event1( uintptr_t log_entry, uint32_t ids...) {...} + * void _trace_event_mbox1( uintptr_t log_entry, uint32_t ids...) {...} + * void _trace_event_atomic1( uintptr_t log_entry, uint32_t ids...) {...} + * void _trace_event_mbox_atomic1(uintptr_t log_entry, uint32_t ids...) {...} */ _TRACE_EVENT_NTH_IMPL_GROUP(0) /* Implementation of - * void _trace_event1( uint32_t log_entry, uint32_t params...) {...} - * void _trace_event_mbox1( uint32_t log_entry, uint32_t params...) {...} - * void _trace_event_atomic1( uint32_t log_entry, uint32_t params...) {...} - * void _trace_event_mbox_atomic1(uint32_t log_entry, uint32_t params...) {...} + * void _trace_event1( uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} + * void _trace_event_mbox1( uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} + * void _trace_event_atomic1( uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} + * void _trace_event_mbox_atomic1(uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} */ _TRACE_EVENT_NTH_IMPL_GROUP(1) /* Implementation of - * void _trace_event2( uint32_t log_entry, uint32_t params...) {...} - * void _trace_event_mbox2( uint32_t log_entry, uint32_t params...) {...} - * void _trace_event_atomic2( uint32_t log_entry, uint32_t params...) {...} - * void _trace_event_mbox_atomic2(uint32_t log_entry, uint32_t params...) {...} + * void _trace_event2( uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} + * void _trace_event_mbox2( uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} + * void _trace_event_atomic2( uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} + * void _trace_event_mbox_atomic2(uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} */ _TRACE_EVENT_NTH_IMPL_GROUP(2) /* Implementation of - * void _trace_event3( uint32_t log_entry, uint32_t params...) {...} - * void _trace_event_mbox3( uint32_t log_entry, uint32_t params...) {...} - * void _trace_event_atomic3( uint32_t log_entry, uint32_t params...) {...} - * void _trace_event_mbox_atomic3(uint32_t log_entry, uint32_t params...) {...} + * void _trace_event3( uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} + * void _trace_event_mbox3( uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} + * void _trace_event_atomic3( uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} + * void _trace_event_mbox_atomic3(uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} */ _TRACE_EVENT_NTH_IMPL_GROUP(3) /* Implementation of - * void _trace_event4( uint32_t log_entry, uint32_t params...) {...} - * void _trace_event_mbox4( uint32_t log_entry, uint32_t params...) {...} - * void _trace_event_atomic4( uint32_t log_entry, uint32_t params...) {...} - * void _trace_event_mbox_atomic4(uint32_t log_entry, uint32_t params...) {...} + * void _trace_event4( uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} + * void _trace_event_mbox4( uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} + * void _trace_event_atomic4( uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} + * void _trace_event_mbox_atomic4(uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} */ _TRACE_EVENT_NTH_IMPL_GROUP(4) /* Implementation of - * void _trace_event5( uint32_t log_entry, uint32_t params...) {...} - * void _trace_event_mbox5( uint32_t log_entry, uint32_t params...) {...} - * void _trace_event_atomic5( uint32_t log_entry, uint32_t params...) {...} - * void _trace_event_mbox_atomic5(uint32_t log_entry, uint32_t params...) {...} + * void _trace_event5( uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} + * void _trace_event_mbox5( uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} + * void _trace_event_atomic5( uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} + * void _trace_event_mbox_atomic5(uintptr_t log_entry, uint32_t ids..., + * uint32_t params...) {...} */ _TRACE_EVENT_NTH_IMPL_GROUP(5) From 1d559f820c5dfccd2b7568040dafe9805fc3af53 Mon Sep 17 00:00:00 2001 From: ArturX Kloniecki Date: Fri, 2 Nov 2018 18:50:11 +0100 Subject: [PATCH 2/4] debugability: Refactor pipeline traces to fully utilize new trace_event Implemented set of macros for pipelines to allow reporting of pipeline and component IDs. Refactor all traces to provide useful, human readible messages. Signed-off-by: ArturX Kloniecki --- src/audio/pipeline.c | 169 ++++++++++++++++++------------- src/include/sof/audio/pipeline.h | 26 ++++- src/include/sof/ipc.h | 9 +- 3 files changed, 130 insertions(+), 74 deletions(-) diff --git a/src/audio/pipeline.c b/src/audio/pipeline.c index 79e95809fad5..3d1394289b8f 100644 --- a/src/audio/pipeline.c +++ b/src/audio/pipeline.c @@ -70,7 +70,8 @@ static void connect_upstream(struct pipeline *p, struct comp_dev *start, { struct list_item *clist; - tracev_value(current->comp.id); + tracev_pipe_with_ids(p, "connect_upstream(), current->comp.id = %u", + current->comp.id); /* complete component init */ current->pipeline = p; @@ -110,7 +111,8 @@ static void connect_downstream(struct pipeline *p, struct comp_dev *start, { struct list_item *clist; - tracev_value(current->comp.id); + tracev_pipe_with_ids(p, "connect_downstream(), current->comp.id = %u", + current->comp.id); /* complete component init */ current->pipeline = p; @@ -142,7 +144,8 @@ static void disconnect_upstream(struct pipeline *p, struct comp_dev *start, { struct list_item *clist; - tracev_value(current->comp.id); + tracev_pipe_with_ids(p, "disconnect_upstream(), current->comp.id = %u", + current->comp.id); /* complete component init */ current->pipeline = NULL; @@ -171,7 +174,8 @@ static void disconnect_downstream(struct pipeline *p, struct comp_dev *start, { struct list_item *clist; - tracev_value(current->comp.id); + tracev_pipe_with_ids(p, "disconnect_downstream(), current->comp.id = " + "%u", current->comp.id); /* complete component init */ current->pipeline = NULL; @@ -238,12 +242,12 @@ struct pipeline *pipeline_new(struct sof_ipc_pipe_new *pipe_desc, { struct pipeline *p; - trace_pipe("new"); + trace_pipe("pipeline_new()"); /* allocate new pipeline */ p = rzalloc(RZONE_RUNTIME, SOF_MEM_CAPS_RAM, sizeof(*p)); if (p == NULL) { - trace_pipe_error("ePN"); + trace_pipe_error("pipeline_new() error: Out of Memory"); return NULL; } @@ -264,11 +268,12 @@ struct pipeline *pipeline_new(struct sof_ipc_pipe_new *pipe_desc, /* pipelines must be inactive */ int pipeline_free(struct pipeline *p) { - trace_pipe("fre"); + trace_pipe_with_ids(p, "pipeline_free()"); /* make sure we are not in use */ if (p->sched_comp->state > COMP_STATE_READY) { - trace_pipe_error("epb"); + trace_pipe_error_with_ids(p, "pipeline_free() error: Pipeline in " + "use"); return -EBUSY; } @@ -290,12 +295,13 @@ int pipeline_complete(struct pipeline *p) /* now walk downstream and upstream form "start" component and complete component task and pipeline init */ - trace_pipe("com"); - trace_value(p->ipc_pipe.pipeline_id); + trace_pipe_with_ids(p, "pipeline_complete(), p->ipc_pipe.pipeline_id = " + "%u", p->ipc_pipe.pipeline_id); /* check whether pipeline is already complete */ if (p->status != COMP_STATE_INIT) { - trace_pipe_error("epc"); + trace_pipe_error_with_ids(p, "pipeline_complete() error: " + "Pipeline already complete"); return -EINVAL; } @@ -309,7 +315,7 @@ int pipeline_complete(struct pipeline *p) int pipeline_comp_connect(struct pipeline *p, struct comp_dev *source_comp, struct comp_buffer *sink_buffer) { - trace_pipe("cnc"); + trace_pipe_with_ids(p, "pipeline_comp_connect()"); /* connect source to buffer */ spin_lock(&source_comp->lock); @@ -321,8 +327,10 @@ int pipeline_comp_connect(struct pipeline *p, struct comp_dev *source_comp, if (sink_buffer->source && sink_buffer->sink) sink_buffer->connected = 1; - tracev_value((source_comp->comp.id << 16) | - sink_buffer->ipc_buffer.comp.id); + tracev_pipe_with_ids(p, "pipeline_comp_connect(), (source_comp->comp.id" + " << 16) | sink_buffer->ipc_buffer.comp.id = %08x", + (source_comp->comp.id << 16) | + sink_buffer->ipc_buffer.comp.id); return 0; } @@ -330,7 +338,7 @@ int pipeline_comp_connect(struct pipeline *p, struct comp_dev *source_comp, int pipeline_buffer_connect(struct pipeline *p, struct comp_buffer *source_buffer, struct comp_dev *sink_comp) { - trace_pipe("cbc"); + trace_pipe_with_ids(p, "pipeline_buffer_connect()"); /* connect sink to buffer */ spin_lock(&sink_comp->lock); @@ -342,8 +350,10 @@ int pipeline_buffer_connect(struct pipeline *p, if (source_buffer->source && source_buffer->sink) source_buffer->connected = 1; - tracev_value((source_buffer->ipc_buffer.comp.id << 16) | - sink_comp->comp.id); + tracev_pipe_with_ids(p, "pipeline_buffer_connect(), (source_buffer->" + "ipc_buffer.comp.id << 16) | sink_comp->comp.id = " + "%08x", (source_buffer->ipc_buffer.comp.id << 16) | + sink_comp->comp.id); return 0; } @@ -359,8 +369,8 @@ static int component_op_downstream(struct op_data *op_data, struct list_item *clist; int err = 0; - tracev_pipe("CO-"); - tracev_value(current->comp.id); + tracev_pipe("component_op_downstream(), current->comp.id = %u", + current->comp.id); /* do operation on this component */ switch (op_data->op) { @@ -393,20 +403,23 @@ static int component_op_downstream(struct op_data *op_data, case COMP_OPS_BUFFER: /* handled by other API call */ case COMP_OPS_CACHE: default: - trace_pipe_error("eOi"); - trace_error_value(op_data->op); + trace_pipe_error("component_op_downstream() error: op_data->op" + "= %d", op_data->op); return -EINVAL; } /* don't walk the graph any further if this component fails */ if (err < 0) { - trace_pipe_error("eOp"); + trace_pipe_error("component_op_downstream() error: err = %d", + err); return err; } else if (err > 0 || (current != start && current->is_endpoint)) { /* we finish walking the graph if we reach the DAI or component is * currently active and configured already (err > 0). */ - tracev_pipe("C-D"); + tracev_pipe("component_op_downstream() DAI or component " + "currently active or configured already, err = %d", + err); return err; } @@ -441,8 +454,8 @@ static int component_op_upstream(struct op_data *op_data, struct list_item *clist; int err = 0; - tracev_pipe("CO+"); - tracev_value(current->comp.id); + tracev_pipe("component_op_upstream(), current->comp.id = %u", + current->comp.id); /* do operation on this component */ switch (op_data->op) { @@ -475,17 +488,19 @@ static int component_op_upstream(struct op_data *op_data, case COMP_OPS_BUFFER: /* handled by other API call */ case COMP_OPS_CACHE: default: - trace_pipe_error("eOi"); - trace_error_value(op_data->op); + trace_pipe_error("component_op_upstream() error, op_data->op = " + "%d", op_data->op); return -EINVAL; } /* don't walk the graph any further if this component fails */ if (err < 0) { - trace_pipe_error("eOp"); + trace_pipe_error("component_op_upstream() error: Component " + "failed, err = %d", err); return err; } else if (err > 0 || (current != start && current->is_endpoint)) { - tracev_pipe("C+D"); + tracev_pipe("component_op_upstream(), err > 0 || (current != " + "start && current->is_endpoint)"); return 0; } @@ -539,7 +554,8 @@ static int component_prepare_buffers_upstream(struct comp_dev *start, err = component_prepare_buffers_upstream(start, buffer->source, buffer); if (err < 0) { - trace_pipe_error("eBD"); + trace_pipe_error("component_prepare_buffers_upstream()" + " error: err = %d", err); break; } } @@ -579,7 +595,8 @@ static int component_prepare_buffers_downstream(struct comp_dev *start, err = component_prepare_buffers_downstream(start, buffer->sink, buffer); if (err < 0) { - trace_pipe_error("eBD"); + trace_pipe_error("component_prepare_buffers_downstream" + "() error: err = %d", err); break; } } @@ -595,7 +612,7 @@ int pipeline_prepare(struct pipeline *p, struct comp_dev *dev) int ret = -1; uint32_t flags; - trace_pipe("pre"); + trace_pipe_with_ids(p, "pipeline_prepare()"); op_data.p = p; op_data.op = COMP_OPS_PREPARE; @@ -689,7 +706,7 @@ void pipeline_cache(struct pipeline *p, struct comp_dev *dev, int cmd) cache_command cache_cmd = comp_get_cache_command(cmd); uint32_t flags; - trace_pipe("cac"); + trace_pipe_with_ids(p, "pipeline_cache()"); spin_lock_irq(&p->lock, flags); @@ -704,7 +721,8 @@ void pipeline_cache(struct pipeline *p, struct comp_dev *dev, int cmd) if (cache_cmd) cache_cmd(p, sizeof(*p)); else - trace_pipe_error("ccN"); + trace_pipe_error_with_ids(p, "pipeline_cache() error: Missing " + "cache_cmd"); spin_unlock_irq(&p->lock, flags); } @@ -718,8 +736,10 @@ static int pipeline_trigger_on_core(struct pipeline *p, struct comp_dev *host, /* check if requested core is enabled */ if (!cpu_is_core_enabled(p->ipc_pipe.core)) { - trace_pipe_error("pt0"); - trace_error_value(p->ipc_pipe.core); + trace_pipe_error_with_ids(p, "pipeline_trigger_on_core() error:" + "Requested core is not enabled, " + "p->ipc_pipe.core = %u", + p->ipc_pipe.core); return -EINVAL; } @@ -730,9 +750,10 @@ static int pipeline_trigger_on_core(struct pipeline *p, struct comp_dev *host, /* send IDC pipeline trigger message */ ret = idc_send_msg(&pipeline_trigger, IDC_BLOCKING); if (ret < 0) { - trace_pipe_error("pt1"); - trace_error_value(host->comp.id); - trace_error_value(cmd); + trace_pipe_error_with_ids(p, "pipeline_trigger_on_core() error:" + " idc_send_msg returned %d, host->" + "comp.id = %u, cmd = %d", + ret, host->comp.id, cmd); return ret; } @@ -750,7 +771,7 @@ int pipeline_trigger(struct pipeline *p, struct comp_dev *host, int cmd) int ret; uint32_t flags; - trace_pipe("cmd"); + trace_pipe_with_ids(p, "pipeline_trigger()"); /* if current core is different than requested */ if (p->ipc_pipe.core != cpu_get_id()) @@ -771,9 +792,9 @@ int pipeline_trigger(struct pipeline *p, struct comp_dev *host, int cmd) } if (ret < 0) { - trace_ipc_error("pc0"); - trace_error_value(host->comp.id); - trace_error_value(cmd); + trace_ipc_error("pipeline_trigger() error: ret = %d, host->" + "comp.id = %u, cmd = %d", ret, host->comp.id, + cmd); } spin_unlock_irq(&p->lock, flags); @@ -800,7 +821,7 @@ int pipeline_params(struct pipeline *p, struct comp_dev *host, int ret; uint32_t flags; - trace_pipe("Par"); + trace_pipe_with_ids(p, "pipeline_params()"); op_data.p = p; op_data.op = COMP_OPS_PARAMS; @@ -818,8 +839,8 @@ int pipeline_params(struct pipeline *p, struct comp_dev *host, } if (ret < 0) { - trace_ipc_error("pp0"); - trace_error_value(host->comp.id); + trace_ipc_error("pipeline_params() error: ret = %d, host->comp" + ".id = %u", ret, host->comp.id); } spin_unlock_irq(&p->lock, flags); @@ -833,7 +854,7 @@ int pipeline_reset(struct pipeline *p, struct comp_dev *host) int ret; uint32_t flags; - trace_pipe("PRe"); + trace_pipe_with_ids(p, "pipeline_reset()"); op_data.p = p; op_data.op = COMP_OPS_RESET; @@ -849,8 +870,8 @@ int pipeline_reset(struct pipeline *p, struct comp_dev *host) } if (ret < 0) { - trace_ipc_error("pr0"); - trace_error_value(host->comp.id); + trace_ipc_error("pipeline_reset() error: ret = %d, host->comp." + "id = %u", ret, host->comp.id); } spin_unlock_irq(&p->lock, flags); @@ -876,8 +897,8 @@ static int pipeline_copy_from_upstream(struct comp_dev *start, struct list_item *clist; int err = 0; - tracev_pipe("CP+"); - tracev_value(current->comp.id); + tracev_pipe("pipeline_copy_from_upstream(), current->comp.id = %u", + current->comp.id); /* stop going upstream if we reach an end point in this pipeline */ if (current->is_endpoint && current != start) @@ -900,8 +921,9 @@ static int pipeline_copy_from_upstream(struct comp_dev *start, /* continue upstream */ err = pipeline_copy_from_upstream(start, buffer->source); if (err < 0) { - trace_pipe_error("ePU"); - trace_error_value(current->comp.id); + trace_pipe_error("pipeline_copy_from_upstream() error:" + " err = %d, current->comp.id = %u", + err, current->comp.id); return err; } } @@ -911,7 +933,7 @@ static int pipeline_copy_from_upstream(struct comp_dev *start, err = comp_copy(current); /* return back downstream */ - tracev_pipe("CD+"); + tracev_pipe("pipeline_copy_from_upstream() buffer from upstream copied"); return err; } @@ -934,8 +956,8 @@ static int pipeline_copy_to_downstream(struct comp_dev *start, struct list_item *clist; int err = 0; - tracev_pipe("CP-"); - tracev_value(current->comp.id); + tracev_pipe("pipeline_copy_to_downstream(), current->comp.id = %u", + current->comp.id); /* component copy/process to downstream */ if (current != start) { @@ -963,15 +985,16 @@ static int pipeline_copy_to_downstream(struct comp_dev *start, /* continue downstream */ err = pipeline_copy_to_downstream(start, buffer->sink); if (err < 0) { - trace_pipe_error("ePD"); - trace_error_value(current->comp.id); + trace_pipe_error("pipeline_copy_to_downstream() error: " + "err = %d, current->comp.id = %u", + err, current->comp.id); return err; } } out: /* return back upstream */ - tracev_pipe("CD-"); + tracev_pipe("pipeline_copy_to_downstream() completed"); return err; } @@ -1195,12 +1218,14 @@ static int pipeline_xrun_recover(struct pipeline *p) { int ret; - trace_pipe_error("pxr"); + trace_pipe_error_with_ids(p, "pipeline_xrun_recover()"); /* notify all pipeline comps we are in XRUN */ ret = pipeline_trigger(p, p->source_comp, COMP_TRIGGER_XRUN); if (ret < 0) { - trace_pipe_error("px0"); + trace_pipe_error_with_ids(p, "pipeline_xrun_recover() error: " + "Pipelines notification about XRUN " + "failed, ret = %d", ret); return ret; } p->xrun_bytes = 0; @@ -1208,14 +1233,18 @@ static int pipeline_xrun_recover(struct pipeline *p) /* prepare the pipeline */ ret = pipeline_prepare(p, p->source_comp); if (ret < 0) { - trace_pipe_error("px1"); + trace_pipe_error_with_ids(p, "pipeline_xrun_recover() error: " + "pipeline_prepare() failed, ret = %d", + ret); return ret; } /* restart pipeline comps */ ret = pipeline_trigger(p, p->source_comp, COMP_TRIGGER_START); if (ret < 0) { - trace_pipe_error("px2"); + trace_pipe_error_with_ids(p, "pipeline_xrun_recover() error: " + "pipeline_trigger() failed, ret = %d", + ret); return ret; } @@ -1225,7 +1254,9 @@ static int pipeline_xrun_recover(struct pipeline *p) if (p->sched_comp->params.direction == SOF_IPC_STREAM_PLAYBACK) { ret = pipeline_copy(p->sched_comp); if (ret < 0) { - trace_pipe_error("px3"); + trace_pipe_error_with_ids(p, "pipeline_xrun_recover() " + "error: pipeline_copy() " + "failed, ret = %d", ret); return ret; } } @@ -1255,7 +1286,9 @@ void pipeline_schedule_cancel(struct pipeline *p) /* cancel and wait for pipeline to complete */ err = schedule_task_cancel(&p->pipe_task); if (err < 0) - trace_pipe_error("pC0"); + trace_pipe_error_with_ids(p, "pipeline_schedule_cancel() error:" + " schedule_task_cancel() failed, err " + "= %d", err); } static void pipeline_task(void *arg) @@ -1264,7 +1297,7 @@ static void pipeline_task(void *arg) struct comp_dev *dev = p->sched_comp; int err; - tracev_pipe("PWs"); + tracev_pipe_with_ids(p, "pipeline_task()"); /* are we in xrun ? */ if (p->xrun_bytes) { @@ -1282,13 +1315,13 @@ static void pipeline_task(void *arg) } sched: - tracev_pipe("PWe"); + tracev_pipe("pipeline_task() sched"); } /* init pipeline */ int pipeline_init(void) { - trace_pipe("PIn"); + trace_pipe("pipeline_init()"); pipe_data = rzalloc(RZONE_RUNTIME, SOF_MEM_CAPS_RAM, sizeof(*pipe_data)); diff --git a/src/include/sof/audio/pipeline.h b/src/include/sof/audio/pipeline.h index c12163224e91..f6c098ab7c01 100644 --- a/src/include/sof/audio/pipeline.h +++ b/src/include/sof/audio/pipeline.h @@ -43,9 +43,29 @@ #include /* pipeline tracing */ -#define trace_pipe(__e) trace_event(TRACE_CLASS_PIPE, __e) -#define trace_pipe_error(__e) trace_error(TRACE_CLASS_PIPE, __e) -#define tracev_pipe(__e) tracev_event(TRACE_CLASS_PIPE, __e) +#define trace_pipe(format, ...) \ + trace_event(TRACE_CLASS_PIPE, format, ##__VA_ARGS__) +#define trace_pipe_with_ids(pipe_ptr, format, ...) \ + trace_event_with_ids(TRACE_CLASS_PIPE, \ + pipe_ptr->ipc_pipe.pipeline_id, \ + pipe_ptr->ipc_pipe.comp_id, \ + format, ##__VA_ARGS__) + +#define trace_pipe_error(format, ...) \ + trace_error(TRACE_CLASS_PIPE, format, ##__VA_ARGS__) +#define trace_pipe_error_with_ids(pipe_ptr, format, ...) \ + trace_error_with_ids(TRACE_CLASS_PIPE, \ + pipe_ptr->ipc_pipe.pipeline_id, \ + pipe_ptr->ipc_pipe.comp_id, \ + format, ##__VA_ARGS__) + +#define tracev_pipe(format, ...) \ + tracev_event(TRACE_CLASS_PIPE, format, ##__VA_ARGS__) +#define tracev_pipe_with_ids(pipe_ptr, format, ...) \ + tracev_event_with_ids(TRACE_CLASS_PIPE, \ + pipe_ptr->ipc_pipe.pipeline_id, \ + pipe_ptr->ipc_pipe.comp_id, \ + format, ##__VA_ARGS__) struct ipc_pipeline_dev; struct ipc; diff --git a/src/include/sof/ipc.h b/src/include/sof/ipc.h index 0844d3d5b84c..b98bbbd04019 100644 --- a/src/include/sof/ipc.h +++ b/src/include/sof/ipc.h @@ -45,9 +45,12 @@ struct sof; struct dai_config; -#define trace_ipc(__e) trace_event(TRACE_CLASS_IPC, __e) -#define tracev_ipc(__e) tracev_event(TRACE_CLASS_IPC, __e) -#define trace_ipc_error(__e) trace_error(TRACE_CLASS_IPC, __e) +#define trace_ipc(format, ...) \ + trace_event(TRACE_CLASS_IPC, format, ##__VA_ARGS__) +#define tracev_ipc(format, ...) \ + tracev_event(TRACE_CLASS_IPC, format, ##__VA_ARGS__) +#define trace_ipc_error(format, ...) \ + trace_error(TRACE_CLASS_IPC, format, ##__VA_ARGS__) #define MSG_QUEUE_SIZE 12 From 8449f249048fc9a64764b85feab0b0c739b722ad Mon Sep 17 00:00:00 2001 From: ArturX Kloniecki Date: Mon, 5 Nov 2018 18:20:18 +0100 Subject: [PATCH 3/4] debugability: Refactor ipc handler traces to fully utilize trace_event Signed-off-by: ArturX Kloniecki --- src/ipc/handler.c | 196 +++++++++++++++++++++++++++------------------- 1 file changed, 117 insertions(+), 79 deletions(-) diff --git a/src/ipc/handler.c b/src/ipc/handler.c index f3b15c18ec09..7ec9cb491f68 100644 --- a/src/ipc/handler.c +++ b/src/ipc/handler.c @@ -81,7 +81,8 @@ static inline struct sof_ipc_hdr *mailbox_validate(void) /* validate component header */ if (hdr->size > SOF_IPC_MSG_MAX_SIZE) { - trace_ipc_error("ebg"); + trace_ipc_error("mailbox_validate() error: Invalid size of " + "component header."); return NULL; } @@ -179,26 +180,29 @@ static int ipc_stream_pcm_params(uint32_t stream) struct comp_dev *cd; int err, posn_offset; - trace_ipc("SAl"); + trace_ipc("ipc_stream_pcm_params()"); /* sanity check size */ if (IPC_INVALID_SIZE(pcm_params)) { - trace_ipc_error("eAS"); + trace_ipc_error("ipc_stream_pcm_params() error: Invalid size of" + "IPC pcm params."); return -EINVAL; } /* get the pcm_dev */ pcm_dev = ipc_get_comp(_ipc, pcm_params->comp_id); if (pcm_dev == NULL) { - trace_ipc_error("eAC"); - trace_error_value(pcm_params->comp_id); + trace_ipc_error("ipc_stream_pcm_params() error: Requested " + "pcm_dev ID = %u not found.", + pcm_params->comp_id); return -ENODEV; } /* sanity check comp */ if (pcm_dev->cd->pipeline == NULL) { - trace_ipc_error("eA1"); - trace_error_value(pcm_params->comp_id); + trace_ipc_error("ipc_stream_pcm_params() error: Requested " + "pcm_dev ID = %u has no pipeline associated.", + pcm_params->comp_id); return -EINVAL; } @@ -220,7 +224,9 @@ static int ipc_stream_pcm_params(uint32_t stream) err = ipc_get_page_descriptors(iipc->dmac, iipc->page_table, &pcm_params->params.buffer); if (err < 0) { - trace_ipc_error("eAp"); + trace_ipc_error("ipc_stream_pcm_params() error: " + "ipc_get_page_descriptors() failed with err = " + "%d", err); goto error; } @@ -232,13 +238,16 @@ static int ipc_stream_pcm_params(uint32_t stream) &pcm_params->params.buffer, &elem_array, host->direction); if (err < 0) { - trace_ipc_error("eAP"); + trace_ipc_error("ipc_stream_pcm_params() error: " + "ipc_parse_page_descriptors() failed with err =" + " %d", err); goto error; } err = comp_host_buffer(cd, &elem_array, ring_size); if (err < 0) { - trace_ipc_error("ePb"); + trace_ipc_error("ipc_stream_pcm_params() error: " + "comp_host_buffer() failed with err = %d", err); goto error; } @@ -248,20 +257,23 @@ static int ipc_stream_pcm_params(uint32_t stream) /* configure pipeline audio params */ err = pipeline_params(pcm_dev->cd->pipeline, pcm_dev->cd, pcm_params); if (err < 0) { - trace_ipc_error("eAa"); + trace_ipc_error("ipc_stream_pcm_params() error: " + "pipeline_params() failed with err = %d", err); goto error; } /* prepare pipeline audio params */ err = pipeline_prepare(pcm_dev->cd->pipeline, pcm_dev->cd); if (err < 0) { - trace_ipc_error("eAr"); + trace_ipc_error("ipc_stream_pcm_params() error: " + "pipeline_prepare() failed with err = %d", err); goto error; } posn_offset = ipc_get_posn_offset(_ipc, pcm_dev->cd->pipeline); if (posn_offset < 0) { - trace_ipc_error("eAo"); + trace_ipc_error("ipc_stream_pcm_params() error: " + "ipc_get_posn_offset() failed."); goto error; } /* write component values to the outbox */ @@ -280,7 +292,8 @@ static int ipc_stream_pcm_params(uint32_t stream) err = pipeline_reset(pcm_dev->cd->pipeline, pcm_dev->cd); if (err < 0) - trace_ipc_error("eA!"); + trace_ipc_error("ipc_stream_pcm_params() error: " + "pipeline_reset() failed with err = %d", err); return -EINVAL; } @@ -290,25 +303,28 @@ static int ipc_stream_pcm_free(uint32_t header) struct sof_ipc_stream *free_req = _ipc->comp_data; struct ipc_comp_dev *pcm_dev; - trace_ipc("SFr"); + trace_ipc("ipc_stream_pcm_free()"); /* sanity check size */ if (IPC_INVALID_SIZE(free_req)) { - trace_ipc_error("eFs"); + trace_ipc_error("ipc_stream_pcm_free() error: Invalid size of " + "IPC."); return -EINVAL; } /* get the pcm_dev */ pcm_dev = ipc_get_comp(_ipc, free_req->comp_id); if (pcm_dev == NULL) { - trace_ipc_error("eFr"); + trace_ipc_error("ipc_stream_pcm_free() error: Requested pcm_dev" + " ID = %u not found.", free_req->comp_id); return -ENODEV; } /* sanity check comp */ if (pcm_dev->cd->pipeline == NULL) { - trace_ipc_error("eF1"); - trace_error_value(free_req->comp_id); + trace_ipc_error("ipc_stream_pcm_free() error: Requested pcm_dev" + " ID = %u has no pipeline associated.", + free_req->comp_id); return -EINVAL; } @@ -323,20 +339,22 @@ static int ipc_stream_position(uint32_t header) struct sof_ipc_stream_posn posn; struct ipc_comp_dev *pcm_dev; - trace_ipc("pos"); + trace_ipc("ipc_stream_position()"); memset(&posn, 0, sizeof(posn)); /* sanity check size */ if (IPC_INVALID_SIZE(stream)) { - trace_ipc_error("ePs"); + trace_ipc_error("ipc_stream_position() error: Invalid size of " + "IPC"); return -EINVAL; } /* get the pcm_dev */ pcm_dev = ipc_get_comp(_ipc, stream->comp_id); if (pcm_dev == NULL) { - trace_ipc_error("epo"); + trace_ipc_error("ipc_stream_position() error: Requested pcm_dev" + " ID = %u not found.", stream->comp_id); return -ENODEV; } @@ -392,18 +410,20 @@ static int ipc_stream_trigger(uint32_t header) uint32_t ipc_cmd = (header & SOF_CMD_TYPE_MASK) >> SOF_CMD_TYPE_SHIFT; int ret; - trace_ipc("tri"); + trace_ipc("ipc_stream_trigger()"); /* sanity check size */ if (IPC_INVALID_SIZE(stream)) { - trace_ipc_error("eRs"); + trace_ipc_error("ipc_stream_trigger() error: Invalid size of " + "IPC"); return -EINVAL; } /* get the pcm_dev */ pcm_dev = ipc_get_comp(_ipc, stream->comp_id); if (pcm_dev == NULL) { - trace_ipc_error("eRg"); + trace_ipc_error("ipc_stream_trigger() error: Requested pcm_dev " + " ID = %u not found.", stream->comp_id); return -ENODEV; } @@ -428,8 +448,9 @@ static int ipc_stream_trigger(uint32_t header) /* trigger the component */ ret = pipeline_trigger(pcm_dev->cd->pipeline, pcm_dev->cd, cmd); if (ret < 0) { - trace_ipc_error("eRc"); - trace_error_value(ipc_cmd); + trace_ipc_error("ipc_stream_trigger() error: pipeline_trigger()" + " failed with ret = %d, ipc_cmd = %u", ret, + ipc_cmd); } return ret; @@ -454,7 +475,8 @@ static int ipc_glb_stream_message(uint32_t header) case iCS(SOF_IPC_STREAM_POSITION): return ipc_stream_position(header); default: - trace_ipc_error("es1"); + trace_ipc_error("ipc_glb_stream_message() error: Invalid " + "command, cmd = %u", cmd); return -EINVAL; } } @@ -469,14 +491,14 @@ static int ipc_dai_config(uint32_t header) struct dai *dai; int ret; - trace_ipc("DsF"); + trace_ipc("ipc_dai_config()"); /* get DAI */ dai = dai_get(config->type, config->dai_index, 0 /* existing only */); if (dai == NULL) { - trace_ipc_error("eDi"); - trace_error_value(config->type); - trace_error_value(config->dai_index); + trace_ipc_error("ipc_dai_config() error: Requested DAI not " + "found, type = %u, dai_index = %u", + config->type, config->dai_index); return -ENODEV; } @@ -484,7 +506,8 @@ static int ipc_dai_config(uint32_t header) ret = dai_set_config(dai, config); dai_put(dai); /* free ref immediately */ if (ret < 0) { - trace_ipc_error("eDC"); + trace_ipc_error("ipc_dai_config() error: dai_set_config() " + "failed with ret = %d", ret); return ret; } @@ -502,8 +525,8 @@ static int ipc_glb_dai_message(uint32_t header) case iCS(SOF_IPC_DAI_LOOPBACK): //return ipc_comp_set_value(header, COMP_CMD_LOOPBACK); default: - trace_ipc_error("eDc"); - trace_error_value(header); + trace_ipc_error("ipc_glb_dai_message() error: Invalid command " + "header = %u", header); return -EINVAL; } } @@ -516,7 +539,7 @@ static int ipc_pm_context_size(uint32_t header) { struct sof_ipc_pm_ctx pm_ctx; - trace_ipc("PMs"); + trace_ipc("ipc_pm_context_size()"); bzero(&pm_ctx, sizeof(pm_ctx)); @@ -532,7 +555,7 @@ static int ipc_pm_context_save(uint32_t header) struct sof_ipc_pm_ctx *pm_ctx = _ipc->comp_data; struct intel_ipc_data *iipc = ipc_get_drvdata(_ipc); - trace_ipc("PMs"); + trace_ipc("ipc_pm_context_save()"); /* TODO: check we are inactive - all streams are suspended */ @@ -568,7 +591,7 @@ static int ipc_pm_context_restore(uint32_t header) { struct sof_ipc_pm_ctx *pm_ctx = _ipc->comp_data; - trace_ipc("PMr"); + trace_ipc("ipc_pm_context_restore()"); /* restore context placeholder */ mailbox_hostbox_write(0, pm_ctx, sizeof(*pm_ctx)); @@ -581,7 +604,7 @@ static int ipc_pm_core_enable(uint32_t header) struct sof_ipc_pm_core_config *pm_core_config = _ipc->comp_data; int i = 0; - trace_ipc("PMc"); + trace_ipc("ipc_pm_core_enable()"); for (i = 0; i < PLATFORM_CORE_COUNT; i++) { if (i != PLATFORM_MASTER_CORE_ID) { @@ -629,11 +652,12 @@ static int ipc_dma_trace_config(uint32_t header) struct sof_ipc_dma_trace_params *params = _ipc->comp_data; int err; - trace_ipc("DA1"); + trace_ipc("ipc_dma_trace_config()"); /* sanity check size */ if (IPC_INVALID_SIZE(params)) { - trace_ipc_error("DAs"); + trace_ipc_error("ipc_dma_trace_config() error: Invalid size of " + "IPC"); return -EINVAL; } @@ -645,11 +669,13 @@ static int ipc_dma_trace_config(uint32_t header) err = ipc_get_page_descriptors(iipc->dmac, iipc->page_table, ¶ms->buffer); if (err < 0) { - trace_ipc_error("eCp"); + trace_ipc_error("ipc_dma_trace_config() error: " + "ipc_get_page_descriptors() failed with err = " + "%u", err); goto error; } - trace_ipc("DAg"); + trace_ipc("ipc_dma_trace_config() Page descriptors acquired."); /* Parse host tables */ ring_size = params->buffer.size; @@ -657,13 +683,17 @@ static int ipc_dma_trace_config(uint32_t header) err = ipc_parse_page_descriptors(iipc->page_table, ¶ms->buffer, &elem_array, SOF_IPC_STREAM_CAPTURE); if (err < 0) { - trace_ipc_error("ePP"); + trace_ipc_error("ipc_dma_trace_config() error: " + "ipc_parse_page_descriptors() failed with err =" + " %d", err); goto error; } err = dma_trace_host_buffer(_ipc->dmat, &elem_array, ring_size); if (err < 0) { - trace_ipc_error("ePb"); + trace_ipc_error("ipc_dma_trace_config() error: " + "dma_trace_host_buffer() failed with err = %d", + err); goto error; } @@ -674,11 +704,14 @@ static int ipc_dma_trace_config(uint32_t header) /* host buffer size for DMA trace */ _ipc->dmat->host_size = params->buffer.size; #endif - trace_ipc("DAp"); + trace_ipc("ipc_dma_trace_config() DMA trace configured."); err = dma_trace_enable(_ipc->dmat); - if (err < 0) + if (err < 0) { + trace_ipc_error("ipc_dma_trace_config() error: " + "dma_trace_enable() failed with err = %d", err); goto error; + } return 0; @@ -687,8 +720,6 @@ static int ipc_dma_trace_config(uint32_t header) dma_sg_free(&elem_array); #endif - if (err < 0) - trace_ipc_error("eA!"); return -EINVAL; } @@ -711,14 +742,14 @@ static int ipc_glb_debug_message(uint32_t header) { uint32_t cmd = (header & SOF_CMD_TYPE_MASK) >> SOF_CMD_TYPE_SHIFT; - trace_ipc("Idn"); + trace_ipc("ipc_glb_debug_message()"); switch (cmd) { case iCS(SOF_IPC_TRACE_DMA_PARAMS): return ipc_dma_trace_config(header); default: - trace_ipc_error("eDc"); - trace_error_value(header); + trace_ipc_error("ipc_glb_debug_message() error: Unknown command" + ", header = %u", header); return -EINVAL; } } @@ -759,20 +790,21 @@ static int ipc_comp_value(uint32_t header, uint32_t cmd) struct sof_ipc_ctrl_data *data = _ipc->comp_data; int ret; - trace_ipc("VoG"); + trace_ipc("ipc_comp_value()"); /* get the component */ comp_dev = ipc_get_comp(_ipc, data->comp_id); if (comp_dev == NULL){ - trace_ipc_error("eVg"); - trace_error_value(data->comp_id); + trace_ipc_error("ipc_comp_value() error: Requested comp_dev ID " + "= %u not found.", data->comp_id); return -ENODEV; } /* get component values */ ret = ipc_comp_cmd(comp_dev->cd, cmd, data); if (ret < 0) { - trace_ipc_error("eVG"); + trace_ipc_error("ipc_comp_value() error: ipc_comp_cmd() failed," + " cmd = %u", cmd); return ret; } @@ -795,8 +827,8 @@ static int ipc_glb_comp_message(uint32_t header) case iCS(SOF_IPC_COMP_GET_DATA): return ipc_comp_value(header, COMP_CMD_GET_DATA); default: - trace_ipc_error("eCc"); - trace_error_value(header); + trace_ipc_error("ipc_glb_comp_message() error: Unknown command," + "header = %u", header); return -EINVAL; } } @@ -807,12 +839,13 @@ static int ipc_glb_tplg_comp_new(uint32_t header) struct sof_ipc_comp_reply reply; int ret; - trace_ipc("tcn"); + trace_ipc("ipc_glb_tplg_comp_new()"); /* register component */ ret = ipc_comp_new(_ipc, comp); if (ret < 0) { - trace_ipc_error("cn1"); + trace_ipc_error("ipc_glb_tplg_comp_new() error: ipc_comp_new() " + "failed."); return ret; } @@ -831,11 +864,12 @@ static int ipc_glb_tplg_buffer_new(uint32_t header) struct sof_ipc_comp_reply reply; int ret; - trace_ipc("Ibn"); + trace_ipc("ipc_glb_tplg_buffer_new()"); ret = ipc_buffer_new(_ipc, ipc_buffer); if (ret < 0) { - trace_ipc_error("bn1"); + trace_ipc_error("ipc_glb_tplg_buffer_new() error: " + "ipc_buffer_new() failed."); return ret; } @@ -854,17 +888,19 @@ static int ipc_glb_tplg_pipe_new(uint32_t header) struct sof_ipc_comp_reply reply; int ret; - trace_ipc("Ipn"); + trace_ipc("ipc_glb_tplg_pipe_new()"); /* sanity check size */ if (IPC_INVALID_SIZE(ipc_pipeline)) { - trace_ipc_error("Ips"); + trace_ipc_error("ipc_glb_tplg_pipe_new() error: Invalid size of" + " IPC"); return -EINVAL; } ret = ipc_pipeline_new(_ipc, ipc_pipeline); if (ret < 0) { - trace_ipc_error("pn1"); + trace_ipc_error("ipc_glb_tplg_pipe_new() error: " + "ipc_pipeline_new() failed."); return ret; } @@ -881,7 +917,7 @@ static int ipc_glb_tplg_pipe_complete(uint32_t header) { struct sof_ipc_pipe_ready *ipc_pipeline = _ipc->comp_data; - trace_ipc("Ipc"); + trace_ipc("ipc_glb_tplg_pipe_complete()"); return ipc_pipeline_complete(_ipc, ipc_pipeline->comp_id); } @@ -890,11 +926,12 @@ static int ipc_glb_tplg_comp_connect(uint32_t header) { struct sof_ipc_pipe_comp_connect *connect = _ipc->comp_data; - trace_ipc("Icn"); + trace_ipc("ipc_glb_tplg_comp_connect()"); /* sanity check size */ if (IPC_INVALID_SIZE(connect)) { - trace_ipc_error("Ics"); + trace_ipc_error("ipc_glb_tplg_comp_connect() error: Invalid " + "size of IPC"); return -EINVAL; } @@ -907,11 +944,12 @@ static int ipc_glb_tplg_free(uint32_t header, struct sof_ipc_free *ipc_free = _ipc->comp_data; int ret; - trace_ipc("Tcf"); + trace_ipc("ipc_glb_tplg_free()"); /* sanity check size */ if (IPC_INVALID_SIZE(ipc_free)) { - trace_ipc_error("Tcs"); + trace_ipc_error("ipc_glb_tplg_free() error: Invalid size of " + "IPC"); return -EINVAL; } @@ -919,8 +957,8 @@ static int ipc_glb_tplg_free(uint32_t header, ret = free_func(_ipc, ipc_free->id); if (ret < 0) { - trace_error(TRACE_CLASS_IPC, - "ipc-glb-tplg-free free_func failed %d", ret); + trace_ipc_error("ipc_glb_tplg_free() error: free_func() failed " + "with ret = %d", ret); } return ret; @@ -948,8 +986,8 @@ static int ipc_glb_tplg_message(uint32_t header) case iCS(SOF_IPC_TPLG_BUFFER_FREE): return ipc_glb_tplg_free(header, ipc_buffer_free); default: - trace_ipc_error("eTc"); - trace_error_value(header); + trace_ipc_error("ipc_glb_tplg_message() error: Unknown command," + "header = %u", header); return -EINVAL; } } @@ -965,7 +1003,7 @@ int ipc_cmd(void) hdr = mailbox_validate(); if (hdr == NULL) { - trace_ipc_error("hdr"); + trace_ipc_error("ipc_cmd() error: Missing IPC header."); return -EINVAL; } @@ -989,8 +1027,8 @@ int ipc_cmd(void) case iGS(SOF_IPC_GLB_TRACE_MSG): return ipc_glb_debug_message(hdr->cmd); default: - trace_ipc_error("eGc"); - trace_error_value(type); + trace_ipc_error("ipc_cmd() error: Unknown command, type = %u", + type); return -EINVAL; } } @@ -1110,8 +1148,8 @@ int ipc_queue_host_message(struct ipc *ipc, uint32_t header, void *tx_data, msg = msg_get_empty(ipc); if (msg == NULL) { - trace_error(TRACE_CLASS_IPC, "eQb header 0x08x replace %d", - header, replace); + trace_ipc_error("ipc_queue_host_message() error: header 0x08x " + "replace %d", header, replace); ret = -EBUSY; goto out; } From 42179929d2f6c515a1322acd9c32c9176dcfb0c9 Mon Sep 17 00:00:00 2001 From: ArturX Kloniecki Date: Wed, 7 Nov 2018 13:45:56 +0100 Subject: [PATCH 4/4] debugability: Refactor dai traces to fully utilize trace_event Signed-off-by: ArturX Kloniecki --- src/audio/dai.c | 115 +++++++++++++++++++++++++++++------------------- 1 file changed, 70 insertions(+), 45 deletions(-) diff --git a/src/audio/dai.c b/src/audio/dai.c index d79f7f3a3258..372771283b51 100644 --- a/src/audio/dai.c +++ b/src/audio/dai.c @@ -52,10 +52,12 @@ #define DAI_PTR_INIT_HOST 2 /* buffer ptr initialized by host */ /* tracing */ -#define trace_dai(__e) trace_event(TRACE_CLASS_DAI, __e) -#define trace_dai_error(__e) trace_error(TRACE_CLASS_DAI, __e) -#define tracev_dai(__e) tracev_event(TRACE_CLASS_DAI, __e) - +#define trace_dai(format, ...) trace_event(TRACE_CLASS_DAI, format, \ + ##__VA_ARGS__) +#define trace_dai_error(format, ...) trace_error(TRACE_CLASS_DAI, format, \ + ##__VA_ARGS__) +#define tracev_dai(format, ...) tracev_event(TRACE_CLASS_DAI, format, \ + ##__VA_ARGS__) struct dai_data { /* local DMA config */ @@ -91,7 +93,9 @@ static void dai_buffer_process(struct comp_dev *dev) /* make sure there is available bytes for next period */ if (dma_buffer->avail < dd->period_bytes) { - trace_dai_error("xru"); + trace_dai_error("dai_buffer_process() error: " + "Insufficient bytes for next period. " + "comp_underrun()"); comp_underrun(dev, dma_buffer, dd->period_bytes, 0); } } else { @@ -105,7 +109,9 @@ static void dai_buffer_process(struct comp_dev *dev) /* make sure there is free bytes for next period */ if (dma_buffer->free < dd->period_bytes) { - trace_dai_error("xro"); + trace_dai_error("dai_buffer_process() error: " + "Insufficient free bytes for next " + "period. comp_overrun()"); comp_overrun(dev, dma_buffer, dd->period_bytes, 0); } } @@ -126,7 +132,7 @@ static void dai_dma_cb(void *data, uint32_t type, struct dma_sg_elem *next) struct dai_data *dd = comp_get_drvdata(dev); struct comp_buffer *dma_buffer; - tracev_dai("irq"); + tracev_dai("dai_dma_cb()"); /* stop dma copy for pause/stop/xrun */ if (dev->state != COMP_STATE_ACTIVE || dd->xrun) { @@ -168,7 +174,7 @@ static struct comp_dev *dai_new(struct sof_ipc_comp *comp) struct dai_data *dd; uint32_t dir, caps, dma_dev; - trace_dai("new"); + trace_dai("dai_new()"); dev = rzalloc(RZONE_RUNTIME, SOF_MEM_CAPS_RAM, COMP_SIZE(struct sof_ipc_comp_dai)); @@ -188,7 +194,8 @@ static struct comp_dev *dai_new(struct sof_ipc_comp *comp) dd->dai = dai_get(dai->type, dai->dai_index, DAI_CREAT); if (dd->dai == NULL) { - trace_dai_error("eDg"); + trace_dai_error("dai_new() error: dai_get() failed to create " + "DAI."); goto error; } @@ -213,7 +220,8 @@ static struct comp_dev *dai_new(struct sof_ipc_comp *comp) } dd->dma = dma_get(dir, caps, dma_dev, DMA_ACCESS_SHARED); if (dd->dma == NULL) { - trace_dai_error("eDd"); + trace_dai_error("dai_new() error: dma_get() failed to get " + "shared access to DMA."); goto error; } @@ -272,11 +280,13 @@ static int dai_playback_params(struct comp_dev *dev) /* resize the buffer if space is available to align with period size */ err = buffer_set_size(dma_buffer, buffer_size); if (err < 0) { - trace_dai_error("ep1"); - trace_error_value(source_config->periods_sink); - trace_error_value(dd->period_bytes); - trace_error_value(buffer_size); - trace_error_value(dma_buffer->alloc_size); + trace_dai_error("dai_playback_params() error: buffer_set_size()" + " failed to resize buffer. " + "source_config->periods_sink = %u; " + "dd->period_bytes = %u; buffer_size = %u; " + "dma_buffer->alloc_size = %u", + source_config->periods_sink, dd->period_bytes, + buffer_size, dma_buffer->alloc_size); return err; } @@ -288,7 +298,9 @@ static int dai_playback_params(struct comp_dev *dev) (uintptr_t)(dma_buffer->r_ptr), dai_fifo(dd->dai, SOF_IPC_STREAM_PLAYBACK)); if (err < 0) { - trace_dai_error("ep3"); + trace_dai_error("dai_playback_params() error: " + "dma_sg_alloc() failed with err = %d", + err); return err; } } @@ -322,11 +334,13 @@ static int dai_capture_params(struct comp_dev *dev) /* resize the buffer if space is available to align with period size */ err = buffer_set_size(dma_buffer, buffer_size); if (err < 0) { - trace_dai_error("ec1"); - trace_error_value(sink_config->periods_sink); - trace_error_value(dd->period_bytes); - trace_error_value(buffer_size); - trace_error_value(dma_buffer->alloc_size); + trace_dai_error("dai_capture_params() error: buffer_set_size()" + " failed to resize buffer. " + "sink_config->periods_sink = %u; " + "dd->period_bytes = %u; buffer_size = %u; " + "dma_buffer->alloc_size = %u", + sink_config->periods_sink, dd->period_bytes, + buffer_size); return err; } @@ -338,7 +352,9 @@ static int dai_capture_params(struct comp_dev *dev) (uintptr_t)(dma_buffer->w_ptr), dai_fifo(dd->dai, SOF_IPC_STREAM_CAPTURE)); if (err < 0) { - trace_dai_error("ec3"); + trace_dai_error("dai_capture_params() error: " + "dma_sg_alloc() failed with err = %d", + err); return err; } } @@ -352,18 +368,19 @@ static int dai_params(struct comp_dev *dev) struct comp_buffer *dma_buffer; struct sof_ipc_comp_config *dconfig = COMP_GET_CONFIG(dev); - trace_dai("par"); + trace_dai("dai_params()"); /* can set params on only init state */ if (dev->state != COMP_STATE_READY) { - trace_dai_error("wdp"); + trace_dai_error("dai_params() error: Component is not in init " + "state."); return -EINVAL; } /* get DMA channel, once the stream_tag is known */ dd->chan = dma_channel_get(dd->dma, dev->params.stream_tag); if (dd->chan < 0) { - trace_dai_error("eDc"); + trace_dai_error("dai_params() error: dma_channel_get() failed"); return -EINVAL; } @@ -378,13 +395,15 @@ static int dai_params(struct comp_dev *dev) /* calculate period size based on config */ dev->frame_bytes = comp_frame_bytes(dev); if (dev->frame_bytes == 0) { - trace_dai_error("ed1"); + trace_dai_error("dai_params() error: comp_frame_bytes() " + "returned 0."); return -EINVAL; } dd->period_bytes = dev->frames * dev->frame_bytes; if (dd->period_bytes == 0) { - trace_dai_error("ed2"); + trace_dai_error("dai_params() error: device has no bytes (no " + "frames to copy to sink)."); return -EINVAL; } @@ -409,7 +428,7 @@ static int dai_prepare(struct comp_dev *dev) struct comp_buffer *dma_buffer; int ret = 0; - trace_dai("pre"); + trace_dai("dai_prepare()"); ret = comp_set_state(dev, COMP_TRIGGER_PREPARE); if (ret < 0) @@ -418,7 +437,8 @@ static int dai_prepare(struct comp_dev *dev) dev->position = 0; if (!dd->config.elem_array.elems) { - trace_dai_error("wdm"); + trace_dai_error("dai_prepare() error: Missing " + "dd->config.elem_array.elems."); comp_set_state(dev, COMP_TRIGGER_RESET); return -EINVAL; } @@ -457,7 +477,7 @@ static int dai_reset(struct comp_dev *dev) struct dai_data *dd = comp_get_drvdata(dev); struct dma_sg_config *config = &dd->config; - trace_dai("res"); + trace_dai("dai_reset()"); dma_channel_put(dd->dma, dd->chan); @@ -517,8 +537,7 @@ static int dai_comp_trigger(struct comp_dev *dev, int cmd) struct comp_buffer *dma_buffer; int ret; - trace_dai("trg"); - tracev_value(cmd); + trace_dai("dai_comp_trigger(), command = %u", cmd); ret = comp_set_state(dev, cmd); if (ret < 0) @@ -526,7 +545,7 @@ static int dai_comp_trigger(struct comp_dev *dev, int cmd) switch (cmd) { case COMP_TRIGGER_START: - trace_dai("tsa"); + trace_dai("dai_comp_trigger(), START"); if (!dd->pointer_init) dai_pointer_init(dev); /* only start the DAI if we are not XRUN handling @@ -582,13 +601,13 @@ static int dai_comp_trigger(struct comp_dev *dev, int cmd) platform_dai_wallclock(dev, &dd->wallclock); break; case COMP_TRIGGER_XRUN: - trace_dai("txr"); + trace_dai("dai_comp_trigger(), XRUN"); dd->xrun = 1; /* fallthrough */ case COMP_TRIGGER_PAUSE: case COMP_TRIGGER_STOP: - trace_dai("tsp"); + trace_dai("dai_comp_trigger(), PAUSE/STOP"); ret = dma_stop(dd->dma, dd->chan); dai_trigger(dd->dai, COMP_TRIGGER_STOP, dev->params.direction); break; @@ -655,7 +674,7 @@ static int dai_config(struct comp_dev *dev, struct sof_ipc_dai_config *config) /* The frame bytes setting follows only FIFO A setting in * this DMIC driver version. */ - trace_dai("did"); + trace_dai("dai_config(), config->type = SOF_DAI_INTEL_DMIC"); /* We can use always the largest burst length. */ dd->config.burst_elems = 8; @@ -680,11 +699,15 @@ static int dai_config(struct comp_dev *dev, struct sof_ipc_dai_config *config) dev->frame_bytes = 2 * config->dmic.fifo_bits_a >> 3; } - trace_value(config->dmic.fifo_bits_a); - trace_value(config->dmic.num_pdm_active); - trace_value(config->dmic.pdm[0].enable_mic_a); - trace_value(config->dmic.pdm[0].enable_mic_b); - trace_value(dev->frame_bytes); + trace_dai("dai_config(), config->dmic.fifo_bits_a = %u; " + "config->dmic.num_pdm_active = %u; " + "config->dmic.pdm[0].enable_mic_a = %u; " + "config->dmic.pdm[0].enable_mic_b = %u; " + "dev->frame_bytes = %u", config->dmic.fifo_bits_a, + config->dmic.num_pdm_active, + config->dmic.pdm[0].enable_mic_a, + config->dmic.pdm[0].enable_mic_b, + dev->frame_bytes); break; case SOF_DAI_INTEL_HDA: /* set to some non-zero value to satisfy the condition below, @@ -695,12 +718,14 @@ static int dai_config(struct comp_dev *dev, struct sof_ipc_dai_config *config) break; default: /* other types of DAIs not handled for now */ - trace_dai_error("de2"); + trace_dai_error("dai_config() error: Handling of DAIs other " + "than SOF_DAI_INTEL_SSP, SOF_DAI_INTEL_DMIC or " + "SOF_DAI_INTEL_HDA is not handled for now."); break; } if (dev->frame_bytes == 0) { - trace_dai_error("de1"); + trace_dai_error("dai_config() error: dev->frame_bytes == 0"); return -EINVAL; } @@ -713,7 +738,7 @@ static void dai_cache(struct comp_dev *dev, int cmd) switch (cmd) { case COMP_CACHE_WRITEBACK_INV: - trace_dai("wtb"); + trace_dai("dai_cache(), COMP_CACHE_WRITEBACK_INV"); dd = comp_get_drvdata(dev); @@ -726,7 +751,7 @@ static void dai_cache(struct comp_dev *dev, int cmd) break; case COMP_CACHE_INVALIDATE: - trace_dai("inv"); + trace_dai("dai_cache(), COMP_CACHE_INVALIDATE"); dcache_invalidate_region(dev, sizeof(*dev));