[PATCH 0/4] ASoC: SOF: Improve the spcm and ipc4 copier prints

[PATCH 0/4] ASoC: SOF: Improve the spcm and ipc4 copier prints

[Peter Ujfalusi]

Hi,

Introduce new wrapper to present spcm related debug and error prints in
a unified way and provide additional details to help to understand the
reasons and configuration used when the log was captured.

Change the way we print information about the ipc4 copier module to
use type specific prints, again to provide better information for
debugging.

Regards,
Peter
---
Peter Ujfalusi (4):
  ASoC: SOF: Relocate and rework functionality for PCM stream freeing
  ASoC: SOF: pcm: Move period/buffer configuration print after platform
    open
  ASoC: SOF: pcm: Add snd_sof_pcm specific wrappers for dev_dbg() and
    dev_err()
  ASoC: SOF: ipc4-topology: Improve the information in prepare_copier
    prints

 sound/soc/sof/ipc3-pcm.c      |  13 +--
 sound/soc/sof/ipc3-topology.c |  20 +---
 sound/soc/sof/ipc4-pcm.c      |  16 ++--
 sound/soc/sof/ipc4-topology.c |  40 ++++----
 sound/soc/sof/pcm.c           | 169 ++++++++++++++++++++++++----------
 sound/soc/sof/sof-audio.c     |  49 ----------
 sound/soc/sof/sof-audio.h     |  17 +++-
 7 files changed, 170 insertions(+), 154 deletions(-)

-- 
2.48.1

[PATCH 1/4] ASoC: SOF: Relocate and rework functionality for PCM stream freeing

[Peter Ujfalusi]

Move the sof_pcm_stream_free() from sof-audio.c to pcm.c as static function
and add wrapper to free all active stream, which is going to be used in
ipc3/4 topology code (removes duplicated code).

With this change most of the PCM stream related code is located in one
source file for easier lookup and simplified flow.

Signed-off-by: Peter Ujfalusi <peter.ujfalusi@linux.intel.com>
Reviewed-by: Liam Girdwood <liam.r.girdwood@intel.com>
Reviewed-by: Bard Liao <yung-chuan.liao@linux.intel.com>
Reviewed-by: Ranjani Sridharan <ranjani.sridharan@linux.intel.com>
---
 sound/soc/sof/ipc3-topology.c | 20 ++-------
 sound/soc/sof/ipc4-topology.c | 18 +-------
 sound/soc/sof/pcm.c           | 78 +++++++++++++++++++++++++++++++++++
 sound/soc/sof/sof-audio.c     | 49 ----------------------
 sound/soc/sof/sof-audio.h     |  3 +-
 5 files changed, 84 insertions(+), 84 deletions(-)

diff --git a/sound/soc/sof/ipc3-topology.c b/sound/soc/sof/ipc3-topology.c
index e98b53b67d12..473d416bc910 100644
--- a/sound/soc/sof/ipc3-topology.c
+++ b/sound/soc/sof/ipc3-topology.c
@@ -2386,28 +2386,16 @@ static int sof_ipc3_set_up_all_pipelines(struct snd_sof_dev *sdev, bool verify)
 static int sof_tear_down_left_over_pipelines(struct snd_sof_dev *sdev)
 {
 	struct snd_sof_widget *swidget;
-	struct snd_sof_pcm *spcm;
-	int dir, ret;
+	int ret;
 
 	/*
 	 * free all PCMs and their associated DAPM widgets if their connected DAPM widget
 	 * list is not NULL. This should only be true for paused streams at this point.
 	 * This is equivalent to the handling of FE DAI suspend trigger for running streams.
 	 */
-	list_for_each_entry(spcm, &sdev->pcm_list, list) {
-		for_each_pcm_streams(dir) {
-			struct snd_pcm_substream *substream = spcm->stream[dir].substream;
-
-			if (!substream || !substream->runtime || spcm->stream[dir].suspend_ignored)
-				continue;
-
-			if (spcm->stream[dir].list) {
-				ret = sof_pcm_stream_free(sdev, substream, spcm, dir, true);
-				if (ret < 0)
-					return ret;
-			}
-		}
-	}
+	ret = sof_pcm_free_all_streams(sdev);
+	if (ret)
+		return ret;
 
 	/*
 	 * free any left over DAI widgets. This is equivalent to the handling of suspend trigger
diff --git a/sound/soc/sof/ipc4-topology.c b/sound/soc/sof/ipc4-topology.c
index c04c62478827..21e29bfd4b22 100644
--- a/sound/soc/sof/ipc4-topology.c
+++ b/sound/soc/sof/ipc4-topology.c
@@ -3401,9 +3401,6 @@ static int sof_ipc4_dai_get_param(struct snd_sof_dev *sdev, struct snd_sof_dai *
 
 static int sof_ipc4_tear_down_all_pipelines(struct snd_sof_dev *sdev, bool verify)
 {
-	struct snd_sof_pcm *spcm;
-	int dir, ret;
-
 	/*
 	 * This function is called during system suspend, we need to make sure
 	 * that all streams have been freed up.
@@ -3415,21 +3412,8 @@ static int sof_ipc4_tear_down_all_pipelines(struct snd_sof_dev *sdev, bool verif
 	 *
 	 * This will also make sure that paused streams handled correctly.
 	 */
-	list_for_each_entry(spcm, &sdev->pcm_list, list) {
-		for_each_pcm_streams(dir) {
-			struct snd_pcm_substream *substream = spcm->stream[dir].substream;
-
-			if (!substream || !substream->runtime || spcm->stream[dir].suspend_ignored)
-				continue;
 
-			if (spcm->stream[dir].list) {
-				ret = sof_pcm_stream_free(sdev, substream, spcm, dir, true);
-				if (ret < 0)
-					return ret;
-			}
-		}
-	}
-	return 0;
+	return sof_pcm_free_all_streams(sdev);
 }
 
 static int sof_ipc4_link_setup(struct snd_sof_dev *sdev, struct snd_soc_dai_link *link)
diff --git a/sound/soc/sof/pcm.c b/sound/soc/sof/pcm.c
index 35a7462d8b69..709baa1b0bd6 100644
--- a/sound/soc/sof/pcm.c
+++ b/sound/soc/sof/pcm.c
@@ -191,6 +191,84 @@ static int sof_pcm_hw_params(struct snd_soc_component *component,
 	return 0;
 }
 
+static int sof_pcm_stream_free(struct snd_sof_dev *sdev,
+			       struct snd_pcm_substream *substream,
+			       struct snd_sof_pcm *spcm, int dir,
+			       bool free_widget_list)
+{
+	const struct sof_ipc_pcm_ops *pcm_ops = sof_ipc_get_ops(sdev, pcm);
+	int ret;
+	int err = 0;
+
+	if (spcm->prepared[substream->stream]) {
+		/* stop DMA first if needed */
+		if (pcm_ops && pcm_ops->platform_stop_during_hw_free)
+			snd_sof_pcm_platform_trigger(sdev, substream,
+						     SNDRV_PCM_TRIGGER_STOP);
+
+		/* free PCM in the DSP */
+		if (pcm_ops && pcm_ops->hw_free) {
+			ret = pcm_ops->hw_free(sdev->component, substream);
+			if (ret < 0) {
+				dev_err(sdev->dev, "%s: pcm_ops hw_free failed %d\n",
+					__func__, ret);
+				err = ret;
+			}
+		}
+
+		spcm->prepared[substream->stream] = false;
+		spcm->pending_stop[substream->stream] = false;
+	}
+
+	/* reset the DMA */
+	ret = snd_sof_pcm_platform_hw_free(sdev, substream);
+	if (ret < 0) {
+		dev_err(sdev->dev, "%s: platform hw free failed %d\n",
+			__func__, ret);
+		if (!err)
+			err = ret;
+	}
+
+	/* free widget list */
+	if (free_widget_list) {
+		ret = sof_widget_list_free(sdev, spcm, dir);
+		if (ret < 0) {
+			dev_err(sdev->dev, "%s: sof_widget_list_free failed %d\n",
+				__func__, ret);
+			if (!err)
+				err = ret;
+		}
+	}
+
+	return err;
+}
+
+int sof_pcm_free_all_streams(struct snd_sof_dev *sdev)
+{
+	struct snd_pcm_substream *substream;
+	struct snd_sof_pcm *spcm;
+	int dir, ret;
+
+	list_for_each_entry(spcm, &sdev->pcm_list, list) {
+		for_each_pcm_streams(dir) {
+			substream = spcm->stream[dir].substream;
+
+			if (!substream || !substream->runtime ||
+			    spcm->stream[dir].suspend_ignored)
+				continue;
+
+			if (spcm->stream[dir].list) {
+				ret = sof_pcm_stream_free(sdev, substream, spcm,
+							  dir, true);
+				if (ret < 0)
+					return ret;
+			}
+		}
+	}
+
+	return 0;
+}
+
 static int sof_pcm_hw_free(struct snd_soc_component *component,
 			   struct snd_pcm_substream *substream)
 {
diff --git a/sound/soc/sof/sof-audio.c b/sound/soc/sof/sof-audio.c
index 9a52781bf8d8..a9664b4cf43f 100644
--- a/sound/soc/sof/sof-audio.c
+++ b/sound/soc/sof/sof-audio.c
@@ -829,55 +829,6 @@ bool snd_sof_stream_suspend_ignored(struct snd_sof_dev *sdev)
 	return false;
 }
 
-int sof_pcm_stream_free(struct snd_sof_dev *sdev, struct snd_pcm_substream *substream,
-			struct snd_sof_pcm *spcm, int dir, bool free_widget_list)
-{
-	const struct sof_ipc_pcm_ops *pcm_ops = sof_ipc_get_ops(sdev, pcm);
-	int ret;
-	int err = 0;
-
-	if (spcm->prepared[substream->stream]) {
-		/* stop DMA first if needed */
-		if (pcm_ops && pcm_ops->platform_stop_during_hw_free)
-			snd_sof_pcm_platform_trigger(sdev, substream, SNDRV_PCM_TRIGGER_STOP);
-
-		/* free PCM in the DSP */
-		if (pcm_ops && pcm_ops->hw_free) {
-			ret = pcm_ops->hw_free(sdev->component, substream);
-			if (ret < 0) {
-				dev_err(sdev->dev, "%s: pcm_ops hw_free failed %d\n",
-					__func__, ret);
-				err = ret;
-			}
-		}
-
-		spcm->prepared[substream->stream] = false;
-		spcm->pending_stop[substream->stream] = false;
-	}
-
-	/* reset the DMA */
-	ret = snd_sof_pcm_platform_hw_free(sdev, substream);
-	if (ret < 0) {
-		dev_err(sdev->dev, "%s: platform hw free failed %d\n",
-			__func__, ret);
-		if (!err)
-			err = ret;
-	}
-
-	/* free widget list */
-	if (free_widget_list) {
-		ret = sof_widget_list_free(sdev, spcm, dir);
-		if (ret < 0) {
-			dev_err(sdev->dev, "%s: sof_widget_list_free failed %d\n",
-				__func__, ret);
-			if (!err)
-				err = ret;
-		}
-	}
-
-	return err;
-}
-
 /*
  * Generic object lookup APIs.
  */
diff --git a/sound/soc/sof/sof-audio.h b/sound/soc/sof/sof-audio.h
index 62f3c11a9216..7d4810924682 100644
--- a/sound/soc/sof/sof-audio.h
+++ b/sound/soc/sof/sof-audio.h
@@ -649,8 +649,7 @@ int sof_widget_list_setup(struct snd_sof_dev *sdev, struct snd_sof_pcm *spcm,
 int sof_widget_list_free(struct snd_sof_dev *sdev, struct snd_sof_pcm *spcm, int dir);
 int sof_pcm_dsp_pcm_free(struct snd_pcm_substream *substream, struct snd_sof_dev *sdev,
 			 struct snd_sof_pcm *spcm);
-int sof_pcm_stream_free(struct snd_sof_dev *sdev, struct snd_pcm_substream *substream,
-			struct snd_sof_pcm *spcm, int dir, bool free_widget_list);
+int sof_pcm_free_all_streams(struct snd_sof_dev *sdev);
 int get_token_u32(void *elem, void *object, u32 offset);
 int get_token_u16(void *elem, void *object, u32 offset);
 int get_token_comp_format(void *elem, void *object, u32 offset);
-- 
2.48.1

[PATCH 2/4] ASoC: SOF: pcm: Move period/buffer configuration print after platform open

[Peter Ujfalusi]

The platform specific pcm_open call via snd_sof_pcm_platform_open() can
modify the initial buffer configuration via constraints.

Move the prints as last step in the sof_pcm_open() function to reflect the
final setup.

Signed-off-by: Peter Ujfalusi <peter.ujfalusi@linux.intel.com>
Reviewed-by: Liam Girdwood <liam.r.girdwood@intel.com>
Reviewed-by: Bard Liao <yung-chuan.liao@linux.intel.com>
Reviewed-by: Ranjani Sridharan <ranjani.sridharan@linux.intel.com>
---
 sound/soc/sof/pcm.c | 24 +++++++++++++-----------
 1 file changed, 13 insertions(+), 11 deletions(-)

diff --git a/sound/soc/sof/pcm.c b/sound/soc/sof/pcm.c
index 709baa1b0bd6..d09be241e95e 100644
--- a/sound/soc/sof/pcm.c
+++ b/sound/soc/sof/pcm.c
@@ -536,15 +536,6 @@ static int sof_pcm_open(struct snd_soc_component *component,
 	 */
 	runtime->hw.buffer_bytes_max = le32_to_cpu(caps->buffer_size_max);
 
-	dev_dbg(component->dev, "period min %zd max %zd bytes\n",
-		runtime->hw.period_bytes_min,
-		runtime->hw.period_bytes_max);
-	dev_dbg(component->dev, "period count %d max %d\n",
-		runtime->hw.periods_min,
-		runtime->hw.periods_max);
-	dev_dbg(component->dev, "buffer max %zd bytes\n",
-		runtime->hw.buffer_bytes_max);
-
 	/* set wait time - TODO: come from topology */
 	substream->wait_time = 500;
 
@@ -554,10 +545,21 @@ static int sof_pcm_open(struct snd_soc_component *component,
 	spcm->prepared[substream->stream] = false;
 
 	ret = snd_sof_pcm_platform_open(sdev, substream);
-	if (ret < 0)
+	if (ret < 0) {
 		dev_err(component->dev, "error: pcm open failed %d\n", ret);
+		return ret;
+	}
 
-	return ret;
+	dev_dbg(component->dev, "period bytes min %zd, max %zd\n",
+		runtime->hw.period_bytes_min,
+		runtime->hw.period_bytes_max);
+	dev_dbg(component->dev, "period count min %d, max %d\n",
+		runtime->hw.periods_min,
+		runtime->hw.periods_max);
+	dev_dbg(component->dev, "buffer bytes max %zd\n",
+		runtime->hw.buffer_bytes_max);
+
+	return 0;
 }
 
 static int sof_pcm_close(struct snd_soc_component *component,
-- 
2.48.1

[PATCH 3/4] ASoC: SOF: pcm: Add snd_sof_pcm specific wrappers for dev_dbg() and dev_err()

[Peter Ujfalusi]

Introduce spcm_dbg() and spcm_err() macros to provide consistent printing
for debug and error messages which includes usable information in the
print's prefix.

Update the prints in pcm.c, ipc3-pcm.c and ipc4-pcm.c to take advantage of
the features provided by the macros.

Signed-off-by: Peter Ujfalusi <peter.ujfalusi@linux.intel.com>
Reviewed-by: Liam Girdwood <liam.r.girdwood@intel.com>
Reviewed-by: Bard Liao <yung-chuan.liao@linux.intel.com>
Reviewed-by: Ranjani Sridharan <ranjani.sridharan@linux.intel.com>
---
 sound/soc/sof/ipc3-pcm.c  | 13 +++---
 sound/soc/sof/ipc4-pcm.c  | 16 ++++---
 sound/soc/sof/pcm.c       | 95 +++++++++++++++++----------------------
 sound/soc/sof/sof-audio.h | 14 ++++++
 4 files changed, 72 insertions(+), 66 deletions(-)

diff --git a/sound/soc/sof/ipc3-pcm.c b/sound/soc/sof/ipc3-pcm.c
index 1c1b8f595367..90ef5d99f626 100644
--- a/sound/soc/sof/ipc3-pcm.c
+++ b/sound/soc/sof/ipc3-pcm.c
@@ -117,22 +117,23 @@ static int sof_ipc3_pcm_hw_params(struct snd_soc_component *component,
 	if (platform_params->cont_update_posn)
 		pcm.params.cont_update_posn = 1;
 
-	dev_dbg(component->dev, "stream_tag %d", pcm.params.stream_tag);
+	spcm_dbg(spcm, substream->stream, "stream_tag %d\n",
+		 pcm.params.stream_tag);
 
 	/* send hw_params IPC to the DSP */
 	ret = sof_ipc_tx_message(sdev->ipc, &pcm, sizeof(pcm),
 				 &ipc_params_reply, sizeof(ipc_params_reply));
 	if (ret < 0) {
-		dev_err(component->dev, "HW params ipc failed for stream %d\n",
-			pcm.params.stream_tag);
+		spcm_err(spcm, substream->stream,
+			 "STREAM_PCM_PARAMS ipc failed for stream_tag %d\n",
+			 pcm.params.stream_tag);
 		return ret;
 	}
 
 	ret = snd_sof_set_stream_data_offset(sdev, &spcm->stream[substream->stream],
 					     ipc_params_reply.posn_offset);
 	if (ret < 0) {
-		dev_err(component->dev, "%s: invalid stream data offset for PCM %d\n",
-			__func__, spcm->pcm.pcm_id);
+		spcm_err(spcm, substream->stream, "invalid stream data offset\n");
 		return ret;
 	}
 
@@ -171,7 +172,7 @@ static int sof_ipc3_pcm_trigger(struct snd_soc_component *component,
 		stream.hdr.cmd |= SOF_IPC_STREAM_TRIG_STOP;
 		break;
 	default:
-		dev_err(component->dev, "Unhandled trigger cmd %d\n", cmd);
+		spcm_err(spcm, substream->stream, "Unhandled trigger cmd %d\n", cmd);
 		return -EINVAL;
 	}
 
diff --git a/sound/soc/sof/ipc4-pcm.c b/sound/soc/sof/ipc4-pcm.c
index 18fff2df76f9..5ec109094031 100644
--- a/sound/soc/sof/ipc4-pcm.c
+++ b/sound/soc/sof/ipc4-pcm.c
@@ -313,7 +313,7 @@ static int sof_ipc4_chain_dma_trigger(struct snd_sof_dev *sdev,
 		set_fifo_size = false;
 		break;
 	default:
-		dev_err(sdev->dev, "Unexpected state %d", state);
+		spcm_err(spcm, direction, "Unexpected pipeline state %d\n", state);
 		return -EINVAL;
 	}
 
@@ -333,8 +333,8 @@ static int sof_ipc4_chain_dma_trigger(struct snd_sof_dev *sdev,
 		struct sof_ipc4_pipeline *pipeline = pipe_widget->private;
 
 		if (!pipeline->use_chain_dma) {
-			dev_err(sdev->dev,
-				"All pipelines in chained DMA stream should have use_chain_dma attribute set.");
+			spcm_err(spcm, direction,
+				 "All pipelines in chained DMA path should have use_chain_dma attribute set.");
 			return -EINVAL;
 		}
 
@@ -389,12 +389,12 @@ static int sof_ipc4_trigger_pipelines(struct snd_soc_component *component,
 	int ret;
 	int i;
 
-	dev_dbg(sdev->dev, "trigger cmd: %d state: %d\n", cmd, state);
-
 	spcm = snd_sof_find_spcm_dai(component, rtd);
 	if (!spcm)
 		return -EINVAL;
 
+	spcm_dbg(spcm, substream->stream, "cmd: %d, state: %d\n", cmd, state);
+
 	pipeline_list = &spcm->stream[substream->stream].pipeline_list;
 
 	/* nothing to trigger if the list is empty */
@@ -465,7 +465,7 @@ static int sof_ipc4_trigger_pipelines(struct snd_soc_component *component,
 	 */
 	ret = sof_ipc4_set_multi_pipeline_state(sdev, SOF_IPC4_PIPE_PAUSED, trigger_list);
 	if (ret < 0) {
-		dev_err(sdev->dev, "failed to pause all pipelines\n");
+		spcm_err(spcm, substream->stream, "failed to pause all pipelines\n");
 		goto free;
 	}
 
@@ -494,7 +494,9 @@ static int sof_ipc4_trigger_pipelines(struct snd_soc_component *component,
 	/* else set the RUNNING/RESET state in the DSP */
 	ret = sof_ipc4_set_multi_pipeline_state(sdev, state, trigger_list);
 	if (ret < 0) {
-		dev_err(sdev->dev, "failed to set final state %d for all pipelines\n", state);
+		spcm_err(spcm, substream->stream,
+			 "failed to set final state %d for all pipelines\n",
+			 state);
 		/*
 		 * workaround: if the firmware is crashed while setting the
 		 * pipelines to reset state we must ignore the error code and
diff --git a/sound/soc/sof/pcm.c b/sound/soc/sof/pcm.c
index d09be241e95e..372ed71a17aa 100644
--- a/sound/soc/sof/pcm.c
+++ b/sound/soc/sof/pcm.c
@@ -99,8 +99,8 @@ sof_pcm_setup_connected_widgets(struct snd_sof_dev *sdev, struct snd_soc_pcm_run
 		ret = snd_soc_dapm_dai_get_connected_widgets(dai, dir, &list,
 							     dpcm_end_walk_at_be);
 		if (ret < 0) {
-			dev_err(sdev->dev, "error: dai %s has no valid %s path\n", dai->name,
-				snd_pcm_direction_name(dir));
+			spcm_err(spcm, dir, "dai %s has no valid %s path\n",
+				 dai->name, snd_pcm_direction_name(dir));
 			return ret;
 		}
 
@@ -108,8 +108,7 @@ sof_pcm_setup_connected_widgets(struct snd_sof_dev *sdev, struct snd_soc_pcm_run
 
 		ret = sof_widget_list_setup(sdev, spcm, params, platform_params, dir);
 		if (ret < 0) {
-			dev_err(sdev->dev, "error: failed widget list set up for pcm %d dir %d\n",
-				spcm->pcm.pcm_id, dir);
+			spcm_err(spcm, dir, "Widget list set up failed\n");
 			spcm->stream[dir].list = NULL;
 			snd_soc_dapm_dai_free_widgets(&list);
 			return ret;
@@ -139,6 +138,8 @@ static int sof_pcm_hw_params(struct snd_soc_component *component,
 	if (!spcm)
 		return -EINVAL;
 
+	spcm_dbg(spcm, substream->stream, "Entry: hw_params\n");
+
 	/*
 	 * Handle repeated calls to hw_params() without free_pcm() in
 	 * between. At least ALSA OSS emulation depends on this.
@@ -151,12 +152,9 @@ static int sof_pcm_hw_params(struct snd_soc_component *component,
 		spcm->prepared[substream->stream] = false;
 	}
 
-	dev_dbg(component->dev, "pcm: hw params stream %d dir %d\n",
-		spcm->pcm.pcm_id, substream->stream);
-
 	ret = snd_sof_pcm_platform_hw_params(sdev, substream, params, &platform_params);
 	if (ret < 0) {
-		dev_err(component->dev, "platform hw params failed\n");
+		spcm_err(spcm, substream->stream, "platform hw params failed\n");
 		return ret;
 	}
 
@@ -210,8 +208,8 @@ static int sof_pcm_stream_free(struct snd_sof_dev *sdev,
 		if (pcm_ops && pcm_ops->hw_free) {
 			ret = pcm_ops->hw_free(sdev->component, substream);
 			if (ret < 0) {
-				dev_err(sdev->dev, "%s: pcm_ops hw_free failed %d\n",
-					__func__, ret);
+				spcm_err(spcm, substream->stream,
+					 "pcm_ops->hw_free failed %d\n", ret);
 				err = ret;
 			}
 		}
@@ -223,8 +221,8 @@ static int sof_pcm_stream_free(struct snd_sof_dev *sdev,
 	/* reset the DMA */
 	ret = snd_sof_pcm_platform_hw_free(sdev, substream);
 	if (ret < 0) {
-		dev_err(sdev->dev, "%s: platform hw free failed %d\n",
-			__func__, ret);
+		spcm_err(spcm, substream->stream,
+			 "platform hw free failed %d\n", ret);
 		if (!err)
 			err = ret;
 	}
@@ -233,8 +231,8 @@ static int sof_pcm_stream_free(struct snd_sof_dev *sdev,
 	if (free_widget_list) {
 		ret = sof_widget_list_free(sdev, spcm, dir);
 		if (ret < 0) {
-			dev_err(sdev->dev, "%s: sof_widget_list_free failed %d\n",
-				__func__, ret);
+			spcm_err(spcm, substream->stream,
+				 "sof_widget_list_free failed %d\n", ret);
 			if (!err)
 				err = ret;
 		}
@@ -285,8 +283,7 @@ static int sof_pcm_hw_free(struct snd_soc_component *component,
 	if (!spcm)
 		return -EINVAL;
 
-	dev_dbg(component->dev, "pcm: free stream %d dir %d\n",
-		spcm->pcm.pcm_id, substream->stream);
+	spcm_dbg(spcm, substream->stream, "Entry: hw_free\n");
 
 	ret = sof_pcm_stream_free(sdev, substream, spcm, substream->stream, true);
 
@@ -311,6 +308,8 @@ static int sof_pcm_prepare(struct snd_soc_component *component,
 	if (!spcm)
 		return -EINVAL;
 
+	spcm_dbg(spcm, substream->stream, "Entry: prepare\n");
+
 	if (spcm->prepared[substream->stream]) {
 		if (!spcm->pending_stop[substream->stream])
 			return 0;
@@ -324,15 +323,12 @@ static int sof_pcm_prepare(struct snd_soc_component *component,
 			return ret;
 	}
 
-	dev_dbg(component->dev, "pcm: prepare stream %d dir %d\n",
-		spcm->pcm.pcm_id, substream->stream);
-
 	/* set hw_params */
 	ret = sof_pcm_hw_params(component,
 				substream, &spcm->params[substream->stream]);
 	if (ret < 0) {
-		dev_err(component->dev,
-			"error: set pcm hw_params after resume\n");
+		spcm_err(spcm, substream->stream,
+			 "failed to set hw_params after resume\n");
 		return ret;
 	}
 
@@ -362,8 +358,7 @@ static int sof_pcm_trigger(struct snd_soc_component *component,
 	if (!spcm)
 		return -EINVAL;
 
-	dev_dbg(component->dev, "pcm: trigger stream %d dir %d cmd %d\n",
-		spcm->pcm.pcm_id, substream->stream, cmd);
+	spcm_dbg(spcm, substream->stream, "Entry: trigger (cmd: %d)\n", cmd);
 
 	spcm->pending_stop[substream->stream] = false;
 
@@ -412,7 +407,7 @@ static int sof_pcm_trigger(struct snd_soc_component *component,
 			reset_hw_params = true;
 		break;
 	default:
-		dev_err(component->dev, "Unhandled trigger cmd %d\n", cmd);
+		spcm_err(spcm, substream->stream, "Unhandled trigger cmd %d\n", cmd);
 		return -EINVAL;
 	}
 
@@ -514,9 +509,7 @@ static int sof_pcm_open(struct snd_soc_component *component,
 	if (!spcm)
 		return -EINVAL;
 
-	dev_dbg(component->dev, "pcm: open stream %d dir %d\n",
-		spcm->pcm.pcm_id, substream->stream);
-
+	spcm_dbg(spcm, substream->stream, "Entry: open\n");
 
 	caps = &spcm->pcm.caps[substream->stream];
 
@@ -546,18 +539,16 @@ static int sof_pcm_open(struct snd_soc_component *component,
 
 	ret = snd_sof_pcm_platform_open(sdev, substream);
 	if (ret < 0) {
-		dev_err(component->dev, "error: pcm open failed %d\n", ret);
+		spcm_err(spcm, substream->stream,
+			 "platform pcm open failed %d\n", ret);
 		return ret;
 	}
 
-	dev_dbg(component->dev, "period bytes min %zd, max %zd\n",
-		runtime->hw.period_bytes_min,
-		runtime->hw.period_bytes_max);
-	dev_dbg(component->dev, "period count min %d, max %d\n",
-		runtime->hw.periods_min,
-		runtime->hw.periods_max);
-	dev_dbg(component->dev, "buffer bytes max %zd\n",
-		runtime->hw.buffer_bytes_max);
+	spcm_dbg(spcm, substream->stream, "period bytes min %zd, max %zd\n",
+		 runtime->hw.period_bytes_min, runtime->hw.period_bytes_max);
+	spcm_dbg(spcm, substream->stream, "period count min %d, max %d\n",
+		 runtime->hw.periods_min, runtime->hw.periods_max);
+	spcm_dbg(spcm, substream->stream, "buffer bytes max %zd\n", runtime->hw.buffer_bytes_max);
 
 	return 0;
 }
@@ -578,13 +569,12 @@ static int sof_pcm_close(struct snd_soc_component *component,
 	if (!spcm)
 		return -EINVAL;
 
-	dev_dbg(component->dev, "pcm: close stream %d dir %d\n",
-		spcm->pcm.pcm_id, substream->stream);
+	spcm_dbg(spcm, substream->stream, "Entry: close\n");
 
 	err = snd_sof_pcm_platform_close(sdev, substream);
 	if (err < 0) {
-		dev_err(component->dev, "error: pcm close failed %d\n",
-			err);
+		spcm_err(spcm, substream->stream,
+			 "platform pcm close failed %d\n", err);
 		/*
 		 * keep going, no point in preventing the close
 		 * from happening
@@ -616,7 +606,8 @@ static int sof_pcm_new(struct snd_soc_component *component,
 		return 0;
 	}
 
-	dev_dbg(component->dev, "creating new PCM %s\n", spcm->pcm.pcm_name);
+	dev_dbg(spcm->scomp->dev, "pcm%u (%s): Entry: pcm_construct\n",
+		spcm->pcm.pcm_id, spcm->pcm.pcm_name);
 
 	/* do we need to pre-allocate playback audio buffer pages */
 	if (!spcm->pcm.playback)
@@ -624,16 +615,15 @@ static int sof_pcm_new(struct snd_soc_component *component,
 
 	caps = &spcm->pcm.caps[stream];
 
-	/* pre-allocate playback audio buffer pages */
-	dev_dbg(component->dev,
-		"spcm: allocate %s playback DMA buffer size 0x%x max 0x%x\n",
-		caps->name, caps->buffer_size_min, caps->buffer_size_max);
-
 	if (!pcm->streams[stream].substream) {
-		dev_err(component->dev, "error: NULL playback substream!\n");
+		spcm_err(spcm, stream, "NULL playback substream!\n");
 		return -EINVAL;
 	}
 
+	/* pre-allocate playback audio buffer pages */
+	spcm_dbg(spcm, stream, "allocate %s playback DMA buffer size 0x%x max 0x%x\n",
+		 caps->name, caps->buffer_size_min, caps->buffer_size_max);
+
 	snd_pcm_set_managed_buffer(pcm->streams[stream].substream,
 				   SNDRV_DMA_TYPE_DEV_SG, sdev->dev,
 				   0, le32_to_cpu(caps->buffer_size_max));
@@ -646,16 +636,15 @@ static int sof_pcm_new(struct snd_soc_component *component,
 
 	caps = &spcm->pcm.caps[stream];
 
-	/* pre-allocate capture audio buffer pages */
-	dev_dbg(component->dev,
-		"spcm: allocate %s capture DMA buffer size 0x%x max 0x%x\n",
-		caps->name, caps->buffer_size_min, caps->buffer_size_max);
-
 	if (!pcm->streams[stream].substream) {
-		dev_err(component->dev, "error: NULL capture substream!\n");
+		spcm_err(spcm, stream, "NULL capture substream!\n");
 		return -EINVAL;
 	}
 
+	/* pre-allocate capture audio buffer pages */
+	spcm_dbg(spcm, stream, "allocate %s capture DMA buffer size 0x%x max 0x%x\n",
+		 caps->name, caps->buffer_size_min, caps->buffer_size_max);
+
 	snd_pcm_set_managed_buffer(pcm->streams[stream].substream,
 				   SNDRV_DMA_TYPE_DEV_SG, sdev->dev,
 				   0, le32_to_cpu(caps->buffer_size_max));
diff --git a/sound/soc/sof/sof-audio.h b/sound/soc/sof/sof-audio.h
index 7d4810924682..36ab75e11779 100644
--- a/sound/soc/sof/sof-audio.h
+++ b/sound/soc/sof/sof-audio.h
@@ -617,6 +617,20 @@ struct snd_sof_pcm *snd_sof_find_spcm_comp(struct snd_soc_component *scomp,
 void snd_sof_pcm_period_elapsed(struct snd_pcm_substream *substream);
 void snd_sof_pcm_init_elapsed_work(struct work_struct *work);
 
+/*
+ * snd_sof_pcm specific wrappers for dev_dbg() and dev_err() to provide
+ * consistent and useful prints.
+ */
+#define spcm_dbg(__spcm, __dir, __fmt, ...)					\
+	dev_dbg((__spcm)->scomp->dev, "pcm%u (%s), dir %d: " __fmt,		\
+		(__spcm)->pcm.pcm_id, (__spcm)->pcm.pcm_name, __dir,		\
+		##__VA_ARGS__)
+
+#define spcm_err(__spcm, __dir, __fmt, ...)					\
+	dev_err((__spcm)->scomp->dev, "%s: pcm%u (%s), dir %d: " __fmt,		\
+		__func__, (__spcm)->pcm.pcm_id, (__spcm)->pcm.pcm_name, __dir,	\
+		##__VA_ARGS__)
+
 #if IS_ENABLED(CONFIG_SND_SOC_SOF_COMPRESS)
 void snd_sof_compr_fragment_elapsed(struct snd_compr_stream *cstream);
 void snd_sof_compr_init_elapsed_work(struct work_struct *work);
-- 
2.48.1

[PATCH 4/4] ASoC: SOF: ipc4-topology: Improve the information in prepare_copier prints

[Peter Ujfalusi]

It is useful to know the explicit type and if the copier (host/dai) is
configured to use ChainDMA or not and also the stream_tag for the host
copier.

Change the prints to carry more information for debugging purposes.

Signed-off-by: Peter Ujfalusi <peter.ujfalusi@linux.intel.com>
Reviewed-by: Bard Liao <yung-chuan.liao@linux.intel.com>
Reviewed-by: Liam Girdwood <liam.r.girdwood@intel.com>
Reviewed-by: Ranjani Sridharan <ranjani.sridharan@linux.intel.com>
---
 sound/soc/sof/ipc4-topology.c | 22 +++++++++++++++-------
 1 file changed, 15 insertions(+), 7 deletions(-)

diff --git a/sound/soc/sof/ipc4-topology.c b/sound/soc/sof/ipc4-topology.c
index 21e29bfd4b22..a23f55ed5696 100644
--- a/sound/soc/sof/ipc4-topology.c
+++ b/sound/soc/sof/ipc4-topology.c
@@ -1815,15 +1815,19 @@ sof_ipc4_prepare_copier_module(struct snd_sof_widget *swidget,
 	bool single_output_bitdepth;
 	int i;
 
-	dev_dbg(sdev->dev, "copier %s, type %d", swidget->widget->name, swidget->id);
-
 	switch (swidget->id) {
 	case snd_soc_dapm_aif_in:
 	case snd_soc_dapm_aif_out:
 	{
+		struct snd_sof_widget *pipe_widget = swidget->spipe->pipe_widget;
+		struct sof_ipc4_pipeline *pipeline = pipe_widget->private;
 		struct sof_ipc4_gtw_attributes *gtw_attr;
-		struct snd_sof_widget *pipe_widget;
-		struct sof_ipc4_pipeline *pipeline;
+
+		dev_dbg(sdev->dev,
+			"Host copier %s, type %d, ChainDMA: %s, stream_tag: %d\n",
+			swidget->widget->name, swidget->id,
+			str_yes_no(pipeline->use_chain_dma),
+			platform_params->stream_tag);
 
 		/* parse the deep buffer dma size */
 		ret = sof_update_ipc_object(scomp, &deep_buffer_dma_ms,
@@ -1840,9 +1844,6 @@ sof_ipc4_prepare_copier_module(struct snd_sof_widget *swidget,
 		copier_data = &ipc4_copier->data;
 		available_fmt = &ipc4_copier->available_fmt;
 
-		pipe_widget = swidget->spipe->pipe_widget;
-		pipeline = pipe_widget->private;
-
 		if (pipeline->use_chain_dma) {
 			u32 host_dma_id;
 			u32 fifo_size;
@@ -1896,6 +1897,10 @@ sof_ipc4_prepare_copier_module(struct snd_sof_widget *swidget,
 		struct snd_sof_widget *pipe_widget = swidget->spipe->pipe_widget;
 		struct sof_ipc4_pipeline *pipeline = pipe_widget->private;
 
+		dev_dbg(sdev->dev, "Dai copier %s, type %d, ChainDMA: %s\n",
+			swidget->widget->name, swidget->id,
+			str_yes_no(pipeline->use_chain_dma));
+
 		if (pipeline->use_chain_dma)
 			return 0;
 
@@ -1929,6 +1934,9 @@ sof_ipc4_prepare_copier_module(struct snd_sof_widget *swidget,
 	}
 	case snd_soc_dapm_buffer:
 	{
+		dev_dbg(sdev->dev, "Module copier %s, type %d\n",
+			swidget->widget->name, swidget->id);
+
 		ipc4_copier = (struct sof_ipc4_copier *)swidget->private;
 		copier_data = &ipc4_copier->data;
 		available_fmt = &ipc4_copier->available_fmt;
-- 
2.48.1

Re: [PATCH 0/4] ASoC: SOF: Improve the spcm and ipc4 copier prints

[Mark Brown]

On Thu, 06 Feb 2025 11:28:24 +0200, Peter Ujfalusi wrote:
> Introduce new wrapper to present spcm related debug and error prints in
> a unified way and provide additional details to help to understand the
> reasons and configuration used when the log was captured.
> 
> Change the way we print information about the ipc4 copier module to
> use type specific prints, again to provide better information for
> debugging.
> 
> [...]

Applied to

   https://git.kernel.org/pub/scm/linux/kernel/git/broonie/sound.git for-next

Thanks!

[1/4] ASoC: SOF: Relocate and rework functionality for PCM stream freeing
      commit: 169ec0a541aac8afb215ab591b0fd53276686014
[2/4] ASoC: SOF: pcm: Move period/buffer configuration print after platform open
      commit: 4d2ea16576c8aa1437048cf436bff85653f139fe
[3/4] ASoC: SOF: pcm: Add snd_sof_pcm specific wrappers for dev_dbg() and dev_err()
      commit: 860693187c597645b28a421d8acb26428b8afd3f
[4/4] ASoC: SOF: ipc4-topology: Improve the information in prepare_copier prints
      commit: 583348bd65ceaf4a5067a6267dd236929e1b4b37

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