[BUG][Zephyr] ./multiple-pause-resume.sh sof-test fails

Describe the bug
Sof-test case ./multiple-pause-resume.sh fails on TGL system with Soundwire codec and SOF compiled with Zephyr as RTOS.

To Reproduce
export TPLG=/lib/firmware/intel/sof-tplg/sof-tgl-rt711-4ch.tplg
cd sof-test/test-case
./multiple-pause-resume.sh

Reproduction Rate
100%

Expected behavior
Test passes.

Impact
Showstopper for product use.

Notes
A XTOS build from same SOF git revision and same topology definition, passes the test

Environment

Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
- Kernel: dcea805219d0276916c6ef3266fa1c4d40eced55
- SOF: 9235eb8
- Zephyr: 21d1ad3762302b3e461953df59430c77e0709274
Name of the topology file
- Topology: sof-tgl-rt711-4ch.tplg
Name of the platform(s) on which the bug is observed.
- Platform: TGL RVP

Screenshots or console output

Kernel log

[   64.215981] sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 10 dir 1 cmd 3
[   64.215989] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[   64.217191] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[   64.217464] sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0xa0]=0x20240000 successful
[   64.217488]  dmic01: ASoC: trigger BE dmic01 cmd 3
[   64.318132]  dmic01: ASoC: trigger BE dmic01 cmd 4
[   64.318136]  DMIC: ASoC: post trigger FE DMIC cmd 4
[   64.318137] sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 10 dir 1 cmd 4
[   64.318654] sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0xa0]=0x2024001e successful
[   64.318657] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[   64.385723]  DMIC16kHz: ASoC: pre trigger FE DMIC16kHz cmd 0
[   64.385730] sof-audio-pci-intel-tgl 0000:00:1f.3: pcm: trigger stream 11 dir 1 cmd 0
[   64.821456] sof-audio-pci-intel-tgl 0000:00:1f.3: error: ipc timed out for 0x60070000 size 12
[   64.821463] sof-audio-pci-intel-tgl 0000:00:1f.3: status: fw entered - code 00000005
[   64.821554] sof-audio-pci-intel-tgl 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[   64.821561] sof-audio-pci-intel-tgl 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000007 rirb 00
[   64.821562] sof-audio-pci-intel-tgl 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[   64.821566] sof-audio-pci-intel-tgl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[   64.821568] sof-audio-pci-intel-tgl 0000:00:1f.3: error: waking up any trace sleepers
[   64.821571] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -110
[   64.821577]  DMIC: ASoC: trigger FE cmd: 4 failed: -110
[   64.821578] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[   64.821580]  DMIC: ASoC: pre trigger FE DMIC cmd 3

FW log (with adsplog.py)

45355692: dmic_irq_handler(): full fifo A or PDM overrun
45357800: dmic_stop(), dmic_active_fifos = -5
45359645: task cancel 0xbe056f28 0x1fffa0c0U
45361731: num_tasks 3 total_num_tasks 3
45363514: dmic_irq_handler(), OUTSTAT0 = 0x28000000, OUTSTAT1 = 0x80000000
45366545: dmic_irq_handler(): full fifo A or PDM overrun
45368645: dmic_stop(), dmic_active_fifos = -6
45370477: task cancel 0xbe056f28 0x1fffa0c0U
45372623: dmic_irq_handler(), OUTSTAT0 = 0x28000000, OUTSTAT1 = 0x80000000
45375656: dmic_irq_handler(): full fifo A or PDM overrun
45377756: dmic_stop(), dmic_active_fifos = -6
45379585: task cancel 0xbe056f28 0x1fffa0c0U
45381731: dmic_irq_handler(), OUTSTAT0 = 0x28000000, OUTSTAT1 = 0x80000000
45384764: dmic_irq_handler(): full fifo A or PDM overrun
45386862: dmic_stop(), dmic_active_fifos = -6
45388693: task cancel 0xbe056f28 0x1fffa0c0U

@keqiaozhang

FYI @keqiaozhang and @lyakh -- this is the only case in run-all-tests.sh on my TGL system that behaves differently from a XTOS-built FW. SOF+Zephyr+softest all latest mainline as of today.

@kv2019i

@kv2019i the DMIC irq handler serves no use. We can disable it as it has issues with xtos too. @singalsu please confirm we are no using this ?

@lgirdwood

@lgirdwood Yep, IRQ handler can be disabled.

@singalsu

Hmm, if I remove the dmic irq, the problems seems to be resolved. @singalsu I note in the error logs that uncached_dmic_active_fifos goes to negative values when the test case fails and it seems dmic_stop does not really stop the irqs. In current Zephyr builds for cavs25, the uncached mappings are not available, so cache_to_uncache() accesses are actually cached. This probably is related as dmic_active_fifos should be accessed uncached.

@singalsu

Hmm, if I remove the dmic irq, the problems seems to be resolved. @singalsu I note in the error logs that uncached_dmic_active_fifos goes to negative values when the test case fails and it seems dmic_stop does not really stop the irqs.

Let nuke those IRQs :)

In current Zephyr builds for cavs25, the uncached mappings are not available, so cache_to_uncache() accesses are actually cached.

My understanding is that the Zephyr allocator should be returning uncached pointers. @lyakh please confirm.

This probably is related as dmic_active_fifos should be accessed uncached.

not sure about uncached if it's a HW IP region ?, but will need invalidated.

IRQs indicate things went wrong, ignoring those can hide issues. But in normal working system they are not needed.

If dmic_active_fifos goes negative the state machine is messed up, too many stops() called and logic failing or yet another multi-core inconsistency with count not increasing into two when when both FIFOs are active. I'm debugging maybe a related issue in SOF.

@singalsu

IRQs indicate things went wrong, ignoring those can hide issues. But in normal working system they are not needed.

If dmic_active_fifos goes negative the state machine is messed up, too many stops() called and logic failing or yet another multi-core inconsistency with count not increasing into two when when both FIFOs are active. I'm debugging maybe a related issue in SOF.

@singalsu can you make sure the DMIC allocates with the SOF_MEM_ZONE_RUNTIME_SHARED attribute when it allocates memory. Can you confirm this is the case today.

@lyakh

In current Zephyr builds for cavs25, the uncached mappings are not available, so cache_to_uncache() accesses are actually cached.

My understanding is that the Zephyr allocator should be returning uncached pointers. @lyakh please confirm.

@lgirdwood it should be and it currently is on cAVS 1.5 and 1.8. And it will be on 2.0 and 2.5 too once we have fixed those linker scripts.

I found a clear bug in current mainline that explains failures with the multiple-pause-resume.sh test -> #4283

On Zephyr SOF builds, the result is more severe than with XTOS and thus the higher reproduction rate.

However, there is more subtle issue still on Zephyr and I still get dmic-irq flood. This seems to relate to coherence of 'dmic_active_fifos'. I could prove today that that value of this variable changes outside dmic_start/dmic_stop. So I'll keep this bug open to debug the rootcause for this.

Some more clues. It seems the bug happens in the case when fifo-b is just started, fifo-a gets a pause req and then there seems to be a race with two dmic_stop(): one implementing the pause on fifoa, and another called from dmic IRQ due to xrun.

This trace from modified code that uses bitmasks to track fifos (BIT(dai->index)) so 0x3 if both fifos used:

159530232: dmic_start(), done active_fifos = 3
159532449: task add 0x9e05c2c8 0x1fffa180U
159534523: task params pri 0 flags 0 start 0 period 1000
159537234: new added task->start 159529746 at 159537257
159539805: num_tasks 5 total_num_tasks 5
159612043: validate(), ll drift detected, delta = 69182
162640387: pipe trigger cmd 2
162642054: eq_iir_trigger()
162643414: dw_dma_pause(): dma 0 channel 0 pause
162656614: dmic active_fifo ca 9e0e0ee8
162658487: dmic active_fifo uc 9e0e0ee8
162660307: dmic_stop(), dmic_active_fifos = 3
162662244: dmic_stop(), DEBUG dmic_active_fifos = 3, in_active 0
162664913: task cancel 0x9e055cc8 0x1fffa0c0U
162667144: num_tasks 4 total_num_tasks 4
162669106: task cancel 0x9e05ba80 0x1fffa180U
162671316: num_tasks 3 total_num_tasks 3
ve 0
# KV: we are potentially missing traces here, dmic_active_fifos = 3 at this point
168287287: task cancel 0x9e056f88 0x1fffa0c0U
168289620: dmic_irq_handler(), OUTSTAT0 = 0x28000000, OUTSTAT1 = 0x80000000
168292840: dmic_irq_handler(): full fifo A or PDM overrun
168295091: dmic active_fifo ca 9e0e0ee8
168296888: dmic active_fifo uc 9e0e0ee8
# KV: but here when we call dmic_stop() from IRQ, dmic_active_fifos is 1! 
168298701: dmic_stop(), dmic_active_fifos = 1
168300647: dmic_stop(), DEBUG dmic_active_fifos = 1, in_active 0
168303308: task cancel 0x9e056f88 0x1fffa0c0U
168305644: dmic_irq_handler(), OUTSTAT0 = 0x28000000, OUTSTAT1 = 0x80000000

The interrupt handling seems to behave slightly differently, which explains why the problem is only seen on Zephyr builds.

With following two fixes to SOF, ./multiple-pause-resume.sh now passes cleanly on Zephyr:

#4283
#4297

Fixes merged, closing.

Navigation Menu

Repository navigation

[BUG][Zephyr] ./multiple-pause-resume.sh sof-test fails #4250

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[BUG][Zephyr] ./multiple-pause-resume.sh sof-test fails #4250

Description

Activity

kv2019i commented on May 26, 2021

lgirdwood commented on May 26, 2021

singalsu commented on May 26, 2021

kv2019i commented on May 27, 2021

lgirdwood commented on May 27, 2021

singalsu commented on May 27, 2021

lgirdwood commented on May 27, 2021

lyakh commented on May 31, 2021

kv2019i commented on Jun 2, 2021

kv2019i commented on Jun 3, 2021

kv2019i commented on Jun 4, 2021

kv2019i commented on Jun 11, 2021

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions