Skip to content

[BUG] IPC times out when changing volume repeatedly  #1263

Closed
Closed
[BUG] IPC times out when changing volume repeatedly #1263
Assignees
ranj063bkokoszx
Labels
CMLApplies to Comet Lake platformGLKApplies to Gemini Lake platformHDAApplies to HD-Audio bus for codec connectionI2SApplies to I2S bus for codec connectionP1Blocker bugs or important featuresWHLApplies to WhiskeyLake platformbugSomething isn't working as expected
Milestone
1.3

Description

@keqiaozhang
keqiaozhang
opened on Apr 15, 2019

Describe the bug
This issue occurs during the volume change stress test, we can send IPC interrupts continuously by changing the PGA* volume.

To Reproduce
The test script is attached.
sof-test-volume.txt

Expected behavior
No ipc errors when sending ipc interrupts continuously.

Impact
IPC timed out

Environment

  1. Kernel: origin/topic/sof-dev-2de29f
    Firmware: origin/sof-master-00bbb1
  2. tplg name：sof-glk-da7219.tplg
  3. GLK Chromebook.
  4. Reproducibility Rate：100%

Screenshots or console output

[  483.621778] sof-audio-pci 0000:00:0e.0: ipc rx: 0x90020000: GLB_TRACE_MSG
[  483.621784] sof-audio-pci 0000:00:0e.0: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  483.626384] sof-audio-pci 0000:00:0e.0: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[  483.933022] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x50020000 size 108
[  483.933027] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[  483.933065] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[  483.933067] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[  483.933069] sof-audio-pci 0000:00:0e.0: error: set/get ctrl ipc comp 35
[  483.933083] sof-audio-pci 0000:00:0e.0: ipc tx: 0x50010000: GLB_COMP_MSG: SET_VALUE: SET_VALUE
[  484.237031] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x50010000 size 108
[  484.237035] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[  484.237072] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[  484.237073] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[  484.237075] sof-audio-pci 0000:00:0e.0: error: set/get ctrl ipc comp 35

Kmsg and trace
dmesg.log
logger.log

Activity

  1. keqiaozhang
    added
    bugSomething isn't working as expected
    br-master
    GLKApplies to Gemini Lake platform
    on Apr 15, 2019

  2. keqiaozhang commented on Apr 15, 2019

    @keqiaozhang
    keqiaozhang
    on Apr 15, 2019
    CollaboratorAuthor

    @Jiangxinx please help to check this issue on other platforms, like UP2 byt etc.

  3. keqiaozhang commented on Apr 15, 2019

    @keqiaozhang
    keqiaozhang
    on Apr 15, 2019
    CollaboratorAuthor

    I can also reproduce this issue on WHL, I believe this is a common issue.

  4. emilchudzik commented on Apr 15, 2019

    @emilchudzik
    emilchudzik
    on Apr 15, 2019
    Contributor

    I have the same issue on WHL but after boot OS without making any playback, just checked dmesg:
    image

    Environment:
    Platform: WHL RVP - HDA mode
    Kernel: 
    2de29fa [thesofproject/linux: topic/sof-dev]
    +d04ccf494 [RanderWang/linux: cml-validation-20190415]
    +bfb0729dd [RanderWang/linux: cml-validation-20190415]
    +8a2b13a81 [RanderWang/linux: cml-validation-20190415]
    +63ceb8f68 [RanderWang/linux: cml-validation-20190415]
    +db89510d0 [RanderWang/linux: cml-validation-20190415]

    Firmware: 00bbb113d [thesofproject/sof: master]
    Topology: 00bbb11 [thesofproject/sof: master] -> sof-hda-generic.tplg
    Pulse audio enabled.

    dmesg.txt
    logger_sof-cnl_00bbb113.txt
    logger.txt

  5. mengdonglin
    added
    WHLApplies to WhiskeyLake platform
    P1Blocker bugs or important features
    on Apr 15, 2019
  6. mengdonglin
    assigned
    dabekjakub
    on Apr 15, 2019

  7. mengdonglin commented on Apr 15, 2019

    @mengdonglin
    mengdonglin
    on Apr 15, 2019
    Collaborator

    @dabekjakub Please help to check from firmware side. Thanks!

  8. xiulipan commented on Apr 15, 2019

    @xiulipan
    xiulipan
    on Apr 15, 2019
    Contributor

    @dabekjakub @emilchudzik
    That is an interesting issue, as both Volume and IPC used the scheduler. I suggest to check if there is any conflict or corruption happen before schedule tasks.

    sof/src/audio/volume.c

    Line 343 in e14ab70

    schedule_task(&cd->volwork, VOL_RAMP_US, 0, 0);

    sof/src/ipc/handler.c

    Lines 1280 to 1283 in e14ab70

    void ipc_schedule_process(struct ipc *ipc)
    {
    schedule_task(&ipc->ipc_task, 0, 100, 0);
    }

  9. bkokoszx commented on Apr 15, 2019

    @bkokoszx
    bkokoszx
    on Apr 15, 2019
    Collaborator

    @keqiaozhang @emilchudzik
    Could you check whether PR #1269 fixes this issue. In scheduler API refactor (#1089) task priority levels were changed to increasing order (0 - lowest; 1 - highest). I think that driver set pipeline priority level to default "0" value, so now pipeline task has lower priority level than ipc task.

  10. keqiaozhang commented on Apr 16, 2019

    @keqiaozhang
    keqiaozhang
    on Apr 16, 2019
    CollaboratorAuthor

    @bkokoszx
    This issue still can be reproduced after applying PR #1269 .

    
[  153.062892] sof-audio-pci 0000:00:0e.0: ipc rx: 0x90020000: GLB_TRACE_MSG
[  153.062898] sof-audio-pci 0000:00:0e.0: ipc rx done: 0x90020000: GLB_TRACE_MSG
[  153.066971] sof-audio-pci 0000:00:0e.0: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
[  153.373058] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x50020000 size 108
[  153.373064] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[  153.373102] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[  153.373104] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[  153.373106] sof-audio-pci 0000:00:0e.0: error: set/get ctrl ipc comp 35
[  153.373121] sof-audio-pci 0000:00:0e.0: ipc tx: 0x50010000: GLB_COMP_MSG: SET_VALUE: SET_VALUE
[  153.677057] sof-audio-pci 0000:00:0e.0: error: ipc timed out for 0x50010000 size 108
[  153.677060] sof-audio-pci 0000:00:0e.0: status: fw entered - code 00000005
[  153.677097] sof-audio-pci 0000:00:0e.0: error: unexpected fault 0x00000000 trace 0x00004000
[  153.677098] sof-audio-pci 0000:00:0e.0: error: waking up any trace sleepers
[  153.677101] sof-audio-pci 0000:00:0e.0: error: set/get ctrl ipc comp 35
[  153.677343] sof-audio-pci 0000:00:0e.0: ipc tx: 0x50020000: GLB_COMP_MSG: SET_VALUE: GET_VALUE
  11. mengdonglin
    assigned
    ranj063
    on Apr 16, 2019

  12. emilchudzik commented on Apr 16, 2019

    @emilchudzik
    emilchudzik
    on Apr 16, 2019
    Contributor

    I have no issue with PR #1269 applied on the current sof master branch without reverting any others commits.
    Without this PR I had an erros even during boot.
    With this patch loading FW is ok, and changing volume also works good:
    image

    Environment:
    Platform: WHL RVP - HDA mode
    Kernel:
    2de29fa [thesofproject/linux: topic/sof-dev]
    +d04ccf494 [RanderWang/linux: cml-validation-20190415]
    +bfb0729dd [RanderWang/linux: cml-validation-20190415]
    +8a2b13a81 [RanderWang/linux: cml-validation-20190415]
    +63ceb8f68 [RanderWang/linux: cml-validation-20190415]
    +db89510d0 [RanderWang/linux: cml-validation-20190415]

    Firmware: 1b15fad [thesofproject/sof: master] + 624c189
    Topology: 1b15fad [thesofproject/sof: master] -> sof-hda-generic.tplg

    Pulse audio enabled or disabled - also works.

  13. 59 remaining items

  14. ranj063 commented on Apr 23, 2019

    @ranj063
    ranj063
    on Apr 23, 2019
    Collaborator

    @lgirdwood @tlauda i didnt pay much attention to this earlier but when the IPC timeout happens, the ROM status is 0x000005 and the FW is in panic and the other day I pointed out that the panic status in the FW is 0xa which is the code for WFI. Does that tell you anything at all?

    This definitely shows that its not the host that's missing the IPC but rather that the DSP is in panic.

  15. xiulipan commented on Apr 23, 2019

    @xiulipan
    xiulipan
    on Apr 23, 2019
    Contributor

    @ranj063
    If that panic happen, then we will have very serious problem.To avoid chaos brought by the waiti in none-zero IRQ level we add this panic. If we face it again, we may have some serious wrong with the IRQ handler or stack? Since we only have one waiti in the main loop.

  16. ranj063 commented on Apr 23, 2019

    @ranj063
    ranj063
    on Apr 23, 2019
    Collaborator

    @xiulipan at this point we cannot rule out anything.

  17. lgirdwood commented on Apr 24, 2019

    @lgirdwood
    lgirdwood
    on Apr 24, 2019
    Member

    @ranj063 can you confirm that every time this is reproduced you see PANIC WFI ? Also on which platform(s) ? Since CNL+ have a different WFI path. Can you paste the relevant kernel log excerpt.

    @xiulipan It is unlikely to be entering WFI deliberately during runlevel > 0, but a bad pointer or some stack corruption could easily jump to this code.

  18. ranj063 commented on Apr 24, 2019

    @ranj063
    ranj063
    on Apr 24, 2019
    Collaborator

    @lgirdwood the WFI I saw was with the fuzzer with the BYT QEMU DSP is from my comment earlier #1263 (comment) and yes it is every time the IPC times out. A04 shows 0xa as the panic code along with "dead"

    I'll probably need to set up the fuzzer with the APL QEMU to see if I can reproduce it. I'm travelling today and tomorrow, so I can get to it on Friday.

  19. lgirdwood commented on Apr 24, 2019

    @lgirdwood
    lgirdwood
    on Apr 24, 2019
    Member

    @ranj063 I guess you dont have CML HW ? What errors did you see on the HW (and what HW) ?

  20. xiulipan commented on Apr 24, 2019

    @xiulipan
    xiulipan
    on Apr 24, 2019
    Contributor

    @lgirdwood @ranj063
    Yes, maybe need to test on real HW on CML/CNL/WHL.
    If it is real some pointer conceptual then we may need to check what would make this happen? My guess is call8 and call12 difference.

  21. ranj063 commented on Apr 24, 2019

    @ranj063
    ranj063
    on Apr 24, 2019
    Collaborator

    @lgirdwood I do have access to CML but won't be able to get to it until Friday. I'm traveling the next 2 days. I'll work with xiuli here and see if I can get you some errors

  22. ClarexZhou commented on Apr 25, 2019

    @ClarexZhou
    ClarexZhou
    on Apr 25, 2019

    ipc error for 0x50010000 occurred during stress test on volume change on CML laptop.

    [  359.576267] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x30130000: GLB_TPLG_MSG: PIPE_COMPLETE
[  359.576268] sof-audio-pci 0000:00:1f.3: tplg: complete pipeline PIPELINE.1.HDA0.OUT id 5
[  359.576269] sof-audio-pci 0000:00:1f.3: ipc tx: 0x30130000: GLB_TPLG_MSG: PIPE_COMPLETE
[  359.576333] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x30130000: GLB_TPLG_MSG: PIPE_COMPLETE
[  359.576337] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50010000: GLB_COMP_MSG: SET_VALUE: SET_VALUE
[  359.576520] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50010000: GLB_COMP_MSG: SET_VALUE: SET_VALUE
[  359.576527] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50010000: GLB_COMP_MSG: SET_VALUE: SET_VALUE
[  359.576701] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50010000: GLB_COMP_MSG: SET_VALUE: SET_VALUE
[  359.576708] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50010000: GLB_COMP_MSG: SET_VALUE: SET_VALUE
[  359.576877] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50010000: GLB_COMP_MSG: SET_VALUE: SET_VALUE
[  359.576890] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50010000: GLB_COMP_MSG: SET_VALUE: SET_VALUE
[  359.577059] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x50010000: GLB_COMP_MSG: SET_VALUE: SET_VALUE
[  359.577063] sof-audio-pci 0000:00:1f.3: ipc tx: 0x50010000: GLB_COMP_MSG: SET_VALUE: SET_VALUE
[  359.577148] sof-audio-pci 0000:00:1f.3: error: ipc error for 0x50010000 size 108
[  359.577151] sof-audio-pci 0000:00:1f.3: error: set/get ctrl ipc comp 38
[  359.577152] sof-audio-pci 0000:00:1f.3: error: failed kcontrol value set for widget: 31
[  359.577153] sof-audio-pci 0000:00:1f.3: error: restoring kcontrols after resume
[  359.577154] sof-audio-pci 0000:00:1f.3: error: failed to restore pipeline after resume -22
[  359.577165] sof-audio-pci 0000:00:1f.3: pcm: open stream 0 dir 0
[  359.577165] sof-audio-pci 0000:00:1f.3: error: pcm open failed to resume -22
[  359.577167] sof-audio-pci 0000:00:1f.3: ASoC: can't open component 0000:00:1f.3: -22
[  359.577168]  HDA Analog: ASoC: failed to start FE -22
[  359.577381] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
[  359.577403] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG

    volumeIPCtimeOut_logger.log
    volumeIPCtimeOut_dmesg.log

    Test Recipe
    Kernel repo | https://github.com/RanderWang/linux/tree/cml-validation-20190425

    Made from:
    f7e9d4a [thesofproject/linux: topic/sof-dev]

    8a8e045 [RanderWang/linux: cml-validation-20190425]
    62eaa40 [RanderWang/linux: cml-validation-20190425]
    bf461fd [RanderWang/linux: cml-validation-20190425]
    49bb879 [RanderWang/linux: cml-validation-20190425]
    6af82dc [RanderWang/linux: cml-validation-20190425]
    e54f292 [RanderWang/linux: cml-validation-20190425]
    e026573 [RanderWang/linux: cml-validation-20190425]
    3bdeae3 [RanderWang/linux: cml-validation-20190425]
    cea87d5 [RanderWang/linux: cml-validation-20190425]

    Firmware repo | https://github.com/RanderWang/sof/tree/cml-linux-20190425
    Made from:
    395a34e [thesofproject/sof: master]
    279c995 [RanderWang/sof: cml-linux-20190425]
    8598799 [RanderWang/sof: cml-linux-20190425]

    Topology: | https://github.com/RanderWang/sof/tree/cml-linux-20190425
    file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg

    Kconfig: | https://sof-ci-storage.sh.intel.com/daily/20190425/linux-2e945691-1/config-daily-hda-20190425

  23. ClarexZhou commented on Apr 26, 2019

    @ClarexZhou
    ClarexZhou
    on Apr 26, 2019

    Error not occurred after run Volume stress test 11000 times on CML laptop, using below daily build +2PR: #1326 and #1327.

    Kernel repo | https://github.com/RanderWang/linux/tree/cml-validation-20190426
    Firmware repo | https://github.com/RanderWang/sof/tree/cml-linux-20190426
    Topology: | https://github.com/RanderWang/sof/tree/cml-linux-20190426
    file: tools/topology/sof-hda-generic.m4, sof-hda-generic-2ch.tplg

  24. keqiaozhang commented on Apr 26, 2019

    @keqiaozhang
    keqiaozhang
    on Apr 26, 2019
    CollaboratorAuthor

    I also got 10K iterations pass on GLK. But I need to apply PR#849 and PR#850 in kernel side.

    Test recipe:
    kernel: sof-dev + PR #849 and PR #850
    sof: master +PR #1326 and PR #1327.

  25. ranj063 commented on Apr 26, 2019

    @ranj063
    ranj063
    on Apr 26, 2019
    Collaborator

    @keqiaozhang can we also test this on CML. All patches have been merged now both FW and kernel side

  26. wenqingfu commented on Apr 26, 2019

    @wenqingfu
    wenqingfu
    on Apr 26, 2019

    can we also test this on CML

    @ClarexZhou has tested. see below quote two posts above:

    Error not occurred after run Volume stress test 11000 times on CML laptop

  27. ranj063 commented on Apr 26, 2019

    @ranj063
    ranj063
    on Apr 26, 2019
    Collaborator

    @wenqingfu thanks! this issue is good to be closed.

  28. ranj063
    closed this as completedon Apr 26, 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 platformGLKApplies to Gemini Lake platformHDAApplies to HD-Audio bus for codec connectionI2SApplies to I2S bus for codec connectionP1Blocker bugs or important featuresWHLApplies to WhiskeyLake platformbugSomething isn't working as expected

Type

No type

Projects

No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions