[BUG][BDW] Stutter on bdw-rt5677 output

Describe the bug
All pulseaudio sound output stutters until any alsa utility or plugin is used with -Dhw:.... The stream sounds 50% interlaced with null at ~10hz. The stutter is corrected for any pulseaudio output that starts after any use of alsa (aplay, arec, audacity plugins...) with -Dhw: exits.

The stutter is present if and only if SND_SOC_SOF_DEBUG_ENABLE_FIRMWARE_TRACE=n in the kernel, which makes debugging interesting. This could also be a driver bug.

To Reproduce

pulseaudio --start
pacat </dev/urandom #(or anything)

Reproduction Rate
100%

Expected behavior
Clear audio output

Impact
Very annoying with only pulseaudio, irrelevant on alsa.

Environment
All FW, tplg, and kernel modules built-in.

Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
- Kernel: torvalds/linux@22fbc03, sof-dev (thesofproject/linux@53b27a2), sof-dev-rebase (thesofproject/linux@ecda593)
- SOF: 1.5.1 (88707ca), master (878f15b)
Name of the topology file
- Topology: sof-bdw-rt5677.tplg
Name of the platform(s) on which the bug is observed.
- Platform: bdw-rt5677

Screenshots or console output
All logs are identical, with the exception of FW logs, which cannot be produced (see above).

Pragmatic note: bdw-rt5677 is a rare platform, and the workaround of setting SND_SOC_SOF_DEBUG_ENABLE_FIRMWARE_TRACE=y is very easy, so this may not deserve any kind of priority.

Could be 2 things

DMA position reporting latency where HW pointer being used by PA is too old (if HW pointer is being transfered via IPC rather than read from DSP memory directly). Should default to memory readback.
PA is writting to same period that DW DMA is reading. This can cause races with HW vs SW IO. Trace may change the timing here and make it work.

It does sound like PA is writting too close (or beyond) the HW pointer due to either 1 or 2.

@caseorum

@caseorum I've heard somewhat random noises at times but I have never been able to point to a specific root cause. I am also confused by the description "All sound output stutters until any alsa utility or plugin is used". PulseAudio will typically idle after 5s and close the streams, so is the problem happening on startup only when PulseAudio is first started?

Also what do you mean by 'alsa utility'. Alsa utils can use the :hw device, or the :pulse device. Do you mean to say that the sound is good only when PulseAudio is NOT used?

@plbossart

@plbossart Yes, I mean all pulseaudio output stutters until after anything from alsa closes -Dhw:.... -Dpulse stutters. I'll edit to clarify. PA's stream idle/wake changes nothing.

@lgirdwood

@lgirdwood That sounds right. This bug is with the low-latency pipeline, and using the media playback pipeline yields the same blip of silence separated by a longer interval of audio. That might be race-condition weirdness, because their buffers have similar size.

@caseorum

@caseorum don't use the media pipeline, it was never tested and likely is broken.
I still don't get the sequence that makes things work.

@plbossart

@plbossart You're right, the media pipeline fails spectacularly after several seconds, but that looks unrelated. Are you trying to reproduce this? How can I help? PA saves and restores device state, so that database could be affecting what you see on boot. Or maybe systemd, udev, or alsa are storing some kind of persistent state? I boot every time with a fresh install of PA with only default configs and no state from previous boots.

@caseorum

@caseorum the quickest thing to test is to get PA to render further back from the HW ptr. There may be a PA alsa-sink-module or alsa-source-module config setting for this.
The topology could also be updated to specify a larger minimum period size and buffer size (on the host side - not the DSP pipeline buffer), alternatively PA config could be used to set buffer/period size.
Finally the DSP pipeline topology could also be updated to have 3 or more periods (instead of 2) on the pipeline "host" component. This is the component that connects to the host and does the data copying to/from host.

@lgirdwood

@lgirdwood I think PA's handling of hw_ptr isn't exposed via module parameters, and I was staying out of modifying PA itself for the time being. I did test ring buffer periods (module-alsa-card fragments). I'll get to topology changes in a bit.
PA defaults to 4 periods of 25ms:

D: [pulseaudio] alsa-util.c: Hardware PCM card 0 'sof-bdw rt5677' device 0 subdevice 0
D: [pulseaudio] alsa-util.c: Its setup is:
D: [pulseaudio] alsa-util.c:   stream       : PLAYBACK
D: [pulseaudio] alsa-util.c:   access       : MMAP_INTERLEAVED
D: [pulseaudio] alsa-util.c:   format       : S16_LE
D: [pulseaudio] alsa-util.c:   subformat    : STD
D: [pulseaudio] alsa-util.c:   channels     : 2
D: [pulseaudio] alsa-util.c:   rate         : 48000
D: [pulseaudio] alsa-util.c:   exact rate   : 48000 (48000/1)
D: [pulseaudio] alsa-util.c:   msbits       : 16
D: [pulseaudio] alsa-util.c:   buffer_size  : 4800
D: [pulseaudio] alsa-util.c:   period_size  : 1200
D: [pulseaudio] alsa-util.c:   period_time  : 25000
D: [pulseaudio] alsa-util.c:   tstamp_mode  : ENABLE
D: [pulseaudio] alsa-util.c:   tstamp_type  : MONOTONIC
D: [pulseaudio] alsa-util.c:   period_step  : 1
D: [pulseaudio] alsa-util.c:   avail_min    : 1200
D: [pulseaudio] alsa-util.c:   period_event : 1
D: [pulseaudio] alsa-util.c:   start_threshold  : -1
D: [pulseaudio] alsa-util.c:   stop_threshold   : 5404319552844595200
D: [pulseaudio] alsa-util.c:   silence_threshold: 0
D: [pulseaudio] alsa-util.c:   silence_size : 0
D: [pulseaudio] alsa-util.c:   boundary     : 5404319552844595200
D: [pulseaudio] alsa-util.c:   appl_ptr     : 0
D: [pulseaudio] alsa-util.c:   hw_ptr       : 0

(Aside: Those are special values of start_threshold, appl_ptr, and hw_ptr, right?)

Playback stutters with 4 or 5 periods, and is happy with anything else, even 2 and 3. Here's the odd behavior:
set periods = 4 => stutter
set periods != 4, 5 => clean
set periods = 4 => clean
set periods = 5 => stutter
set periods = 4 => stutter
So it behaves like a "stutter bit" that is active at boot, set by 5 periods, read by 4 periods, and cleared by all other integers.

With trace enabled, it's bugged consistently at periods 5, 7(slightly), and 10, no bit-setting behavior. So these numbers are more or less meaningless and this looks like a race condition that is sensitive to timing in the FW and the period count in the ring buffer, so presumably buffer size.
This also explains the alsa-util / pulseaudio difference. They set different ring buffers by default.

@caseorum

@caseorum I don't think we've tested with odd number of periods, I would stay away from this for now.
are you positive that with the 2 period settings things work fine, including with the trace disabled?

@caseorum

@caseorum Now that I think of it, this reminds me of thesofproject/linux#2200.
That looks like what you are experiencing. I closed it thinking it was a Debian setup issue but maybe I was on to something.

What distro are you using if I want to reproduce your findings?

@caseorum

@caseorum can you try host periods at 3 i.e.

diff --git a/tools/topology/sof/pipe-volume-playback.m4 b/tools/topology/sof/pipe-volume-playback.m4
index cb7d2ad67..0cb84464d 100644
--- a/tools/topology/sof/pipe-volume-playback.m4
+++ b/tools/topology/sof/pipe-volume-playback.m4
@@ -44,7 +44,7 @@ W_DATA(DEF_PGA_CONF, DEF_PGA_TOKENS)
 
 # Host "Passthrough Playback" PCM
 # with 2 sink and 0 source periods
-W_PCM_PLAYBACK(PCM_ID, Passthrough Playback, 2, 0, SCHEDULE_CORE)
+W_PCM_PLAYBACK(PCM_ID, Passthrough Playback, 3, 0, SCHEDULE_CORE)
 
 # "Volume" has 2 source and x sink periods
 W_PGA(0, PIPELINE_FORMAT, DAI_PERIODS, 2, DEF_PGA_CONF, SCHEDULE_CORE,

and rebuild topology.

@plbossart

I've confirmed that the ring buffer period count is irrelevant and PA isn't involved. It's just buffer size and format.

Without trace:
speaker-test -Dhw:0,0 -c2 -S5 -r48000 -FS16_LE -b 100000 -P4 # stutter for literally any value of -P !
speaker-test -Dhw:0,0 -c2 -S5 -r48000 -FS32_LE -b 100000 -P4 # horrible popping, any -P
With trace:
speaker-test -Dhw:0,0 -c2 -S5 -r48000 -FS16_LE -b 125000 -P4 # stutter, any -P
speaker-test -Dhw:0,0 -c2 -S5 -r48000 -FS32_LE -b 125000 -P4 # stutter, any -P

So I think this really is a FW/driver bug. It appears that for any system, there is a buffer size that fails.

@plbossart Yes! I've run into that in testing, but I haven't yet isolated it to make sure it's the same bug. I bet so.
This is an arch linux userspace with alsa-* built from their git HEADs, if you'd like to try it. So only the alsa-* dependencies are really from arch. But my system is userspace-agnostic, so I can try another.

@lgirdwood

can you try host periods at 3

@lgirdwood Done. No change.

@plbossart

@plbossart There's an issue with the constraints, like minimum buffer size, but I don't think that's related. The ALSA ring buffers and periods are consistently sane. I also think I've ruled out odd-size errors, since booting a pretty minimal kernel without trace (config.gz) is bugged for some extremely sane sizes (19200 bytes, 2-periods even). Because there's something stateful going on, even CI-passing configs could hit this error after some amount of use.

That sensitivity to trace is important. Either the IPC message is causing different (better, but still bad) DMA config to be set, or it's the fact that trace is also using DMA. I bet it's the latter, and that @lgirdwood is on the money with the optimized DMA stuff, so that's where I'm turning my attention.

Unfortunately I can't rule out that this isn't just broadwell, since I don't have a later chromebook to torture. It's a sneaky bug.

@plbossart

@plbossart @caseorum fwiw, the last page (where we hear the distortion) is treated differently in the page tables

/*
 * Parse the host page tables and create the audio DMA SG configuration
 * for host audio DMA buffer. This involves creating a dma_sg_elem for each
 * page table entry and adding each elem to a list in struct dma_sg_config.
 */
static int ipc_parse_page_descriptors(uint8_t *page_table,
				      struct sof_ipc_host_buffer *ring,
				      struct dma_sg_elem_array *elem_array,
				      uint32_t direction)
{
	int i;
	uint32_t idx;
	uint32_t phy_addr;
	struct dma_sg_elem *e;

	/* the ring size may be not multiple of the page size, the last
	 * page may be not full used. The used size should be in range
	 * of (ring->pages - 1, ring->pages] * PAGES.
	 */
	if ((ring->size <= HOST_PAGE_SIZE * (ring->pages - 1)) ||
	    (ring->size > HOST_PAGE_SIZE * ring->pages)) {
		/* error buffer size */
		tr_err(&ipc_tr, "ipc_parse_page_descriptors(): error buffer size");
		return -EINVAL;
	}

	elem_array->elems = rzalloc(SOF_MEM_ZONE_RUNTIME, 0, SOF_MEM_CAPS_RAM,
				    sizeof(struct dma_sg_elem) * ring->pages);
	if (!elem_array->elems) {
		tr_err(&ipc_tr, "ipc_parse_page_descriptors(): There is no heap free with this block size: %d",
		       sizeof(struct dma_sg_elem) * ring->pages);
		return -ENOMEM;
	}

	elem_array->count = ring->pages;

	for (i = 0; i < ring->pages; i++) {
		idx = (((i << 2) + i)) >> 1;
		phy_addr = page_table[idx] | (page_table[idx + 1] << 8)
				| (page_table[idx + 2] << 16);

		if (i & 0x1)
			phy_addr <<= 8;
		else
			phy_addr <<= 12;
		phy_addr &= 0xfffff000;

		e = elem_array->elems + i;

		if (direction == SOF_IPC_STREAM_PLAYBACK)
			e->src = phy_addr;
		else
			e->dest = phy_addr;

		/* the last page may be not full used */
		if (i == (ring->pages - 1))
			e->size = ring->size - HOST_PAGE_SIZE * i;
		else
			e->size = HOST_PAGE_SIZE;
	}

	return 0;
}

AFAIU this works on BYT, CHT (as they also use page tables), so I can only assume this is probably correct (but trying a buffer size of 4k multiples would prove it).

My suspicion is the DMA elem config for the buffer wrap (especially if DMA is running in speculative one shot mode). The host DMA is using the speculative "one shot" mode

static uint32_t host_dma_get_split(struct host_data *hd, uint32_t bytes)
{
	struct dma_sg_elem *local_elem = hd->config.elem_array.elems;
	uint32_t split_src = 0;
	uint32_t split_dst = 0;

	if (local_elem->src + bytes > hd->source->current_end)
		split_src = bytes -
			(hd->source->current_end - local_elem->src);

	if (local_elem->dest + bytes > hd->sink->current_end)
		split_dst = bytes -
			(hd->sink->current_end - local_elem->dest);

	/* get max split, so the current copy will be minimum */
	return MAX(split_src, split_dst);
}

/**
 * Calculates bytes to be copied in one shot mode.
 * @param dev Host component device.
 * @return Bytes to be copied.
 */
static uint32_t host_get_copy_bytes_one_shot(struct comp_dev *dev)
{
	struct host_data *hd = comp_get_drvdata(dev);
	struct dma_sg_elem *local_elem = hd->config.elem_array.elems;
	uint32_t copy_bytes = 0;
	uint32_t split_value;
	uint32_t flags = 0;

	buffer_lock(hd->local_buffer, &flags);

	/* calculate minimum size to copy */
	if (dev->direction == SOF_IPC_STREAM_PLAYBACK)
		copy_bytes = audio_stream_get_free_bytes(&hd->local_buffer->stream);
	else
		copy_bytes = audio_stream_get_avail_bytes(&hd->local_buffer->stream);

	buffer_unlock(hd->local_buffer, flags);

	/* copy_bytes should be aligned to minimum possible chunk of
	 * data to be copied by dma.
	 */
	copy_bytes = ALIGN_DOWN(copy_bytes, hd->dma_copy_align);

	split_value = host_dma_get_split(hd, copy_bytes);
	if (split_value)
		copy_bytes -= split_value;

	local_elem->size = copy_bytes;

	return copy_bytes;
}

/**
 * Performs copy operation for host component working in one shot mode.
 * It means DMA needs to be reconfigured after every transfer.
 * @param dev Host component device.
 * @return 0 if succeeded, error code otherwise.
 */
static int host_copy_one_shot(struct comp_dev *dev)
{
	struct host_data *hd = comp_get_drvdata(dev);
	uint32_t copy_bytes = 0;
	int ret = 0;

	comp_dbg(dev, "host_copy_one_shot()");

	copy_bytes = host_get_copy_bytes_one_shot(dev);
	if (!copy_bytes) {
		comp_info(dev, "host_copy_one_shot(): no bytes to copy");
		return ret;
	}

	/* reconfigure transfer */
	ret = dma_set_config(hd->chan, &hd->config);
	if (ret < 0) {
		comp_err(dev, "host_copy_one_shot(): dma_set_config() failed, ret = %u", ret);
		return ret;
	}

	ret = dma_copy(hd->chan, copy_bytes, DMA_COPY_ONE_SHOT);
	if (ret < 0) {
		comp_err(dev, "host_copy_one_shot(): dma_copy() failed, ret = %u", ret);
		return ret;
	}

	return ret;
}

This means the number of bytes copied is variable depending on free space in the destination buffer and the buffer wrap (handled in the split case above) is possible too small a transfer for the BDW DMA. It's worth adding some debug trace here and print out the copy size when it's good and bad.

@caseorum

@caseorum I'll retest on CHT, I have test devices and I am afraid we haven't done a good job at changing the configuration of the ring buffer. Murphy's Law still applies.

I can confirm this bug does not occur on BYT/CHT. I tested with all sequences that are reproducibly wrong on Broadwell and no issues at all.

Clearly the Broadwell DMA has some issues.

Right. So the thought is that this and #3503 have the same root cause, namely that the BDW DMA minimum is larger than 4k. Datasheet time.

@caseorum

@caseorum @plbossart I suspect that the smallest transfer size is limited to the channel burst size. It would be quick to try gradually small buffer (in steps of 4kB) until it fails and then workout the page table size and ultimately transfer size that breaks.

Oh, furthermore if smallest transfer size is say 16 bytes then I would further assume that all transfers must be aligned on 16 bytes for size.

@lgirdwood

@lgirdwood Got it. This does mean splitting out the logic for broadwell. Or would you restrict all of them, relatively harmlessly?
I don't dip into the audio world very often, but I vaguely remember a discussion about broadwell's odd DMA situation somewhere. Maybe kernel. I'll look.

@caseorum

@caseorum I think in the case for BDW we can set some attributes for DMA transfer size and alignment. We alreday have similar attributes so adding extra should not be too hard.

@lgirdwood

@lgirdwood @plbossart I've finally been able to look at this again today. Experimentally, the BDW minimum transfer is 4 bytes. This and #3503 are caused by the ptable DMA transfer size being too small by up to 3 bytes, so the ptable wasn't always copied in full. Are you sure this doesn't affect other ptable platforms? Maybe #3503 doesn't affect them because they have smaller minimum copies, but this error should get them all.

I've submitted a PR that works on broadwell (#3659).

@caseorum

Impressive work @caseorum.

I must admit I never understood the concept of page table, and the arithmetic used both on driver https://github.com/thesofproject/linux/blob/332d9bf12a58fe890e5ce47ce22e5af89a7699d8/sound/soc/sof/utils.c#L133 and firmware sides.

@lgirdwood and @keyonjie are probably the best people to comment on this.

@caseorum

@caseorum good work - fwiw, the Designware DMA IP has a lot of config options and it's likely on BDW the minimum transfer is 4 bytes (which may be different on other IP that uses this DMAC).

@lgirdwood

Thank you @lgirdwood and @plbossart. I'm glad I went bug hunting.

Navigation Menu

Repository navigation

[BUG][BDW] Stutter on bdw-rt5677 output #3492

31 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[BUG][BDW] Stutter on bdw-rt5677 output #3492

Description

Activity

lgirdwood commented on Oct 4, 2020

plbossart commented on Oct 5, 2020

caseorum commented on Oct 5, 2020

caseorum commented on Oct 5, 2020

plbossart commented on Oct 5, 2020

caseorum commented on Oct 5, 2020

lgirdwood commented on Oct 6, 2020

caseorum commented on Oct 6, 2020

caseorum commented on Oct 6, 2020

plbossart commented on Oct 6, 2020

plbossart commented on Oct 6, 2020

lgirdwood commented on Oct 6, 2020

caseorum commented on Oct 6, 2020

caseorum commented on Oct 6, 2020

31 remaining items

caseorum commented on Oct 8, 2020

lgirdwood commented on Oct 8, 2020

plbossart commented on Oct 8, 2020

plbossart commented on Oct 8, 2020

caseorum commented on Oct 8, 2020

lgirdwood commented on Oct 8, 2020

lgirdwood commented on Oct 8, 2020

caseorum commented on Oct 8, 2020

lgirdwood commented on Oct 8, 2020

caseorum commented on Dec 1, 2020

plbossart commented on Dec 1, 2020

lgirdwood commented on Dec 2, 2020

caseorum commented on Dec 2, 2020

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions