Tools: Testbench: Set default trace level to info

src/include/sof/trace/trace.h

@@ -245,10 +245,12 @@ do {								\
 	(void)id_1;						\
 	(void)id_2;						\
 	struct timeval tv;					\
+	char slevel[5][4] = {"dis", "err", "wrn", "inf", "dbg"}; \
 	char *msg = "(%s:%d) " format;				\
-	if (level >= host_trace_level) {			\
+	if (level <= host_trace_level) {			\
 		gettimeofday(&tv, NULL);				\
-		fprintf(stderr, "%ld.%6.6ld:", tv.tv_sec, tv.tv_usec);	\
+		fprintf(stderr, "trace: [%ld.%6.6ld] <%s> ", tv.tv_sec, tv.tv_usec, \
+			slevel[level]);					\
 		fprintf(stderr, msg, strrchr(__FILE__, '/') + 1,	\
 			__LINE__, ##__VA_ARGS__);			\
 		fprintf(stderr, "\n");					\

tools/test/audio/comp_run.sh

@@ -43,7 +43,7 @@ parse_args ()
     FS_IN=48000
     FS_OUT=
     VALGRIND=true
-    DEBUG=-q
+    DEBUG=
     SOURCED_CONFIG=false
     FN_TRACE=
     EXTRA_OPTS=

tools/test/audio/tdfb_direction_test.m

@@ -80,6 +80,7 @@ function tdfb_direction_test()
 test.nch_out = bf.num_output_channels;
 test.ch_in = 1:test.nch_in;
 test.ch_out = 1:test.nch_out;
+test.extra_opts='-d 4';
 test.trace = 'tdfb_direction.txt';
 if length(arrayid)
 	test.comp = sprintf('tdfb_%s', arrayid);

tools/test/audio/tdfb_test.m

@@ -72,7 +72,7 @@ function tdfb_test()
 test.nch_out = bf.num_output_channels;
 test.ch_in = 1:test.nch_in;
 test.ch_out = 1:test.nch_out;
-test.extra_opts='-q'; % Quiet mode, comment out to debug with testbench traces
+test.extra_opts='';
 if length(arrayid)
 	test.comp = sprintf('tdfb_%s', arrayid);
 end

tools/testbench/file.c

@@ -706,7 +706,7 @@ static int file_free(struct processing_module *mod)
 	struct copier_data *ccd = module_get_private_data(mod);
 	struct file_comp_data *cd = get_file_comp_data(ccd);
 
-	tb_debug_print("file_free()");
+	tb_debug_print("file_free()\n");
 
 	if (cd->fs.mode == FILE_READ)
 		fclose(cd->fs.rfh);
@@ -771,7 +771,7 @@ static int file_process(struct processing_module *mod,
 	cd->fs.copy_count++;
 	if (cd->fs.reached_eof || (cd->max_copies && cd->fs.copy_count >= cd->max_copies)) {
 		cd->fs.reached_eof = true;
-		tb_debug_print("file_process(): reached EOF");
+		tb_debug_print("file_process(): reached EOF\n");
 	}
 
 	if (samples) {
@@ -798,7 +798,7 @@ static int file_prepare(struct processing_module *mod,
 	struct comp_dev *dev = mod->dev;
 	struct file_comp_data *cd = get_file_comp_data(module_get_private_data(mod));
 
-	tb_debug_print("file_prepare()");
+	tb_debug_print("file_prepare()\n");
 
 	/* file component sink/source buffer period count */
 	cd->max_frames = dev->frames;
@@ -840,14 +840,14 @@ static int file_reset(struct processing_module *mod)
 {
 	struct file_comp_data *cd = module_get_private_data(mod);
 
-	tb_debug_print("file_reset()");
+	tb_debug_print("file_reset()\n");
 	cd->copies_timeout_count = 0;
 	return 0;
 }
 
 static int file_trigger(struct comp_dev *dev, int cmd)
 {
-	tb_debug_print("file_trigger()");
+	tb_debug_print("file_trigger()\n");
 	return comp_set_state(dev, cmd);
 }
 
@@ -857,7 +857,7 @@ static int file_get_hw_params(struct comp_dev *dev,
 	struct processing_module *mod = comp_mod(dev);
 	struct file_comp_data *cd = get_file_comp_data(module_get_private_data(mod));
 
-	tb_debug_print("file_hw_params()");
+	tb_debug_print("file_hw_params()\n");
 	params->direction = dir;
 	params->rate = cd->rate;
 	params->channels = cd->channels;

tools/testbench/include/testbench/trace.h

@@ -13,4 +13,6 @@
 
 void tb_enable_trace(unsigned int log_level);
 
+bool tb_check_trace(unsigned int log_level);
+
 #endif /* _TESTBENCH_TRACE_H */

tools/testbench/include/testbench/utils.h

@@ -98,7 +98,7 @@ struct testbench_prm {
 	int pipeline_num;
 	int copy_iterations;
 	bool copy_check;
-	bool quiet;
+	int trace_level;
 	int dynamic_pipeline_iterations;
 	int tick_period_us;
 	int pipeline_duration_ms;

tools/testbench/testbench.c

@@ -15,6 +15,7 @@
 #include "testbench/file.h"
 #include "testbench/utils.h"
 
+#include <ctype.h>
 #include <getopt.h>
 #include <limits.h>
 #include <stdbool.h>
@@ -117,39 +118,37 @@ static void print_usage(char *executable)
 	printf("Usage: %s <options> -i <input_file> ", executable);
 	printf("-o <output_file1,output_file2,...>\n\n");
 	printf("Options for processing:\n");
-	printf("  -t <topology file>\n");
-	printf("  -a <comp1=comp1_library,comp2=comp2_library>, override default library\n\n");
+	printf("  -t <topology file>\n\n");
 	printf("Options to control test:\n");
-	printf("  -d Run in debug mode\n");
-	printf("  -q Run in quiet mode, suppress traces output\n");
+	printf("  -d <level> Sets the traces print level:\n");
+	printf("     0 all traces are suppressed\n");
+	printf("     1 shows error traces\n");
+	printf("     2 shows warning traces and previous\n");
+	printf("     3 shows info traces and previous\n");
+	printf("     4 shows debug traces and previous, plus other testbench  debug messages\n");
 	printf("  -p <pipeline1,pipeline2,...>\n");
-	printf("  -s Use real time priorities for threads (needs sudo)\n");
 	printf("  -C <number of copy() iterations>\n");
 	printf("  -D <pipeline duration in ms>\n");
 	printf("  -P <number of dynamic pipeline iterations>\n");
-	printf("  -T <microseconds for tick, 0 for batch mode>\n");
+	printf("  -T <microseconds for tick, 0 for batch mode>\n\n");
 	printf("Options for input and output format override:\n");
 	printf("  -b <input_format>, S16_LE, S24_LE, or S32_LE\n");
 	printf("  -c <input channels>\n");
 	printf("  -n <output channels>\n");
 	printf("  -r <input rate>\n");
 	printf("  -R <output rate>\n\n");
-	printf("Environment variables\n");
-	printf("  SOF_HOST_CORE0=<i> - Map DSP core 0..N to host i..i+N\n");
 	printf("Help:\n");
 	printf("  -h\n\n");
 	printf("Example Usage:\n");
-	printf("%s -i in.txt -o out.txt -t test.tplg ", executable);
-	printf("-r 48000 -R 96000 -c 2 ");
-	printf("-b S16_LE -a volume=libsof_volume.so\n");
+	printf("%s -r 48000 -c 2 -b S16_LE -i in.raw -o out.raw -t <test.tplg>\n\n", executable);
 }
 
 static int parse_input_args(int argc, char **argv, struct testbench_prm *tp)
 {
 	int option = 0;
 	int ret = 0;
 
-	while ((option = getopt(argc, argv, "hd:qi:o:t:b:r:R:c:n:C:P:p:T:D:")) != -1) {
+	while ((option = getopt(argc, argv, "hd:i:o:t:b:r:R:c:n:C:P:p:T:D:")) != -1) {
 		switch (option) {
 		/* input sample file */
 		case 'i':
@@ -194,7 +193,13 @@ static int parse_input_args(int argc, char **argv, struct testbench_prm *tp)
 
 		/* set debug log level */
 		case 'd':
-			host_trace_level = atoi(optarg);
+			if (isdigit((int)*optarg)) {
+				tp->trace_level = atoi(optarg);
+			} else {
+				fprintf(stderr, "Error: Debug level must be a digit.\n");
+				print_usage(argv[0]);
+				exit(EXIT_FAILURE);
+			}
 			break;
 
 		/* number of pipeline copy() iterations */
@@ -203,10 +208,6 @@ static int parse_input_args(int argc, char **argv, struct testbench_prm *tp)
 			tp->copy_check = true;
 			break;
 
-		case 'q':
-			tp->quiet = true;
-			break;
-
 		/* number of dynamic pipeline iterations */
 		case 'P':
 			tp->dynamic_pipeline_iterations = atoi(optarg);
@@ -296,8 +297,8 @@ static void test_pipeline_stats(struct testbench_prm *tp, long long delta_t)
 		printf("File component cycles: %lld\n", file_cycles);
 		printf("Pipeline cycles: %lld\n", pipeline_cycles);
 		printf("Pipeline MCPS: %6.2f\n", pipeline_mcps);
-		if (!tp->quiet)
-			printf("Warning: Use -q to avoid printing to increase MCPS.\n");
+		if (tb_check_trace(LOG_LEVEL_DEBUG))
+			printf("Warning: Use -d 3 or smaller value to avoid traces to increase MCPS.\n");
 	}
 
 	if (delta_t)
@@ -439,6 +440,7 @@ int main(int argc, char **argv)
 	tp->pipeline_num = 1;
 	tp->pipeline_duration_ms = 5000;
 	tp->copy_iterations = 1;
+	tp->trace_level = LOG_LEVEL_INFO;
 
 	/* command line arguments*/
 	ret = parse_input_args(argc, argv, tp);
@@ -477,12 +479,6 @@ int main(int argc, char **argv)
 		goto out;
 	}
 
-	if (tp->quiet)
-		tb_enable_trace(0); /* reduce trace output */
-	else
-		tb_enable_trace(1);
-
-
 	/* initialize ipc and scheduler */
 	if (tb_setup(sof_get(), tp) < 0) {
 		fprintf(stderr, "error: pipeline init\n");

tools/testbench/topology_ipc3.c

@@ -20,6 +20,7 @@
 
 #include "testbench/utils.h"
 #include "testbench/file.h"
+#include "testbench/trace.h"
 
 #include <errno.h>
 #include <math.h>
@@ -614,9 +615,10 @@ static int tb_load_widget(struct testbench_prm *tb, struct tplg_context *ctx)
 		break;
 	/* unsupported widgets */
 	default:
-		printf("info: Widget %s id %d unsupported and skipped: size %d priv size %d\n",
-		       ctx->widget->name, ctx->widget->id,
-		       ctx->widget->size, ctx->widget->priv.size);
+		if (tb_check_trace(LOG_LEVEL_DEBUG))
+			printf("debug: Widget %s id %d unsupported and skipped: size %d priv size %d\n",
+			       ctx->widget->name, ctx->widget->id,
+			       ctx->widget->size, ctx->widget->priv.size);
 		break;
 	}
 
@@ -687,8 +689,8 @@ int tb_parse_topology(struct testbench_prm *tb)
 		/* read next topology header */
 		hdr = tplg_get_hdr(ctx);
 
-		fprintf(stdout, "type: %x, size: 0x%x count: %d index: %d\n",
-			hdr->type, hdr->payload_size, hdr->count, hdr->index);
+		tplg_debug("type: %x, size: 0x%x count: %d index: %d\n",
+			   hdr->type, hdr->payload_size, hdr->count, hdr->index);
 
 		ctx->hdr = hdr;
 

tools/testbench/topology_ipc4.c

@@ -20,6 +20,7 @@
 #include "testbench/topology_ipc4.h"
 #include "testbench/file.h"
 #include "testbench/file_ipc4.h"
+#include "testbench/trace.h"
 #include "ipc4/pipeline.h"
 
 #define SOF_IPC4_FW_PAGE(x) ((((x) + BIT(12) - 1) & ~(BIT(12) - 1)) >> 12)
@@ -1150,9 +1151,10 @@ static int tb_load_widget(struct testbench_prm *tp)
 
 	/* unsupported widgets */
 	default:
-		printf("info: Widget %s id %d unsupported and skipped: size %d priv size %d\n",
-		       ctx->widget->name, ctx->widget->id,
-		       ctx->widget->size, ctx->widget->priv.size);
+		if (tb_check_trace(LOG_LEVEL_DEBUG))
+			printf("Widget %s id %d unsupported and skipped: size %d priv size %d\n",
+			       ctx->widget->name, ctx->widget->id,
+			       ctx->widget->size, ctx->widget->priv.size);
 		break;
 	}
 
@@ -1518,7 +1520,7 @@ int tb_set_running_state(struct testbench_prm *tp)
 		return ret;
 	}
 
-	fprintf(stdout, "pipelines are set to paused state\n");
+	tb_debug_print("pipelines are set to paused state\n");
 	ret = tb_pipelines_set_state(tp, SOF_IPC4_PIPELINE_STATE_RUNNING, SOF_IPC_STREAM_PLAYBACK);
 	if (ret) {
 		fprintf(stderr, "error: failed to set state to running\n");
@@ -1529,7 +1531,7 @@ int tb_set_running_state(struct testbench_prm *tp)
 	if (ret)
 		fprintf(stderr, "error: failed to set state to running\n");
 
-	fprintf(stdout, "pipelines are set to running state\n");
+	tb_debug_print("pipelines are set to running state\n");
 	return ret;
 }
 

tools/testbench/utils.c

@@ -228,10 +228,14 @@ void tb_debug_print(char *message)
 void tb_enable_trace(unsigned int log_level)
 {
 	host_trace_level = log_level;
-	if (host_trace_level)
-		tb_debug_print("trace print enabled\n");
-	else
-		tb_debug_print("trace print disabled\n");
+	if (host_trace_level >= LOG_LEVEL_DEBUG)
+		tb_debug_print("Verbose trace print enabled\n");
+}
+
+/* Helper to control messages print */
+bool tb_check_trace(unsigned int log_level)
+{
+	return host_trace_level >= log_level;
 }
 
 void tb_gettime(struct timespec *td)

tools/testbench/utils_ipc3.c

@@ -16,6 +16,7 @@
 
 #include "testbench/utils.h"
 #include "testbench/file.h"
+#include "testbench/trace.h"
 
 /* testbench helper functions for pipeline setup and trigger */
 
@@ -51,6 +52,7 @@ int tb_setup(struct sof *sof, struct testbench_prm *tp)
 	/* other necessary initializations, todo: follow better SOF init */
 	pipeline_posn_init(sof);
 	init_system_notify(sof);
+	tb_enable_trace(tp->trace_level);
 
 	/* init IPC */
 	if (ipc_init(sof) < 0) {

tools/testbench/utils_ipc4.c

@@ -20,6 +20,7 @@
 #include "testbench/utils.h"
 #include "testbench/file.h"
 #include "testbench/topology_ipc4.h"
+#include "testbench/trace.h"
 
 #if defined __XCC__
 #include <xtensa/tie/xt_timer.h>
@@ -66,6 +67,7 @@ int tb_setup(struct sof *sof, struct testbench_prm *tp)
 	/* other necessary initializations */
 	pipeline_posn_init(sof);
 	init_system_notify(sof);
+	tb_enable_trace(tp->trace_level);
 
 	/* init IPC */
 	if (ipc_init(sof) < 0) {
@@ -457,7 +459,7 @@ int tb_set_up_all_pipelines(struct testbench_prm *tp)
 		return ret;
 	}
 
-	fprintf(stdout, "pipelines set up complete\n");
+	tb_debug_print("pipelines set up complete\n");
 	return 0;
 }