[BUG] Underflows and errors with sof-test/test-case/multiple-pause-resume.sh

@lgirdwood

Describe the bug

The multi-pause-resume test has not worked in a very long time, and recent changes to the DW DMA make it worse:

export TPLG=/lib/firmware/intel/sof-tplg/sof-apl-pcm512x.tplg
sof-test/test-case/multiple-pause-resume.sh --min 1000 --max 2000

with tag releases/tgl/v7.0-rc1

[146419386.718750] (     1985.520874) c0 dw-dma                 src/drivers/dw/dma.c:1056 ERROR dw_dma_get_data_size(): xrun detected
[146419390.156250] (        3.437500) c0 dai          6.39           src/audio/dai.c:653  ERROR dai_report_xrun(): overrun due to no data available
[146419392.916667] (        2.760417) c0 dai          6.39           src/audio/dai.c:694  ERROR comp_overrun(): sink->free = 768, copy_bytes = 0

[  146.922720] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[  146.922930] sof-audio-pci 0000:00:0e.0: error: ipc error for 0x60050000 size 12
[  146.922949] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x240000 successful
[  146.922958] sof-audio-pci 0000:00:0e.0: ASoC: error at snd_soc_pcm_component_trigger on 0000:00:0e.0: -22
[  146.922966]  Port5: ASoC: trigger FE cmd: 0 failed: -22

with SOF master 1c53b8e

no dmesg issue, but repeated error messages in sof-logger:

(1/3) pcm'Port5' cmd'aplay' id'0': Wait for 1891 ms before resume
#+                                                 | 00%arecord: pcm_read:2149: read error: Input/output error
(2/3) pcm'DMIC' cmd'arecord' id'5': Wait for 1967 ms before pause
#+                                                 | 00%aplay: pcm_write:2057: write error: Input/output error
(2/3) pcm'Port5' cmd'aplay' id'0': Wait for 1416 ms before pause
 

[ 51026583.229167] (        2.968750) c0 dmic-dai     2.0   src/drivers/intel/dmic.c:1537 ERROR dmic_irq_handler(): full fifo A or PDM overrun
[ 51026586.927083] (        3.697917) c0 dmic-dai     2.1   src/drivers/intel/dmic.c:1533 dmic_irq_handler(), OUTSTAT0 = 536870912
[ 51026589.947917] (        3.020833) c0 dmic-dai     2.1   src/drivers/intel/dmic.c:1534 dmic_irq_handler(), OUTSTAT1 = 2147483648
[ 51026602.552083] (       12.604167) c0 dmic-dai     2.0   src/drivers/intel/dmic.c:1533 dmic_irq_handler(), OUTSTAT0 = 671088640
[ 51026605.989583] (        3.437500) c0 dmic-dai     2.0   src/drivers/intel/dmic.c:1534 dmic_irq_handler(), OUTSTAT1 = 2147483648

reverting 61a2c75 ('dma: dw: fix locking and calculations in dw_dma_get_data_size') goes back to the initial behavior, IPC error but no dmic_irq_handler issues.

Clearly there's something not working for these dmic paths. @lgirdwood @singalsu FYI.

To Reproduce

use command line and commits above

Reproduction Rate
100%

Expected behavior
No errors, d'uh.

Impact
Prevents CI tests from working reliably.

Environment

Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
- Kernel: b31892bc2404c4ecc59d863a1d5cadba6740be5b
- SOF: see above
Name of the topology file
- Topology: export TPLG=/lib/firmware/intel/sof-tplg/sof-apl-pcm512x.tplg
Name of the platform(s) on which the bug is observed.
- Platform: APL w/ PCM512x

@plbossart

@plbossart Reproduced on apl_up2_pcm512x. I think we may need to enable the xrun recovery feature? Now I think we just simply stop the stream.

I also captured an alsabat failure on sh-cml-hel-rt5682-01, trace log shows that it's related to XRUN:
http://sof-tcr.sh.intel.com/#/tests/3bc51155-084a-4d27-8280-698d9fc37058/detail


    0      2          SSP         736360670.000000         4.322917 ers/intel/cavs/ssp.c:877 	ssp_trigger() cmd 1
    0      2          SSP         736360702.187500        32.187500 ers/intel/cavs/ssp.c:806 	ssp_start()
    0      2  SCHEDULE_LL         736360765.677083        63.489582 edule/timer_domain.c:47  	timer_domain_register()
    0      1          DMA         736362013.802083      1248.125000 src/drivers/dw/dma.c:1078	dw_dma_get_data_size() error: xrun detected
    0      1          DAI 1.4     736362020.781250         6.979167      src/audio/dai.c:603 	dai_report_xrun() error: underrun due to no data available
    0      1         COMP 1.4     736362026.562500         5.781250      src/audio/dai.c:760 	comp_underrun() error: dev->comp.id = 4, source->avail = 128, copy_bytes = 0
    0      2         PIPE 1.5     736362033.697917         7.135417 src/audio/pipeline.c:664 	pipeline_trigger()

@plbossart

@plbossart Reproduced on apl_up2_pcm512x. I think we may need to enable the xrun recovery feature? Now I think we just simply stop the stream.

Sorry @xiulipan I don't get your point. If we are using aplay/arecord for this tests, then the xrun recovery should already be functional at the userspace level.

@keqiaozhang

I also captured an alsabat failure on sh-cml-hel-rt5682-01, trace log shows that it's related to XRUN:
http://sof-tcr.sh.intel.com/#/tests/3bc51155-084a-4d27-8280-698d9fc37058/detail


    0      2          SSP         736360670.000000         4.322917 ers/intel/cavs/ssp.c:877 	ssp_trigger() cmd 1
    0      2          SSP         736360702.187500        32.187500 ers/intel/cavs/ssp.c:806 	ssp_start()
    0      2  SCHEDULE_LL         736360765.677083        63.489582 edule/timer_domain.c:47  	timer_domain_register()
    0      1          DMA         736362013.802083      1248.125000 src/drivers/dw/dma.c:1078	dw_dma_get_data_size() error: xrun detected
    0      1          DAI 1.4     736362020.781250         6.979167      src/audio/dai.c:603 	dai_report_xrun() error: underrun due to no data available
    0      1         COMP 1.4     736362026.562500         5.781250      src/audio/dai.c:760 	comp_underrun() error: dev->comp.id = 4, source->avail = 128, copy_bytes = 0
    0      2         PIPE 1.5     736362033.697917         7.135417 src/audio/pipeline.c:664 	pipeline_trigger()

that looks like a different class of problem @keqiaozhang. alsa-bat should be just using the headphone output, so if we have xruns with just one stream in normal playback it's really something else. Can you file a separate bug please?

@lyakh

So 61a2c75 changes behaviour in that both free & avail are updated regardless of direction which is a bug in the function. I suspect the caller's usage is also incorrect.

1cdff03 also fixes a race which was a problem on Zephyr and may also be a problem here.

@lyakh can you take a look at this. The DW DMA position update logic is problematic i.e. the 2 data_size functions below are DAI specific and we really need a func for each DMA_DIR type

/* capture */
static int dw_dma_avail_data_size(struct dma_chan_data *channel)
{
	struct dw_dma_chan_data *dw_chan = dma_chan_get_data(channel);
	int32_t read_ptr = dw_chan->ptr_data.current_ptr;
	int32_t write_ptr = dma_reg_read(channel->dma, DW_DAR(channel->index)); 
	int size;

	size = write_ptr - read_ptr;
	if (size < 0)
		size += dw_chan->ptr_data.buffer_bytes;

	if (!size)
		tr_info(&dwdma_tr, "dw_dma_avail_data_size() size is 0!");

	tr_dbg(&dwdma_tr, "DAR %x reader 0x%x free 0x%x avail 0x%x", write_ptr,
	       read_ptr, dw_chan->ptr_data.buffer_bytes - size, size);

	return size;
}

/* playback */
static int dw_dma_free_data_size(struct dma_chan_data *channel)
{
	struct dw_dma_chan_data *dw_chan = dma_chan_get_data(channel);
	int32_t read_ptr = dma_reg_read(channel->dma, DW_SAR(channel->index));
	int32_t write_ptr = dw_chan->ptr_data.current_ptr;
	int size;

	size = read_ptr - write_ptr;
	if (size < 0)
		size += dw_chan->ptr_data.buffer_bytes;

	if (!size)
		tr_info(&dwdma_tr, "dw_dma_free_data_size() size is 0!");

	tr_dbg(&dwdma_tr, "SAR %x writer 0x%x free 0x%x avail 0x%x", read_ptr,
	       write_ptr, size, dw_chan->ptr_data.buffer_bytes - size);

	return size;
}

static int dw_dma_get_data_size(struct dma_chan_data *channel,
				uint32_t *avail, uint32_t *free)
{
	struct dw_dma_chan_data *dw_chan = dma_chan_get_data(channel);
	uint32_t flags;
	int ret = 0;

	tr_dbg(&dwdma_tr, "dw_dma_get_data_size(): dma %d channel %d get data size",
	       channel->dma->plat_data.id, channel->index);

	irq_local_disable(flags);

	if (channel->direction == DMA_DIR_HMEM_TO_LMEM ||
	    channel->direction == DMA_DIR_DEV_TO_MEM) {
		*avail = dw_dma_avail_data_size(channel);
		*free = dw_chan->ptr_data.buffer_bytes - *avail;
	} else {
		*free = dw_dma_free_data_size(channel);
		*avail = dw_chan->ptr_data.buffer_bytes - *free;
	}
	irq_local_enable(flags);

#if CONFIG_HW_LLI
	if (!(dma_reg_read(channel->dma, DW_DMA_CHAN_EN) &
	      DW_CHAN(channel->index))) {
		tr_err(&dwdma_tr, "dw_dma_get_data_size(): xrun detected");
		return -ENODATA;
	}
#endif

	return ret;
}

@plbossart

reverting 61a2c75 ('dma: dw: fix locking and calculations in dw_dma_get_data_size') goes back to the initial behavior, IPC error but no dmic_irq_handler issues.

@plbossart I was able to reproduce dmic_irq_handler() errors with that patch reverted too.

@lgirdwood

While debugging this, I tried running single-stream playback and capture tests check-signal-stop-start.sh -m playback and -m capture and while they do report success I see over- and underrun messages during each pass like

020-08-06 13:16:27 UTC [INFO] Stop/start count: 21
underrun!!! (at least 180,765 ms long)

and

2020-08-06 13:17:37 UTC [INFO] Stop/start count: 10
overrun!!! (at least 177,647 ms long)

are those "normal" / expected? @lgirdwood @plbossart @marc-hb

While debugging this, I tried running single-stream playback and capture tests check-signal-stop-start.sh -m playback and -m capture and while they do report success I see over- and underrun messages during each pass like

I've never used this script, and I don't think it's part of the CI tests we run?
This could be a 'test the test script issue'.

@lyakh

@lyakh can you take a look at this. The DW DMA position update logic is problematic i.e. the 2 data_size functions below are DAI specific and we really need a func for each DMA_DIR type

@lgirdwood could you please elaborate a bit? Why do you think those functions should be different for different DAIs and for each DMA_DIR_*? The DMA is working for some time as is and also single-stream tests work, doesn't that mean, that calculations there are correct? I can understand that it could be concurrency, i.e. a caching or a locking problem, but calculations as such seem correct?

@lyakh

@lyakh over/under runs on BYT could be caused by the driver & FW using IPC for stream positions (they should use the memory window for this). Please check the driver.

The position functions are DAI specific since they only use DAR OR SAR but not both. If we do host <-> DSP copies then DAR and SAR will both increment. When we do IO with a DAI only DAR or SAR will increment, not both. i.e. on playback to SSP the SAR will increment (as DMAC reads buffer) but DAR is constant (as it writes to SSP FIFO).

@lgirdwood

@lgirdwood ok, got it, thanks! However, I now suspect a different problem: I suspect a problem with DMIC on APL. The same tests work on other platforms and SSP capture (instead of DMIC) works on APL too. On APL DMIC however I see sometimes

[4324191540.000000] (        5.156250) c0 dmic-dai     2.0   src/drivers/intel/dmic.c:1427 dmic_stop(), dmic_active_fifos = 1
[4324191544.739584] (        4.739583) c0 ll-schedule        ./schedule/ll_schedule.c:427  task cancel 0xbe062d48 dmic-work <59c87728-d8f9-42f6-b89d-5870a87b0e1e>
[4324191548.593750] (        3.854167) c0 ll-schedule        ./schedule/ll_schedule.c:285  num_tasks 3 total_num_tasks 3
[4324989540.520834] (   797991.937500) c0 ll-schedule  2.1   src/drivers/intel/dmic.c:1534 dmic_irq_handler(), OUTSTAT1 = 2147483648
[4324989549.635417] (        9.114583) c0 dmic-dai     2.0   src/drivers/intel/dmic.c:1533 dmic_irq_handler(), OUTSTAT0 = 671088640

i.e. a DMIC interrupt comes after the DMIC has been stopped. @singalsu any clues?

@lyakh

@lyakh do the tests work on GLK (cAVS1.5) as well, or only on cAVS1.8+ platforms (CNL/CML/ICL/TGL)? That could be a hint to dig further.

@lyakh

@lyakh do the tests work on GLK (cAVS1.5) as well, or only on cAVS1.8+ platforms (CNL/CML/ICL/TGL)? That could be a hint to dig further.

@plbossart I don't think I've got any GLK systems and that test isn't in CI / daily. If somebody could run it on such a device, would be interesting. Would it make sense to try this on MB BYT?

@plbossart

> @plbossart I don't think I've got any GLK systems and that test isn't in CI / daily. If somebody could run it on such a device, would be interesting. Would it make sense to try this on MB BYT?

There is a GLK/BOBBA device in the CI list, and there should be a daily test for it. @xiulipan can you point @lyakh to those daily tests?

I think this also need to work on MinnowBoard.

Also interesting: I wasn't actually sure whether simultaneous capture and playback on the same SSP is supposed to work. It seems to work on CNL, but also breaks on APL

Could be something specific to APL then, not related to the actual IOs. Maybe a memory issue, APL has rather small internal memories.

@plbossart

@plbossart I don't think I've got any GLK systems and that test isn't in CI / daily. If somebody could run it on such a device, would be interesting. Would it make sense to try this on MB BYT?

There is a GLK/BOBBA device in the CI list, and there should be a daily test for it. @xiulipan can you point @lyakh to those daily tests?

I think this also need to work on MinnowBoard.

@plbossart yes, I did see that device in the list, and as I mentioned above, that test is neither in CI nor in daily sets, so for now it can only be checked manually.

@lyakh

@lyakh one other thing to check is that we are not reading back LLI descriptors for current block status and always readback HW registers. i.e. the HH LLI mode means descriptors are copied back to RAM (after being updated by DMAC) and must be invalidated before DSP reads them.

I think I know when the problem occurs. It occurs when SSP playback pauses while DMIC capture is still running. In such a case pausing the playback masks, clears and disables the DMA interrupt. But then it finds, that another DMA client (DMIC) is still running, so it re-enables the interrupt. But it's too late - the DMIC overflows and doesn't recover from it any more. Interestingly, on other platforms (e.g. CNL) the same works.

@lyakh

@lyakh btw - there are differences to IRQ mapings between APL and CNL for DW-DMA. IIR one has an IRQ per channel and ther other the IRQ is shared for all channels.

@lyakh

@lyakh btw - there are differences to IRQ mapings between APL and CNL for DW-DMA. IIR one has an IRQ per channel and ther other the IRQ is shared for all channels.

@lgirdwood exactly, this seems to be the reason, but interestingly APL has an interrupt per channel and CNL has them shared.

More fun: an important and relevant difference is also the use of scheduler domains: the CNL uses HDA generic topologies, which use the timer domain for everything, and it doesn't use SSPs. Whereas APL / UP2 uses the DMA scheduler domain for the SSP5, and somehow that also moves DMIC to the same domain, even though in topology it's assigned to the timer domain.

@lyakh

More fun: an important and relevant difference is also the use of scheduler domains: the CNL uses HDA generic topologies, which use the timer domain for everything, and it doesn't use SSPs. Whereas APL / UP2 uses the DMA scheduler domain for the SSP5, and somehow that also moves DMIC to the same domain, even though in topology it's assigned to the timer domain.

Good catch @lyakh. I think the DMA scheduler should only be used when the SSP is in slave mode (codec master).

But I fail to see why this would lead to a difference, if we use the DMA scheduler the interrupts are going to be more or less the same as the timer ticks, they cannot drift when the SOC is clock master.

@plbossart

@plbossart good question why the DMA scheduler is used with SSP in master mode. And my above statement, that on APL in a DMIC + SSP test both pipelines are driven by the DMA scheduler might have been at least partially wrong... To be continued tomorrow.

@plbossart

@plbossart good question why the DMA scheduler is used with SSP in master mode. And my above statement, that on APL in a DMIC + SSP test both pipelines are driven by the DMA scheduler might have been at least partially wrong... To be continued tomorrow.

Chromebooks with CML (Helios?) do make use of SSP+DMIC, so that's also a good reference point.

@plbossart

@plbossart good question why the DMA scheduler is used with SSP in master mode. And my above statement, that on APL in a DMIC + SSP test both pipelines are driven by the DMA scheduler might have been at least partially wrong... To be continued tomorrow.

Chromebooks with CML (Helios?) do make use of SSP+DMIC, so that's also a good reference point.

@plbossart thanks, good to know!

As explained in #3289 this seems to be fixed but only for codec-slave modes. I don't think we're even testing the codec-master mode? Fixing it has a lower priority probably?

Navigation Menu

Repository navigation

[BUG] Underflows and errors with sof-test/test-case/multiple-pause-resume.sh #3256

1 remaining item

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[BUG] Underflows and errors with sof-test/test-case/multiple-pause-resume.sh #3256

Description

Activity

xiulipan commented on Jul 31, 2020

keqiaozhang commented on Jul 31, 2020

plbossart commented on Jul 31, 2020

plbossart commented on Jul 31, 2020

lgirdwood commented on Aug 5, 2020

lyakh commented on Aug 6, 2020

lyakh commented on Aug 6, 2020

plbossart commented on Aug 6, 2020

lyakh commented on Aug 6, 2020

lgirdwood commented on Aug 7, 2020

lyakh commented on Aug 7, 2020

plbossart commented on Aug 7, 2020

1 remaining item

lyakh commented on Aug 7, 2020

plbossart commented on Aug 7, 2020

plbossart commented on Aug 7, 2020

lyakh commented on Aug 8, 2020

lgirdwood commented on Aug 10, 2020

lyakh commented on Aug 10, 2020

lgirdwood commented on Aug 10, 2020

lyakh commented on Aug 10, 2020

lyakh commented on Aug 10, 2020

plbossart commented on Aug 10, 2020

lyakh commented on Aug 10, 2020

plbossart commented on Aug 10, 2020

lyakh commented on Aug 10, 2020

lyakh commented on Aug 11, 2020

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions