Add and fix many logger and dma-related comments. No code change.

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(...)

src/include/ipc/trace.h

@@ -27,15 +27,15 @@
 
 #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;
 	struct sof_ipc_host_buffer buffer;
 	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 */

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;

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

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

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)
 {

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;

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();

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();

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,13 +42,15 @@ struct ldc_entry_header {
 	uint32_t text_len;
 };
 
+/** Dictionary entry + unformatted parameters */
 struct ldc_entry {
 	struct ldc_entry_header header;
 	char *file_name;
 	char *text;
 	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);

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)
 {

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 "