Skip to content

[BUG] IPC error on TRIGGER_PAUSE when multiple pause-resume on CML_SKU0983_SDW #4919

Closed
Closed
[BUG] IPC error on TRIGGER_PAUSE when multiple pause-resume on CML_SKU0983_SDW#4919
Labels
CMLApplies to Comet Lake platformIntel Linux Daily testsThis issue can be found in internal Linux daily testsbugSomething isn't working as expected

Description

@ghost
ghost
opened on Oct 26, 2021

Describe the bug
IPC error on TRIGGER_PAUSE when multiple pause-resume on CML_SKU0983_SDW.
Happened on daily test 7618?model=CML_SKU0983_SDW&testcase=multiple-pause-resume-25.

To Reproduce
TPLG=/lib/firmware/intel/sof-tplg/sof-cml-rt711-rt1308-mono-rt715.tplg ~/sof-test/test-case/multiple-pause-resume.sh -r 25

Reproduction Rate
Only once in the daily test, didn't reproduce with 100 rounds pause-resume and 5 loop iterations manually.

Environment
Kernel Branch: topic/sof-dev
Kernel Commit: thesofproject/linux@6b090e61
SOF Branch: main
SOF Commit: 1ef769dd8761
Topology: sof-cml-rt711-rt1308-mono-rt715.tplg
Platform: CML_SKU0983_SDW

Screenshots or console output

dmesg:

[ 3422.884359] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x20140000 successful
[ 3422.884370] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: In hda_link_pcm_trigger cmd=3
[ 3422.884396] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: In hda_link_pcm_trigger cmd=4
[ 3422.884402] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: trigger stream 6 dir 0 cmd 4
[ 3422.885026] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: FW Poll Status: reg[0x160]=0x2014001e successful
[ 3422.885040] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[ 3422.885849] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx succeeded: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[ 3422.940205] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: trigger stream 7 dir 0 cmd 3
[ 3422.940238] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[ 3422.940510] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx error for 0x60060000 (msg/reply size: 12/12): -16
[ 3422.940548] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: FW Poll Status: reg[0x180]=0x20240000 successful
[ 3422.940564] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -16
[ 3422.940580] kernel:  HDMI 3: ASoC: trigger FE cmd: 3 failed: -16
[ 3422.940596] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: trigger stream 7 dir 0 cmd 4
[ 3422.940612] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: FW Poll Status: reg[0x180]=0x2024001e successful
[ 3422.940632] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x60070000: GLB_STREAM_MSG: TRIG_RELEASE
[ 3422.941868] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx error for 0x60070000 (msg/reply size: 12/12): -16
[ 3422.941897] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ASoC: error at soc_component_trigger on 0000:00:1f.3: -16
[ 3422.941912] kernel:  HDMI 3: ASoC: trigger FE cmd: 4 failed: -16
[ 3422.942516] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: trigger stream 7 dir 0 cmd 3
[ 3422.942542] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[ 3422.942951] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx succeeded: 0x60060000: GLB_STREAM_MSG: TRIG_PAUSE
[ 3422.942978] kernel: sof-audio-pci-intel-cnl 0000:00:1f.3: FW Poll Status: reg[0x180]=0x20240000 successful

sof-logger:

[    78880755.407227] (       65610.312500) c0 ipc                  src/ipc/ipc3/handler.c:1555 INFO ipc: new cmd 0x60060000
[    78880769.625977] (          14.218749) c0 pipe         8.43  ....../pipeline-stream.c:310  INFO pipe trigger cmd 2



[    78881341.136370] (         529.479126) c0 ipc                  src/ipc/ipc3/handler.c:1555 INFO ipc: new cmd 0x60070000
[    78881354.782203] (          13.645833) c0 pipe         8.43  ....../pipeline-stream.c:310  INFO pipe trigger cmd 10



[    78882505.355074] (          13.958333) c0 ll-schedule        ./schedule/ll_schedule.c:115  INFO task complete 0xbe1b02c0 pipe-task 
[    78813898.586967] (        2064.635254) c0 hda-dma            ..../intel/hda/hda-dma.c:950  ERROR hda_dma_link_check_xrun(): underrun detected
[    78815145.097334] (        1246.510376) c0 hda-dma            ..../intel/hda/hda-dma.c:950  ERROR hda_dma_link_check_xrun(): underrun detected
[    78880787.230142] (          17.604166) c0 hda-dma            ..../intel/hda/hda-dma.c:674  ERROR hda-dmac: 7 channel 1 not idle after stop
[    78880800.146809] (          12.916666) c0 pipe         8.43  ....../pipeline-stream.c:368  ERROR pipeline_trigger_run(): ret = -16, host->comp.id = 38, cmd = 2
[    78880811.657225] (          11.510416) c0 ipc                  src/ipc/ipc3/handler.c:469  ERROR ipc: comp 38 trigger 0x60000 failed -16
[    78882468.219659] (        1113.437500) c0 hda-dma            ..../intel/hda/hda-dma.c:614  ERROR hda-dmac: 7 channel 1 busy. dgcs 0x800900 status 5
[    78882480.407159] (          12.187499) c0 pipe         8.43  ....../pipeline-stream.c:398  ERROR pipeline_trigger(): ret = -16, host->comp.id = 38, cmd = 10
[    78882491.396741] (          10.989583) c0 pipe         8.43  ..../pipeline-schedule.c:92   ERROR pipeline_task(): failed to trigger components: -16
[    78882515.980074] (          10.625000) c0 ll-schedule        ./schedule/ll_schedule.c:118  INFO num_tasks 3 total_num_tasks 3
[    78883642.490446] (        1126.510376) c0 ipc                  src/ipc/ipc3/handler.c:1555 INFO ipc: new cmd 0x60060000
[    78883656.396695] (          13.906249) c0 pipe         8.43  ....../pipeline-stream.c:310  INFO pipe trigger cmd 2
[    78883823.323772] (         166.927078) c0 ll-schedule        ./schedule/ll_schedule.c:517  INFO task cancel 0xbe1b02c0 pipe-task 
[    78909161.916515] (       25338.591797) c0 ipc                  src/ipc/ipc3/handler.c:1555 INFO ipc: new cmd 0x60070000
[    78909176.031098] (          14.114583) c0 pipe         8.43  ....../pipeline-stream.c:310  INFO pipe trigger cmd 10
[    78909190.666514] (          14.635416) c0 ll-schedule        ./schedule/ll_schedule.c:391  INFO task add 0xbe1b02c0 pipe-task 
[    78909201.447763] (          10.781250) c0 ll-schedule        ./schedule/ll_schedule.c:395  INFO task params pri 0 flags 0 start 0 period 1000
[    78909218.166513] (          16.718750) c0 ll-schedule        ./schedule/ll_schedule.c:307  INFO new added task->start 1930264339 at 1930250816
[    78909228.999846] (          10.833333) c0 ll-schedule        ./schedule/ll_schedule.c:310  INFO num_tasks 4 total_num_tasks 4

full_dmesg.txt
full_slogger.txt

Activity

  1. ghost added
    bugSomething isn't working as expected
    on Oct 26, 2021
  2. ghost added
    CMLApplies to Comet Lake platform
    on Oct 26, 2021
  3. ghost added
    Intel Linux Daily testsThis issue can be found in internal Linux daily tests
    on Oct 26, 2021

  4. bkokoszx commented on Oct 26, 2021

    @bkokoszx
    bkokoszx
    on Oct 26, 2021
    Collaborator

    Hi @YongAnLu00
    Can you try to make a bisect and figure out which commit introduce this bug?

  6. lgirdwood commented on Oct 27, 2021

    @lgirdwood
    lgirdwood
    on Oct 27, 2021
    Member

    @plbossart fyi - could be related to SDW

  7. plbossart commented on Oct 27, 2021

    @plbossart
    plbossart
    on Oct 27, 2021
    Member

    @lgirdwood no the errors are related to HDA link DMA.

  8. plbossart commented on Oct 27, 2021

    @plbossart
    plbossart
    on Oct 27, 2021
    Member

    I can reproduce this issue with my local device using the following command

    TPLG=/lib/firmware/intel/sof-tplg/sof-cml-rt711-rt1308-mono-rt715.tplg ~/sof-test/test-case/multiple-pause-resume.sh -r 25 -l 100

    results.tar.gz

  9. plbossart commented on Oct 27, 2021

    @plbossart
    plbossart
    on Oct 27, 2021
    Member

    reproduced it twice, the second time in less that 4mn.

    The suspect is the SOF patch "drivers: Intel: hda-dma: ensure DMA channel is idle after stop"

    This was not checked before so maybe we always had the issue but never returned -EBUSY.

    will try with the latest kernel now to see if we see the issue in the two-step stop mode.

  10. keyonjie
    added 2 commits that reference this issue on Nov 4, 2021

    drivers: Intel: hda-dma: only check DGCS_BUSY with delayed stop

    9e4b18d

    drivers: Intel: hda-dma: only check DGCS_BUSY with delayed stop

    e096ca7

  11. lgirdwood commented on Nov 11, 2021

    @lgirdwood
    lgirdwood
    on Nov 11, 2021
    Member

    @plbossart @keyonjie any updates, can we close ?

  12. plbossart commented on Dec 12, 2022

    @plbossart
    plbossart
    on Dec 12, 2022
    Member

    no update for a year and HDAudio completely redone -> closing.

  13. plbossart
    closed this as completedon Dec 12, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    CMLApplies to Comet Lake platformIntel Linux Daily testsThis issue can be found in internal Linux daily testsbugSomething 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