[PATCH 0/7] ASoC: SOF: start using tracing instead of dev_dbg

[PATCH 0/7] ASoC: SOF: start using tracing instead of dev_dbg

[Pierre-Louis Bossart]

Multiple maintainers have told us to start using the tracing
subsystem. Wish granted, this patchset suggested by Noah Klayman
removes a number of verbose and arguably useless dev_dbg or dev_vdbg
logs.

Beyond higher efficiency and less intrusive instrumentation, the use
of bpftrace scripts bring new functionality and helps gather
statistics on usage count on a running system, see how we can get
information on suspend/resume times with [1]

[1] https://github.com/thesofproject/sof-test/blob/main/kernel_tracing/bpftrace_scripts/suspend_resume_time.bt

Bard Liao (2):
  ASoC: SOF: add widget setup/free tracing
  ASoC: SOF: Intel: replace dev_vdbg with tracepoints

Noah Klayman (5):
  ASoC: SOF: Intel: add HDA interrupt source tracing
  ASoC: SOF: Intel: remove unneeded dev_vdbg
  ASoC: SOF: remove unneeded dev_vdbg
  ASoC: SOF: replace dev_vdbg with tracepoints
  ASoC: SOF: replace ipc4-loader dev_vdbg with tracepoints

 include/trace/events/sof.h       | 121 +++++++++++++++++++++++++
 include/trace/events/sof_intel.h | 148 +++++++++++++++++++++++++++++++
 sound/soc/sof/core.c             |   3 +
 sound/soc/sof/intel/cnl.c        |   9 +-
 sound/soc/sof/intel/hda-dsp.c    |   4 +-
 sound/soc/sof/intel/hda-ipc.c    |  11 +--
 sound/soc/sof/intel/hda-pcm.c    |   4 +-
 sound/soc/sof/intel/hda-stream.c |   9 +-
 sound/soc/sof/intel/hda.c        |  19 +++-
 sound/soc/sof/intel/mtl.c        |   3 +-
 sound/soc/sof/ipc3.c             |  12 +--
 sound/soc/sof/ipc4-loader.c      |   7 +-
 sound/soc/sof/pcm.c              |   5 +-
 sound/soc/sof/sof-audio.c        |   5 ++
 sound/soc/sof/sof-utils.c        |   2 -
 sound/soc/sof/topology.c         |   9 --
 16 files changed, 320 insertions(+), 51 deletions(-)
 create mode 100644 include/trace/events/sof.h
 create mode 100644 include/trace/events/sof_intel.h

-- 
2.34.1

[PATCH 1/7] ASoC: SOF: add widget setup/free tracing

[Pierre-Louis Bossart]

From: Bard Liao <yung-chuan.liao@linux.intel.com>

Enables tracking of use_count during widget setup and free routines.
Useful for debugging unbalanced use_counts during suspend/resume.

Reviewed-by: Péter Ujfalusi <peter.ujfalusi@linux.intel.com>
Signed-off-by: Noah Klayman <noah.klayman@intel.com>
Signed-off-by: Bard Liao <yung-chuan.liao@linux.intel.com>
Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
---
 include/trace/events/sof.h | 44 ++++++++++++++++++++++++++++++++++++++
 sound/soc/sof/core.c       |  3 +++
 sound/soc/sof/sof-audio.c  |  5 +++++
 3 files changed, 52 insertions(+)
 create mode 100644 include/trace/events/sof.h

diff --git a/include/trace/events/sof.h b/include/trace/events/sof.h
new file mode 100644
index 0000000000000..f25eef6c95c09
--- /dev/null
+++ b/include/trace/events/sof.h
@@ -0,0 +1,44 @@
+/* SPDX-License-Identifier: GPL-2.0-only */
+/*
+ * Copyright(c) 2022 Intel Corporation. All rights reserved.
+ *
+ * Author: Noah Klayman <noah.klayman@intel.com>
+ */
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM sof
+
+#if !defined(_TRACE_SOF_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_SOF_H
+#include <linux/tracepoint.h>
+#include <sound/sof/stream.h>
+#include "../../../sound/soc/sof/sof-audio.h"
+
+DECLARE_EVENT_CLASS(sof_widget_template,
+	TP_PROTO(struct snd_sof_widget *swidget),
+	TP_ARGS(swidget),
+	TP_STRUCT__entry(
+		__string(name, swidget->widget->name)
+		__field(int, use_count)
+	),
+	TP_fast_assign(
+		__assign_str(name, swidget->widget->name);
+		__entry->use_count = swidget->use_count;
+	),
+	TP_printk("name=%s use_count=%d", __get_str(name), __entry->use_count)
+);
+
+DEFINE_EVENT(sof_widget_template, sof_widget_setup,
+	TP_PROTO(struct snd_sof_widget *swidget),
+	TP_ARGS(swidget)
+);
+
+DEFINE_EVENT(sof_widget_template, sof_widget_free,
+	TP_PROTO(struct snd_sof_widget *swidget),
+	TP_ARGS(swidget)
+);
+
+#endif /* _TRACE_SOF_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/sound/soc/sof/core.c b/sound/soc/sof/core.c
index c99b5e6c026c1..3e6141d03770f 100644
--- a/sound/soc/sof/core.c
+++ b/sound/soc/sof/core.c
@@ -15,6 +15,9 @@
 #include "sof-priv.h"
 #include "ops.h"
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/sof.h>
+
 /* see SOF_DBG_ flags */
 static int sof_core_debug =  IS_ENABLED(CONFIG_SND_SOC_SOF_DEBUG_ENABLE_FIRMWARE_TRACE);
 module_param_named(sof_debug, sof_core_debug, int, 0444);
diff --git a/sound/soc/sof/sof-audio.c b/sound/soc/sof/sof-audio.c
index ea9663d448eb8..a3d3dd7a00375 100644
--- a/sound/soc/sof/sof-audio.c
+++ b/sound/soc/sof/sof-audio.c
@@ -9,6 +9,7 @@
 //
 
 #include <linux/bitfield.h>
+#include <trace/events/sof.h>
 #include "sof-audio.h"
 #include "sof-of-dev.h"
 #include "ops.h"
@@ -36,6 +37,8 @@ int sof_widget_free(struct snd_sof_dev *sdev, struct snd_sof_widget *swidget)
 	if (!swidget->private)
 		return 0;
 
+	trace_sof_widget_free(swidget);
+
 	/* only free when use_count is 0 */
 	if (--swidget->use_count)
 		return 0;
@@ -86,6 +89,8 @@ int sof_widget_setup(struct snd_sof_dev *sdev, struct snd_sof_widget *swidget)
 	if (!swidget->private)
 		return 0;
 
+	trace_sof_widget_setup(swidget);
+
 	/* widget already set up */
 	if (++swidget->use_count > 1)
 		return 0;
-- 
2.34.1

[PATCH 2/7] ASoC: SOF: Intel: add HDA interrupt source tracing

[Pierre-Louis Bossart]

From: Noah Klayman <noah.klayman@intel.com>

The Intel HDaudio controller relies on a single interrupt line which
wire-ORs multiple interrupt sources, such as stream, IPC, SoundWire and
wakes. This patch adds the ability to trace each event occurrence.

Reviewed-by: Bard Liao <yung-chuan.liao@linux.intel.com>
Reviewed-by: Péter Ujfalusi <peter.ujfalusi@linux.intel.com>
Signed-off-by: Noah Klayman <noah.klayman@intel.com>
Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
---
 include/trace/events/sof_intel.h | 34 ++++++++++++++++++++++++++++++++
 sound/soc/sof/intel/hda.c        | 19 ++++++++++++++----
 2 files changed, 49 insertions(+), 4 deletions(-)
 create mode 100644 include/trace/events/sof_intel.h

diff --git a/include/trace/events/sof_intel.h b/include/trace/events/sof_intel.h
new file mode 100644
index 0000000000000..37a9b92d494ef
--- /dev/null
+++ b/include/trace/events/sof_intel.h
@@ -0,0 +1,34 @@
+/* SPDX-License-Identifier: GPL-2.0-only */
+/*
+ * Copyright(c) 2022 Intel Corporation. All rights reserved.
+ *
+ * Author: Noah Klayman <noah.klayman@intel.com>
+ */
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM sof_intel
+
+#if !defined(_TRACE_SOF_INTEL_H) || defined(TRACE_HEADER_MULTI_READ)
+#define _TRACE_SOF_INTEL_H
+#include <linux/tracepoint.h>
+#include "../../../sound/soc/sof/sof-audio.h"
+
+TRACE_EVENT(sof_intel_hda_irq,
+	TP_PROTO(struct snd_sof_dev *sdev, char *source),
+	TP_ARGS(sdev, source),
+	TP_STRUCT__entry(
+		__string(device_name, dev_name(sdev->dev))
+		__string(source, source)
+	),
+	TP_fast_assign(
+		__assign_str(device_name, dev_name(sdev->dev));
+		__assign_str(source, source);
+	),
+	TP_printk("device_name=%s source=%s",
+		  __get_str(device_name), __get_str(source))
+);
+
+#endif /* _TRACE_SOF_INTEL_H */
+
+/* This part must be outside protection */
+#include <trace/define_trace.h>
diff --git a/sound/soc/sof/intel/hda.c b/sound/soc/sof/intel/hda.c
index dfb3b424fb5e3..eec54c8bb0e9a 100644
--- a/sound/soc/sof/intel/hda.c
+++ b/sound/soc/sof/intel/hda.c
@@ -31,6 +31,9 @@
 #include "../ops.h"
 #include "hda.h"
 
+#define CREATE_TRACE_POINTS
+#include <trace/events/sof_intel.h>
+
 #if IS_ENABLED(CONFIG_SND_SOC_SOF_HDA)
 #include <sound/soc-acpi-intel-match.h>
 #endif
@@ -954,17 +957,25 @@ static irqreturn_t hda_dsp_interrupt_thread(int irq, void *context)
 	struct sof_intel_hda_dev *hdev = sdev->pdata->hw_pdata;
 
 	/* deal with streams and controller first */
-	if (hda_dsp_check_stream_irq(sdev))
+	if (hda_dsp_check_stream_irq(sdev)) {
+		trace_sof_intel_hda_irq(sdev, "stream");
 		hda_dsp_stream_threaded_handler(irq, sdev);
+	}
 
-	if (hda_check_ipc_irq(sdev))
+	if (hda_check_ipc_irq(sdev)) {
+		trace_sof_intel_hda_irq(sdev, "ipc");
 		sof_ops(sdev)->irq_thread(irq, sdev);
+	}
 
-	if (hda_dsp_check_sdw_irq(sdev))
+	if (hda_dsp_check_sdw_irq(sdev)) {
+		trace_sof_intel_hda_irq(sdev, "sdw");
 		hda_dsp_sdw_thread(irq, hdev->sdw);
+	}
 
-	if (hda_sdw_check_wakeen_irq(sdev))
+	if (hda_sdw_check_wakeen_irq(sdev)) {
+		trace_sof_intel_hda_irq(sdev, "wakeen");
 		hda_sdw_process_wakeen(sdev);
+	}
 
 	hda_check_for_state_change(sdev);
 
-- 
2.34.1

[PATCH 3/7] ASoC: SOF: Intel: remove unneeded dev_vdbg

[Pierre-Louis Bossart]

From: Noah Klayman <noah.klayman@intel.com>

This patch removes an unneeded dev_vdbg call in hda-stream.

Reviewed-by: Bard Liao <yung-chuan.liao@linux.intel.com>
Reviewed-by: Péter Ujfalusi <peter.ujfalusi@linux.intel.com>
Signed-off-by: Noah Klayman <noah.klayman@intel.com>
Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
---
 sound/soc/sof/intel/hda-stream.c | 3 ---
 1 file changed, 3 deletions(-)

diff --git a/sound/soc/sof/intel/hda-stream.c b/sound/soc/sof/intel/hda-stream.c
index b58662faa4aad..8344363beec09 100644
--- a/sound/soc/sof/intel/hda-stream.c
+++ b/sound/soc/sof/intel/hda-stream.c
@@ -93,9 +93,6 @@ static int hda_setup_bdle(struct snd_sof_dev *sdev,
 		bdl++;
 		hstream->frags++;
 		offset += chunk;
-
-		dev_vdbg(sdev->dev, "bdl, frags:%d, chunk size:0x%x;\n",
-			 hstream->frags, chunk);
 	}
 
 	*bdlp = bdl;
-- 
2.34.1

[PATCH 4/7] ASoC: SOF: remove unneeded dev_vdbg

[Pierre-Louis Bossart]

From: Noah Klayman <noah.klayman@intel.com>

This patch removes some unneeded dev_vdbg calls.

Reviewed-by: Bard Liao <yung-chuan.liao@linux.intel.com>
Reviewed-by: Péter Ujfalusi <peter.ujfalusi@linux.intel.com>
Signed-off-by: Noah Klayman <noah.klayman@intel.com>
Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
---
 sound/soc/sof/sof-utils.c | 2 --
 sound/soc/sof/topology.c  | 9 ---------
 2 files changed, 11 deletions(-)

diff --git a/sound/soc/sof/sof-utils.c b/sound/soc/sof/sof-utils.c
index a3300ecee0628..b6345a7345af7 100644
--- a/sound/soc/sof/sof-utils.c
+++ b/sound/soc/sof/sof-utils.c
@@ -45,8 +45,6 @@ int snd_sof_create_page_table(struct device *dev,
 		u32 pfn = snd_sgbuf_get_addr(dmab, i * PAGE_SIZE) >> PAGE_SHIFT;
 		u8 *pg_table;
 
-		dev_vdbg(dev, "pfn i %i idx %d pfn %x\n", i, idx, pfn);
-
 		pg_table = (u8 *)(page_table + idx);
 
 		/*
diff --git a/sound/soc/sof/topology.c b/sound/soc/sof/topology.c
index 9273a70fec25c..6087483deb48e 100644
--- a/sound/soc/sof/topology.c
+++ b/sound/soc/sof/topology.c
@@ -1011,9 +1011,6 @@ static int sof_connect_dai_widget(struct snd_soc_component *scomp,
 	}
 
 	list_for_each_entry(rtd, &card->rtd_list, list) {
-		dev_vdbg(scomp->dev, "tplg: check widget: %s stream: %s dai stream: %s\n",
-			 w->name,  w->sname, rtd->dai_link->stream_name);
-
 		/* does stream match DAI link ? */
 		if (!rtd->dai_link->stream_name ||
 		    strcmp(w->sname, rtd->dai_link->stream_name))
@@ -1537,9 +1534,6 @@ static int sof_dai_load(struct snd_soc_component *scomp, int index,
 
 	stream = SNDRV_PCM_STREAM_PLAYBACK;
 
-	dev_vdbg(scomp->dev, "tplg: pcm %s stream tokens: playback d0i3:%d\n",
-		 spcm->pcm.pcm_name, spcm->stream[stream].d0i3_compatible);
-
 	caps = &spcm->pcm.caps[stream];
 
 	/* allocate playback page table buffer */
@@ -1567,9 +1561,6 @@ static int sof_dai_load(struct snd_soc_component *scomp, int index,
 	if (!spcm->pcm.capture)
 		return ret;
 
-	dev_vdbg(scomp->dev, "tplg: pcm %s stream tokens: capture d0i3:%d\n",
-		 spcm->pcm.pcm_name, spcm->stream[stream].d0i3_compatible);
-
 	caps = &spcm->pcm.caps[stream];
 
 	/* allocate capture page table buffer */
-- 
2.34.1

[PATCH 5/7] ASoC: SOF: Intel: replace dev_vdbg with tracepoints

[Pierre-Louis Bossart]

From: Bard Liao <yung-chuan.liao@linux.intel.com>

This patch replaces all dev_vdbg calls with tracepoints to reduce
overhead and enable use of trace collection and analysis tools.

Reviewed-by: Péter Ujfalusi <peter.ujfalusi@linux.intel.com>
Signed-off-by: Noah Klayman <noah.klayman@intel.com>
Signed-off-by: Bard Liao <yung-chuan.liao@linux.intel.com>
Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
---
 include/trace/events/sof_intel.h | 114 +++++++++++++++++++++++++++++++
 sound/soc/sof/intel/cnl.c        |   9 +--
 sound/soc/sof/intel/hda-dsp.c    |   4 +-
 sound/soc/sof/intel/hda-ipc.c    |  11 ++-
 sound/soc/sof/intel/hda-pcm.c    |   4 +-
 sound/soc/sof/intel/hda-stream.c |   6 +-
 sound/soc/sof/intel/mtl.c        |   3 +-
 7 files changed, 130 insertions(+), 21 deletions(-)

diff --git a/include/trace/events/sof_intel.h b/include/trace/events/sof_intel.h
index 37a9b92d494ef..2a77f9d26c0bf 100644
--- a/include/trace/events/sof_intel.h
+++ b/include/trace/events/sof_intel.h
@@ -11,6 +11,7 @@
 #if !defined(_TRACE_SOF_INTEL_H) || defined(TRACE_HEADER_MULTI_READ)
 #define _TRACE_SOF_INTEL_H
 #include <linux/tracepoint.h>
+#include <sound/hdaudio.h>
 #include "../../../sound/soc/sof/sof-audio.h"
 
 TRACE_EVENT(sof_intel_hda_irq,
@@ -28,6 +29,119 @@ TRACE_EVENT(sof_intel_hda_irq,
 		  __get_str(device_name), __get_str(source))
 );
 
+DECLARE_EVENT_CLASS(sof_intel_ipc_firmware_template,
+	TP_ARGS(struct snd_sof_dev *sdev, u32 msg, u32 msg_ext),
+	TP_PROTO(sdev, msg, msg_ext),
+	TP_STRUCT__entry(
+		__string(device_name, dev_name(sdev->dev))
+		__field(u32, msg)
+		__field(u32, msg_ext)
+	),
+	TP_fast_assign(
+		__assign_str(device_name, dev_name(sdev->dev));
+		__entry->msg = msg;
+		__entry->msg_ext = msg_ext;
+	),
+	TP_printk("device_name=%s msg=%#x msg_ext=%#x",
+		  __get_str(device_name), __entry->msg, __entry->msg_ext)
+);
+
+DEFINE_EVENT(sof_intel_ipc_firmware_template, sof_intel_ipc_firmware_response,
+	TP_PROTO(struct snd_sof_dev *sdev, u32 msg, u32 msg_ext),
+	TP_ARGS(sdev, msg, msg_ext)
+);
+
+DEFINE_EVENT(sof_intel_ipc_firmware_template, sof_intel_ipc_firmware_initiated,
+	TP_PROTO(struct snd_sof_dev *sdev, u32 msg, u32 msg_ext),
+	TP_ARGS(sdev, msg, msg_ext)
+);
+
+TRACE_EVENT(sof_intel_D0I3C_updated,
+	TP_PROTO(struct snd_sof_dev *sdev, u8 reg),
+	TP_ARGS(sdev, reg),
+	TP_STRUCT__entry(
+		__string(device_name, dev_name(sdev->dev))
+		__field(u8, reg)
+	),
+	TP_fast_assign(
+		__assign_str(device_name, dev_name(sdev->dev));
+		__entry->reg = reg;
+	),
+	TP_printk("device_name=%s register=%#x",
+		  __get_str(device_name), __entry->reg)
+);
+
+TRACE_EVENT(sof_intel_hda_irq_ipc_check,
+	TP_PROTO(struct snd_sof_dev *sdev, u32 irq_status),
+	TP_ARGS(sdev, irq_status),
+	TP_STRUCT__entry(
+		__string(device_name, dev_name(sdev->dev))
+		__field(u32, irq_status)
+	),
+	TP_fast_assign(
+		__assign_str(device_name, dev_name(sdev->dev));
+		__entry->irq_status = irq_status;
+	),
+	TP_printk("device_name=%s irq_status=%#x",
+		  __get_str(device_name), __entry->irq_status)
+);
+
+TRACE_EVENT(sof_intel_hda_dsp_pcm,
+	TP_PROTO(struct snd_sof_dev *sdev,
+		struct hdac_stream *hstream,
+		struct snd_pcm_substream *substream,
+		snd_pcm_uframes_t pos
+	),
+	TP_ARGS(sdev, hstream, substream, pos),
+	TP_STRUCT__entry(
+		__string(device_name, dev_name(sdev->dev))
+		__field(u32, hstream_index)
+		__field(u32, substream)
+		__field(unsigned long, pos)
+	),
+	TP_fast_assign(
+		__assign_str(device_name, dev_name(sdev->dev));
+		__entry->hstream_index = hstream->index;
+		__entry->substream = substream->stream;
+		__entry->pos = pos;
+	),
+	TP_printk("device_name=%s hstream_index=%d substream=%d pos=%lu",
+		  __get_str(device_name), __entry->hstream_index,
+		  __entry->substream, __entry->pos)
+);
+
+TRACE_EVENT(sof_intel_hda_dsp_stream_status,
+	TP_PROTO(struct device *dev, struct hdac_stream *s, u32 status),
+	TP_ARGS(dev, s, status),
+	TP_STRUCT__entry(
+		__string(device_name, dev_name(dev))
+		__field(u32, stream)
+		__field(u32, status)
+	),
+	TP_fast_assign(
+		__assign_str(device_name, dev_name(dev));
+		__entry->stream = s->index;
+		__entry->status = status;
+	),
+	TP_printk("device_name=%s stream=%d status=%#x",
+		  __get_str(device_name), __entry->stream, __entry->status)
+);
+
+TRACE_EVENT(sof_intel_hda_dsp_check_stream_irq,
+	TP_PROTO(struct snd_sof_dev *sdev, u32 status),
+	TP_ARGS(sdev, status),
+	TP_STRUCT__entry(
+		__string(device_name, dev_name(sdev->dev))
+		__field(u32, status)
+	),
+	TP_fast_assign(
+		__assign_str(device_name, dev_name(sdev->dev));
+		__entry->status = status;
+	),
+	TP_printk("device_name=%s status=%#x",
+		  __get_str(device_name), __entry->status)
+);
+
 #endif /* _TRACE_SOF_INTEL_H */
 
 /* This part must be outside protection */
diff --git a/sound/soc/sof/intel/cnl.c b/sound/soc/sof/intel/cnl.c
index 0bb91df272805..180001d0a38ae 100644
--- a/sound/soc/sof/intel/cnl.c
+++ b/sound/soc/sof/intel/cnl.c
@@ -17,6 +17,7 @@
 
 #include <sound/sof/ext_manifest4.h>
 #include <sound/sof/ipc4/header.h>
+#include <trace/events/sof_intel.h>
 #include "../ipc4-priv.h"
 #include "../ops.h"
 #include "hda.h"
@@ -121,9 +122,7 @@ irqreturn_t cnl_ipc_irq_thread(int irq, void *context)
 		msg_ext = hipci & CNL_DSP_REG_HIPCIDR_MSG_MASK;
 		msg = hipcida & CNL_DSP_REG_HIPCIDA_MSG_MASK;
 
-		dev_vdbg(sdev->dev,
-			 "ipc: firmware response, msg:0x%x, msg_ext:0x%x\n",
-			 msg, msg_ext);
+		trace_sof_intel_ipc_firmware_response(sdev, msg, msg_ext);
 
 		/* mask Done interrupt */
 		snd_sof_dsp_update_bits(sdev, HDA_DSP_BAR,
@@ -153,9 +152,7 @@ irqreturn_t cnl_ipc_irq_thread(int irq, void *context)
 		msg = hipctdr & CNL_DSP_REG_HIPCTDR_MSG_MASK;
 		msg_ext = hipctdd & CNL_DSP_REG_HIPCTDD_MSG_MASK;
 
-		dev_vdbg(sdev->dev,
-			 "ipc: firmware initiated, msg:0x%x, msg_ext:0x%x\n",
-			 msg, msg_ext);
+		trace_sof_intel_ipc_firmware_initiated(sdev, msg, msg_ext);
 
 		/* handle messages from DSP */
 		if ((hipctdr & SOF_IPC_PANIC_MAGIC_MASK) == SOF_IPC_PANIC_MAGIC) {
diff --git a/sound/soc/sof/intel/hda-dsp.c b/sound/soc/sof/intel/hda-dsp.c
index 671c3e02d7df8..1319c8e34021b 100644
--- a/sound/soc/sof/intel/hda-dsp.c
+++ b/sound/soc/sof/intel/hda-dsp.c
@@ -18,6 +18,7 @@
 #include <linux/module.h>
 #include <sound/hdaudio_ext.h>
 #include <sound/hda_register.h>
+#include <trace/events/sof_intel.h>
 #include "../sof-audio.h"
 #include "../ops.h"
 #include "hda.h"
@@ -397,8 +398,7 @@ static int hda_dsp_update_d0i3c_register(struct snd_sof_dev *sdev, u8 value)
 		return ret;
 	}
 
-	dev_vdbg(bus->dev, "D0I3C updated, register = 0x%x\n",
-		 snd_hdac_chip_readb(bus, VS_D0I3C));
+	trace_sof_intel_D0I3C_updated(sdev, snd_hdac_chip_readb(bus, VS_D0I3C));
 
 	return 0;
 }
diff --git a/sound/soc/sof/intel/hda-ipc.c b/sound/soc/sof/intel/hda-ipc.c
index 65e688f749eaf..c597ef491d383 100644
--- a/sound/soc/sof/intel/hda-ipc.c
+++ b/sound/soc/sof/intel/hda-ipc.c
@@ -16,6 +16,7 @@
  */
 
 #include <sound/sof/ipc4/header.h>
+#include <trace/events/sof_intel.h>
 #include "../ops.h"
 #include "hda.h"
 
@@ -212,9 +213,7 @@ irqreturn_t hda_dsp_ipc_irq_thread(int irq, void *context)
 		msg = hipci & HDA_DSP_REG_HIPCI_MSG_MASK;
 		msg_ext = hipcie & HDA_DSP_REG_HIPCIE_MSG_MASK;
 
-		dev_vdbg(sdev->dev,
-			 "ipc: firmware response, msg:0x%x, msg_ext:0x%x\n",
-			 msg, msg_ext);
+		trace_sof_intel_ipc_firmware_response(sdev, msg, msg_ext);
 
 		/* mask Done interrupt */
 		snd_sof_dsp_update_bits(sdev, HDA_DSP_BAR,
@@ -255,9 +254,7 @@ irqreturn_t hda_dsp_ipc_irq_thread(int irq, void *context)
 		msg = hipct & HDA_DSP_REG_HIPCT_MSG_MASK;
 		msg_ext = hipcte & HDA_DSP_REG_HIPCTE_MSG_MASK;
 
-		dev_vdbg(sdev->dev,
-			 "ipc: firmware initiated, msg:0x%x, msg_ext:0x%x\n",
-			 msg, msg_ext);
+		trace_sof_intel_ipc_firmware_initiated(sdev, msg, msg_ext);
 
 		/* mask BUSY interrupt */
 		snd_sof_dsp_update_bits(sdev, HDA_DSP_BAR,
@@ -312,7 +309,7 @@ bool hda_dsp_check_ipc_irq(struct snd_sof_dev *sdev)
 
 	/* store status */
 	irq_status = snd_sof_dsp_read(sdev, HDA_DSP_BAR, HDA_DSP_REG_ADSPIS);
-	dev_vdbg(sdev->dev, "irq handler: irq_status:0x%x\n", irq_status);
+	trace_sof_intel_hda_irq_ipc_check(sdev, irq_status);
 
 	/* invalid message ? */
 	if (irq_status == 0xffffffff)
diff --git a/sound/soc/sof/intel/hda-pcm.c b/sound/soc/sof/intel/hda-pcm.c
index 6888e0a4665d2..0a9c80216a8c2 100644
--- a/sound/soc/sof/intel/hda-pcm.c
+++ b/sound/soc/sof/intel/hda-pcm.c
@@ -18,6 +18,7 @@
 #include <linux/moduleparam.h>
 #include <sound/hda_register.h>
 #include <sound/pcm_params.h>
+#include <trace/events/sof_intel.h>
 #include "../sof-audio.h"
 #include "../ops.h"
 #include "hda.h"
@@ -196,8 +197,7 @@ snd_pcm_uframes_t hda_dsp_pcm_pointer(struct snd_sof_dev *sdev,
 found:
 	pos = bytes_to_frames(substream->runtime, pos);
 
-	dev_vdbg(sdev->dev, "PCM: stream %d dir %d position %lu\n",
-		 hstream->index, substream->stream, pos);
+	trace_sof_intel_hda_dsp_pcm(sdev, hstream, substream, pos);
 	return pos;
 }
 
diff --git a/sound/soc/sof/intel/hda-stream.c b/sound/soc/sof/intel/hda-stream.c
index 8344363beec09..be60e7785da94 100644
--- a/sound/soc/sof/intel/hda-stream.c
+++ b/sound/soc/sof/intel/hda-stream.c
@@ -19,6 +19,7 @@
 #include <sound/hdaudio_ext.h>
 #include <sound/hda_register.h>
 #include <sound/sof.h>
+#include <trace/events/sof_intel.h>
 #include "../ops.h"
 #include "../sof-audio.h"
 #include "hda.h"
@@ -697,7 +698,7 @@ bool hda_dsp_check_stream_irq(struct snd_sof_dev *sdev)
 	spin_lock_irq(&bus->reg_lock);
 
 	status = snd_hdac_chip_readl(bus, INTSTS);
-	dev_vdbg(bus->dev, "stream irq, INTSTS status: 0x%x\n", status);
+	trace_sof_intel_hda_dsp_check_stream_irq(sdev, status);
 
 	/* if Register inaccessible, ignore it.*/
 	if (status != 0xffffffff)
@@ -736,8 +737,7 @@ static bool hda_dsp_stream_check(struct hdac_bus *bus, u32 status)
 		if (status & BIT(s->index) && s->opened) {
 			sd_status = snd_hdac_stream_readb(s, SD_STS);
 
-			dev_vdbg(bus->dev, "stream %d status 0x%x\n",
-				 s->index, sd_status);
+			trace_sof_intel_hda_dsp_stream_status(bus->dev, s, sd_status);
 
 			snd_hdac_stream_writeb(s, SD_STS, sd_status);
 
diff --git a/sound/soc/sof/intel/mtl.c b/sound/soc/sof/intel/mtl.c
index efc91feb83e9e..5408c34b04ef7 100644
--- a/sound/soc/sof/intel/mtl.c
+++ b/sound/soc/sof/intel/mtl.c
@@ -11,6 +11,7 @@
 
 #include <linux/firmware.h>
 #include <sound/sof/ipc4/header.h>
+#include <trace/events/sof_intel.h>
 #include "../ipc4-priv.h"
 #include "../ops.h"
 #include "hda.h"
@@ -63,7 +64,7 @@ static bool mtl_dsp_check_ipc_irq(struct snd_sof_dev *sdev)
 	hfintipptr = snd_sof_dsp_read(sdev, HDA_DSP_BAR, MTL_HFINTIPPTR) & MTL_HFINTIPPTR_PTR_MASK;
 	irq_status = snd_sof_dsp_read(sdev, HDA_DSP_BAR, hfintipptr + MTL_DSP_IRQSTS);
 
-	dev_vdbg(sdev->dev, "irq handler: irq_status:0x%x\n", irq_status);
+	trace_sof_intel_hda_irq_ipc_check(sdev, irq_status);
 
 	if (irq_status != U32_MAX && (irq_status & MTL_DSP_IRQSTS_IPC))
 		return true;
-- 
2.34.1

[PATCH 6/7] ASoC: SOF: replace dev_vdbg with tracepoints

[Pierre-Louis Bossart]

From: Noah Klayman <noah.klayman@intel.com>

This patch removes unneeded dev_vdbg calls and replaces remaining ones
with tracepoints to reduce overhead and enable use of trace collection
and analysis tools.

Signed-off-by: Noah Klayman <noah.klayman@intel.com>
Reviewed-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
Reviewed-by: Bard Liao <yung-chuan.liao@linux.intel.com>
Reviewed-by: Péter Ujfalusi <peter.ujfalusi@linux.intel.com>
---
 include/trace/events/sof.h | 60 ++++++++++++++++++++++++++++++++++++++
 sound/soc/sof/ipc3.c       | 12 ++++----
 sound/soc/sof/pcm.c        |  5 ++--
 3 files changed, 68 insertions(+), 9 deletions(-)

diff --git a/include/trace/events/sof.h b/include/trace/events/sof.h
index f25eef6c95c09..03751323aaa84 100644
--- a/include/trace/events/sof.h
+++ b/include/trace/events/sof.h
@@ -11,6 +11,7 @@
 #if !defined(_TRACE_SOF_H) || defined(TRACE_HEADER_MULTI_READ)
 #define _TRACE_SOF_H
 #include <linux/tracepoint.h>
+#include <linux/types.h>
 #include <sound/sof/stream.h>
 #include "../../../sound/soc/sof/sof-audio.h"
 
@@ -38,6 +39,65 @@ DEFINE_EVENT(sof_widget_template, sof_widget_free,
 	TP_ARGS(swidget)
 );
 
+TRACE_EVENT(sof_ipc3_period_elapsed_position,
+	TP_PROTO(struct snd_sof_dev *sdev, struct sof_ipc_stream_posn *posn),
+	TP_ARGS(sdev, posn),
+	TP_STRUCT__entry(
+		__string(device_name, dev_name(sdev->dev))
+		__field(u64, host_posn)
+		__field(u64, dai_posn)
+		__field(u64, wallclock)
+	),
+	TP_fast_assign(
+		__assign_str(device_name, dev_name(sdev->dev));
+		__entry->host_posn = posn->host_posn;
+		__entry->dai_posn = posn->dai_posn;
+		__entry->wallclock = posn->wallclock;
+	),
+	TP_printk("device_name=%s host_posn=%#llx dai_posn=%#llx wallclock=%#llx",
+		  __get_str(device_name), __entry->host_posn, __entry->dai_posn,
+		  __entry->wallclock)
+);
+
+TRACE_EVENT(sof_pcm_pointer_position,
+	TP_PROTO(struct snd_sof_dev *sdev,
+		struct snd_sof_pcm *spcm,
+		struct snd_pcm_substream *substream,
+		snd_pcm_uframes_t dma_posn,
+		snd_pcm_uframes_t dai_posn
+	),
+	TP_ARGS(sdev, spcm, substream, dma_posn, dai_posn),
+	TP_STRUCT__entry(
+		__string(device_name, dev_name(sdev->dev))
+		__field(u32, pcm_id)
+		__field(int, stream)
+		__field(unsigned long, dma_posn)
+		__field(unsigned long, dai_posn)
+	),
+	TP_fast_assign(
+		__assign_str(device_name, dev_name(sdev->dev));
+		__entry->pcm_id = le32_to_cpu(spcm->pcm.pcm_id);
+		__entry->stream = substream->stream;
+		__entry->dma_posn = dma_posn;
+		__entry->dai_posn = dai_posn;
+	),
+	TP_printk("device_name=%s pcm_id=%d stream=%d dma_posn=%lu dai_posn=%lu",
+		  __get_str(device_name), __entry->pcm_id, __entry->stream,
+		  __entry->dma_posn, __entry->dai_posn)
+);
+
+TRACE_EVENT(sof_stream_position_ipc_rx,
+	TP_PROTO(struct device *dev),
+	TP_ARGS(dev),
+	TP_STRUCT__entry(
+		__string(device_name, dev_name(dev))
+	),
+	TP_fast_assign(
+		__assign_str(device_name, dev_name(dev));
+	),
+	TP_printk("device_name=%s", __get_str(device_name))
+);
+
 #endif /* _TRACE_SOF_H */
 
 /* This part must be outside protection */
diff --git a/sound/soc/sof/ipc3.c b/sound/soc/sof/ipc3.c
index 82fa320253bef..b28af3a48b707 100644
--- a/sound/soc/sof/ipc3.c
+++ b/sound/soc/sof/ipc3.c
@@ -9,6 +9,7 @@
 
 #include <sound/sof/stream.h>
 #include <sound/sof/control.h>
+#include <trace/events/sof.h>
 #include "sof-priv.h"
 #include "sof-audio.h"
 #include "ipc3-priv.h"
@@ -23,7 +24,7 @@ static void ipc3_log_header(struct device *dev, u8 *text, u32 cmd)
 	u8 *str2 = NULL;
 	u32 glb;
 	u32 type;
-	bool vdbg = false;
+	bool is_sof_ipc_stream_position = false;
 
 	glb = cmd & SOF_GLB_TYPE_MASK;
 	type = cmd & SOF_CMD_TYPE_MASK;
@@ -118,7 +119,7 @@ static void ipc3_log_header(struct device *dev, u8 *text, u32 cmd)
 		case SOF_IPC_STREAM_TRIG_XRUN:
 			str2 = "TRIG_XRUN"; break;
 		case SOF_IPC_STREAM_POSITION:
-			vdbg = true;
+			is_sof_ipc_stream_position = true;
 			str2 = "POSITION"; break;
 		case SOF_IPC_STREAM_VORBIS_PARAMS:
 			str2 = "VORBIS_PARAMS"; break;
@@ -206,8 +207,8 @@ static void ipc3_log_header(struct device *dev, u8 *text, u32 cmd)
 	}
 
 	if (str2) {
-		if (vdbg)
-			dev_vdbg(dev, "%s: 0x%x: %s: %s\n", text, cmd, str, str2);
+		if (is_sof_ipc_stream_position)
+			trace_sof_stream_position_ipc_rx(dev);
 		else
 			dev_dbg(dev, "%s: 0x%x: %s: %s\n", text, cmd, str, str2);
 	} else {
@@ -852,8 +853,7 @@ static void ipc3_period_elapsed(struct snd_sof_dev *sdev, u32 msg_id)
 		return;
 	}
 
-	dev_vdbg(sdev->dev, "posn : host 0x%llx dai 0x%llx wall 0x%llx\n",
-		 posn.host_posn, posn.dai_posn, posn.wallclock);
+	trace_sof_ipc3_period_elapsed_position(sdev, &posn);
 
 	memcpy(&stream->posn, &posn, sizeof(posn));
 
diff --git a/sound/soc/sof/pcm.c b/sound/soc/sof/pcm.c
index 49f7cb049f62d..14571b821ecac 100644
--- a/sound/soc/sof/pcm.c
+++ b/sound/soc/sof/pcm.c
@@ -13,6 +13,7 @@
 #include <linux/pm_runtime.h>
 #include <sound/pcm_params.h>
 #include <sound/sof.h>
+#include <trace/events/sof.h>
 #include "sof-of-dev.h"
 #include "sof-priv.h"
 #include "sof-audio.h"
@@ -384,9 +385,7 @@ static snd_pcm_uframes_t sof_pcm_pointer(struct snd_soc_component *component,
 	dai = bytes_to_frames(substream->runtime,
 			      spcm->stream[substream->stream].posn.dai_posn);
 
-	dev_vdbg(component->dev,
-		 "PCM: stream %d dir %d DMA position %lu DAI position %lu\n",
-		 spcm->pcm.pcm_id, substream->stream, host, dai);
+	trace_sof_pcm_pointer_position(sdev, spcm, substream, host, dai);
 
 	return host;
 }
-- 
2.34.1

[PATCH 7/7] ASoC: SOF: replace ipc4-loader dev_vdbg with tracepoints

[Pierre-Louis Bossart]

From: Noah Klayman <noah.klayman@intel.com>

This patch replaces dev_vdbg with tracepoints in new ipc4-loader code.

Reviewed-by: Bard Liao <yung-chuan.liao@linux.intel.com>
Reviewed-by: Péter Ujfalusi <peter.ujfalusi@linux.intel.com>
Signed-off-by: Noah Klayman <noah.klayman@intel.com>
Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
---
 include/trace/events/sof.h  | 17 +++++++++++++++++
 sound/soc/sof/ipc4-loader.c |  7 ++++---
 2 files changed, 21 insertions(+), 3 deletions(-)

diff --git a/include/trace/events/sof.h b/include/trace/events/sof.h
index 03751323aaa84..21c2a1efb9f6e 100644
--- a/include/trace/events/sof.h
+++ b/include/trace/events/sof.h
@@ -98,6 +98,23 @@ TRACE_EVENT(sof_stream_position_ipc_rx,
 	TP_printk("device_name=%s", __get_str(device_name))
 );
 
+TRACE_EVENT(sof_ipc4_fw_config,
+	TP_PROTO(struct snd_sof_dev *sdev, char *key, u32 value),
+	TP_ARGS(sdev, key, value),
+	TP_STRUCT__entry(
+		__string(device_name, dev_name(sdev->dev))
+		__string(key, key)
+		__field(u32, value)
+	),
+	TP_fast_assign(
+		__assign_str(device_name, dev_name(sdev->dev));
+		__assign_str(key, key);
+		__entry->value = value;
+	),
+	TP_printk("device_name=%s key=%s value=%d",
+		  __get_str(device_name), __get_str(key), __entry->value)
+);
+
 #endif /* _TRACE_SOF_H */
 
 /* This part must be outside protection */
diff --git a/sound/soc/sof/ipc4-loader.c b/sound/soc/sof/ipc4-loader.c
index c678f05d0ef55..e635ae515fa9f 100644
--- a/sound/soc/sof/ipc4-loader.c
+++ b/sound/soc/sof/ipc4-loader.c
@@ -8,6 +8,7 @@
 #include <linux/firmware.h>
 #include <sound/sof/ext_manifest4.h>
 #include <sound/sof/ipc4/header.h>
+#include <trace/events/sof.h>
 #include "ipc4-priv.h"
 #include "sof-audio.h"
 #include "sof-priv.h"
@@ -194,13 +195,13 @@ static int sof_ipc4_query_fw_configuration(struct snd_sof_dev *sdev)
 				 fw_ver->build);
 			break;
 		case SOF_IPC4_FW_CFG_DL_MAILBOX_BYTES:
-			dev_vdbg(sdev->dev, "DL mailbox size: %u\n", *tuple->value);
+			trace_sof_ipc4_fw_config(sdev, "DL mailbox size", *tuple->value);
 			break;
 		case SOF_IPC4_FW_CFG_UL_MAILBOX_BYTES:
-			dev_vdbg(sdev->dev, "UL mailbox size: %u\n", *tuple->value);
+			trace_sof_ipc4_fw_config(sdev, "UL mailbox size", *tuple->value);
 			break;
 		case SOF_IPC4_FW_CFG_TRACE_LOG_BYTES:
-			dev_vdbg(sdev->dev, "Trace log size: %u\n", *tuple->value);
+			trace_sof_ipc4_fw_config(sdev, "Trace log size", *tuple->value);
 			ipc4_data->mtrace_log_bytes = *tuple->value;
 			break;
 		default:
-- 
2.34.1

Re: [PATCH 0/7] ASoC: SOF: start using tracing instead of dev_dbg

[Mark Brown]

On Mon, 19 Sep 2022 14:21:01 +0200, Pierre-Louis Bossart wrote:
> Multiple maintainers have told us to start using the tracing
> subsystem. Wish granted, this patchset suggested by Noah Klayman
> removes a number of verbose and arguably useless dev_dbg or dev_vdbg
> logs.
> 
> Beyond higher efficiency and less intrusive instrumentation, the use
> of bpftrace scripts bring new functionality and helps gather
> statistics on usage count on a running system, see how we can get
> information on suspend/resume times with [1]
> 
> [...]

Applied to

   broonie/sound.git for-next

Thanks!

[1/7] ASoC: SOF: add widget setup/free tracing
      commit: fa6e73d69193d0ba3b794f7c303beae498732f40
[2/7] ASoC: SOF: Intel: add HDA interrupt source tracing
      commit: baedc6300b3d52c71a06f4bddd426488ec243c2b
[3/7] ASoC: SOF: Intel: remove unneeded dev_vdbg
      commit: 032e7c68bb4f4d977d2dd7f7629771973131f15e
[4/7] ASoC: SOF: remove unneeded dev_vdbg
      commit: 4a232cc910b943947a52da363bce1265911555f7
[5/7] ASoC: SOF: Intel: replace dev_vdbg with tracepoints
      commit: d272b65704bbbb9c054093c8c7dffb7b1793539f
[6/7] ASoC: SOF: replace dev_vdbg with tracepoints
      commit: bcd2cc350ded769963970c4b0074b38bc9240a64
[7/7] ASoC: SOF: replace ipc4-loader dev_vdbg with tracepoints
      commit: 794cd3bd69315f724532e35fbc1c45dfad9a79e6

All being well this means that it will be integrated into the linux-next
tree (usually sometime in the next 24 hours) and sent to Linus during
the next merge window (or sooner if it is a bug fix), however if
problems are discovered then the patch may be dropped or reverted.

You may get further e-mails resulting from automated or manual testing
and review of the tree, please engage with people reporting problems and
send followup patches addressing any issues that are reported if needed.

If any updates are required or you are submitting further changes they
should be sent as incremental updates against current git, existing
patches will not be replaced.

Please add any relevant lists and maintainers to the CCs when replying
to this mail.

Thanks,
Mark