Skip to content

comp_new ipc failure due to invalid ipc size with SMP arch option #766

Closed
Closed
comp_new ipc failure due to invalid ipc size with SMP arch option#766
Assignees
ranj063
Labels
APLApplies to Apollolake platformGLKApplies to Gemini Lake platformP1Blocker bugs or important featuresbugSomething isn't working as expectedreverifyIssue to be reverified

Description

@ranj063
ranj063
opened on Dec 20, 2018

I ran into this issue today where the comp_new ipc failed because of invalid size during the suspend_stress_test. I did not use the chrome suspend_stress_test command but instead used a
custom script to suspend and resume the dsp using a debugfs entry.

The ipc size is 76 which seems to be correct but the config.hdr.size doesnt match the expected size.

dmesg logs:

[  253.116672] sof-audio sof-audio: ipc tx: 0x30010000
[  253.116796] sof-audio sof-audio: ipc tx succeeded: 0x30010000
[  253.116811] sof-audio sof-audio: ipc tx: 0x30100000
[  253.116905] sof-audio sof-audio: ipc tx succeeded: 0x30100000
[  253.116934] sof-audio sof-audio: ipc tx: 0x30010000
[  253.117204] sof-audio sof-audio: error: ipc error for 0x30010000 size 0x14
[  253.117223] sof-audio sof-audio: error: failed to load widget type 23 with ID: 27
[  253.117226] sof-audio sof-audio: error: failed to restore pipeline after resume -22

logger:

0      2         PIPE             95961.562500        18.177084           pipeline.c:245 	pipeline_new()
    0      2          IPC             96060.781250        99.218750            apl-ipc.c:114 	ipc: msg rx -> 0x30010000
    0      2          IPC             96114.687500        53.906250            handler.c:908 	ipc: hdr 0x30010000 tx (76) > rx (28)
    0      2          IPC             96118.333333         3.645833            handler.c:911 	ipc: pipe 5 comp 27 -> new (type 1)
    0      2         HOST             96131.093750        12.760417               host.c:338 	host_new()
    0      1         HOST             96135.156250         4.062500               host.c:341 	ipc: size 0 expected 36
    0      1         COMP             96141.354167         6.197917          component.c:90  	comp_new() error: unable to create the new component
    0      1          IPC             96146.406250         5.052083                ipc.c:119 	ipc_comp_new() error: component cd = NULL

Steps to reproduce:
kernel: https://github.com/ranj063/linux/tree/debug/suspend_stress_test
FW & TPLG : glk-005-drop-stable

Run the following script on the device after boot:
https://github.com/ranj063/misc/blob/master/pm_script.sh

Activity

  1. ranj063
    added
    bugSomething isn't working as expected
    P1Blocker bugs or important features
    and removed
    P1Blocker bugs or important features
    bugSomething isn't working as expected
    on Dec 20, 2018
  2. jajanusz
    assigned
    dabekjakub
    on Dec 20, 2018

  3. lgirdwood commented on Dec 20, 2018

    @lgirdwood
    lgirdwood
    on Dec 20, 2018
    Member

    @jajanusz @dabekjakub, @ranj063 mentioned a similar bug on this mornings call, can we confirm what the hdr.size is on the DSP and host sides. It could be some corruption at one end....

  4. ranj063 commented on Dec 20, 2018

    @ranj063
    ranj063
    on Dec 20, 2018
    CollaboratorAuthor

    @dabekjakub I have pushed some changed to the kernel to print debug messages with the ipc data before sending the ipc to the same branch as below:
    https://github.com/ranj063/linux/tree/debug/suspend_stress_test

  5. ranj063 commented on Dec 21, 2018

    @ranj063
    ranj063
    on Dec 21, 2018
    CollaboratorAuthor

    @dabekjakub some more logs from the changes I made today. I printed the ipc header and payload on both the host and DSP and I can clearly see that all the data is there but the ipc still fails. This is really baffling.

    logger:
    0 2 IPC 96065.156250 125.156250 apl-ipc.c:114 ipc: msg rx -> 0x30010000
    0 2 IPC 96070.572917 5.416667 handler.c:1064 ipc: hdr 0x30010000 tx (80) > rx (28)
    0 2 IPC 96073.854167 3.281250 handler.c:1067 ipc: pipe 5 comp 31 -> new (type 2)
    0 2 IPC 96077.395833 3.541667 handler.c:80 ipc header cmd: 0x30010000 size: 80

    0      2          IPC             96081.406250         4.010417            handler.c:145 	id: 31 type: 2 pipeline_id: 5
0      2          IPC             96085.156250         3.750000            handler.c:80  	ipc header cmd: 0x30010000 size: 80

0      2          IPC             96089.062500         3.906250            handler.c:145 	id: 31 type: 2 pipeline_id: 5
0      2          IPC             96092.604167         3.541667            handler.c:150 	config header

0      2          IPC             96095.989583         3.385417            handler.c:80  	ipc header cmd: 0x0 size: 36

0      2          IPC             96099.947917         3.958333            handler.c:153 	periods_sink: 0 periods_source: 2
0      2          IPC             96103.229167         3.281250            handler.c:155 	preload_count: 2 frame_fmt: 2
0      2          IPC             96106.302083         3.072917            handler.c:156 	xrun_action: 0

0      2          IPC             96109.479167         3.177083            handler.c:184 	dir: 0 dai_index: 3
0      2          IPC             96112.656250         3.177083            handler.c:186 	type: 3 dmac_config: 0

0      2          DAI             96125.729167        13.072917                dai.c:178 	dai_new()
0      1          DAI             96183.489583        57.760418                dai.c:204 	dai_new() error: dai_get() failed to create DAI.
0      1         COMP             96191.718750         8.229167          component.c:90  	comp_new() error: unable to create the new component
0      1          IPC             96196.614583         4.895833                ipc.c:119 	ipc_comp_new() error: component cd = NULL
0      1          IPC             96201.770833         5.156250            handler.c:1075	ipc: pipe 5 comp 31 creation failed -22

    driver logs:
    1686.285024] sof-audio sof-audio: ipc header cmd: 0x30010000 size: 80
    [ 1686.285025] sof-audio sof-audio: ipc comp id: 31 type: 2 pipeline id: 5
    [ 1686.285026] sof-audio sof-audio: config header
    [ 1686.285028] sof-audio sof-audio: ipc header cmd: 0x0 size: 36
    [ 1686.285029] sof-audio sof-audio: periods_sink: 0 periods_source: 2 preload_count: 2 frame_fmt: 2 xrun_action: 0
    [ 1686.285031] sof-audio sof-audio: dir: 0 dai_index: 3 type: 3 dmac_config: 0
    [ 1686.285055] sof-audio sof-audio: ipc tx: 0x30010000
    [ 1686.285265] sof-audio sof-audio: ipc rx: 0x90020000
    [ 1686.285282] sof-audio sof-audio: ipc rx done: 0x90020000
    [ 1686.285302] sof-audio sof-audio: error: ipc error for 0x30010000 size 0x14
    [ 1686.285311] sof-audio sof-audio: error: failed to load widget type 27 with ID: 31
    [ 1686.285314] sof-audio sof-audio: error: failed to restore pipeline after resume -22

  6. ranj063
    changed the title [-]comp_new ipc failure due to invalid ipc size[/-] [+]comp_new ipc failure due to invalid ipc size with suspend_stress_test speed up script[/+] on Dec 21, 2018

  7. keyonjie commented on Dec 21, 2018

    @keyonjie
    keyonjie
    on Dec 21, 2018
    Contributor

    @dabekjakub some more logs from the changes I made today. I printed the ipc header and payload on both the host and DSP and I can clearly see that all the data is there but the ipc still fails. This is really baffling.

    [ 1686.285314] sof-audio sof-audio: error: failed to restore pipeline after resume -22

    @ranj063 can you share the FW patch you used for this log also?

  8. ranj063 commented on Dec 21, 2018

    @ranj063
    ranj063
    on Dec 21, 2018
    CollaboratorAuthor

    @keyonjie here it is:
    https://github.com/ranj063/sof/tree/debug/suspend_stress_test

    Please make sure to change the xtensa-build-all.sh to use "xtensa" instead of xtensa-smp for ARCH in apollolake.

  9. dabekjakub commented on Dec 21, 2018

    @dabekjakub
    dabekjakub
    on Dec 21, 2018
    Member

    @ranj063 that is in line with what i observed. i will have to track where the change of size to 0 occurs.

  10. ranj063 commented on Dec 21, 2018

    @ranj063
    ranj063
    on Dec 21, 2018
    CollaboratorAuthor

    @dabekjakub, @xiulipan made an amazing discovery that this could be related to the multicore support in the FW. We are testing this with xtensa arch option instead of xtensa-smp and it seems to be doing better. Do give it a try and let us know.

  11. ranj063
    changed the title [-]comp_new ipc failure due to invalid ipc size with suspend_stress_test speed up script[/-] [+]comp_new ipc failure due to invalid ipc size with suspend_stress_test with SMP arch option[/+] on Dec 21, 2018
  12. ranj063
    added
    bugSomething isn't working as expected
    on Dec 21, 2018

  13. 20 remaining items

  14. michalgrodzicki commented on Feb 13, 2019

    @michalgrodzicki
    michalgrodzicki
    on Feb 13, 2019

    I dont want to close this issue yet. We have met IPC errors lately in several different situations. This script is the only way to reproduce it consistently. I will work with @fredoh9 to check if the IPC message is intact at the point when the doorbell is sent to the DSP

    @ranj063 I'll asign this issue to you.

  15. michalgrodzicki
    assigned
    ranj063
    and unassigned
    dabekjakub
    on Feb 13, 2019

  16. naveen-manohar commented on Apr 2, 2019

    @naveen-manohar
    naveen-manohar
    on Apr 2, 2019
    Contributor

    Issue observed on CML v4 series during stress cycle
    2019-03-28T14:33:40,309989+05:30 sof-audio-pci 0000:00:1f.3: error: ipc error for 0x30010000 size 0x14
    2019-03-28T14:33:40,309997+05:30 sof-audio-pci 0000:00:1f.3: error: DSP failed to add widget id 0 type 27 name : SSP1.OUT stream SSP1-Codec reply -22
    2019-03-28T14:33:40,309999+05:30 sof-audio-pci 0000:00:1f.3: ASoC: failed to load widget SSP1.OUT
    2019-03-28T14:33:40,310001+05:30 sof-audio-pci 0000:00:1f.3: error: tplg component load failed -22
    2019-03-28T14:33:40,310005+05:30 sof-audio-pci 0000:00:1f.3: error: failed to load DSP topology -22

    cc: @sathyap-chrome

  17. sathyap-chrome commented on Apr 2, 2019

    @sathyap-chrome
    sathyap-chrome
    on Apr 2, 2019
    Contributor

    The issue noted by @naveen-manohar is seen on power cycling stress test on CML.
    This is seen 1 / 2 times in 100 power cycles.

  18. lgirdwood commented on Apr 2, 2019

    @lgirdwood
    lgirdwood
    on Apr 2, 2019
    Member

    @naveen-manohar @sathyap-chrome could someone attach dmesg and sof-logger output. Thanks.

  19. naveen-manohar commented on Apr 2, 2019

    @naveen-manohar
    naveen-manohar
    on Apr 2, 2019
    Contributor

    failure_dmesg.txt
    pass_dmesg.txt

    PFA dmesg between working and non-working scenario

  20. tlauda commented on Apr 17, 2019

    @tlauda
    tlauda
    on Apr 17, 2019
    Contributor

    @naveen-manohar @sathyap-chrome Could you verify with FW having this change: 95b896b? It should fix wrong IPC data on SMP reported in this issue.

  21. jajanusz commented on Apr 30, 2019

    @jajanusz
    jajanusz
    on Apr 30, 2019
    Contributor

    @naveen-manohar @sathyap-chrome ping

  22. sathyap-chrome commented on May 6, 2019

    @sathyap-chrome
    sathyap-chrome
    on May 6, 2019
    Contributor

    We failed with similar error.
    The test was done using
    Topology : cml_drop_0003 branch
    Firmware : master

    Signature 1:
    2019-04-29T12:59:40,045482+05:30 sof-audio-pci 0000:00:1f.3: error: ipc error for 0x30010000 size 20
    2019-04-29T12:59:40,045491+05:30 sof-audio-pci 0000:00:1f.3: error: DSP failed to add widget id 0 type 27 name : SSP0.OUT stream SSP0-Codec reply -22
    2019-04-29T12:59:40,045495+05:30 sof-audio-pci 0000:00:1f.3: ASoC: failed to load widget SSP0.OUT

    Signature 2:
    2019-04-29T04:20:08,655337-07:00 sof-audio-pci 0000:00:1f.3: error: ipc error for 0x30010000 size 20
    2019-04-29T04:20:08,655346-07:00 sof-audio-pci 0000:00:1f.3: error: DSP failed to add widget id 0 type 27 name : HDA2.OUT stream iDisp3 reply -22
    2019-04-29T04:20:08,655350-07:00 sof-audio-pci 0000:00:1f.3: ASoC: failed to load widget HDA2.OUT
    dmesg_cold.txt
    dmesg_warm.txt

  23. sathyap-chrome commented on May 6, 2019

    @sathyap-chrome
    sathyap-chrome
    on May 6, 2019
    Contributor

    Update: Topology and kernel : SOF V0.3 for CML.

  24. tlauda commented on Jun 6, 2019

    @tlauda
    tlauda
    on Jun 6, 2019
    Contributor

    @naveen-manohar @sathyap-chrome Do we still observe such issues with kernel without MSI?

  25. tlauda
    added
    reverifyIssue to be reverified
    on Jun 6, 2019

  26. jajanusz commented on Jun 17, 2019

    @jajanusz
    jajanusz
    on Jun 17, 2019
    Contributor

    @naveen-manohar @sathyap-chrome Closing as we don't have this error on RVPs and probably the problem is gone on your side on kernel w/o MSI. Feel free to reopen this issue, if you still have this problem.

  27. jajanusz
    closed this as completedon Jun 17, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

APLApplies to Apollolake platformGLKApplies to Gemini Lake platformP1Blocker bugs or important featuresbugSomething isn't working as expectedreverifyIssue to be reverified

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions