diff --git a/src/drivers/intel/hda/hda-dma.c b/src/drivers/intel/hda/hda-dma.c index 46bf0970fa43..ea96b6006830 100644 --- a/src/drivers/intel/hda/hda-dma.c +++ b/src/drivers/intel/hda/hda-dma.c @@ -218,7 +218,7 @@ static void hda_dma_get_dbg_vals(struct dma_chan_data *chan, } \ } \ } while (0) -#else +#else /* HDA_DMA_PTR_DBG */ #define hda_dma_dbg_count_reset(...) #define hda_dma_get_dbg_vals(...) #define hda_dma_ptr_trace(...) diff --git a/src/include/ipc/trace.h b/src/include/ipc/trace.h index bdfc000424df..c7f6258f386c 100644 --- a/src/include/ipc/trace.h +++ b/src/include/ipc/trace.h @@ -27,7 +27,7 @@ #define SOF_TRACE_FILENAME_SIZE 32 -/* DMA for Trace params info - SOF_IPC_DEBUG_DMA_PARAMS */ +/* DMA for Trace params info - SOF_IPC_TRACE_DMA_PARAMS */ /* Deprecated - use sof_ipc_dma_trace_params_ext */ struct sof_ipc_dma_trace_params { struct sof_ipc_cmd_hdr hdr; @@ -35,7 +35,7 @@ struct sof_ipc_dma_trace_params { uint32_t stream_tag; } __attribute__((packed, aligned(4))); -/* DMA for Trace params info - SOF_IPC_DEBUG_DMA_PARAMS_EXT */ +/* DMA for Trace params info - SOF_IPC_TRACE_DMA_PARAMS_EXT */ struct sof_ipc_dma_trace_params_ext { struct sof_ipc_cmd_hdr hdr; struct sof_ipc_host_buffer buffer; @@ -44,7 +44,7 @@ struct sof_ipc_dma_trace_params_ext { uint32_t reserved[8]; } __attribute__((packed, aligned(4))); -/* DMA for Trace params info - SOF_IPC_DEBUG_DMA_PARAMS */ +/* DMA for Trace params info - SOF_IPC_TRACE_DMA_POSITION */ struct sof_ipc_dma_trace_posn { struct sof_ipc_reply rhdr; uint32_t host_offset; /* Offset of DMA host buffer */ diff --git a/src/include/sof/trace/dma-trace.h b/src/include/sof/trace/dma-trace.h index 947aeb6cce67..bb47133506f0 100644 --- a/src/include/sof/trace/dma-trace.h +++ b/src/include/sof/trace/dma-trace.h @@ -24,7 +24,7 @@ struct dma_trace_buf { void *addr; /* buffer base address */ void *end_addr; /* buffer end address */ uint32_t size; /* size of buffer in bytes */ - uint32_t avail; /* avail bytes in buffer */ + uint32_t avail; /* bytes available to read */ }; struct dma_trace_data { @@ -33,7 +33,7 @@ struct dma_trace_data { struct dma_copy dc; struct sof_ipc_dma_trace_posn posn; struct ipc_msg *msg; - uint32_t old_host_offset; + uint32_t old_host_offset; /**< Last posn.offset sent to host */ uint32_t host_size; struct task dmat_work; uint32_t enabled; diff --git a/src/include/sof/trace/trace.h b/src/include/sof/trace/trace.h index b77fb3d91f10..d77ca0dc0aa7 100644 --- a/src/include/sof/trace/trace.h +++ b/src/include/sof/trace/trace.h @@ -116,6 +116,10 @@ struct trace_filter { * image size. This way more elaborate log messages are possible and encouraged, * for better debugging experience, without worrying about runtime performance. */ +/* Map the different trace_xxxx_with_ids(... ) levels to the + * _trace_event_with_ids(level_xxxx, ...) macro shared across log + * levels. + */ #define trace_event_with_ids(class, ctx, id_1, id_2, format, ...) \ _trace_event_with_ids(LOG_LEVEL_INFO, class, ctx, id_1, id_2, \ format, ##__VA_ARGS__) @@ -137,6 +141,8 @@ void trace_flush(void); void trace_on(void); void trace_off(void); void trace_init(struct sof *sof); + +/* All tracing macros in this file end up calling these functions in the end. */ 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, @@ -156,6 +162,9 @@ int trace_filter_update(const struct trace_filter *elem); #define trace_point(x) platform_trace_point(x) +/** The start of this linker output MUST match the 'ldc_entry_header' + * struct defined in the logger program running in user space. + */ #define _DECLARE_LOG_ENTRY(lvl, format, comp_class, params) \ __section(".static_log." #lvl) \ static const struct { \ @@ -191,6 +200,10 @@ _thrown_from_macro_BASE_LOG_in_trace_h #define STATIC_ASSERT_ARG_SIZE(...) \ META_MAP(1, trace_check_size_uint32, __VA_ARGS__) +/** _log_message is where the memory-saving dictionary magic described + * above happens: the "format" string argument is moved to a special + * linker section and replaced by a &log_entry pointer to it. + */ #define _log_message(log_func, atomic, lvl, comp_class, ctx, id_1, id_2, format, ...) \ do { \ _DECLARE_LOG_ENTRY(lvl, format, comp_class, \ @@ -247,8 +260,8 @@ static inline int trace_filter_update(const struct trace_filter *filter) #endif /* CONFIG_TRACE */ -/* verbose tracing */ #if CONFIG_TRACEV +/* Enable tr_dbg() statements by defining tracev_...() */ #define tracev_event_with_ids(class, ctx, id_1, id_2, format, ...) \ _trace_event_with_ids(LOG_LEVEL_VERBOSE, class, \ ctx, id_1, id_2, \ @@ -267,24 +280,30 @@ static inline int trace_filter_update(const struct trace_filter *filter) #endif /* CONFIG_TRACEV */ -/* error tracing */ +/* The _error_ level has 2, 1 or 0 backends depending on Kconfig */ #if CONFIG_TRACEE +/* LOG_LEVEL_CRITICAL messages are duplicated to the mail box */ #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__) #define trace_error_atomic_with_ids(...) trace_error_with_ids(__VA_ARGS__) + #elif CONFIG_TRACE +/* Goes to trace_log_filtered() too but with a downgraded, LOG_INFO level */ #define trace_error_with_ids(...) trace_event_with_ids(__VA_ARGS__) #define trace_error_atomic_with_ids(...) \ trace_event_atomic_with_ids(__VA_ARGS__) -#else /* CONFIG_TRACEE CONFIG_TRACE */ + +#else /* CONFIG_TRACEE, CONFIG_TRACE */ #define trace_error_with_ids(class, ctx, id_1, id_2, format, ...) \ trace_unused(class, ctx, id_1, id_2, format, ##__VA_ARGS__) #define trace_error_atomic_with_ids(class, ctx, id_1, id_2, format, ...) \ trace_unused(class, ctx, id_1, id_2, format, ##__VA_ARGS__) -#endif /* CONFIG_TRACEE CONFIG_TRACE */ + +#endif /* CONFIG_TRACEE, CONFIG_TRACE */ + #define _TRACE_INV_CLASS TRACE_CLASS_DEPRECATED #define _TRACE_INV_ID -1 diff --git a/src/include/user/trace.h b/src/include/user/trace.h index 01502719ea89..6550a91ba6ee 100644 --- a/src/include/user/trace.h +++ b/src/include/user/trace.h @@ -24,10 +24,10 @@ #define LOG_LEVEL_DEBUG 4 #define LOG_LEVEL_VERBOSE LOG_LEVEL_DEBUG -#define TRACE_ID_LENGTH 12 +#define TRACE_ID_LENGTH 12 /* bit field length */ /* - * Log entry header. + * Log entry protocol 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 diff --git a/src/ipc/dma-copy.c b/src/ipc/dma-copy.c index 209124eea2d1..72ec470af02f 100644 --- a/src/ipc/dma-copy.c +++ b/src/ipc/dma-copy.c @@ -73,7 +73,7 @@ int dma_copy_to_host_nowait(struct dma_copy *dc, struct dma_sg_config *host_sg, return size; } -#else +#else /* CONFIG_DMA_GW */ int dma_copy_to_host_nowait(struct dma_copy *dc, struct dma_sg_config *host_sg, int32_t host_offset, void *local_ptr, int32_t size) @@ -128,7 +128,7 @@ int dma_copy_to_host_nowait(struct dma_copy *dc, struct dma_sg_config *host_sg, return local_sg_elem.size; } -#endif +#endif /* CONFIG_DMA_GW */ int dma_copy_new(struct dma_copy *dc) { diff --git a/src/ipc/handler-ipc3.c b/src/ipc/handler-ipc3.c index 22b39c6fb5f9..1de2fa16da95 100644 --- a/src/ipc/handler-ipc3.c +++ b/src/ipc/handler-ipc3.c @@ -710,6 +710,11 @@ static int ipc_dma_trace_config(uint32_t header) IPC_COPY_CMD(params, ipc->comp_data); if (iCS(header) == SOF_IPC_TRACE_DMA_PARAMS_EXT) + /* As version 5.12 Linux sends the monotonic + * ktime_get(). Search for + * "SOF_IPC_TRACE_DMA_PARAMS_EXT" in your particular + * kernel version. + */ platform_timer_set_delta(timer, params.timestamp_ns); else timer->delta = 0; diff --git a/src/trace/dma-trace.c b/src/trace/dma-trace.c index d2f20766bd00..efabc75c00c3 100644 --- a/src/trace/dma-trace.c +++ b/src/trace/dma-trace.c @@ -46,6 +46,9 @@ static int dma_trace_get_avail_data(struct dma_trace_data *d, struct dma_trace_buf *buffer, int avail); +/** Periodically runs and starts the DMA even when the buffer is not + * full. + */ static enum task_state trace_work(void *data) { struct dma_trace_data *d = data; @@ -311,7 +314,8 @@ static int dma_trace_get_avail_data(struct dma_trace_data *d, return size; } -#endif + +#endif /* CONFIG_DMA_GW */ int dma_trace_enable(struct dma_trace_data *d) { @@ -360,6 +364,7 @@ int dma_trace_enable(struct dma_trace_data *d) return err; } +/** Sends all pending DMA messages to mailbox (for emergencies) */ void dma_trace_flush(void *t) { struct dma_trace_data *trace_data = dma_trace_data_get(); @@ -465,6 +470,7 @@ static int dtrace_calc_buf_overflow(struct dma_trace_buf *buffer, return overflow; } +/** Ring buffer implementation, drops on overflow. */ static void dtrace_add_event(const char *e, uint32_t length) { struct dma_trace_data *trace_data = dma_trace_data_get(); @@ -535,6 +541,7 @@ static void dtrace_add_event(const char *e, uint32_t length) } +/** Main dma-trace entry point */ void dtrace_event(const char *e, uint32_t length) { struct dma_trace_data *trace_data = dma_trace_data_get(); diff --git a/src/trace/trace.c b/src/trace/trace.c index b2cc2d50a33c..c7c9af9b0b2a 100644 --- a/src/trace/trace.c +++ b/src/trace/trace.c @@ -218,6 +218,11 @@ static bool trace_filter_flood(uint32_t log_level, uint32_t entry, uint64_t mess } #endif /* CONFIG_TRACE_FILTERING_ADAPTIVE */ +/** Implementation shared and invoked by both adaptive filtering and + * not. Serializes events into trace messages and passes them to + * dtrace_event() or to mtrace_event() or to both depending on the log + * lvl and the Kconfiguration. + */ 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) { @@ -230,7 +235,7 @@ static void vatrace_log(bool send_atomic, uint32_t log_entry, const struct tr_ct struct trace *trace = trace_get(); #endif /* CONFIG TRACEM */ - /* fill log content */ + /* fill log content. arg_count is in the dictionary. */ put_header(data, ctx->uuid_p, id_1, id_2, log_entry, platform_timer_get(timer_get())); for (i = 0; i < arg_count; ++i) @@ -457,6 +462,7 @@ int trace_filter_update(const struct trace_filter *filter) return ret > 0 ? ret : -EINVAL; } +/** Sends all pending DMA messages to mailbox (for emergencies) */ void trace_flush(void) { struct trace *trace = trace_get(); diff --git a/tools/logger/convert.c b/tools/logger/convert.c index dc044c0a049c..d024fa897779 100644 --- a/tools/logger/convert.c +++ b/tools/logger/convert.c @@ -30,6 +30,9 @@ #define TRACE_IDS_MASK ((1 << TRACE_ID_LENGTH) - 1) #define INVALID_TRACE_ID (-1 & TRACE_IDS_MASK) +/** Dictionary entry. This MUST match the start of the linker output + * defined by _DECLARE_LOG_ENTRY(). + */ struct ldc_entry_header { uint32_t level; uint32_t component_class; @@ -39,6 +42,7 @@ struct ldc_entry_header { uint32_t text_len; }; +/** Dictionary entry + unformatted parameters */ struct ldc_entry { struct ldc_entry_header header; char *file_name; @@ -46,6 +50,7 @@ struct ldc_entry { uint32_t *params; }; +/** Dictionary entry + formatted parameters */ struct proc_ldc_entry { int subst_mask; struct ldc_entry_header header; @@ -187,6 +192,15 @@ static const char *asprintf_entry_text(uint32_t entry_address) return entry.text; } +/** printf-like formatting from the binary ldc_entry input to the + * formatted proc_lpc_entry output. Also copies the unmodified + * ldc_entry_header from input to output. + * + * @param[out] pe copy of the header + formatted output + * @param[in] e copy of the dictionary entry with unformatted, + uint32_t params have been inserted. + @param[in] use_colors whether to use ANSI terminal codes +*/ static void process_params(struct proc_ldc_entry *pe, const struct ldc_entry *e, int use_colors) @@ -389,6 +403,10 @@ static char *format_file_name(char *file_name_raw, int full_name) return name; } +/** Formats and outputs one entry from the trace + the corresponding + * ldc_entry from the dictionary passed as arguments. Expects the log + * variables to have already been copied into the ldc_entry. + */ static void print_entry_params(const struct log_entry_header *dma_log, const struct ldc_entry *entry, uint64_t last_timestamp) { @@ -443,7 +461,7 @@ static void print_entry_params(const struct log_entry_header *dma_log, else ids[0] = '\0'; - if (raw_output) { + if (raw_output) { /* "raw" means script-friendly (not all hex) */ const char *entry_fmt = "%s%u %u %s%s%s "; if (time_precision >= 0) @@ -501,6 +519,7 @@ static void print_entry_params(const struct log_entry_header *dma_log, get_level_name(entry->header.level)); } + /* Minimal, printf-like formatting */ process_params(&proc_entry, entry, use_colors); switch (proc_entry.header.params_num) { @@ -608,6 +627,15 @@ static int read_entry_from_ldc_file(struct ldc_entry *entry, uint32_t log_entry_ return ret; } +/** Gets the dictionary entry matching the log entry argument, reads + * from the log the variable number of arguments needed by this entry + * and passes everything to print_entry_params() to finish processing + * this log entry. So not just "fetch" but everything else after it too. + * + * @param[in] dma_log protocol header from any trace (not just from the + * "DMA" trace) + * @param[out] last_timestamp timestamp found for this entry + */ static int fetch_entry(const struct log_entry_header *dma_log, uint64_t *last_timestamp) { struct ldc_entry entry; @@ -642,6 +670,10 @@ static int fetch_entry(const struct log_entry_header *dma_log, uint64_t *last_ti size_t size = sizeof(uint32_t) * entry.header.params_num; uint8_t *n; + /* Repeatedly read() how much we still miss until we got + * enough for the number of params needed by this + * particular statement. + */ for (n = (uint8_t *)entry.params; size; n += ret, size -= ret) { ret = read(global_config->serial_fd, n, size); if (ret < 0) { @@ -718,10 +750,13 @@ static int serial_read(uint64_t *last_timestamp) } } - /* fetching entry from elf dump */ + /* fetching entry from elf dump and complete processing this log + * line + */ return fetch_entry(&dma_log, last_timestamp); } +/** Main logger loop */ static int logger_read(void) { struct log_entry_header dma_log; @@ -742,6 +777,7 @@ static int logger_read(void) return ret; } + /* One iteration per log statement */ while (!ferror(global_config->in_fd)) { /* getting entry parameters from dma dump */ ret = fread(&dma_log, sizeof(dma_log), 1, global_config->in_fd); diff --git a/tools/logger/filter.c b/tools/logger/filter.c index 6a069614764d..b70af55f156b 100644 --- a/tools/logger/filter.c +++ b/tools/logger/filter.c @@ -263,8 +263,6 @@ static int filter_parse_entry(char *input_str, struct list_item *out_list) * List of `sof_ipc_dma_trace_filter_elem` is writend to debugFS, * and then send as IPC to FW (this action is implemented in driver). * Each line in debugFS represents single IPC message. - * - * @param format log level settings in format `log_level=component` */ int filter_update_firmware(void) { diff --git a/tools/logger/logger.c b/tools/logger/logger.c index ffea4dc79a6e..787be151127b 100644 --- a/tools/logger/logger.c +++ b/tools/logger/logger.c @@ -40,7 +40,7 @@ static void usage(void) fprintf(stdout, "%s:\t \t\t\tDisplay mailbox or DMA trace contents\n", APP_NAME); fprintf(stdout, "%s:\t -i infile -o outfile\tDump infile contents " "to outfile\n", APP_NAME); - fprintf(stdout, "%s:\t -l *.ldc_file\t\t*.ldc files generated by smex\n", + fprintf(stdout, "%s:\t -l *.ldc_file\t\t.ldc input file generated by smex\n", APP_NAME); fprintf(stdout, "%s:\t -p \t\t\tInput from stdin\n", APP_NAME); fprintf(stdout, "%s:\t -v ver_file\t\tEnable checking firmware version " diff --git a/tools/logger/misc.c b/tools/logger/misc.c index ead80e2bd66e..716949d615c8 100644 --- a/tools/logger/misc.c +++ b/tools/logger/misc.c @@ -43,6 +43,9 @@ char *asprintf(const char *format, ...) extern struct convert_config *global_config; +/** Prints 1. once to stderr. 2. a second time to the global out_fd if + * out_fd is neither stderr nor stdout (because the -o option was used). + */ void log_err(const char *fmt, ...) { FILE *out_fd = global_config ? global_config->out_fd : NULL; @@ -53,6 +56,7 @@ void log_err(const char *fmt, ...) va_start(args, fmt); + /* Print into buff first, then outputs buff twice */ va_copy(args_alloc, args); needed_size = vsnprintf(NULL, 0, fmt, args_alloc) + 1; buff = malloc(needed_size);