Skip to content

ASoC: SOF: ipc: Rate-limit IPC transmission error messages #6020

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

Open
anantxgarg wants to merge 1 commit into
base: topic/sof-dev
Choose a base branch
from
Open

ASoC: SOF: ipc: Rate-limit IPC transmission error messages #6020

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
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
6 changes: 3 additions & 3 deletions sound/soc/sof/ipc3-pcm.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -119,9 +119,9 @@ static int sof_ipc3_pcm_hw_params(struct snd_soc_component *component,
ret = sof_ipc_tx_message(sdev->ipc, &pcm, sizeof(pcm),
&ipc_params_reply, sizeof(ipc_params_reply));
if (ret < 0) {
spcm_err(spcm, substream->stream,
"STREAM_PCM_PARAMS ipc failed for stream_tag %d\n",
pcm.params.stream_tag);
spcm_err_ratelimited(spcm, substream->stream,
"STREAM_PCM_PARAMS ipc failed for stream_tag %d\n",
pcm.params.stream_tag);
return ret;
}

Expand Down
17 changes: 9 additions & 8 deletions sound/soc/sof/ipc3.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -298,17 +298,17 @@ static int ipc3_wait_tx_done(struct snd_sof_ipc *ipc, void *reply_data)
msecs_to_jiffies(sdev->ipc_timeout));

if (ret == 0) {
dev_err(sdev->dev,
"ipc tx timed out for %#x (msg/reply size: %d/%zu)\n",
hdr->cmd, hdr->size, msg->reply_size);
dev_err_ratelimited(sdev->dev,
"ipc tx timed out for %#x (msg/reply size: %d/%zu)\n",
hdr->cmd, hdr->size, msg->reply_size);
snd_sof_handle_fw_exception(ipc->sdev, "IPC timeout");
ret = -ETIMEDOUT;
} else {
ret = msg->reply_error;
if (ret < 0) {
dev_err(sdev->dev,
"ipc tx error for %#x (msg/reply size: %d/%zu): %d\n",
hdr->cmd, hdr->size, msg->reply_size, ret);
dev_err_ratelimited(sdev->dev,
"ipc tx error for %#x (msg/reply size: %d/%zu): %d\n",
hdr->cmd, hdr->size, msg->reply_size, ret);
} else {
if (sof_debug_check_flag(SOF_DBG_PRINT_IPC_SUCCESS_LOGS))
ipc3_log_header(sdev->dev, "ipc tx succeeded", hdr->cmd);
Expand Down Expand Up @@ -371,8 +371,9 @@ static int sof_ipc3_tx_msg(struct snd_sof_dev *sdev, void *msg_data, size_t msg_
/* ensure the DSP is in D0 before sending a new IPC */
ret = snd_sof_dsp_set_power_state(sdev, &target_state);
if (ret < 0) {
dev_err(sdev->dev, "%s: resuming DSP failed: %d\n",
__func__, ret);
dev_err_ratelimited(sdev->dev,
"%s: resuming DSP failed: %d\n",
__func__, ret);
return ret;
}
}
Expand Down
8 changes: 4 additions & 4 deletions sound/soc/sof/ipc4.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -412,15 +412,15 @@ static int ipc4_wait_tx_done(struct snd_sof_ipc *ipc, void *reply_data)
ret = wait_event_timeout(msg->waitq, msg->ipc_complete,
msecs_to_jiffies(sdev->ipc_timeout));
if (ret == 0) {
dev_err(sdev->dev, "ipc timed out for %#x|%#x\n",
ipc4_msg->primary, ipc4_msg->extension);
dev_err_ratelimited(sdev->dev, "ipc timed out for %#x|%#x\n",
ipc4_msg->primary, ipc4_msg->extension);
snd_sof_handle_fw_exception(ipc->sdev, "IPC timeout");
return -ETIMEDOUT;
}

if (msg->reply_error) {
dev_err(sdev->dev, "ipc error for msg %#x|%#x\n",
ipc4_msg->primary, ipc4_msg->extension);
dev_err_ratelimited(sdev->dev, "ipc error for msg %#x|%#x\n",
ipc4_msg->primary, ipc4_msg->extension);
ret = msg->reply_error;
} else {
if (reply_data) {
Expand Down
4 changes: 2 additions & 2 deletions sound/soc/sof/pcm.c
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -351,8 +351,8 @@ static int sof_pcm_prepare(struct snd_soc_component *component,

ret = sof_pcm_hw_params(component, substream, &spcm->params[substream->stream]);
if (ret < 0) {
spcm_err(spcm, substream->stream,
"failed to set hw_params after resume\n");
spcm_err_ratelimited(spcm, substream->stream,
"failed to set hw_params after resume\n");

@ujfalusi ujfalusi Nov 4, 2026

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

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

ASoC still going to fill up the kernel log even if we rate limit.

You can still reproduce the issue with recent kernel and user space?

checkpatch reports several issues, the commit message is misaligned and if possible also align the parameters as well.

@anantxgarg anantxgarg Nov 4, 2026 •
edited
Loading

Copy link
Copy Markdown
Author

Choose a reason for hiding this comment

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

Wrapping fixed.
The issue occurred on kernel 6.8.0-147-generic, PipeWire 1.0.5 where in from what i could determine, after waking up from suspend the the DSP failed the resume handshake which led to STREAM_PCM_PARAMS returning -EINVAL. Pipewire then repeatedly retried snd_pcm_prepare() which produced around 26 GB of log files within a few hours. I havent yet tried to recreate it on newer kernels.

ASoC is still going to fill it up even if we ratelimit in sof, however it would lead to a 75% reduction in error messages. It seems to me a worthwhile change to make.
Further changes upstream to ASoC core will be required to address that issue in particular.

return ret;
}

Expand Down
6 changes: 6 additions & 0 deletions sound/soc/sof/sof-audio.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -668,6 +668,12 @@ struct snd_sof_widget *snd_sof_find_swidget_by_comp_id(struct snd_sof_dev *sdev,
(__spcm)->pcm.pcm_name, __dir, \
##__VA_ARGS__)

#define spcm_err_ratelimited(__spcm, __dir, __fmt, ...) \
dev_err_ratelimited((__spcm)->scomp->dev, "%s: pcm%u (%s), dir %d: " __fmt, \
__func__, le32_to_cpu((__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);
Expand Down
Loading