[BUG] Reported delay is increasing with each PAUSE/RESUME cycle #8985
Description
Describe the bug
During audio playback (aplay -i, mpalyer/mpv/vlc using ALSA directly) pausing/resuming the playback will cause the kernel reported delay to increase with each cycle.
To Reproduce
aplay -Dhw:0,0 -i -fdat /dev/zero # or some other non HDMI PCM.
Press to pause, press to resume and repeat.
The following kernel patch can be used to print the values:
diff --git a/sound/soc/sof/ipc4-pcm.c b/sound/soc/sof/ipc4-pcm.c
index 307bee63756b..29c6bbb86132 100644
--- a/sound/soc/sof/ipc4-pcm.c
+++ b/sound/soc/sof/ipc4-pcm.c
@@ -966,6 +975,7 @@ static int sof_ipc4_pcm_pointer(struct snd_soc_component *component,
struct snd_sof_pcm_stream *sps;
u64 dai_cnt, host_cnt, host_ptr;
struct snd_sof_pcm *spcm;
+ u64 tmp_cnt;
int ret;
spcm = snd_sof_find_spcm_dai(component, rtd);
@@ -1008,6 +1018,7 @@ static int sof_ipc4_pcm_pointer(struct snd_soc_component *component,
sof_mailbox_read(sdev, time_info->llp_offset, &llp, sizeof(llp));
dai_cnt = ((u64)llp.reading.llp_u << 32) | llp.reading.llp_l;
}
+ tmp_cnt = dai_cnt;
dai_cnt += time_info->stream_end_offset;
/* In two cases dai dma counter is not accurate
@@ -1053,10 +1064,18 @@ static int sof_ipc4_pcm_pointer(struct snd_soc_component *component,
}
if (head_cnt < tail_cnt) {
+ pr_warn("[for_report] | offset: %llu / %llu, tail_cnt: %lu (%llu), head_cnt: %lu, delay: %lu (OhNooo)\n",
+ time_info->stream_start_offset, time_info->stream_end_offset,
+ tail_cnt, tmp_cnt, head_cnt,
+ substream->runtime->boundary - tail_cnt + head_cnt);
time_info->delay = time_info->boundary - tail_cnt + head_cnt;
goto out;
}
+ pr_warn("[for_report] | offset: %llu / %llu, tail_cnt: %lu (%llu), head_cnt: %lu, delay: %lu\n",
+ time_info->stream_start_offset, time_info->stream_end_offset,
+ tail_cnt, tmp_cnt, head_cnt, head_cnt - tail_cnt);
+
time_info->delay = head_cnt - tail_cnt;
out:
@@ -1067,6 +1086,7 @@ static int sof_ipc4_pcm_pointer(struct snd_soc_component *component,
div64_u64_rem(host_ptr, snd_pcm_lib_buffer_bytes(substream), &host_ptr);
*pointer = bytes_to_frames(substream->runtime, host_ptr);
+ pr_warn("[for_report] | ldp pointer: %lu\n", *pointer);
return 0;
}Reproduction Rate
10/10
Expected behavior
The delay value remains stationary and not increasing to infinity over time.
Impact
Applications usi PAUSE/RESUME and also using the pcm delay for A/V sync will misbehave due to the drift in the delay reporting.
CRAS, Pulseaudio, PipeWire is not affected as they don't use the ALSA pause/resume.
Environment
- Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
- Kernel: topic/sof-dev
- SOF: HEAD + copier: Use correct multiplier for latency to bytes calculation #8972 w/o the PR the delay will increase much, much faster
- Name of the topology file
- Topology: any
- Name of the platform(s) on which the bug is observed.
- Platform: TGL/MTL/LNL
Screenshots or console output
logs collected with sof-hda-generic topology, playback on hw:0,0
On stream start the reported delay:
kernel: offset: 156 / 0, tail_cnt: 71 (227), head_cnt: 192, delay: 121
After ~20 iteration (with #8972 applied):
kernel: offset: 3924 / 1365876, tail_cnt: 1362029 (77), head_cnt: 1364064, delay: 2035
Possible reason
copier_comp_trigger() is used to calculate the new stream_start_offset and stream_end_offset for the host side to use for the calculation.
The code uses the comp_position() of the dai copier and a calculated latency to provide new set of offsets.
It looks like that the dai pipeline latency is taken into account twice (based on the diff in comp_cosition() and the latancy calculation).
It also apprears that over time some data gone missing in the piperlines and they report increased latencies, but interestingly this latency usually maxes out at 2 (so, two periods).