Repository navigation
TGL: Chrome: cl_dsp_init: timeout HDA_DSP_SRAM_REG_ROM_STATUS read #2805
Description
DUT: TGL Chrome system
BIOS: Coreboot
Kernel: Google Chrome 5.4 kernel
Notes on error:
1)
Multiple reports of this error reported (at least saw 3~4 logs) showing this error
2)
Do not know how to repro, it is reported in random tests.
3)
Some times issue occurred at boot time, some times during suspend/resume
Error snippet-1:
[ 5.809326] sof-audio-pci 0000:00:1f.3: error: cl_dsp_init: timeout HDA_DSP_SRAM_REG_ROM_STATUS read
[ 5.809334] sof-audio-pci 0000:00:1f.3: error: status = 0x00000000 panic = 0x00000000
[ 5.809346] sof-audio-pci 0000:00:1f.3: error: extended rom status: 0x6000021 0x0 0x0 0x0 0x0 0x0 0x25101c2 0x0
[ 5.809357] sof-audio-pci 0000:00:1f.3: error: dsp init failed after 3 attempts with err: -110
[ 5.809361] sof-audio-pci 0000:00:1f.3: ROM error=0xffffffff: FW status=0xffffffff
[ 5.809384] sof-audio-pci 0000:00:1f.3: error: failed to reset DSP
[ 5.809386] sof-audio-pci 0000:00:1f.3: error: failed to boot DSP firmware -110
[ 5.859830] sof-audio-pci 0000:00:1f.3: error: hda_dsp_core_reset_enter: timeout on HDA_DSP_REG_ADSPCS read
[ 5.859834] sof-audio-pci 0000:00:1f.3: error: dsp core reset failed: core_mask 1
[ 5.859946] sof-audio-pci 0000:00:1f.3: error: sof_probe_work failed err: -110
Error snippet-2:
2021-03-18T14:23:26.983675Z ERR kernel: [ 5159.472527] sof-audio-pci 0000:00:1f.3: error: cl_dsp_init: timeout HDA_DSP_SRAM_REG_ROM_STATUS read
2021-03-18T14:23:26.983677Z ERR kernel: [ 5159.472539] sof-audio-pci 0000:00:1f.3: error: status = 0x00000000 panic = 0x00000000
2021-03-18T14:23:26.983681Z ERR kernel: [ 5159.472558] sof-audio-pci 0000:00:1f.3: error: extended rom status: 0x6000021 0x0 0x0 0x0 0x0 0x0 0x25101c2 0x0
2021-03-18T14:23:26.983683Z ERR kernel: [ 5159.472587] sof-audio-pci 0000:00:1f.3: error: dsp init failed after 3 attempts with err: -110
2021-03-18T14:23:26.983685Z ERR kernel: [ 5159.472598] sof-audio-pci 0000:00:1f.3: ROM error=0xffffffff: FW status=0xffffffff
2021-03-18T14:23:26.983686Z ERR kernel: [ 5159.472663] sof-audio-pci 0000:00:1f.3: error: failed to reset DSP
2021-03-18T14:23:26.983687Z ERR kernel: [ 5159.472665] sof-audio-pci 0000:00:1f.3: error: failed to boot DSP firmware after resume -110
2021-03-18T14:23:26.983688Z ERR kernel: [ 5159.472672] PM: dpm_run_callback(): pci_pm_resume+0x0/0xc0 returns -110
2021-03-18T14:23:26.983692Z INFO kernel: [ 5159.472676] sof-audio-pci 0000:00:1f.3: pci_pm_resume+0x0/0xc0 returned -110 after 894734 usecs
2021-03-18T14:23:26.983693Z ERR kernel: [ 5159.472683] PM: Device 0000:00:1f.3 failed to resume: error -110
Activity
plbossart commentedon Mar 22, 2021
@sathya-nujella do you have a servo board or UART connection?
@ranj063 and I have seen similar issues while doing pm_runtime_resume() before a shutdown/reboot. I have a 100% repro rate on my devices (not Chromebooks) in that sequence, whereas I have never seen such a failure during regular suspend/resume tests. Wondering if you can give it a try and check if the logs before the reboot look ok (need UART for this)
sathya-nujella commentedon Mar 22, 2021
Yes, I have servo connected DUT.
ranj063 commentedon Mar 23, 2021
@plbossart the reproduction rate is very low for this issue. We might need to do some reboot stress tests to reproduce it
keyonjie commentedon Mar 29, 2021
@plbossart @ranj063 This could have relationship with that we are using difference suspend/resume logic, comparing with the cAVS FW/driver.
The state 0x6000021 means hang at WAIT_FOR_CSE_CSR(0x6) with _ROM_CSE_IPC_RESET_PHASE_1(0x21).
cujomalainey commentedon Apr 12, 2021
I see the IMR tag, what exactly is IMR?
yongzhi1 commentedon Apr 13, 2021
Isolated Memory Regions?
ranj063 commentedon Apr 19, 2021
@keyonjie and what is the difference you're talking about here? Is it in terms of the fw boot sequence or just the fact that runtime PM resume doesnt involve FW authentication?
keyonjie commentedon Apr 20, 2021
I meant just the runtime PM resume case, but @sathya-nujella told me that this happened on the boot case also, so it looks more miracle to me now, not saying that we have never reproduce it at our end.
plbossart commentedon Apr 20, 2021
well we have to split the variables here.
a) if there is a problem on a cold boot, it's squarely a CSE issue
b) if there is a problem on a D3 exit, it may be because CSE assumes the authentication is done only once. That said I don't see how we could change the flows at this point, TGL FW is past the PV point and having the firmware save/restore its own context in IMR (DDR not visible to the Linux kernel) would be a major change.
mwasko commentedon Apr 21, 2021
@ranj063 @keyonjie it look like we are reading ROM & FW status too late - the DSP is probably already power off and that is why we get 0xFFFFF. We should fix that to gather more information about FW load failure reason
plbossart commentedon Apr 28, 2021
Not following the comment and not getting what the suggestion is @mwasko. we are not turning the DSP off, it's on boot/resume that the problem happens.
25 remaining items
plbossart commentedon Feb 2, 2022
@sathya-nujella is this bug current and is this P1 or P2. Can't be both :-)
sathya-nujella commentedon Feb 2, 2022
Earlier, we got 4~5 reports of this memory allocation failure. Unfortunately the logs from error reports does not have more info. I removed P1 label.
Team ran some tests to see if any memory leaks, they could not repro. @cujomalainey : Please share if any new info with memory leak tests and results.
Not sure if we can add any error prints to understand why only this allocation failing.
cujomalainey commentedon Feb 2, 2022
I have not gotten any more reports in the last couple months either
sathya-nujella commentedon Mar 17, 2022
We are seeing similar reports from ADL projects also.
==
(can not share full log, but sharing snippet)
<6>[118443.870913] entering low_mem (avail RAM = 411600 kB, avail swap 1112004 kB, avail file 132464 kB, anon mem: 2999564 kB)
<4>[119911.540450] low_mem_check: 10 callbacks suppressed
<6>[119911.540453] entering low_mem (avail RAM = 411524 kB, avail swap 611836 kB, avail file 148680 kB, anon mem: 2591800 kB)
<4>[119938.098903] low_mem_check: 23 callbacks suppressed
<6>[119938.098906] entering low_mem (avail RAM = 411476 kB, avail swap 1009824 kB, avail file 129968 kB, anon mem: 2697904 kB)
<4>[119944.235089] low_mem_check: 4 callbacks suppressed
<6>[119944.235092] entering low_mem (avail RAM = 411624 kB, avail swap 856820 kB, avail file 197420 kB, anon mem: 2772084 kB)
<4>[119947.817303] low_mem_check: 2 callbacks suppressed
<6>[119947.817306] entering low_mem (avail RAM = 411588 kB, avail swap 738528 kB, avail file 216212 kB, anon mem: 2618992 kB)
<4>[119977.985510] low_mem_check: 2 callbacks suppressed
<6>[119977.985515] entering low_mem (avail RAM = 411604 kB, avail swap 831396 kB, avail file 203772 kB, anon mem: 2762148 kB)
<4>[119980.342746] low_mem_check: 4 callbacks suppressed
<6>[119980.342750] entering low_mem (avail RAM = 411576 kB, avail swap 793584 kB, avail file 200796 kB, anon mem: 2611456 kB)
<4>[119982.397950] low_mem_check: 4 callbacks suppressed
<6>[119982.397953] entering low_mem (avail RAM = 411632 kB, avail swap 947324 kB, avail file 138056 kB, anon mem: 2773188 kB)
<4>[119983.474889] low_mem_check: 7 callbacks suppressed
<6>[119983.474894] entering low_mem (avail RAM = 411572 kB, avail swap 995828 kB, avail file 140956 kB, anon mem: 2738248 kB)
<4>[120019.402840] low_mem_check: 13 callbacks suppressed
<6>[120019.402843] entering low_mem (avail RAM = 411440 kB, avail swap 855344 kB, avail file 183652 kB, anon mem: 2723896 kB)
<4>[120030.325203] low_mem_check: 5 callbacks suppressed
<6>[120030.325207] entering low_mem (avail RAM = 411460 kB, avail swap 1031072 kB, avail file 120680 kB, anon mem: 2787708 kB)
<4>[120040.011660] low_mem_check: 4 callbacks suppressed
<6>[120040.011670] entering low_mem (avail RAM = 411616 kB, avail swap 857976 kB, avail file 197124 kB, anon mem: 2684164 kB)
<6>[120663.467801] entering low_mem (avail RAM = 411564 kB, avail swap 673516 kB, avail file 232876 kB, anon mem: 2648544 kB)
<4>[120866.887375] low_mem_check: 3 callbacks suppressed
<6>[120866.887379] entering low_mem (avail RAM = 411628 kB, avail swap 641204 kB, avail file 215452 kB, anon mem: 2563300 kB)
<4>[120869.041412] low_mem_check: 3 callbacks suppressed
<6>[120869.041416] entering low_mem (avail RAM = 411432 kB, avail swap 844668 kB, avail file 200268 kB, anon mem: 2588140 kB)
<4>[120882.939864] low_mem_check: 6 callbacks suppressed
<6>[120882.939867] entering low_mem (avail RAM = 411496 kB, avail swap 818148 kB, avail file 163088 kB, anon mem: 2641348 kB)
<4>[120932.116001] low_mem_check: 4 callbacks suppressed
<6>[120932.116004] entering low_mem (avail RAM = 411212 kB, avail swap 925944 kB, avail file 145596 kB, anon mem: 2783476 kB)
<4>[121117.286205] low_mem_check: 2 callbacks suppressed
<6>[121117.286208] entering low_mem (avail RAM = 411376 kB, avail swap 729412 kB, avail file 210024 kB, anon mem: 2587424 kB)
<4>[121719.350285] low_mem_check: 7 callbacks suppressed
<6>[121719.350288] entering low_mem (avail RAM = 411496 kB, avail swap 962364 kB, avail file 168640 kB, anon mem: 2815288 kB)
<4>[121720.546483] low_mem_check: 2 callbacks suppressed
<6>[121720.546489] entering low_mem (avail RAM = 411520 kB, avail swap 974300 kB, avail file 159884 kB, anon mem: 2830484 kB)
<6>[122009.261479] entering low_mem (avail RAM = 411632 kB, avail swap 680616 kB, avail file 220588 kB, anon mem: 2539972 kB)
<4>[122012.672578] low_mem_check: 2 callbacks suppressed
<6>[122012.672581] entering low_mem (avail RAM = 411256 kB, avail swap 622216 kB, avail file 173464 kB, anon mem: 2561992 kB)
<4>[122045.686434] low_mem_check: 11 callbacks suppressed
<6>[122045.686437] entering low_mem (avail RAM = 411568 kB, avail swap 936712 kB, avail file 144224 kB, anon mem: 2755572 kB)
<4>[122938.717495] low_mem_check: 3 callbacks suppressed
<6>[122938.717497] entering low_mem (avail RAM = 411524 kB, avail swap 848976 kB, avail file 145768 kB, anon mem: 2837636 kB)
<4>[123899.294042] low_mem_check: 1 callbacks suppressed
<6>[123899.294045] entering low_mem (avail RAM = 411580 kB, avail swap 1128196 kB, avail file 107948 kB, anon mem: 3045692 kB)
<4>[123959.440362] low_mem_check: 1 callbacks suppressed
<6>[123959.440367] entering low_mem (avail RAM = 411628 kB, avail swap 1116504 kB, avail file 130584 kB, anon mem: 3035388 kB)
<4>[123962.531731] low_mem_check: 8 callbacks suppressed
<6>[123962.531737] entering low_mem (avail RAM = 411432 kB, avail swap 1087532 kB, avail file 138800 kB, anon mem: 2996848 kB)
<6>[123966.531432] entering low_mem (avail RAM = 411640 kB, avail swap 1016124 kB, avail file 157612 kB, anon mem: 2934508 kB)
<4>[124039.275952] low_mem_check: 7 callbacks suppressed
<6>[124039.275956] entering low_mem (avail RAM = 411488 kB, avail swap 903152 kB, avail file 116668 kB, anon mem: 2853648 kB)
<6>[124042.314863] entering low_mem (avail RAM = 411628 kB, avail swap 1066144 kB, avail file 145092 kB, anon mem: 3028248 kB)
<6>[124108.189244] entering low_mem (avail RAM = 411608 kB, avail swap 1009156 kB, avail file 147240 kB, anon mem: 2783316 kB)
<4>[124114.039889] low_mem_check: 1 callbacks suppressed
<6>[124114.039892] entering low_mem (avail RAM = 411324 kB, avail swap 838680 kB, avail file 166252 kB, anon mem: 2729252 kB)
<4>[124115.320102] low_mem_check: 2 callbacks suppressed
<6>[124115.320104] entering low_mem (avail RAM = 411588 kB, avail swap 861612 kB, avail file 186468 kB, anon mem: 2829144 kB)
<4>[124116.381422] low_mem_check: 7 callbacks suppressed
<6>[124116.381425] entering low_mem (avail RAM = 411480 kB, avail swap 761828 kB, avail file 180880 kB, anon mem: 2712276 kB)
<4>[124120.574226] low_mem_check: 7 callbacks suppressed
<6>[124120.574230] entering low_mem (avail RAM = 411484 kB, avail swap 453380 kB, avail file 229412 kB, anon mem: 2432184 kB)
<4>[124121.837282] low_mem_check: 5 callbacks suppressed
<6>[124121.837289] entering low_mem (avail RAM = 411616 kB, avail swap 699220 kB, avail file 214256 kB, anon mem: 2594120 kB)
<3>[124399.176105] i2c_hid_acpi i2c-ELAN2703:00: i2c_hid_get_input: incomplete report (18/22784)
<4>[124471.563053] low_mem_check: 3 callbacks suppressed
<6>[124471.563056] entering low_mem (avail RAM = 411444 kB, avail swap 1157140 kB, avail file 86404 kB, anon mem: 3090564 kB)
<4>[126391.644830] low_mem_check: 5 callbacks suppressed
<6>[126391.644834] entering low_mem (avail RAM = 411640 kB, avail swap 760656 kB, avail file 195572 kB, anon mem: 2588092 kB)
<4>[127084.182702] low_mem_check: 2 callbacks suppressed
<6>[127084.182705] entering low_mem (avail RAM = 411528 kB, avail swap 715492 kB, avail file 226192 kB, anon mem: 2740004 kB)
<4>[127086.036020] low_mem_check: 10 callbacks suppressed
<6>[127086.036023] entering low_mem (avail RAM = 411636 kB, avail swap 662104 kB, avail file 222248 kB, anon mem: 2687260 kB)
<4>[127087.900698] low_mem_check: 13 callbacks suppressed
<6>[127087.900701] entering low_mem (avail RAM = 411356 kB, avail swap 629228 kB, avail file 227500 kB, anon mem: 2633636 kB)
<4>[127091.453093] low_mem_check: 21 callbacks suppressed
<6>[127091.453097] entering low_mem (avail RAM = 411428 kB, avail swap 952932 kB, avail file 157776 kB, anon mem: 2834896 kB)
<3>[127378.667958] uvcvideo 3-1.1:1.1: Failed to resubmit video URB (-1).
<6>[128207.774823] entering low_mem (avail RAM = 411400 kB, avail swap 885328 kB, avail file 189024 kB, anon mem: 2609332 kB)
<6>[130018.314453] entering low_mem (avail RAM = 411540 kB, avail swap 468656 kB, avail file 257688 kB, anon mem: 2344572 kB)
<6>[130671.449154] entering low_mem (avail RAM = 411436 kB, avail swap 725772 kB, avail file 170684 kB, anon mem: 2691592 kB)
<6>[131509.735411] entering low_mem (avail RAM = 411604 kB, avail swap 842260 kB, avail file 168448 kB, anon mem: 2676440 kB)
<3>[131744.017913] i2c_hid_acpi i2c-ELAN2703:00: i2c_hid_get_input: incomplete report (18/22784)
<7>[131812.125790] i915 0000:00:02.0: DP SDP: VSC, revision 0, length 0
<7>[131812.125795] i915 0000:00:02.0: pixelformat: RGB
<7>[131812.125798] i915 0000:00:02.0: colorimetry: sRGB
<7>[131812.125800] i915 0000:00:02.0: bpc: 0
<7>[131812.125802] i915 0000:00:02.0: dynamic range: VESA range
<7>[131812.125804] i915 0000:00:02.0: content type: Not defined
<3>[131815.410907] i915 0000:00:02.0: [drm] ERROR Failed to get ACT after 3000ms, last status: 00
<3>[183543.476435] i915 0000:00:02.0: [drm] ERROR mstb 00000000552c3687 port 2: DPCD read on addr 0x4b0 for 1 bytes NAKed
<7>[183545.394665] i915 0000:00:02.0: DP SDP: VSC, revision 0, length 0
<7>[183545.394669] i915 0000:00:02.0: pixelformat: RGB
<7>[183545.394671] i915 0000:00:02.0: colorimetry: sRGB
<7>[183545.394672] i915 0000:00:02.0: bpc: 0
<7>[183545.394674] i915 0000:00:02.0: dynamic range: VESA range
<7>[183545.394676] i915 0000:00:02.0: content type: Not defined
<7>[183545.395150] i915 0000:00:02.0: DP SDP: VSC, revision 0, length 0
<7>[183545.395151] i915 0000:00:02.0: pixelformat: RGB
<7>[183545.395153] i915 0000:00:02.0: colorimetry: sRGB
<7>[183545.395154] i915 0000:00:02.0: bpc: 0
<7>[183545.395155] i915 0000:00:02.0: dynamic range: VESA range
<7>[183545.395156] i915 0000:00:02.0: content type: Not defined
<3>[183552.222460] i915 0000:00:02.0: [drm] ERROR mstb 00000000552c3687 port 2: DPCD read on addr 0x4b0 for 1 bytes NAKed
<3>[183552.427177] i915 0000:00:02.0: [drm] ERROR mstb 00000000552c3687 port 2: DPCD read on addr 0x4b0 for 1 bytes NAKed
<3>[183552.633954] i915 0000:00:02.0: [drm] ERROR mstb 00000000552c3687 port 2: DPCD read on addr 0x4b0 for 1 bytes NAKed
<3>[183552.838924] i915 0000:00:02.0: [drm] ERROR mstb 00000000552c3687 port 2: DPCD read on addr 0x4b0 for 1 bytes NAKed
<3>[183562.218042] i915 0000:00:02.0: [drm] ERROR mstb 00000000552c3687 port 2: DPCD read on addr 0x4b0 for 1 bytes NAKed
<3>[183562.425074] i915 0000:00:02.0: [drm] ERROR mstb 00000000552c3687 port 2: DPCD read on addr 0x4b0 for 1 bytes NAKed
<3>[183562.632114] i915 0000:00:02.0: [drm] ERROR mstb 00000000552c3687 port 2: DPCD read on addr 0x4b0 for 1 bytes NAKed
<3>[183562.838149] i915 0000:00:02.0: [drm] ERROR mstb 00000000552c3687 port 2: DPCD read on addr 0x4b0 for 1 bytes NAKed
<6>[184213.579600] entering low_mem (avail RAM = 411496 kB, avail swap 928660 kB, avail file 172676 kB, anon mem: 2781336 kB)
<4>[184360.956361] low_mem_check: 2 callbacks suppressed
<6>[184360.956365] entering low_mem (avail RAM = 411404 kB, avail swap 581736 kB, avail file 179852 kB, anon mem: 2770060 kB)
<4>[184362.023891] low_mem_check: 3 callbacks suppressed
<6>[184362.023896] entering low_mem (avail RAM = 411580 kB, avail swap 767380 kB, avail file 130628 kB, anon mem: 2927544 kB)
<4>[184363.381561] low_mem_check: 3 callbacks suppressed
<6>[184363.381564] entering low_mem (avail RAM = 411348 kB, avail swap 719868 kB, avail file 157608 kB, anon mem: 2867816 kB)
<3>[184378.699314] sof-audio-pci-intel-tgl 0000:00:1f.3: error: memory alloc failed: -12
<3>[184378.699330] sof-audio-pci-intel-tgl 0000:00:1f.3: error: dma prepare for ICCMAX stream failed
<3>[184378.699334] sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed to reset DSP
<3>[184378.699337] sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed to boot DSP firmware after resume -12
<3>[184378.699344] sof-audio-pci-intel-tgl 0000:00:1f.3: ASoC: error at snd_soc_pcm_component_pm_runtime_get on 0000:00:1f.3: -12
@sathyap-chrome @Vamshigopal @kv2019i @ranj063
kv2019i commentedon Mar 17, 2022
@sathya-nujella This looks like something else. Here the Linux side memory alloc is failing:
<3>[184378.699314] sof-audio-pci-intel-tgl 0000:00:1f.3: error: memory alloc failed: -12
.. and as a result, DSP boot fails.
cujomalainey commentedon Mar 17, 2022
@kv2019i yea that is what I concluded too, and top always reports about <250MB free when it happens
sathyap-chrome commentedon May 25, 2022
couple more customer reports also show this
[19294.505767] sof-audio-pci-intel-tgl 0000:00:1f.3: error: stream frags exceeded
[19294.505777] sof-audio-pci-intel-tgl 0000:00:1f.3: error: set up of BDL failed
[19294.505780] sof-audio-pci-intel-tgl 0000:00:1f.3: error: iccmax stream prepare failed: -22
[19294.505965] sof-audio-pci-intel-tgl 0000:00:1f.3: error: dma prepare for ICCMAX stream failed
[19294.505968] sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed to reset DSP
[19294.505970] sof-audio-pci-intel-tgl 0000:00:1f.3: error: failed to boot DSP firmware after resume -22
We need to get a good reproduction step and then verify with IMR enabled.
plbossart commentedon May 25, 2022
@sathyap-chrome I thought iccmax was not useful for TGL? @ranj063 am I mistaken?
plbossart commentedon Jun 29, 2022
@cujomalainey @sathya-nujella @kv2019i the information in this issue is either very old, obsolete. If there's still an issue please open a new one to better track it. Closing this one for now.
cujomalainey commentedon Jun 29, 2022
I think we can closed this out without concern, we learned later it is likely a issue in a different domain that is breaking it
sathya-nujella commentedon Jun 30, 2022
Thank you @cujomalainey for the update.