snd_pcm_delay() reporting unexpected values

[kv2019i]

While testing a new extension to alsa-conformance-test to report PCM delay values, I noticed MTL on hda-generic tplg, is reporting odd seeming values (negative delays).

Environment

kernel: 66ee247 (sof-dev)
SOF: 6c188298b958 (SOF main)
platform: MTL
topoplogy: sof-hda-generic-4ch.tplg

Expected outcome

Definition of the PCM delay in alsa-lib is as follows:

 * For playback the delay is defined as the time that a frame that is written                                                                                                                
 * to the PCM stream shortly after this call will take to be actually                                                                                                                        
 * audible. It is as such the overall latency from the write call to the final                                                                                                             

Actual outcome

Negative values reported even if no underrun/overrun condition is seen on the stream. It seems the link position is ahead of the host position, which can't be correct for playback.

Ways to test

• kernel RD patch kv2019i@8febce4
• or use alsa_conformance_test in debug mode and take code from branch https://github.com/kv2019i/cros-audiotest/tree/topic/pcm-delay-debug (UPDATE 22nd Jan: added one patch to the branch to print out calculated delay-corrected playback position to debug output)

Example error

aplay -Dhw:0,0 -traw -fdat /dev/zero

Output from the kernel RD patch:

[ 2106.387543] sof-audio-pci-intel-mtl 0000:00:1f.3: pcm_delay: d=4611686018427387542, tmp=362, pos=1052, hw_ptr=0, start=690,llp=0
[ 2106.468925] sof-audio-pci-intel-mtl 0000:00:1f.3: pcm_delay: d=4611686018427383829, tmp=4267, pos=4958, hw_ptr=192, start=690,llp=0
[ 2106.469404] sof-audio-pci-intel-mtl 0000:00:1f.3: pcm_delay: d=4611686018427387742, tmp=4290, pos=4981, hw_ptr=4128, start=690,llp=0
[ 2106.553960] sof-audio-pci-intel-mtl 0000:00:1f.3: pcm_delay: d=4611686018427383683, tmp=8349, pos=9039, hw_ptr=4128, start=690,llp=0
[ 2106.554421] sof-audio-pci-intel-mtl 0000:00:1f.3: pcm_delay: d=4611686018427387741, tmp=8371, pos=9062, hw_ptr=8208, start=690,llp=0
[ 2106.638929] sof-audio-pci-intel-mtl 0000:00:1f.3: pcm_delay: d=4611686018427383684, tmp=12428, pos=13118, hw_ptr=8208, start=690,llp=0

Output from alsa_conformance_test ("alsa_conformance_test -Phw:0,0 --debug")

TIME_DIFF(s)    HW_LEVEL     PLAYED       DIFF               RATE      DELAY
0.000037840          288        192        192     5073995.771670 4611686018427388022
0.000080551          240        240         48      595895.767899 4611686018427388018
0.000994502          432        288         48       48265.362966 4611686018427388210
0.001015976          384        336         48       47245.210517 4611686018427388162
0.000983345          336        384         48       48812.980185 4611686018427388114

[kv2019i]

@RanderWang Can you check? Anythinig I'm missing in the test procedure?

[RanderWang]

I am working on it. The reason is related to both fw and kerne driver. We change driver logic : send ipc start first or start host dma first

[RanderWang]

[83694.972961] snd_sof 0000:00:1f.3: ipc tx 0x13000004|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
[83694.993852] snd_sof 0000:00:1f.3: ipc tx reply: 0x33000000|0x1: GLB_SET_PIPELINE_STATE
[83694.993886] snd_sof 0000:00:1f.3: ipc tx done : 0x13000004|0x1: GLB_SET_PIPELINE_STATE [data size: 12]
[83694.993899] Message payload: 00000000: 00000002 00000001 00000000
[83694.993907] sof-audio-pci-intel-mtl 0000:00:1f.3: +++++++ stream start +++++++

[83694.984310] copier: copier_comp_trigger: comp:0 0x4 copier_comp_trigger() cmd 7
[83694.984341] copier: copier_comp_trigger: comp:0 0x4 copier_comp_trigger() cmd 1
[83694.984376] copier: copier_comp_trigger: comp:0 0x4 ------- dai pos 4216, dai link 522

FW start to calculate position for HDA host dma stream at 83694.984376 for stream start msg, but HDA stream was started at 83694.993907 in host kernel, almost 10ms later, so at least 480 samples error

[plbossart]

the position in the firmware should be updated when data is received, not when the pipeline is started?

[RanderWang]

the position in the firmware should be updated when data is received, not when the pipeline is started?

this is for stream_start_offset which is to remove the dai link count before host stream is started like mixer case or dai pipeline is started before host pipeline. Yes, your idea is in my shop list. Current design follows REF FW

Sleep 10 MS after the stream is started in FW should be the root reason

/* wait for IPCs to complete on other cores and be nice to any LL work */
static int ipc_wait_for_compound_msg(void)
{
	int try_count = 30; /* timeout out is 30 x 10ms so 300ms for IPC */

	while (atomic_read(&msg_data.delayed_reply)) {
		k_sleep(Z_TIMEOUT_MS(10));

		if (!try_count--) {
			atomic_set(&msg_data.delayed_reply, 0);
			ipc_cmd_err(&ipc_tr, "ipc4: failed to wait schedule thread");
			return IPC4_FAILURE;
		}
	}

	return IPC4_SUCCESS;
}

[RanderWang]

Let's discuss this commit: thesofproject/sof@909a327

This commit results to a batch of host warning since host kernel is blocked to start HDA DMA

[ 4580.800270] <inf> copier: copier_comp_trigger: comp:0 0x4 copier_comp_trigger() cmd 7
[ 4580.800293] <inf> copier: copier_comp_trigger: comp:0 0x4 copier_comp_trigger() cmd 1
[ 4580.800328] <err> copier: copier_comp_trigger: comp:0 0x4 ------- dai pos 4288, dai link 527
[ 4580.800350] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
[ 4580.801273] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
[ 4580.802271] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
[ 4580.803271] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
[ 4580.804271] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
[ 4580.805271] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
[ 4580.806273] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
[ 4580.807271] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
[ 4580.808271] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
[ 4580.809253] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
[ 4580.810258] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
[ 4580.811248] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192

[ujfalusi]

@kv2019i, @RanderWang, can you try this patch:
0001-ASoC-SOF-ipc4-pcm-Correct-delay-reporting.patch.txt

[RanderWang]

@kv2019i, @RanderWang, can you try this patch: 0001-ASoC-SOF-ipc4-pcm-Correct-delay-reporting.patch.txt

I added comments in your commit. The issue is a little tricky, we need to refine both kernel and FW.

[RanderWang]

is https://github.com/thesofproject/linux/blob/topic/sof-dev/sound/soc/sof/intel/hda-stream.c#L1078 correct ?
In my opinion it should be

	if (pos >= hstream->bufsize)
		pos = 0;   // pos -= hstream->bufsize; ?		

[RanderWang]

is https://github.com/thesofproject/linux/blob/topic/sof-dev/sound/soc/sof/intel/hda-stream.c#L1078 correct ? In my opinion it should be

	if (pos >= hstream->bufsize)
		pos = 0;   // pos -= hstream->bufsize; ?		

I add some log and find that pos <= hstream->bufsize, never > hstream->bufsize, so no problem

[ujfalusi]

@RanderWang, it surely looks like that we have different units, the stream_start_offset do appear to be set in bytes by the firmware.
The hw_ptr is supposed to be in frames and if I read the HDA documentation the PPLCLLPL/U is is in bytes?
That might be the issue? We need to convert the link position to frames?

[RanderWang]

@RanderWang, it surely looks like that we have different units, the stream_start_offset do appear to be set in bytes by the firmware. The hw_ptr is supposed to be in frames and if I read the HDA documentation the PPLCLLPL/U is is in bytes? That might be the issue? We need to convert the link position to frames?

PPLCLLPL/U is in frame, I checked the log. Thanks very much!

[ujfalusi]

PPLCLLPL/U is incremented by the value written to DGLLPI, no?
Afaik in the zephyr API the size/len is in bytes and that is what written to DGLLPI.
Furthermore the PPLCLLPL/U is updated only when DGLLPI is written

There is something also odd about the (host) DMA position reporting. We are reading and returning the value of DPIB value in hda_dsp_stream_get_position(), but according to the documentation the DPIB is in bytes and not in frames?

[plbossart]

Yeah, the code is pretty confusing. The DPIB is in bytes but gets converted to frames for PCM (and remains bytes for the compressed position)

We should avoid using 'pos' as a snd_pcm_uframe_t and a u64 with this sort of code:

	pos = hda_dsp_stream_get_position(hstream, substream->stream, true);
found:
	pos = bytes_to_frames(substream->runtime, pos);

hda_dsp_compr_bytes_transferred(struct hdac_stream *hstream, int direction)
{
	u64 buffer_size = hstream->bufsize;
	u64 prev_pos, pos, num_bytes;

	div64_u64_rem(hstream->curr_pos, buffer_size, &prev_pos);
	pos = hda_dsp_stream_get_position(hstream, direction, false);

	if (pos < prev_pos)
		num_bytes = (buffer_size - prev_pos) +  pos;
	else
		num_bytes = pos - prev_pos;

	hstream->curr_pos += num_bytes;
}

a patch would certainly improve the code hint hint wink wink.

[RanderWang]

PPLCLLPL/U is incremented by the value written to DGLLPI, no?

PPLCLLPL/U are meant to be coupled with the GP DMA for tracking the linear link position associated with the DMA channel, so it has nothing to do with DGLLPI which is for hda dma

[kv2019i]

@RanderWang I can confirm thesofproject/sof#8756 makes the reporting values sane again:

TIME_DIFF(s)    HW_LEVEL     PLAYED       DIFF               RATE      DELAY
...
0.000994900          432       1728         48       48246.054880        652
0.000997481          384       1776         48       48121.217346        604
0.001005253          336       1824         48       47749.173591        556

This doesn't yet tell how accurate the delay estimate is, but at least the values look reasonable now. I'll add some more options to the debug tool to analyze the delay behaviour.

[kv2019i]

The alsa-conformance-tool branch at https://github.com/kv2019i/cros-audiotest/tree/topic/pcm-delay-debug has been updated with one more patch to add delay-corrected playback position to debug output. With @RanderWang you fix to FW side (thesofproject/sof#8756), result now looks like (two columns on the right, PLAYED_ADJ and DIFF):

--cut--
TIME_DIFF(s)    HW_LEVEL     PLAYED       DIFF               RATE      DELAY PLAYED_ADJ       DIFF
0.000036242          240        240        240     6622151.095414        506        -26        -26
0.000449354          432        288         48      106820.012729        699         21         47
0.000993288          384        336         48       48324.353058        651         69         48
0.000993165          336        384         48       48330.337859        603        117         48
0.001010638          288        432         48       47494.750841        555        165         48
0.001002244          240        480         48       47892.529165        507        213         48
0.000985767          432        528         48       48693.048154        698        262         49
0.001007981          384        576         48       47619.945217        651        309         47
0.000992656          336        624         48       48355.120001        603        357         48
0.001011655          288        672         48       47447.005155        555        405         48
0.000994731          240        720         48       48254.251652        507        453         48
0.001001403          432        768         48       47932.750351        699        501         48
0.000998029          384        816         48       48094.794841        651        549         48
0.000995340          336        864         48       48224.727229        603        597         48
0.000994432          288        912         48       48268.760458        555        645         48
0.001005210          240        960         48       47751.216164        507        693         48
0.001006761          432       1008         48       47677.651399        698        742         49
0.000996094          384       1056         48       48188.223200        651        789         47
--cut--

[RanderWang]

The alsa-conformance-tool branch at https://github.com/kv2019i/cros-audiotest/tree/topic/pcm-delay-debug has been updated with one more patch to add delay-corrected playback position to debug output. With @RanderWang you fix to FW side (thesofproject/sof#8756), result now looks like (two columns on the right, PLAYED_ADJ and DIFF):

--cut--
TIME_DIFF(s)    HW_LEVEL     PLAYED       DIFF               RATE      DELAY PLAYED_ADJ       DIFF
0.000036242          240        240        240     6622151.095414        506        -26        -26
0.000449354          432        288         48      106820.012729        699         21         47
0.000993288          384        336         48       48324.353058        651         69         48
0.000993165          336        384         48       48330.337859        603        117         48
0.001010638          288        432         48       47494.750841        555        165         48
0.001002244          240        480         48       47892.529165        507        213         48
0.000985767          432        528         48       48693.048154        698        262         49
0.001007981          384        576         48       47619.945217        651        309         47
0.000992656          336        624         48       48355.120001        603        357         48
0.001011655          288        672         48       47447.005155        555        405         48
0.000994731          240        720         48       48254.251652        507        453         48
0.001001403          432        768         48       47932.750351        699        501         48
0.000998029          384        816         48       48094.794841        651        549         48
0.000995340          336        864         48       48224.727229        603        597         48
0.000994432          288        912         48       48268.760458        555        645         48
0.001005210          240        960         48       47751.216164        507        693         48
0.001006761          432       1008         48       47677.651399        698        742         49
0.000996094          384       1056         48       48188.223200        651        789         47
--cut--

@kv2019i thanks ! I can't understand PLAYED_ADJ and DIFF, what are they ? And what's the correct data ?

[RanderWang]

I download the conformance test and debug it.

[kv2019i]

@RanderWang And just to clarify, the results look good with your fix. The PLAYED_ADJ is the actual playback position (appl_ptr - delay), and the DIFF is the difference between two updates. In correct operation, the DIFF should match the time difference recorded in the first column. So when host see time advance by 1ms, the actual playback should advance by 1ms.

One example line:

TIME_DIFF(s)    HW_LEVEL     PLAYED       DIFF               RATE      DELAY PLAYED_ADJ       DIFF
 0.001005210          240        960         48       47751.216164        507        693         48

So the hw_ptr moves by 48 samples (=1ms) and as measured by host system clock, this happened 0.001005210sec since last update (so roughly equals 1ms). The PLAYED field shows that 960 samples has been transferred to the DSP. Using the delay reported by SOF driver, we can now calculate that the actual sample played out to the codec at this point is 693, so there is 960-693=267 delay caused by DSP internal pipelines and link DMA buffering.

What this test cannot validate is whether the 267 sample delay is accurate, this we have to test with other means, but at least we can check the updates are roughly correct and e.g. the PLAYED_ADJ progresses as expected. Specifically, due to DMA bursts, hw-ptr can advance much faster than real-time, but the PLAYED_ADJ should stay stable even during bursts.

[ujfalusi]

My findings so far:

• I can get pretty neat delay reporting by using PPHCLDPL/U for the host DMA position
• but we have some bugs on kernel and in firmware:
• pause/resume or underrun recovery:
  • will shoot the delay upwards (kernel not updating the recalculated start offset)
  • if we take the updated start offset then it will cause the tail overtake the head

Furthermore: I don't get the logic to pause/resume:
pause: stop host first, link last
resume: start link first, host last

I start to think that we should disable the reporting either by setting the fw register area's ABI version to 0 (ipc4_abi_ver_offset) or to unconditionally set teh stream_start_offset to (uint64_t)-1 to mark it invalid.

[plbossart]

• I can get pretty neat delay reporting by using PPHCLDPL/U for the host DMA position

Not following. The delay is the difference between the DPIB position for the host DMA and the hardware counters on the link DMA. Why would we care about the "PPHCLDPL/U for the host DMA" ?

[ujfalusi]

• I can get pretty neat delay reporting by using PPHCLDPL/U for the host DMA position

Not following. The delay is the difference between the DPIB position for the host DMA and the hardware counters on the link DMA. Why would we care about the "PPHCLDPL/U for the host DMA" ?

PPHCLDPL/U is the host DMA position - it is the Linear DMA Position, the same counter as LLP (Linear Link Position), just on the other side of the DSP.
DBIP is moving within the ALSA buffer, LDP is counting the bytes without wrapping at buffer size.

[plbossart]

If you report the hw_ptr using DPIB and the delay with another register, you are asking for trouble...

[ujfalusi]

imho, we would use the correct tool for the task.
DPIB is the DMA pointer within the buffer (byte pointer) -> hw_ptr
LDP is the number of bytes transferred between the host and DSP -> it is like LLP which is used for the link side

The delay is after all: LDP-(LLP+start_offset), iow, the number of frames sent to DSP minus the number of frames left the DSP (on playback)
If the delay in the DSP is longer than the ALSA buffer then the DPIB is unusable for tracking anything, the ALSA buffer itself has nothing to do with the delay, it is just by accident in some case can be used as a substitute, but it does not make it correct.

[plbossart]

the ALSA buffer cannot be smaller than the DSP buffer, it would make no sense to do so powerwise...

And while the logic of keeping symmetry between host and link makes sense at a high level, it also adds an open: how do we know if the LDP and DPIB report the same thing? It's possible that they do, but it's also possible that they don't. On some platforms the DPIB stuff is problematic. Where I am going is that we have to be consistent and report the number of bytes read with the SAME mechanism for hw_ptr and delay. Using separate registers adds an uncertainty on how the hardware actually works.

[ujfalusi]

@plbossart, the delay has nothing to do with the DSP buffer. Well it has in some degree.
Let's say we have 5 components in path in the DSP, each component takes 1ms delay, so the DSP processing adds 5ms delay
if the buffer is 100ms, then the maximum delay is 105ms, minimum delay is 5ms
if the buffer is 5ms, then the maximum delay is 10ms and the minimum is 5ms

How can we use DPIB to report in the 5ms buffer case 8ms delay when we wrap with the buffer size? We cannot.

The pause/resume and underrun makes this whole delay reporting defunct in the first place, so it should be disabled for now, it is unreliable no matter what method we are using to track the host ptr.

The firmware uses 'unrelated' dai_posn in the start offset calculation and ignores the comp_posn, which is the LLP.
If the start offset is based on a close enough guess and then we start guessing on top of it with an about right value: the whole thing will blow up.

[plbossart]

If the ALSA buffer is based on 5ms, it means you care about the latency, and adding an additional 5ms in the DSP processing is just plain silly. It makes no sense to add more wake-ups on the host for a given DSP latency, or more buffers on the DSP for a given host latency.

The DPIB is converted anyways to a linear value when it wraps around.

[ujfalusi]

If the ALSA buffer is based on 5ms, it means you care about the latency, and adding an additional 5ms in the DSP processing is just plain silly. It makes no sense to add more wake-ups on the host for a given DSP latency, or more buffers on the DSP for a given host latency.

How does PA/PW knows the number of components in the DSP for a given PCM? It is possible that the next tplg version will include more things or less for the same path.

The DPIB is converted anyways to a linear value when it wraps around.

I'm fine using the DPIB as proposed by #4791 but you have objected that solution. It is a good indirect approximation.
For me it looks like to this:
we have access to the linear position on the link side (LLP), let's use it.
we have access to the linear position on the host side (LDP), let's use the DPIB pointer which wraps in the ALSA buffer and wrap the LLP with the same buffer size to bring them to the same narrow range.

Yes, we have code for DPIB, it does some calculation and stuff. The way the hw_ptr is calculated is a bit hairy for me, it is not hw_ptr+=pointer (snd_pcm_update_hw_ptr0()) ;)

imho, the ALSA buffer size has no direct relation to the delay. The delay is the number of frames entered to the DSP minus what left it.

The other burning issue is the whole uncertainty of what and how many the link transfers around start, pause, resume.
On start it is going to send out dummy frames until the first real audio (SOF) period arrives.
On pause we stop the host first then the link, not sure how that works, will that leave a 'bubble' in the processing pipeline?
On resume we start the link first then the host, what if that 'bubble' reaches the link before the host starts and can burst it?
Is it always guarantied that the host will stop at (SOF) period boundary and not at arbitrary position?

I can try to run few DPIB vs LDP tests to see how they compare, but as soon as you start to do pause/resume or underrun (mpv does that even w/o the delay reporting) the whole delay shoots out in some direction and become unusable.

[plbossart]

I'm fine using the DPIB as proposed by #4791 but you have objected that solution.

I only asked a question on how the change from boundary to buffer_size work-around would work. I don't know the answer, I just found this was a controversial move without any justification/explanations.

The delay is the number of frames entered to the DSP minus what left it.

Not really, it's the difference between the hw_ptr and the link position. If there is no DSP, we can still compute the delay as LPIB-DPIB. That was true 10 years ago before all the SKL+ changes.

That said, I asked precisions on how DPIB and LDP values are related. I am not trying to block for the sake of blocking, just making sure we're not adding more issues into an already complicated mix.

[ujfalusi]

@plbossart, on the other hand there is another side of complication with using LDP which just occurred to me:
LLP is in frames
LDP is in bytes
LDP will wrap multiple times before LLP would (4x in case of S16_LE for example). Yes, it is u64, it will take some time but has to be handled by wrapping the LLP to hold equal maximum number of frames.

Let me see the DPIB (#4791) in action.

[plbossart]

This problem is generic to all IPC4 platforms, not just MTL