suspend/resume failure after several cycles on Yorp

This issue is more like a regression, before we can do suspend/resume more than hundreds of times. but it's easy to fail now(less then 10 times).

How to reproduce:

sudo suspend_stress_test

Tested with:
soft-master:4ac9248f
sof-master:43da16
kernel-debug/cros-v4.14-rebase: 90eee4
dmesg.log
logger-t.log

@keqiaozhang

@keqiaozhang how do you know suspend/resume failed ? I cant see anything in the logs.

@lgirdwood

@lgirdwood
Not sure whether the relevant error logs are overwrote. I didn't find the log either and that's the reason why I did past the log in comment box.
This issue can easy reproduce with suspend_stress_test tool, this is a buildin tool in chromeOS.
I will reproduce this issue tomorrow and dump the log in time.

@keqiaozhang

@keqiaozhang this is a driver bug. Can you please move it?

This bug is moved to thesofproject/linux#243

Summary:
This issue can be reproduced on UP2.
both sof-logger & sof-logger -t are empty.

dmesg:

[  884.682446] sof-audio sof-audio: ipc tx succeeded: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[  884.684186] sof-audio sof-audio: pcm: trigger stream 0 dir 0 cmd 1
[  884.684192] sof-audio sof-audio: PCM: resume stream 0 dir 0 DMA position 0
[  884.684194] sof-audio sof-audio: pcm: hw params stream 0 dir 0
[  884.684198] sof-audio sof-audio: generating page table for 0000000030deebf6 size 0xff00 pages 16
[  884.684219] sof-audio sof-audio: period_bytes:0xfc0
[  884.684221] sof-audio sof-audio: periods:16
[  884.684229] sof-audio sof-audio: stream_tag 1
[  884.684256] sof-audio sof-audio: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[  884.684380] sof-audio sof-audio: error : DSP panic!
[  884.684389] sof-audio sof-audio: panic: dsp_oops_offset 788480 offset 788480
[  884.684393] sof-audio sof-audio: status: fw entered - code 00000005
[  884.684435] sof-audio sof-audio: error: runtime exception
[  884.684438] sof-audio sof-audio: error: trace point 00004000
[  884.684440] sof-audio sof-audio: error: panic happen at :0
[  884.684443] sof-audio sof-audio: error: DSP Firmware Oops
[  884.684445] sof-audio sof-audio: error: Exception Cause: LoadStorePIFDataErrorCause, Synchronous PIF data error during LoadStore access
[  884.684449] sof-audio sof-audio: EXCCAUSE 0x0000000d EXCVADDR 0x00002340 PS       0x00060025 SAR     0x00000010
[  884.684456] sof-audio sof-audio: EPC1     0xbe024307 EPC2     0xbe01192e EPC3     0xbe013dc0 EPC4    0x00000000
[  884.684463] sof-audio sof-audio: EPC5     0x00000000 EPC6     0x00000000 EPC7     0x00000000 DEPC    0x00000000
[  884.684470] sof-audio sof-audio: EPS2     0x00060720 EPS3     0x00060722 EPS4     0x00000000 EPS5    0x00000000
[  884.684477] sof-audio sof-audio: EPS6     0x00000000 EPS7     0x00000000 INTENABL 0x000101d0 INTERRU 0x00000222
[  884.684484] sof-audio sof-audio: stack dump from 0xbe07fcc0
[  884.684491] sof-audio sof-audio: 0xbe07fcc0: 0xbe024307 0x00060935 0x00000010 0x00000000

** 0xbe024307 in sof-apl.lst-master-xcc-43da1696**

static inline void io_reg_write(uint32_t reg, uint32_t val)
{
        *((volatile uint32_t*)reg) = val;
be024304:       ffea91                  l32r    a9, be0242ac (fbffffdf <xthals_hw_configid0+0x380c03e1>)
}

static inline void io_reg_update_bits(uint32_t reg, uint32_t mask, uint32_t value)
{
        io_reg_write(reg, (io_reg_read(reg) & (~mask)) | (value & mask));
be024307:       08f8                    l32i.n  a15, a8, 0
        return *((volatile uint32_t*)reg);
}

static inline void io_reg_write(uint32_t reg, uint32_t val)
{
        *((volatile uint32_t*)reg) = val;
be024309:       10ff90                  and     a15, a15, a9
be02430c:       0020c0                  memw
be02430f:       72400000fb4011ee        { s32i  a15, a8, 0; movi        a14, 3; nop; nop }
        if (p->chan[channel].dma_ch_work.cb)
                work_cancel_default(&p->chan[channel].dma_ch_work);

        /* disable the channel */
        hda_update_bits(dma, channel, DGCS, DGCS_GEN | DGCS_FIFORDY, 0);
        p->chan[channel].status = COMP_STATE_PREPARE;

Test steps:

aplay -Dhw:0,0 -r 48000 -c 2 -f s16_le -i -vv ~/Music/18_WAV_48000Hz_stereo_16bit.wav
run the following scripts:
i=0
while [ $i -lt 50 ]
do
rtcwake -m mem -s 2
sleep 4
let i++
done

Test env:
sof master: 43da169
sof tool: 937032f
kernel sof-dev: a5ddc3d
tplg: sof-apl-pcm512x.tplg-937032f

Log:
dmesg-apl.log
sof-apl.ldc-master-xcc-43da1696.txt

@markyang

This is also a FW bug so reopened.

This one looks like firmware is not validating DMA channel IDs before dereferencing. i.e. in hda_dma_stop() and other we do not validate channel is valid

static int hda_dma_stop(struct dma *dma, int channel)
{
	struct dma_pdata *p = dma_get_drvdata(dma);
	uint32_t flags;

	spin_lock_irq(&dma->lock, flags);

	trace_host("DDi");

	if (p->chan[channel].dma_ch_work.cb)
		work_cancel_default(&p->chan[channel].dma_ch_work);

	/* disable the channel */
	hda_update_bits(dma, channel, DGCS, DGCS_GEN | DGCS_FIFORDY, 0);
	p->chan[channel].status = COMP_STATE_PREPARE;

	spin_unlock_irq(&dma->lock, flags);
	return 0;
}

This should be validated against correct channel range. Any invalid channels should be logged.

@markyang could you try the following patch. This will display an error if we attempt an invalid channel and will help root cause the issue,

diff --git a/src/drivers/intel/cavs/hda-dma.c b/src/drivers/intel/cavs/hda-dma.c
index 865bdc73..57bcccfb 100644
--- a/src/drivers/intel/cavs/hda-dma.c
+++ b/src/drivers/intel/cavs/hda-dma.c
@@ -467,6 +467,11 @@ static int hda_dma_stop(struct dma *dma, int channel)
        struct dma_pdata *p = dma_get_drvdata(dma);
        uint32_t flags;
 
+       if (channel >= HDA_DMA_MAX_CHANS || channel < 0) {
+               trace_error(TRACE_CLASS_HOST, "invalid channel %d", channel);
+               return -EINVAL;
+       }
+
        spin_lock_irq(&dma->lock, flags);
 
        trace_host("DDi");

@lgirdwood

@lgirdwood I've added your patch, but the issue cannot be reproduced any more.

Summary:
This issue cannot be reproduced on UP2 now(slept 50 times), but metallic noise was found.
sof-logger is empty. sof-logger -t log is attached below.

dmesg:

[ 1725.525343] PM: suspend entry (deep)
[ 1725.525346] PM: Syncing filesystems ... done.
[ 1725.526265] Freezing user space processes ... (elapsed 0.002 seconds) done.
[ 1725.529255] OOM killer disabled.
[ 1725.529257] Freezing remaining freezable tasks ... (elapsed 0.002 seconds) done.
[ 1725.531416] Suspending console(s) (use no_console_suspend to debug)
[ 1725.640177] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 6:0
[ 1725.782240] sof-audio sof-audio: tag 1 not opened!
[ 1725.782259] sof-audio sof-audio: pcm: trigger stream 0 dir 0 cmd 5
[ 1725.782295] sof-audio sof-audio: ipc tx: 0x60000000: GLB_STREAM_MSG: unknown type
[ 1725.782567] sof-audio sof-audio: error: ipc error for 0x60000000 size 0xc
[ 1725.782584]  Port5: ASoC: trigger FE failed -22
[ 1725.782613] sof-audio sof-audio: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 1725.782802] sof-audio sof-audio: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
[ 1725.809053] sof-audio sof-audio: DSP core(s) enabled? 0 : core_mask 3
[ 1725.809087] sof-audio sof-audio: Debug PCIR: 00000000 at  00000044
[ 1725.809095] sof-audio sof-audio: Debug PCIW: 00000010 at  00000044
[ 1725.869295] ACPI: Preparing to enter system sleep state S3
[ 1725.869887] PM: Saving platform NVS memory
[ 1725.869894] Disabling non-boot CPUs ...
[ 1725.886709] smpboot: CPU 1 is now offline

Test steps:

aplay -Dhw:0,0 -r 48000 -c 2 -f s16_le -i -vv ~/Music/18_WAV_48000Hz_stereo_16bit.wav
run the following scripts:
i=0
while [ $i -lt 50 ]
do
rtcwake -m mem -s 3
sleep 3
let i++
done

Test env:
sof master: 40c054a
sof tool: 937032f
kernel sof-dev: af44aa9
tplg: sof-apl-pcm512x.tplg-937032f

Log:
dmesg-apl.log
logger-t.txt

@markyang

@markyang I've re-opened as the patch is NOT a fix, but a check for invalid array bounds. This appears to be a race closing a DMA channel prior to D3. Added @mmaka1 for HDA.

@markyang can you describe use case for metallic noise, how reproducible etc.

@lgirdwood

@lgirdwood please follow the steps below, the metallic noise will occur after sleeping several times.
step 1: run 'aplay -Dhw:0,0 -r 48000 -c 2 -f s16_le -i -vv ~/Music/18_WAV_48000Hz_stereo_16bit.wav' in one Terminal.
step 2: vi suspend_stress.sh

#!/bin/bash
i=0
while [ $i -lt 50 ]
do
	rtcwake -m mem -s 3
	sleep 3
	let i++
done

run 'sudo ./suspend_stress.sh' in another Terminal.

@michalgrodzicki

@michalgrodzicki looks like there is sometimes metallic noise after D3 transition. iirc, @mmaka1 found an timing issue where wrong period was being DMAed and this could be happening after D3.

I retested this issue on Yorp with Ranjani's new person kernel branch:https://github.com/ranj063/linux/commits/topic/cros-sof-v4.14-rebase
The suspend/resume can pass more than 100 iterations.

Move metallic noise issue on UP2 to #577 .

@keqiaozhang

@keqiaozhang can we close then ? or do we need more iterations ?

@lgirdwood

@lgirdwood
Yes, this issue can be closed. I will check with Naveen about how may iterations do we need to test.

Navigation Menu

Repository navigation

suspend/resume failure after several cycles on Yorp #522

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

suspend/resume failure after several cycles on Yorp #522

Description

Activity

lgirdwood commented on Nov 1, 2018

keqiaozhang commented on Nov 1, 2018

ranj063 commented on Nov 1, 2018

keqiaozhang commented on Nov 2, 2018

markyang commented on Nov 2, 2018

lgirdwood commented on Nov 2, 2018

markyang commented on Nov 7, 2018

lgirdwood commented on Nov 7, 2018

markyang commented on Nov 8, 2018

lgirdwood commented on Nov 8, 2018

keqiaozhang commented on Nov 13, 2018

markyang commented on Nov 14, 2018

lgirdwood commented on Nov 14, 2018

keqiaozhang commented on Nov 15, 2018

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions