[BUG]Enabling/disabling secondary cores in a loop fails with an IDC timeout

Describe the bug
Enabling/disabling the secondary cores by sending the PM_CORE_ENABLE IPCs in a loop results in an IDC timeout within20-30 iterations eventually leading to a DSP Panic. Increasing the MEMORY_POWER_CHANGE_DELAY from 256 to 512 helps to a certain extent but the test fails within a few hundred iterations with the same result.

To Reproduce
Send PM_CORE_ENABLE IPC to enable cores 1-3 in a loop.

Reproduction Rate
100% reproduction within 10s of iterations.

Expected behavior
Should be able to enable/disable cores without issues.

Impact
Cannot enable dynamic pipelines with multi-core reliably.

Environment

Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
- Kernel: 16d5c4522645e5754910910df8b9bf20fc4d5fca
- SOF: d486a9f
Name of the topology file
- Topology: sof-adl-nocodec.tplg
Name of the platform(s) on which the bug is observed.
- Platform: ADL RVP

Screenshots or console output

[   34.145262] sof-audio-pci-intel-tgl 0000:00:1f.3: ranjani disabling core 1
[   34.145271] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.145364] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.146157] sof-audio-pci-intel-tgl 0000:00:1f.3: ranjani enabling core 2
[   34.146167] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.156484] sof-audio-pci-intel-tgl 0000:00:1f.3: error: ipc error for 0x40070000 size 12
[   34.157313] sof-audio-pci-intel-tgl 0000:00:1f.3: ranjani disabling core 2
[   34.157319] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.157387] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.158248] sof-audio-pci-intel-tgl 0000:00:1f.3: ranjani enabling core 3
[   34.158258] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.158603] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.159428] sof-audio-pci-intel-tgl 0000:00:1f.3: ranjani disabling core 3
[   34.159434] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.159495] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.160222] sof-audio-pci-intel-tgl 0000:00:1f.3: ranjani enabling core 1
[   34.160228] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.160594] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.160871] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[   34.160883] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
[   34.161266] sof-audio-pci-intel-tgl 0000:00:1f.3: ranjani disabling core 1
[   34.161271] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.161347] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.162001] sof-audio-pci-intel-tgl 0000:00:1f.3: ranjani enabling core 2
[   34.162007] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.172383] sof-audio-pci-intel-tgl 0000:00:1f.3: error: ipc error for 0x40070000 size 12
[   34.173178] sof-audio-pci-intel-tgl 0000:00:1f.3: ranjani disabling core 2
[   34.173183] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.173383] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.174221] sof-audio-pci-intel-tgl 0000:00:1f.3: ranjani enabling core 3
[   34.174230] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.174789] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.175610] sof-audio-pci-intel-tgl 0000:00:1f.3: ranjani disabling core 3
[   34.175619] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.175827] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.176537] sof-audio-pci-intel-tgl 0000:00:1f.3: ranjani enabling core 1
[   34.176542] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.176989] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.177711] sof-audio-pci-intel-tgl 0000:00:1f.3: ranjani disabling core 1
[   34.177716] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.177915] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.178747] sof-audio-pci-intel-tgl 0000:00:1f.3: ranjani enabling core 2
[   34.178754] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40070000: GLB_PM_MSG: CORE_ENABLE
[   34.178920] sof-audio-pci-intel-tgl 0000:00:1f.3: error : DSP panic!
[   34.178930] sof-audio-pci-intel-tgl 0000:00:1f.3: panic: dsp_oops_offset 788480 offset 788480
[   34.178938] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump start ]------------
[   34.178944] sof-audio-pci-intel-tgl 0000:00:1f.3: status: fw entered - code 00000005
[   34.179062] sof-audio-pci-intel-tgl 0000:00:1f.3: error: out of memory
[   34.179067] sof-audio-pci-intel-tgl 0000:00:1f.3: error: trace point 00004000
[   34.179071] sof-audio-pci-intel-tgl 0000:00:1f.3: error: panic at src/lib/alloc.c:161
[   34.179076] sof-audio-pci-intel-tgl 0000:00:1f.3: error: DSP Firmware Oops
[   34.179079] sof-audio-pci-intel-tgl 0000:00:1f.3: EXCCAUSE 0x0000003f EXCVADDR 0x00000000 PS       0x00060b25 SAR     0x00000000
[   34.179085] sof-audio-pci-intel-tgl 0000:00:1f.3: EPC1     0x00000000 EPC2     0xbe046742 EPC3     0x00000000 EPC4    0x00000000
[   34.179090] sof-audio-pci-intel-tgl 0000:00:1f.3: EPC5     0x00000000 EPC6     0x00000000 EPC7     0x00000000 DEPC    0x00000000
[   34.179095] sof-audio-pci-intel-tgl 0000:00:1f.3: EPS2     0x00060b20 EPS3     0x00000000 EPS4     0x00000000 EPS5    0x00000000
[   34.179099] sof-audio-pci-intel-tgl 0000:00:1f.3: EPS6     0x00000000 EPS7     0x00000000 INTENABL 0x00000000 INTERRU 0x00000222
[   34.179104] sof-audio-pci-intel-tgl 0000:00:1f.3: stack dump from 0xbe111d50
[   34.179110] sof-audio-pci-intel-tgl 0000:00:1f.3: 0xbe111d50: 1fffa540 00ffffff 4e36f316 00000000
[   34.179116] sof-audio-pci-intel-tgl 0000:00:1f.3: 0xbe111d54: be043761 be111df0 9e072028 00000000
[   34.179121] sof-audio-pci-intel-tgl 0000:00:1f.3: 0xbe111d58: 7402ad00 5f7ceff3 08eb7828 ffff8d64
[   34.179125] sof-audio-pci-intel-tgl 0000:00:1f.3: 0xbe111d5c: 000c0800 00000000 08eb7828 ffff8d64
[   34.179130] sof-audio-pci-intel-tgl 0000:00:1f.3: 0xbe111d60: 08eb7828 ffff8d64 000000b4 00000000
[   34.179134] sof-audio-pci-intel-tgl 0000:00:1f.3: 0xbe111d64: 07e05340 ffff8d64 0a01f000 ffff8d64
[   34.179138] sof-audio-pci-intel-tgl 0000:00:1f.3: 0xbe111d68: 7402ad00 5f7ceff3 88ccff50 ffffffff
[   34.179143] sof-audio-pci-intel-tgl 0000:00:1f.3: 0xbe111d6c: 02306b80 ffff8d64 88c8d6c0 ffffffff
[   34.179146] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ DSP dump end ]------------
[   34.679854] sof-audio-pci-intel-tgl 0000:00:1f.3: error: ipc timed out for 0x40070000 size 12
[   34.679867] sof-audio-pci-intel-tgl 0000:00:1f.3: preventing DSP entering D3 state to preserve context
[   34.679872] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump start ]------------
[   34.679883] sof-audio-pci-intel-tgl 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000001 rirb 00
[   34.679889] sof-audio-pci-intel-tgl 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[   34.679897] sof-audio-pci-intel-tgl 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[   34.679902] sof-audio-pci-intel-tgl 0000:00:1f.3: ------------[ IPC dump end ]------------

@ranj063

@ranj063 do you have the FW log of it?

Looks we have memory leak during DSP core disable/enable cycles and it lead to system zone used up eventually.

@keyonjie

@keyonjie the out of memory panic is because of a flaw in my script that goes on and does disabling he core after enabling fails. The real problem though is the first IPC error in my dmesg log which is actually because of an IDC timeout when trying to enable the core:

[    61165087.152851] (           0.000000) c0 <uid?>               src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x9 -> enable
[      737055.491545] (      737055.500000) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x3 -> enable

Found valid LDC address after skipping 16 bytes (one line uses 20 + 0 to 16 bytes)

		 --- negative DELTA = -232793.012 us: wrap, IPC_TRACE, other? ---

[    61669349.632814] (           0.000000) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x9 -> enable
[      234933.896915] (      234933.890625) c0 ipc                /schedule/edf_schedule.c:260  INFO edf_scheduler_init()

Found valid LDC address after skipping 4 bytes (one line uses 20 + 0 to 16 bytes)
[      234961.969830] (          28.072916) c1 idc                ......./intel/cavs/idc.c:58   INFO idc_irq_handler(), IPC_IDCTFC_BUSY
[      235017.073995] (          55.104164) c1 idc                ......./intel/cavs/idc.c:165  INFO idc_do_cmd()

Found valid LDC address after skipping 20 bytes (one line uses 20 + 0 to 16 bytes)
[      236336.501025] (        1319.427002) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x5 -> enable
[      236640.719763] (         304.218750) c2 edf-schedule       /schedule/edf_schedule.c:260  INFO edf_scheduler_init()
[      236777.386425] (         136.666656) c2 idc                           src/idc/idc.c:321  INFO idc_init()

Found valid LDC address after skipping 24 bytes (one line uses 20 + 0 to 16 bytes)
[      238767.438429] (        1990.052002) c2 idc                ......./intel/cavs/idc.c:58   INFO idc_irq_handler(), IPC_IDCTFC_BUSY

Found valid LDC address after skipping 16 bytes (one line uses 20 + 0 to 16 bytes)

		 --- negative DELTA = -735749.033 us: wrap, IPC_TRACE, other? ---

[    61172368.037978] (           0.000000) c0 <uid?>               src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x5 -> enable
[      737295.960286] (      737295.937500) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x9 -> enable
[      737586.012358] (         290.052063) c3 edf-schedule       /schedule/edf_schedule.c:260  INFO edf_scheduler_init()
[      737723.043602] (         137.031250) c3 idc                           src/idc/idc.c:321  INFO idc_init()

		 --- negative DELTA = -228170.564 us: wrap, IPC_TRACE, other? ---

[    61681920.517731] (           0.000000) c2 edf-schedule       /schedule/edf_schedule.c:260  INFO edf_scheduler_init()

Found valid LDC address after skipping 20 bytes (one line uses 20 + 0 to 16 bytes)
[        2701.197809] (        2701.197754) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x1 -> enable

Found valid LDC address after skipping 20 bytes (one line uses 20 + 0 to 16 bytes)
[      232129.990776] (      229428.796875) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x3 -> enable

Found valid LDC address after skipping 16 bytes (one line uses 20 + 0 to 16 bytes)

		 --- negative DELTA = -227375.668 us: wrap, IPC_TRACE, other? ---

[    61686674.840458] (           0.000000) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x9 -> enable
[      229821.761701] (      229821.765625) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x1fffaa80 -> enable
[      229849.782533] (          28.020832) c1 idc                ......./intel/cavs/idc.c:58   INFO idc_irq_handler(), IPC_IDCTFC_BUSY
[      229904.417948] (          54.635414) c1 idc                ......./intel/cavs/idc.c:165  INFO idc_do_cmd()
[      229966.345029] (          61.927082) c1 idc                ......./intel/cavs/idc.c:235  INFO idc_free()
[      231588.376214] (        1622.031128) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x5 -> enable
[      231899.001202] (         310.625000) c2 edf-schedule       /schedule/edf_schedule.c:260  INFO edf_scheduler_init()
[      232035.615780] (         136.614578) c2 idc                           src/idc/idc.c:321  INFO idc_init()

Found valid LDC address after skipping 24 bytes (one line uses 20 + 0 to 16 bytes)
[      234168.896945] (        2133.281250) c2 idc                ......./intel/cavs/idc.c:58   INFO idc_irq_handler(), IPC_IDCTFC_BUSY
[      234223.376109] (          54.479164) c2 idc                ......./intel/cavs/idc.c:165  INFO idc_do_cmd()

Found valid LDC address after skipping 20 bytes (one line uses 20 + 0 to 16 bytes)
[      235754.730215] (        1531.354126) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x9 -> enable
[      236045.042704] (         290.312500) c3 edf-schedule       /schedule/edf_schedule.c:260  INFO edf_scheduler_init()
[      236182.021865] (         136.979156) c3 idc                           src/idc/idc.c:321  INFO idc_init()

Found valid LDC address after skipping 24 bytes (one line uses 20 + 0 to 16 bytes)
[      238087.959289] (        1905.937378) c3 idc                ......./intel/cavs/idc.c:58   INFO idc_irq_handler(), IPC_IDCTFC_BUSY

Found valid LDC address after skipping 16 bytes (one line uses 20 + 0 to 16 bytes)

		 --- negative DELTA = -738141.950 us: wrap, IPC_TRACE, other? ---

[    61186620.849912] (           0.000000) c0 <uid?>               src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x9 -> enable
[      739792.939353] (      739792.937500) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x3 -> enable

Found valid LDC address after skipping 16 bytes (one line uses 20 + 0 to 16 bytes)

		 --- negative DELTA = -225806.866 us: wrap, IPC_TRACE, other? ---

[    61700606.923238] (           0.000000) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x9 -> enable
[      228313.168011] (      228313.171875) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x1 -> enable

Found valid LDC address after skipping 16 bytes (one line uses 20 + 0 to 16 bytes)

		 --- negative DELTA = -225982.074 us: wrap, IPC_TRACE, other? ---

[    61702938.016896] (           0.000000) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x1 -> enable

Found valid LDC address after skipping 20 bytes (one line uses 20 + 0 to 16 bytes)
[      227648.220121] (      227648.218750) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x5 -> enable

Found valid LDC address after skipping 16 bytes (one line uses 20 + 0 to 16 bytes)

		 --- negative DELTA = -225917.491 us: wrap, IPC_TRACE, other? ---

[    61704668.745993] (           0.000000) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x3 -> enable
[         304.062488] (         304.062500) c1 ipc                /schedule/edf_schedule.c:260  INFO edf_scheduler_init()

Found valid LDC address after skipping 4 bytes (one line uses 20 + 0 to 16 bytes)
[      228211.970098] (      227907.906250) c2 idc                ......./intel/cavs/idc.c:58   INFO idc_irq_handler(), IPC_IDCTFC_BUSY
[      228267.386763] (          55.416664) c2 idc                ......./intel/cavs/idc.c:165  INFO idc_do_cmd()

Found valid LDC address after skipping 20 bytes (one line uses 20 + 0 to 16 bytes)
[      229767.803370] (        1500.416626) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x9 -> enable
[      230058.063775] (         290.260406) c3 edf-schedule       /schedule/edf_schedule.c:260  INFO edf_scheduler_init()
[      230194.938770] (         136.875000) c3 idc                           src/idc/idc.c:321  INFO idc_init()

Found valid LDC address after skipping 24 bytes (one line uses 20 + 0 to 16 bytes)
[      231959.261616] (        1764.322876) c3 idc                ......./intel/cavs/idc.c:58   INFO idc_irq_handler(), IPC_IDCTFC_BUSY

Found valid LDC address after skipping 16 bytes (one line uses 20 + 0 to 16 bytes)

		 --- negative DELTA = -738831.846 us: wrap, IPC_TRACE, other? ---

[    61197796.161968] (           0.000000) c0 <uid?>               src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x9 -> enable
[      740674.293485] (      740674.312500) c0 ipc                  src/ipc/ipc3/handler.c:661  INFO ipc: pm core mask 0x3 -> enable
[      760951.792679] (       20277.500000) c0 idc                           src/idc/idc.c:114  ERROR idc_wait_in_blocking_mode() error: timeout, target_core 1
[      760969.188512] (          17.395832) c0 idc                ......./intel/cavs/idc.c:147  ERROR idc_send_msg(), power up core 1 failed, reason 0x0
[      760986.167678] (          16.979166) c0 ipc                  src/ipc/ipc3/handler.c:668  ERROR Failed to enable core 1

@ranj063

@ranj063 Okay, then we need to focus on the IDC timeout.

@keyonjie

@keyonjie and @ranj063 please locally merge #4608
This should held shed light on the IDC blockers....

Navigation Menu

Repository navigation

[BUG]Enabling/disabling secondary cores in a loop fails with an IDC timeout #4602

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[BUG]Enabling/disabling secondary cores in a loop fails with an IDC timeout #4602

Description

Activity

keyonjie commented on Aug 5, 2021

keyonjie commented on Aug 5, 2021

ranj063 commented on Aug 5, 2021

keyonjie commented on Aug 6, 2021

lgirdwood commented on Aug 6, 2021

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions