Skip to content

[BUG] [TGL] PM Gate IPC Failure and not able to enter into D0i3 #3823

New issue
New issue
Closed
#3865
Closed
[BUG] [TGL] PM Gate IPC Failure and not able to enter into D0i3#3823
#3865
Assignees
keyonjieslawblauciakbkokoszx
Labels
Fix confirmedFix for the issue has been found and verifiedP1Blocker bugs or important featuresTGLApplies to Tiger LakebugSomething isn't working as expected

Description

@RDharageswari
RDharageswari
opened on Feb 5, 2021

Describe the bug
Start WOV, while there are no active streams.
there will be transition D0i3->D0i0->D3, while this happens the PM_GATE IPC timesout

To Reproduce
The following script can repro the issue:
#!/bin/bash
for i in {1..4}
do
cras_test_client --set_hotword_model 15:0:en_all
cras_test_client --listen_for_hotword /home/root/wov.wav --duration_seconds 10 & pid=pidof cras_test_client
sleep 7
kill -9 $pid
sleep 5
done
Steps to reproduce the behavior: (e.g. list commands or actions used to reproduce the bug)

Reproduction Rate
Several iterations of “D0I3->D0->D3” will reproduce the issue, once in 5 times

Expected behavior
No IPC error

Impact
There is an IPC error after which no streams can be played

Environment
tgl-011-drop-stable

Screenshots or console output
[ 589.957238] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 100 dir 1 cmd 1
[ 589.957583] sof-audio-pci 0000:00:1f.3: FW Poll Status: reg=0x2024001e successful
[ 589.957586] sof-audio-pci 0000:00:1f.3: ipc tx: 0x60040000
[ 589.957750] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x60040000
[ 594.981933] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40080000
[ 594.982140] sof-audio-pci 0000:00:1f.3: ipc tx succeeded: 0x40080000
[ 594.982143] sof-audio-pci 0000:00:1f.3: Current DSP power state: D0I3

[ 598.198506] sof-audio-pci 0000:00:1f.3: pcm: trigger stream 100 dir 1 cmd 0
[ 598.198521] sof-audio-pci 0000:00:1f.3: ipc tx: 0x40080000
[ 598.700217] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40080000 size 32
[ 598.700241] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[ 598.700491] sof-audio-pci 0000:00:1f.3: error: unexpected fault 0x00000000 trace 0x00004000
[ 598.700505] sof-audio-pci 0000:00:1f.3: error: hda irq intsts 0x00000000 intlctl 0xc0000003 rirb 00
[ 598.700509] sof-audio-pci 0000:00:1f.3: error: dsp irq ppsts 0x00000000 adspis 0x00000000
[ 598.700529] sof-audio-pci 0000:00:1f.3: error: host status 0x00000000 dsp status 0x00000000 mask 0x00000003
[ 598.700532] sof-audio-pci 0000:00:1f.3: error: waking up any trace sleepers
[ 598.700541] sof-audio-pci 0000:00:1f.3: error: PM_GATE ipc error -110
[ 598.700553] sof-audio-pci 0000:00:1f.3: failed to set requested target DSP state 0 substate 0
[ 598.700557] sof-audio-pci 0000:00:1f.3: error: resuming DSP -110
[ 598.700621] sof-audio-pci 0000:00:1f.3: error: trace IO error

Activity

  1. RDharageswari
    added
    bugSomething isn't working as expected
    P1Blocker bugs or important features
    TGLApplies to Tiger Lake
    on Feb 5, 2021
  2. RDharageswari
    assigned
    slawblauciak
    ,
    keyonjie
    and
    bkokoszx
    on Feb 5, 2021

  3. lgirdwood commented on Feb 5, 2021

    @lgirdwood
    lgirdwood
    on Feb 5, 2021
    Member

    @RDharageswari what happens when we do

    #!/bin/bash
for i in {1..4}
do
cras_test_client --set_hotword_model 15:0:en_all
cras_test_client --listen_for_hotword /home/root/wov.wav --duration_seconds 10 & pid=pidof cras_test_client
sleep 11
# at this point we have slept for 11 secs so client should have gracefully completed
done

    I am wondering if kill -9 means we are having a different sequence at stream shutdown.

  4. RDharageswari commented on Feb 5, 2021

    @RDharageswari
    RDharageswari
    on Feb 5, 2021
    Author

    Hi Liam,
    cras_test_client --listen_for_hotword /home/root/wov.wav --duration_seconds 10
    The above command works this way: Capture data for "10 duration_seconds" after the keyword is detected.
    The intention of the above script is to get the power sequence right

  5. lgirdwood commented on Feb 5, 2021

    @lgirdwood
    lgirdwood
    on Feb 5, 2021
    Member

    @RDharageswari ok got you, we are capturing for 10 seconds after keyword and not listening for 10 secs. One other thing that comes to mind here is what is the background noise with your test (given the difference in reproduction rates that everyone is seeing) ?

  6. RDharageswari commented on Feb 5, 2021

    @RDharageswari
    RDharageswari
    on Feb 5, 2021
    Author

    Hi Liam,
    there is no background noise here Liam.
    Just the power transition causes this issue.
    This issue is reproducible on RVP also

  7. cujomalainey commented on Feb 5, 2021

    @cujomalainey
    cujomalainey
    on Feb 5, 2021
    Contributor

    I am wondering if kill -9 means we are having a different sequence at stream shutdown.

    I can cause a DSP panic in a similar fashion with arecord so I don't think its the shutdown procedure.

    for i in {0..100};
do timeout 5s arecord -D hw:0,100 -N -f s16_le -c 2 --buffer-size=384000 -r 16000 -d 1 /dev/null;
sleep 5;
done

    [  523.195723] sof-audio-pci 0000:00:1f.3: error : DSP panic!
[  523.195750] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  523.195785] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  525.210427] sof-audio-pci 0000:00:1f.3: error: firmware boot failure
[  525.210454] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  525.210490] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  525.210493] sof-audio-pci 0000:00:1f.3: error: failed to boot DSP firmware after resume -5
[  525.714158] sof-audio-pci 0000:00:1f.3: error: ipc timed out for 0x40080000 size 32
[  525.714166] sof-audio-pci 0000:00:1f.3: info: preventing DSP entering D3 state to preserve context
[  525.714189] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005
[  525.714223] sof-audio-pci 0000:00:1f.3: status: fw entered - code 00000005

    That being said this method is a bit more involved to prevent CRAS from unloading the hotword model

  8. keyonjie commented on Feb 7, 2021

    @keyonjie
    keyonjie
    on Feb 7, 2021
    Contributor

    Hi @slawblauciak @abonislawski @bkokoszx this is not reproduced with the master branch at my end, I spent some time to figure out it could be clock switching related, can you help to backport the upstream version of the WOVCRO and clock switching logic to see if the issue is resolved?

  9. abonislawski commented on Feb 8, 2021

    @abonislawski
    abonislawski
    on Feb 8, 2021
    Member

    @keyonjie just try without commit 445d65f
    this is the only difference

  10. mwasko commented on Feb 8, 2021

    @mwasko
    mwasko
    on Feb 8, 2021
    Contributor

    @keyonjie just try without commit 445d65f
    this is the only difference

    As @abonislawski pointed out, the only significant difference is keeping HPRO clock requested while in D0. This change significantly reduce the LPRO-HPRO clock switch time and improve overall FW performance. It is possible that with this change applied a kernel-FW race condition was revealed.

    @ranj063 @lrgirdwo can you analyze the kernel driver power flows and verify the DSP suspend/resume programming routines?

  11. bkokoszx commented on Feb 8, 2021

    @bkokoszx
    bkokoszx
    on Feb 8, 2021
    Collaborator

    Hi all,
    I'm able to reproduce this issue on Delbin platform also with master branch:

  12. 5 remaining items

  13. ranj063 commented on Feb 9, 2021

    @ranj063
    ranj063
    on Feb 9, 2021
    Collaborator

    @jairaj-arava
    I've got reproduction with latest: https://github.com/thesofproject/sof/commits/tgl-011-drop-stable
    at my end.

    @bkokoszx how are you reproducing it? I mean can you please share the script we can try at our end?

  14. bkokoszx commented on Feb 9, 2021

    @bkokoszx
    bkokoszx
    on Feb 9, 2021
    Collaborator

    @ranj063
    I'm using script, which @RDharageswari shared in issue description: #3823 (comment)

  15. cujomalainey commented on Feb 9, 2021

    @cujomalainey
    cujomalainey
    on Feb 9, 2021
    Contributor

    Unable to repro with this patch thesofproject/linux@248e3df

  16. cujomalainey commented on Feb 9, 2021

    @cujomalainey
    cujomalainey
    on Feb 9, 2021
    Contributor

    Based on code inspection, seems like 5s is the magic number and likely was causing some race conditions with pcm/close and suspend to D3 which raced against the switch to D0i3

  17. ranj063 commented on Feb 10, 2021

    @ranj063
    ranj063
    on Feb 10, 2021
    Collaborator

    @cujomalainey this patch is necessary but I'd be surprised if this is actually the root cause. Techincally, even if the d0i3_work gets scheduled, it shouldnt do anything because snd_sof_dsp_only_d0i3_compatible_stream_active() would return false.

    We're trying to reproduce the issue at our end with this patch. Will update soon

  18. bkokoszx commented on Feb 10, 2021

    @bkokoszx
    bkokoszx
    on Feb 10, 2021
    Collaborator

    With updated kernel, we have reproduction with actual https://github.com/thesofproject/sof/tree/tgl-011-drop-stable.

    We tried also https://github.com/thesofproject/sof/tree/tgl-011-drop-stable with reverted 445d65f and after 300 iterations we do not have reproduction.

  19. slawblauciak commented on Feb 18, 2021

    @slawblauciak
    slawblauciak
    on Feb 18, 2021
    Collaborator

    The issue is a confirmed regression caused by one of later fixes: 445d65f
    The commit has been reverted as it's no longer necessary.

  20. slawblauciak
    added
    Fix confirmedFix for the issue has been found and verified
    on Feb 18, 2021
  21. keyonjie
    added a commit that references this issue on Feb 23, 2021

    cavs: clk: do TGL specific HW recommended flow unconditionally

    2831e42

  22. keyonjie commented on Feb 23, 2021

    @keyonjie
    keyonjie
    on Feb 23, 2021
    Contributor

    Just submitted a fresh PR to address this, it is not the leaving HPRO powered on at WFI lead to the issue, the culprit is that not clearing power gate prevent bit PWRCTL.TCPDSPxPG, per my experiments.

    Please see more detail in my PR:
    #3865

  23. keyonjie
    added a commit that references this issue on Feb 23, 2021

    cavs: clk: do TGL specific HW recommended flow unconditionally

    0015239
  24. keyonjie
    closed this as completedin #3865on Mar 2, 2021
  25. keyonjie
    added a commit that references this issue on Mar 2, 2021

    cavs: clk: do TGL specific HW recommended flow unconditionally

    ebe28dd
  26. keyonjie
    added a commit that references this issue on Mar 10, 2021

    cavs: clk: do TGL specific HW recommended flow unconditionally

    dde4ef6
  27. lgirdwood
    added a commit that references this issue on Mar 18, 2021

    cavs: clk: do TGL specific HW recommended flow unconditionally

    581a29a
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

Fix confirmedFix for the issue has been found and verifiedP1Blocker bugs or important featuresTGLApplies to Tiger LakebugSomething isn't working as expected

Type

No type

Projects

No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions