Skip to content

[SDW][BUG]ipc timed out for 0x40080000 size 32 occurred when run reboot stress test with legacy IRQ mode #1468

New issue
New issue
Closed
Closed
[SDW][BUG]ipc timed out for 0x40080000 size 32 occurred when run reboot stress test with legacy IRQ mode#1468
Assignees
bardliao
Labels
CMLApplies to Comet Lake platformLegacy IRQIssues observed only in legacy IRQ modeSDWApplies to SoundWire bus for codec connectionbugSomething isn't working

Description

@YvonneYang2
YvonneYang2
opened on Nov 12, 2019

Describe the bug
With legacy IRQ mode, ipc timed out for 0x40080000 size 32 occurred when run reboot stress test. Failed at 147th time.

To Reproduce

  1. Run "sudo ./test-reboot.sh 300"

test-reboot.sh.txt

Reproduced rate
Run 300 times, failed 5 times

Expected result
No error occurred when run reboot stress test

Actual result
ipc timed out for 0x40080000 size 32 occurred when run reboot stress test.

dmesg 
[   26.496551] PM: Creating hibernation image:
[   26.632642] PM: Need to copy 438825 pages
[   26.632645] PM: Normal pages needed: 438825 + 1024, available pages: 1606054
[   27.076293] PM: Hibernation image created (438825 pages copied)
[   26.497797] Enabling non-boot CPUs ...
[   26.497827] x86: Booting SMP configuration:
[   26.497829] smpboot: Booting Node 0 Processor 1 APIC 0x2
[   26.498920] CPU1 is up
[   26.498940] smpboot: Booting Node 0 Processor 2 APIC 0x4
[   26.500158] CPU2 is up
[   26.500182] smpboot: Booting Node 0 Processor 3 APIC 0x6
[   26.501328] CPU3 is up
[   26.501348] smpboot: Booting Node 0 Processor 4 APIC 0x1
[   26.502534] CPU4 is up
[   26.502554] smpboot: Booting Node 0 Processor 5 APIC 0x3
[   26.503513] CPU5 is up
[   26.503529] smpboot: Booting Node 0 Processor 6 APIC 0x5
[   26.504500] CPU6 is up
[   26.504515] smpboot: Booting Node 0 Processor 7 APIC 0x7
[   26.505445] CPU7 is up
[   26.508240] ACPI: EC: interrupt unblocked
[   26.535533] sof-audio-pci 0000:00:1f.3: snd_sof_resume
[   26.535535] sof-audio-pci 0000:00:1f.3: DSP will exit from D0i3...
[   26.535549] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40080000: GLB_PM_MSG: unknown type
[   26.739995] nvme nvme0: 8/0/0 default/read/poll queues
[   27.042637] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40080000 size 32
[   27.042642] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[   27.042652] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[   27.042908] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[   27.042916] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0xc0000000 intlctl 0xc0000001 rirb 01
[   27.042919] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x80000000 adspis 0x00000001
[   27.042926] sof-audio-pci 0000:00:1f.3: error: host status 0x80000000 dsp status 0x90020000 mask 0x00000003
[   27.042928] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[   27.042932] sof-audio-pci 0000:00:1f.3: error: PM_GATE ipc error -110
[   27.042935] sof-audio-pci 0000:00:1f.3: error: failed to exit from D0I3 -110
[   27.042948] PM: dpm_run_callback(): pci_pm_thaw+0x0/0x80 returns -110
[   27.042957] PM: Device 0000:00:1f.3 failed to thaw: error -110
[   27.042968] intel-sdw sdw-master-0: intel_resume start
[   27.043580] rt711 sdw:0:25d:711:0: sdw_modify_slave_status: initializing completion for Slave 1
[   27.043698] intel-sdw sdw-master-0: intel_resume done
[   27.562629] i2c_designware i2c_designware.1: controller timed out
[   27.562644] i2c_hid i2c-DELL08AF:00: failed to change power setting.
[   27.562657] PM: dpm_run_callback(): i2c_hid_resume+0x0/0xe0 [i2c_hid] returns -110
[   27.562666] PM: Device i2c-DELL08AF:00 failed to thaw async: error -110
[   29.098654] rt711 sdw:0:25d:711:0: Initialization not complete, timed out
[   29.098673] PM: dpm_run_callback(): rt711_dev_resume+0x0/0x90 [snd_soc_rt711] returns -110
[   29.098681] PM: Device sdw:0:25d:711:0 failed to thaw: error -110
[   29.098693] intel-sdw sdw-master-1: intel_resume start
[   29.099099] rt1308 sdw:1:25d:1308:0: sdw_modify_slave_status: initializing completion for Slave 1
[   29.099218] intel-sdw sdw-master-1: intel_resume done
[   31.146653] rt1308 sdw:1:25d:1308:0: Initialization not complete, timed out
[   31.146670] PM: dpm_run_callback(): rt1308_dev_resume+0x0/0x70 [snd_soc_rt1308_sdw] returns -110
[   31.146677] PM: Device sdw:1:25d:1308:0 failed to thaw: error -110
[   31.146688] intel-sdw sdw-master-3: intel_resume start
[   31.147091] rt715 sdw:3:25d:715:0: sdw_modify_slave_status: initializing completion for Slave 1
[   31.147210] intel-sdw sdw-master-3: intel_resume done
[   33.194653] rt715 sdw:3:25d:715:0: Initialization not complete, timed out
[   33.194671] PM: dpm_run_callback(): rt715_dev_resume+0x0/0x90 [snd_soc_rt715] returns -110
[   33.194678] PM: Device sdw:3:25d:715:0 failed to thaw: error -110
[   33.194715] sdw_rt711_rt1308_rt715 sdw_rt711_rt1308_rt715: ASoC: Scheduli

Test recipe:
kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: 391b5f9
FW: https://github.com/thesofproject/sof/commits/master commit: fb068e6
tplg: same path as FW branch, sof-cml-rt711-rt1308-mono-rt715.tplg
platform: CML SDW Laptop with ALC711+ ALC1308+ ALC715

dmesg_failed_147.log

Activity

  1. YvonneYang2
    added
    bugSomething isn't working
    CMLApplies to Comet Lake platform
    SDWApplies to SoundWire bus for codec connection
    on Nov 12, 2019

  2. YvonneYang2 commented on Nov 12, 2019

    @YvonneYang2
    YvonneYang2
    on Nov 12, 2019
    Author

    Will test it with legacy mode + #1451 to check if can resolve this issue

  3. mengdonglin
    added
    Legacy IRQIssues observed only in legacy IRQ mode
    on Nov 13, 2019

  4. YvonneYang2 commented on Nov 14, 2019

    @YvonneYang2
    YvonneYang2
    on Nov 14, 2019
    Author

    @bardliao
    Issue cannot be reproduced with latest-soundwire-latest(fb40b85) + #1451 in 500 times reboot stress test with Legacy IRQ mode. But occurred once call trace and "snd_soc_register_card failed -517“ at 419th time.

    Reprodued rate
    1/500

    dmesg

    [    3.011691] rt715 sdw:3:25d:715:0: ASoC: Registered DAI 'rt715-aif2'
[    3.011692] rt715 sdw:3:25d:715:0: probe complete
[    3.050237] ------------[ cut here ]------------
[    3.050242] irq 17 handler hda_dsp_ipc_irq_handler+0x0/0x70 [snd_sof_intel_hda_common] enabled interrupts
[    3.050246] WARNING: CPU: 5 PID: 0 at kernel/irq/handle.c:153 __handle_irq_event_percpu+0x178/0x180
[    3.050246] Modules linked in: snd_soc_rt715 snd_soc_rt711 snd_soc_rt1308_sdw snd_soc_rt700 regmap_sdw snd_soc_dmic snd_sof_pci snd_sof_intel_hda_common snd_soc_hdac_hda soundwire_intel_init hid_multitouch(+) soundwire_intel soundwire_generic_allocation soundwire_cadence snd_sof_intel_hda snd_sof_intel_byt snd_soc_acpi_intel_match snd_sof_intel_ipc snd_sof snd_sof_xtensa_dsp snd_soc_acpi snd_hda_ext_core soundwire_bus snd_soc_core snd_intel_dspcfg snd_hda_codec snd_hwdep snd_hda_core snd_pcm snd_seq_midi snd_seq_midi_event snd_rawmidi snd_seq wmi_bmof snd_seq_device snd_timer snd soundcore asix(+) usbnet x86_pkg_temp_thermal intel_powerclamp mei_me intel_lpss_pci mei intel_lpss mfd_core processor_thermal_device intel_soc_dts_iosf wmi int3403_thermal int340x_thermal_zone int3400_thermal acpi_thermal_rel efivarfs i915 i2c_algo_bit drm_kms_helper syscopyarea sysfillrect sysimgblt fb_sys_fops xhci_pci xhci_hcd drm i2c_hid
[    3.050265] CPU: 5 PID: 0 Comm: swapper/5 Not tainted 5.4.0-rc7-sdw-validation-20191113-pr1451-0-9e36022 #rc7
[    3.050266] Hardware name: Dell Inc. Latitude 9510/, BIOS 0.1.3 10/01/2019
[    3.050267] RIP: 0010:__handle_irq_event_percpu+0x178/0x180
[    3.050268] Code: e8 86 ed ff ff e9 20 ff ff ff 45 31 e4 e9 24 ff ff ff 48 8b 13 89 ee 48 c7 c7 60 1c 3c 85 c6 05 ec ca 26 01 01 e8 38 97 fa ff <0f> 0b eb b2 0f 1f 40 00 55 53 48 89 fb 48 83 ec 10 48 8d 74 24 04
[    3.050269] RSP: 0018:ffff975700204f40 EFLAGS: 00010286
[    3.050269] RAX: 0000000000000000 RBX: ffff92f1a2ba9580 RCX: 0000000000000006
[    3.050270] RDX: 0000000000000007 RSI: 0000000000000082 RDI: ffff92f1a43563d0
[    3.050270] RBP: 0000000000000011 R08: 000000000000043a R09: 0000000000000004
[    3.050271] R10: ffff975700204ec8 R11: 0000000000000001 R12: 0000000000000003
[    3.050271] R13: ffff975700204f84 R14: 0000000000000000 R15: 0000000000000000
[    3.050272] FS:  0000000000000000(0000) GS:ffff92f1a4340000(0000) knlGS:0000000000000000
[    3.050272] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[    3.050273] CR2: 0000560c8e2a7d30 CR3: 000000029e17c001 CR4: 00000000003606e0
[    3.050273] Call Trace:
[    3.050275]  <IRQ>
[    3.050276]  handle_irq_event_percpu+0x2b/0x70
[    3.050277]  handle_irq_event+0x22/0x40
[    3.050279]  handle_fasteoi_irq+0x71/0x120
[    3.050281]  do_IRQ+0x41/0xd0
[    3.050282]  common_interrupt+0xf/0xf
[    3.050283]  </IRQ>
[    3.050285] RIP: 0010:cpuidle_enter_state+0xad/0x420
[    3.050286] Code: c4 0f 1f 44 00 00 31 ff e8 f0 b9 9f ff 80 7c 24 0b 00 74 12 9c 58 f6 c4 02 0f 85 49 03 00 00 31 ff e8 97 de a4 ff fb 45 85 ed <0f> 88 17 03 00 00 4c 2b 24 24 48 ba cf f7 53 e3 a5 9b c4 20 49 63
[    3.050287] RSP: 0018:ffff97570010fe80 EFLAGS: 00000202 ORIG_RAX: ffffffffffffffdb
[    3.050287] RAX: ffff92f1a4367940 RBX: ffffffff856af7a0 RCX: 000000000000001f
[    3.050288] RDX: 00000000b5ceb72a RSI: 000000003c9b3031 RDI: 0000000000000000
[    3.050288] RBP: ffff92f19fab2800 R08: 0000000000000002 R09: 00000000000271c0
[    3.050289] R10: ffff97570010fe68 R11: 0000000000000031 R12: 00000000b5ceb72a
[    3.050289] R13: 0000000000000001 R14: 0000000000000001 R15: 0000000000000000
[    3.050291]  cpuidle_enter+0x24/0x40
[    3.050293]  do_idle+0x1d6/0x230
[    3.050294]  cpu_startup_entry+0x14/0x20
[    3.050296]  start_secondary+0x152/0x1a0
[    3.050297]  secondary_startup_64+0xa4/0xb0
[    3.050298] ---[ end trace f6b4d7cae352b2d1 ]---
[    3.059231] input: DELL08AF:00 0488:120A Mouse as /devices/pci0000:00/0000:00:15.1/i2c_designware.1/i2c-9/i2c-DELL08AF:00/0018:0488:120A.0001/input/input10
[    3.059270] input: DELL08AF:00 0488:120A Touchpad as /devices/pci0000:00/0000:00:15.1/i2c_designware.1/i2c-9/i2c-DELL08AF:00/0018:0488:120A.0001/input/input11
[    3.059297] input: DELL08AF:00 0488:120A UNKNOWN as /devices/pci0000:00/0000:00:15.1/i2c_designware.1/i2c-9/i2c-DELL08AF:00/0018:0488:120A.0001/input/input12
[    3.059326] hid-multitouch 0018:0488:120A.0001: input,hidraw0: I2C HID v1.00 Mouse [DELL08AF:00 0488:120A] on i2c-DELL08AF:00
[    3.315282] asix 1-6.1:1.0 eth0: register 'asix' at usb-0000:00:14.0-6.1, ASIX AX88772B USB 2.0 Ethernet, 00:0e:c6:c6:86:d3
[    3.315323] usbcore: registered new interface driver asix
[    3.318122] asix 1-6.1:1.0 enx000ec6c686d3: renamed from eth0
[    3.339761] systemd-udevd (267) used greatest stack depth: 11064 bytes left
[    4.006983] sof-audio-pci 0000:00:1f.3: error: codec #1 probe error, ret: -5
[    4.006987] sof-audio-pci 0000:00:1f.3: Turning i915 HDAC power off
[    4.007097] sof-audio-pci 0000:00:1f.3: loading firmware
[    4.008339] sof-audio-pci 0000:00:1f.3: Debug PCIR: 00000002 at  00000048

    dmesg_failed_419.log

  5. mengdonglin
    assigned
    bardliao
    on Nov 20, 2019

  6. mengdonglin commented on Nov 25, 2019

    @mengdonglin
    mengdonglin
    on Nov 25, 2019

    @YvonneYang2 Please verify latest ttps://github.com/thesofproject/linux/tree/integration/soundwire-latest

    PR #1451 was replaced by PR #1483, and PR #1483 was merged by integration/soundwire-latest

  7. bardliao commented on Nov 25, 2019

    @bardliao
    bardliao
    on Nov 25, 2019
    Collaborator

    @YvonneYang2 Could you retest it with #1543?

  8. YvonneYang2 commented on Nov 25, 2019

    @YvonneYang2
    YvonneYang2
    on Nov 25, 2019
    Author

    Tested reboot stress test 300 times with #1543 in legacy IRQ mode, issue cannot be reproduced.

    But still can reproduce call trace and "snd_soc_register_card failed -517“ same as #1468 (comment). Will try with latest soundwire-latest branch, if issue can still be reproduced, will report a new issue to track it.

    Test recipe:
    kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: 68cadd8 + #1543
    FW: https://github.com/thesofproject/sof/commits/master commit: d6fe2b1
    tplg: Same with FW branch, sof-cml-rt711-rt1308-mono-rt715.tplg
    platform: CML Laptop with ALC711+ ALC1308+ ALC715

  9. bardliao commented on Nov 25, 2019

    @bardliao
    bardliao
    on Nov 25, 2019
    Collaborator

    @YvonneYang2 @plbossart #1468 (comment) seems be similar to #1540?

  10. YvonneYang2 commented on Nov 27, 2019

    @YvonneYang2
    YvonneYang2
    on Nov 27, 2019
    Author

    Tested it 300 times with #1548 , issue cannot be reproduced.

    kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: a370cb0 + #1548
    FW: https://github.com/thesofproject/sof/commits/master commit: db7671a
    tplg: Same with FW branch, sof-cml-rt711-rt1308-mono-rt715.tplg
    platform: CML Laptop with ALC711+ ALC1308+ ALC715 in SDW mode

  11. YvonneYang2 commented on Nov 28, 2019

    @YvonneYang2
    YvonneYang2
    on Nov 28, 2019
    Author

    Tested reboot stress test 500 times with legacy IRQ mode after #1548 has been merged into integration/soundwire-latest branch, issue cannot be reproduced. Close it.

    Test recipe:
    kernel: https://github.com/thesofproject/linux/tree/integration/soundwire-latest commit: d6078f9
    FW: https://github.com/thesofproject/sof/commits/master commit: d740a3e
    tplg: Same with FW branch, sof-cml-rt711-rt1308-mono-rt715.tplg
    platform: CML Laptop with ALC711+ ALC1308+ ALC715 in SDW mode

  12. YvonneYang2
    closed this as completedon Nov 28, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

CMLApplies to Comet Lake platformLegacy IRQIssues observed only in legacy IRQ modeSDWApplies to SoundWire bus for codec connectionbugSomething isn't working

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions