Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[BUG][CML]Ipc timed out for 0x60040000 size 12 after reboot #2279

Closed
dengyangchao opened this issue Jan 13, 2020 · 17 comments
Closed

[BUG][CML]Ipc timed out for 0x60040000 size 12 after reboot #2279

dengyangchao opened this issue Jan 13, 2020 · 17 comments
Assignees
Labels
bug Something isn't working as expected CML Applies to Comet Lake platform IPC timeout IPC timeout observed P1 Blocker bugs or important features
Milestone

Comments

@dengyangchao
Copy link

dengyangchao commented Jan 13, 2020

Describe the bug
Pulse aduio enabled, and Ipc timed out for 0x60040000 size 12 after reboot
When issue occur, system get stalled and hard to use
To Reproduce
1.Reboot system via"sudo reboot"
2.check dmesg via "dmesg -w"

Reproduction Rate
5/5

Expected behavior
system reboot normal

Impact
Ipc timed out for 0x60040000 size 12

Environment
Platform: CML Chrome with onboard codec RT5682 and RT1011 in I2S mode
Firmware: 418c77e https://github.com/thesofproject/sof/commits/master
Kernel: 5e7259b https://github.com/thesofproject/linux/commits/topic/sof-dev
Topology: file: tools/topology/sof-cml-rt1011-rt5682.tplg same as firmware

Dmesg

[   14.494832] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2024001e successful
[   14.494840] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[   14.494848] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 1
[   14.494854] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[   14.494857] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[   14.494859] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[   14.495140] sof-audio-pci 0000:00:1f.3: rate_min: 48000 rate_max: 48000
[   14.495144] sof-audio-pci 0000:00:1f.3: channels_min: 2 channels_max: 2
[   14.495157] sof-audio-pci 0000:00:1f.3: rate_min: 48000 rate_max: 48000
[   14.495159] sof-audio-pci 0000:00:1f.3: channels_min: 2 channels_max: 2
[   14.495166] sof-audio-pci 0000:00:1f.3: rate_min: 48000 rate_max: 48000
[   14.495169] sof-audio-pci 0000:00:1f.3: channels_min: 2 channels_max: 2
[   14.495176] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 1
[   14.495182] sof-audio-pci 0000:00:1f.3: generating page table for 00000000e1f05825 size 0xffc0 pages 16
[   14.495192] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x340000 successful
[   14.495211] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[   14.495217] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[   14.495220] sof-audio-pci 0000:00:1f.3: periods:4
[   14.495236] sof-audio-pci 0000:00:1f.3: stream_tag 3
[   15.000087] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60040000 size 12
[   15.000092] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[   15.000100] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   15.000177] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[   15.000185] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000f83 rirb 00
[   15.000187] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[   15.000193] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[   15.000194] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   15.000201]  DMIC01: ASoC: trigger FE cmd: 1 failed: -110
[   15.000205] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 1 dir 1 cmd 0
[   15.000209] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60050000: GLB_STREAM_MSG: TRIG_STOP
[   15.504133] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60050000 size 12
[   15.504143] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[   15.504159] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   15.504257] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[   15.504269] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000f83 rirb 00
[   15.504273] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[   15.504289] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[   15.504292] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   15.504314] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20240000 successful
[   15.504323]  DMIC01: ASoC: trigger FE cmd: 0 failed: -110
[   15.504385] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[   16.008073] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60010000 size 108
[   16.008076] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[   16.008080] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005

Sof-error-trace

CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1         DMIC          45498075.364583  45498076.000000 rs/intel/cavs/dmic.c:1492	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC          45498105.364583        30.000000 rs/intel/cavs/dmic.c:1492	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC          45498136.927083        31.562500 rs/intel/cavs/dmic.c:1492	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC          45498166.927083        30.000000 rs/intel/cavs/dmic.c:1492	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC          45498198.697917        31.770834 rs/intel/cavs/dmic.c:1492	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC          45498228.697917        30.000000 rs/intel/cavs/dmic.c:1492	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC          45498260.208333        31.510416 rs/intel/cavs/dmic.c:1492	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC          45498290.364583        30.156250 rs/intel/cavs/dmic.c:1492	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC          45498322.135417        31.770834 rs/intel/cavs/dmic.c:1492	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC          45498352.187500        30.052084 rs/intel/cavs/dmic.c:1492	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC          45498383.750000        31.562500 rs/intel/cavs/dmic.c:1492	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC          45498413.750000        30.000000 rs/intel/cavs/dmic.c:1492	dmic_irq_handler() error: full fifo A or PDM overrrun
    0      1         DMIC          45498445.468750        31.718750 rs/intel/cavs/dmic.c:1492	dmic_irq_handler() error: full fifo A or PDM overrrun

amixer.txt
dmesg.log
logger.log
logger-error-trace.log

@dengyangchao dengyangchao added bug Something isn't working as expected CML Applies to Comet Lake platform labels Jan 13, 2020
@dengyangchao
Copy link
Author

Caused by master 91fb594, and may related arecord HW:0,8

@dengyangchao
Copy link
Author

@mmaka1 please help to check this

@lgirdwood lgirdwood added the P1 Blocker bugs or important features label Jan 14, 2020
@lgirdwood
Copy link
Member

lgirdwood commented Jan 14, 2020

@singalsu any comments on the DMIC errors in the log ?

@dengyangchao
Copy link
Author

When issue occur, do suspend-resume via command "sudo rtcwake -m mem -s 10" can make it back to work, but runtime PM always active.

CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1           SA         508938447.239583 508938432.000000      src/lib/agent.c:54  	validate(), ll drift detected, delta = 25416
[  350.040747] sof-audio-pci 0000:00:1f.3: error: failed to set dai config for iDisp3
[  350.040753] sof-audio-pci 0000:00:1f.3: ASoC: can't set iDisp3 Pin hw params: -110
[  350.040765]  iDisp3: ASoC: hw_params BE failed -110
[  350.040769]  HDMI3: ASoC: hw_params BE failed -110
[  350.040781] sof-audio-pci 0000:00:1f.3: pcm: free stream 4 dir 0
[  350.041038] sof-audio-pci 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[  350.520568] PM: suspend entry (s2idle)
[  350.521157] Filesystems sync: 0.000 seconds
[  350.522106] Freezing user space processes ... 
[  350.544581] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x80010000 size 120
[  350.544591] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[  350.544600] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  350.544696] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  350.544707] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[  350.544710] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[  350.544718] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  350.544722] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[  350.544727] sof-audio-pci 0000:00:1f.3: error: failed to set dai config for iDisp3
[  350.544733] sof-audio-pci 0000:00:1f.3: ASoC: can't set iDisp3 Pin hw params: -110
[  350.544745]  iDisp3: ASoC: hw_params BE failed -110
[  350.544749]  HDMI3: ASoC: hw_params BE failed -110
[  350.544761] sof-audio-pci 0000:00:1f.3: pcm: free stream 4 dir 0
[  350.545082] (elapsed 0.022 seconds) done.
[  350.545087] OOM killer disabled.
[  350.545089] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[  350.546799] printk: Suspending console(s) (use no_console_suspend to debug)
[  350.572634] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x20140000 successful
[  350.572655] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[  351.080610] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40010000 size 76
[  351.080614] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[  351.080624] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  351.080879] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[  351.080898] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000000 rirb 00
[  351.080901] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[  351.080913] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[  351.080917] sof-audio-pci 0000:00:1f.3: ctx_save ipc error -110, proceeding with suspend
[  351.081014] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010f0f successful
[  351.081020] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f successful
[  351.081024] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask f
[  351.081076] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000010 at  00000044
[  351.304686] [drm:intel_panel_actually_set_backlight [i915]] set backlight PWM = 0
[  351.409425] ACPI: EC: interrupt blocked
[  360.850569] ACPI: EC: interrupt unblocked
[  361.396418] [drm:intel_dump_cdclk_state [i915]] Current CDCLK 337500 kHz, VCO 8100000 kHz, ref 24000 kHz, bypass 24000 kHz, voltage level 0
[  361.396817] [drm:intel_reference_shared_dpll.isra.11 [i915]] using DPLL 0 for pipe A
[  361.405230] [drm:gen8_de_irq_handler [i915]] hotplug event received, stat 0x01000000, dig 0x12101010, pins 0x00000010, long 0x00000010
[  361.405254] [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:94:DDI A] - long
[  361.410801] [drm:gen8_de_irq_handler [i915]] hotplug event received, stat 0x01000000, dig 0x12101010, pins 0x00000010, long 0x00000010
[  361.410818] [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:94:DDI A] - long
[  361.481736] [drm:gen8_de_irq_handler [i915]] hotplug event received, stat 0x01000000, dig 0x12101010, pins 0x00000010, long 0x00000010
[  361.481778] [drm:intel_hpd_irq_handler [i915]] digital hpd on [ENCODER:94:DDI A] - long
[  361.610683] [drm:intel_panel_actually_set_backlight [i915]] set backlight PWM = 24000
[  361.627718] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
[  361.627729] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000040 at  00000048
[  361.627733] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000000 at  00000048
[  361.631094] sof-audio-pci 0000:00:1f.3: codec_mask = 0x0
[  361.631114] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  00000048
[  361.631118] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000040 at  00000048
[  361.631133] sof-audio-pci 0000:00:1f.3: loading firmware
[  361.631136] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000002 at  00000048
[  361.631139] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000000 at  00000048
[  361.631143] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
[  361.631146] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000004 at  00000044
[  361.631148] sof-audio-pci 0000:00:1f.3: booting DSP firmware
[  361.631211] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[  361.631226] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[  361.631229] sof-audio-pci 0000:00:1f.3: period_bytes:0x0
[  361.631231] sof-audio-pci 0000:00:1f.3: periods:1
[  361.631310] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f0f0f successful
[  361.631318] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0xf0f0f0e successful
[  361.631321] sof-audio-pci 0000:00:1f.3: unstall/run core: core_mask = 1
[  361.631325] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 1 : core_mask 1
[  361.631994] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x80000000 successful
[  361.631999] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x1010e0e successful
[  361.729944] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x5000001 successful
[  361.743082] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x5 successful
[  361.743090] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x240000 successful
[  361.743094] sof-audio-pci 0000:00:1f.3: Firmware download successful, booting...
[  361.754723] sof-audio-pci 0000:00:1f.3: ipc rx: 0x70000000: FW_READY
[  361.754729] sof-audio-pci 0000:00:1f.3: ipc: DSP is ready 0x70000000 offset 0x81000
[  361.754740] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x70000000: FW_READY
[  361.754795] sof-audio-pci 0000:00:1f.3: firmware boot complete
[  361.754807] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000000 at  00000048
[  361.754811] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000002 at  00000048
[  361.754816] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000004 at  00000044
[  361.754820] sof-audio-pci 0000:00:1f.3: Debug PCIW: 00000000 at  00000044
[  361.754828] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[  361.754845] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[  361.754848] sof-audio-pci 0000:00:1f.3: period_bytes:0x0
[  361.754850] sof-audio-pci 0000:00:1f.3: periods:1
[  361.754862] sof-audio-pci 0000:00:1f.3: stream_tag: 1
[  361.754873] sof-audio-pci 0000:00:1f.3: ipc tx: 0x90030000: GLB_TRACE_MSG
[  361.755743] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x90030000: GLB_TRACE_MSG
[  361.755944] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x14001e successful
[  361.755955] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30010000: GLB_TPLG_MSG: COMP_NEW
[  361.756405] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x30010000: GLB_TPLG_MSG: COMP_NEW
[  361.756419] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30010000: GLB_TPLG_MSG: COMP_NEW
[  361.756798] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x30010000: GLB_TPLG_MSG: COMP_NEW
[  361.756808] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30200000: GLB_TPLG_MSG: BUFFER_NEW
[  361.757073] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x30200000: GLB_TPLG_MSG: BUFFER_NEW
[  361.757082] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30200000: GLB_TPLG_MSG: BUFFER_NEW
[  361.757459] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x30200000: GLB_TPLG_MSG: BUFFER_NEW
[  361.757473] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30010000: GLB_TPLG_MSG: COMP_NEW
[  361.757851] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x30010000: GLB_TPLG_MSG: COMP_NEW
[  361.757858] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30100000: GLB_TPLG_MSG: PIPE_NEW
[  361.758091] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x30100000: GLB_TPLG_MSG: PIPE_NEW
[  361.758097] sof-audio-pci 0000:00:1f.3: DSP core(s) enabled? 1 : core_mask 1
[  361.758103] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[  361.758280] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[  361.758291] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30010000: GLB_TPLG_MSG: COMP_NEW

dmesg.log
error-trace.log

@lgirdwood lgirdwood added this to the v1.5 milestone Jan 15, 2020
@lgirdwood
Copy link
Member

@ranj063 @kv2019i it looks like we have a lot of HDMI DAI config IPC errors prior to suspend, and it even looks like we are sending this message during suspend ?

@kv2019i
Copy link
Collaborator

kv2019i commented Jan 15, 2020

@lgirdwood
The HDMI errors don't look right, but I suspect they are not the rootcause but rather second order damage. The first error seems to be at roughly 14.495sec in the bootprocess:

[ 14.494840] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000: GLB_STREAM_MSG: TRIG_START
[ 14.494848] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 1
[ 14.494854] sof-audio-pci 0000:00:1f.3: period min 192 max 16384 bytes
[ 14.494857] sof-audio-pci 0000:00:1f.3: period count 2 max 16
[ 14.494859] sof-audio-pci 0000:00:1f.3: buffer max 65536 bytes
[ 14.495140] sof-audio-pci 0000:00:1f.3: rate_min: 48000 rate_max: 48000
[ 14.495144] sof-audio-pci 0000:00:1f.3: channels_min: 2 channels_max: 2
[ 14.495157] sof-audio-pci 0000:00:1f.3: rate_min: 48000 rate_max: 48000
[ 14.495159] sof-audio-pci 0000:00:1f.3: channels_min: 2 channels_max: 2
[ 14.495166] sof-audio-pci 0000:00:1f.3: rate_min: 48000 rate_max: 48000
[ 14.495169] sof-audio-pci 0000:00:1f.3: channels_min: 2 channels_max: 2
[ 14.495176] sof-audio-pci 0000:00:1f.3: pcm: hw params stream 0 dir 1
[ 14.495182] sof-audio-pci 0000:00:1f.3: generating page table for 00000000e1f05825 size 0xffc0 pages 16
[ 14.495192] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x340000 successful
[ 14.495211] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x40000 successful
[ 14.495217] sof-audio-pci 0000:00:1f.3: period_bytes:0x3fc0
[ 14.495220] sof-audio-pci 0000:00:1f.3: periods:4
[ 14.495236] sof-audio-pci 0000:00:1f.3: stream_tag 3
[ 15.000087] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x60040000 size 12

So TRIG_START fails to IPC error. Then after this, we get errors for all DAIs (including HDMI) when trying to stop and free.

@dengyangchao
Copy link
Author

Disable UCM issue can't be reproduced, update the UCM via thesofproject/alsa-ucm-conf#25 issue can't be reproduced.
So, close issue.

@lgirdwood
Copy link
Member

lgirdwood commented Jan 16, 2020

@dengyangchao I have to reopen this issue as the IPC timeout still exists. i.e. FW should not IPC timeout and crash under any circumstances. Can you narrow down the conditions or IPC sequence that causes the crash.

@mmaka1
Copy link

mmaka1 commented Jan 16, 2020

Having #2285 merged, you could revert the clock back to 400MHz, and grep 'perf' keyword to find cpu peak reported. If >120K then FW execution takes too long and may result in DMIC overruns and other bad behavior. Would be interesting to see when that high load happens.

@lgirdwood
Copy link
Member

@mmaka1 are you suggesting high load could cause the IPC timeout in this issue ?

@lgirdwood lgirdwood added the IPC timeout IPC timeout observed label Feb 12, 2020
@tlauda
Copy link
Contributor

tlauda commented Mar 3, 2020

@lgirdwood @dengyangchao @mmaka1 Anything new?

@aiChaoSONG
Copy link
Collaborator

@tlauda This issue is because we expose wov pipeline to pulseaudio in ucm. remove that pipeline from ucm, no issue at all.

@lgirdwood
Copy link
Member

Pulseaudio will probe each PCM device by attempting to open it multiple times with different configuration params. It then works out which PCM params are supported and which are not supported.
@aiChaoSONG does the FW crash immediately as soon as pulseaudio is started. Can you try and manually start pulseaudio (after host + FW boot) with debug enabled in the command line. If the IPC timeout happens at start it's likely related to the pulseaudio params probing (and we have a race with WoV pipeline / KD code).

@aiChaoSONG
Copy link
Collaborator

aiChaoSONG commented Mar 5, 2020

@lgirdwood I reboot the device, and manually start pulseaudio after DSP suspended (with DMIC16k in UCM), attached file is the log from the time I press ENTER to start pulseaudio. Only hw params IPC error, and NO IPC timeout found. and sof error log is clean. tried 5 times, same result.

dmesg.txt

Since this issue is reported, we have a lot of patch merged, maybe fixed accidentally?
recipe: same recipe used in daily. kernel: 24d9781 sof: 9e1a2b2

@lgirdwood
Copy link
Member

@aiChaoSONG are you confirming it works on master now if pulseaudio started automatically at boot ?

@aiChaoSONG
Copy link
Collaborator

@lgirdwood Yes, even pulseaudio start at boot, ipc timeout is gone, and only three hw param ipc error in dmesg log.

@lgirdwood
Copy link
Member

ok great.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working as expected CML Applies to Comet Lake platform IPC timeout IPC timeout observed P1 Blocker bugs or important features
Projects
None yet
Development

No branches or pull requests

7 participants