Skip to content

ASoC/SoundWire: improve dmesg logs #3631

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
plbossart merged 4 commits into from
May 11, 2022
Merged

ASoC/SoundWire: improve dmesg logs #3631

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
79a45c0
soundwire: intel: uniquify debug message
plbossart May 3, 2022
e1b181e
ASoC: SOF: Intel: hda-dai: enhance debug messages
plbossart May 3, 2022
bd7d302
fixup! ASoC: SOF: IPC4: set the BE DAI ops
plbossart May 3, 2022
c162e51
ASoC: SOF: reduce default verbosity of IPC logs
plbossart May 2, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
28 changes: 14 additions & 14 deletions drivers/soundwire/intel.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1336,8 +1336,8 @@ int intel_link_startup(struct auxiliary_device *auxdev)

if (bus->prop.hw_disabled) {
dev_info(dev,
"SoundWire master %d is disabled, ignoring\n",
sdw->instance);
"%s: SoundWire master %d is disabled, ignoring\n",
__func__, sdw->instance);
return 0;
}

Expand Down Expand Up @@ -1497,8 +1497,8 @@ int intel_link_process_wakeen_event(struct auxiliary_device *auxdev)
bus = &sdw->cdns.bus;

if (bus->prop.hw_disabled || !sdw->startup_done) {
dev_dbg(dev, "SoundWire master %d is disabled or not-started, ignoring\n",
bus->link_id);
dev_dbg(dev, "%s: SoundWire master %d is disabled or not-started, ignoring\n",
__func__, bus->link_id);
return 0;
}

Expand Down Expand Up @@ -1557,8 +1557,8 @@ static int __maybe_unused intel_pm_prepare(struct device *dev)
int ret;

if (bus->prop.hw_disabled || !sdw->startup_done) {
dev_dbg(dev, "SoundWire master %d is disabled or not-started, ignoring\n",
bus->link_id);
dev_dbg(dev, "%s: SoundWire master %d is disabled or not-started, ignoring\n",
__func__, bus->link_id);
return 0;
}

Expand Down Expand Up @@ -1617,8 +1617,8 @@ static int __maybe_unused intel_suspend(struct device *dev)
int ret;

if (bus->prop.hw_disabled || !sdw->startup_done) {
dev_dbg(dev, "SoundWire master %d is disabled or not-started, ignoring\n",
bus->link_id);
dev_dbg(dev, "%s: SoundWire master %d is disabled or not-started, ignoring\n",
__func__, bus->link_id);
return 0;
}

Expand Down Expand Up @@ -1670,8 +1670,8 @@ static int __maybe_unused intel_suspend_runtime(struct device *dev)
int ret;

if (bus->prop.hw_disabled || !sdw->startup_done) {
dev_dbg(dev, "SoundWire master %d is disabled or not-started, ignoring\n",
bus->link_id);
dev_dbg(dev, "%s: SoundWire master %d is disabled or not-started, ignoring\n",
__func__, bus->link_id);
return 0;
}

Expand Down Expand Up @@ -1735,8 +1735,8 @@ static int __maybe_unused intel_resume(struct device *dev)
int ret;

if (bus->prop.hw_disabled || !sdw->startup_done) {
dev_dbg(dev, "SoundWire master %d is disabled or not-started, ignoring\n",
bus->link_id);
dev_dbg(dev, "%s: SoundWire master %d is disabled or not-started, ignoring\n",
__func__, bus->link_id);
return 0;
}

Expand Down Expand Up @@ -1833,8 +1833,8 @@ static int __maybe_unused intel_resume_runtime(struct device *dev)
int ret;

if (bus->prop.hw_disabled || !sdw->startup_done) {
dev_dbg(dev, "SoundWire master %d is disabled or not-started, ignoring\n",
bus->link_id);
dev_dbg(dev, "%s: SoundWire master %d is disabled or not-started, ignoring\n",
__func__, bus->link_id);
return 0;
}

Expand Down
8 changes: 6 additions & 2 deletions sound/soc/sof/intel/hda-dai.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -270,7 +270,6 @@ static int hda_link_dma_trigger(struct snd_pcm_substream *substream, int cmd)
struct hdac_ext_stream *hext_stream = snd_soc_dai_get_dma_data(cpu_dai, substream);
int ret;

dev_dbg(cpu_dai->dev, "%s: cmd=%d\n", __func__, cmd);
if (!hext_stream)
return 0;

Expand Down Expand Up @@ -420,13 +419,15 @@ static int ipc3_hda_dai_trigger(struct snd_pcm_substream *substream,
struct snd_soc_dapm_widget *w;
int ret;

dev_dbg(dai->dev, "%s: cmd=%d dai %s direction %d\n", __func__, cmd,
dai->name, substream->stream);

ret = hda_link_dma_trigger(substream, cmd);
if (ret < 0)
return ret;

w = snd_soc_dai_get_widget(dai, substream->stream);

dev_dbg(dai->dev, "%s: cmd=%d\n", __func__, cmd);
switch (cmd) {
case SNDRV_PCM_TRIGGER_SUSPEND:
case SNDRV_PCM_TRIGGER_STOP:
Expand Down Expand Up @@ -463,6 +464,9 @@ static int ipc4_hda_link_dma_trigger(struct snd_pcm_substream *substream,
struct snd_soc_dai *cpu_dai;
int ret;

dev_dbg(dai->dev, "%s: cmd=%d dai %s direction %d\n", __func__, cmd,
dai->name, substream->stream);

hstream = substream->runtime->private_data;
rtd = asoc_substream_to_rtd(substream);
cpu_dai = asoc_rtd_to_cpu(rtd, 0);
Expand Down
5 changes: 4 additions & 1 deletion sound/soc/sof/ipc3.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -148,6 +148,8 @@ static void ipc3_log_header(struct device *dev, u8 *text, u32 cmd)
case SOF_IPC_TRACE_DMA_PARAMS:
str2 = "DMA_PARAMS"; break;
case SOF_IPC_TRACE_DMA_POSITION:
if (!sof_debug_check_flag(SOF_DBG_PRINT_DMA_POSITION_UPDATE_LOGS))
return;
str2 = "DMA_POSITION"; break;
case SOF_IPC_TRACE_DMA_PARAMS_EXT:
str2 = "DMA_PARAMS_EXT"; break;
Expand Down Expand Up @@ -300,7 +302,8 @@ static int ipc3_wait_tx_done(struct snd_sof_ipc *ipc, void *reply_data)
"ipc tx error for %#x (msg/reply size: %d/%zu): %d\n",
hdr->cmd, hdr->size, msg->reply_size, ret);
} else {
ipc3_log_header(sdev->dev, "ipc tx succeeded", hdr->cmd);
Copy link
Collaborator

@ujfalusi ujfalusi May 4, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we had this debate in past: which one is more important, the start of the TX or the end of the TX. Back then I proposed to drop the start and print either the success or the error when it is done to remove the duplication.

But in some cases it is interesting to know how long a tx took and if we had an RX between the start and the completion of the TX.

Copy link
Member Author

@plbossart plbossart May 4, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We can't continue with all logs enabled @ujfalusi, it's not sustainable for production CI.

We would still see if an RX IPC happened between the start of the TX IPC and the RX IPC error.

We could add a flag to make the success printed optionally if that helps.

Copy link
Collaborator

@ujfalusi ujfalusi May 5, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sure, but this is also the case when the verbose printing is enabled in kernel config.
Dropping the success message is fine I think. No message == all is good.

if (sof_debug_check_flag(SOF_DBG_PRINT_IPC_SUCCESS_LOGS))
ipc3_log_header(sdev->dev, "ipc tx succeeded", hdr->cmd);
Copy link
Collaborator

@ujfalusi ujfalusi May 6, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@plbossart, can we do the same for rx at the end of sof_ipc3_rx_msg():

	if (sof_debug_check_flag(SOF_DBG_PRINT_IPC_SUCCESS_LOGS))
		ipc3_log_header(sdev->dev, "ipc rx done", hdr.cmd);

Copy link
Member Author

@plbossart plbossart May 6, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

we can, it's just that I don't see a parallel between rx and tx.

for tx, we start the IPC and will get an error.

What happens for RX if someone the IPC handling goes south?

Copy link
Member Author

@plbossart plbossart May 9, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ujfalusi can you comment on this one? I am not sure what you are asking for.

Copy link
Collaborator

@ujfalusi ujfalusi May 11, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@plbossart, I would expect it to report an error when handling the received message, but OK, let's leave that one out for now.

if (msg->reply_size)
/* copy the data returned from DSP */
memcpy(reply_data, msg->reply_data,
Expand Down
6 changes: 6 additions & 0 deletions sound/soc/sof/sof-priv.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -37,6 +37,12 @@
#define SOF_DBG_IGNORE_D3_PERSISTENT BIT(7) /* ignore the DSP D3 persistent capability
* and always download firmware upon D3 exit
*/
#define SOF_DBG_PRINT_DMA_POSITION_UPDATE_LOGS BIT(8) /* print DMA position updates
* in dmesg logs
*/
#define SOF_DBG_PRINT_IPC_SUCCESS_LOGS BIT(9) /* print IPC success
* in dmesg logs
*/

/* Flag definitions used for controlling the DSP dump behavior */
#define SOF_DBG_DUMP_REGS BIT(0)
Expand Down