ASoC: SOF: replace dev_vdbg with tracepoints

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>
Link: https://lore.kernel.org/r/20220919122108.43764-7-pierre-louis.bossart@linux.intel.comSigned-off-by: Mark Brown <broonie@kernel.org>

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 */

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

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;
 }