Skip to content

[BUG] LNL has FW reported error: 7 with multiple pipeline playback #8275

Closed

Description

@fredoh9

Describe the bug
First LNL issue.
For LNLM_RVP_NOCODEC, multiple pipeline playback fails with FW reported error: 7 - Unsupported operation requested.

[ 1328.146968] kernel: snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc4 set pipeline instance 6 state 3
[ 1328.146983] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc tx      : 0x13060003|0x0: GLB_SET_PIPELINE_STATE
[ 1328.147386] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc tx reply: 0x33000000|0x0: GLB_SET_PIPELINE_STATE
[ 1328.147493] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc tx done : 0x13060003|0x0: GLB_SET_PIPELINE_STATE
[ 1328.147521] kernel: snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc4 set pipeline instance 6 state 4
[ 1328.147532] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc tx      : 0x13060004|0x0: GLB_SET_PIPELINE_STATE
[ 1328.149150] kernel: snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc tx reply: 0x33000007|0x0: GLB_SET_PIPELINE_STATE
[ 1328.149162] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: FW reported error: 7 - Unsupported operation requested
[ 1328.149388] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: ipc error for msg 0x13060004|0x0
[ 1328.149420] kernel: sof-audio-pci-intel-lnl 0000:00:1f.3: ASoC: error at soc_dai_trigger on SSP1 Pin: -22
[ 1328.149439] kernel:  Port1: ASoC: trigger FE cmd: 1 failed: -22

To Reproduce
TPLG=/lib/firmware/intel/sof-ace-tplg/sof-lnl-nocodec.tplg ~/sof-test/test-case/multiple-pipeline-playback.sh -l 10

Reproduction Rate
100%

Environment

  • kernelBranch : topic/sof-dev
  • kernelCommit : b9c99093f5ed-3
  • sofBranch : main
  • sofCommit : deb7a09
  • TPLG: sof-mtl-nocodec.tplg, symbolic link to /lib/firmware/sof-ace-tplg/sof-lnl-nocodec.tplg

NOTE: There is no LNL topology, MTL nocodec tplg is re-used.

Screenshots or console output
dmesg.txt
mtrace.txt

Activity

  1. added
    bugSomething isn't working as expected
    I2SApplies to I2S bus for codec connection
    LNLApplies to Lunar Lake platform
    on Sep 29, 2023
  2. added this to the v2.8 milestone on Oct 2, 2023
  3. keqiaozhang commented on Oct 31, 2023

    @keqiaozhang
    Collaborator

    This issue not only happens on LNL-NOCODEC platform, but also happens on LNL-SDW platform when testing multiple-pipeline or multiple-pause-resume.

  4. abonislawski commented on Oct 31, 2023

    @abonislawski
    Member

    @jxstelter please take a look if this is any known issue and we will assign someone if required

  5. changed the title [-][BUG] LNL Nocodec has FW reported error: 7 with multiple pipeline playback[/-] [+][BUG] LNL has FW reported error: 7 with multiple pipeline playback[/+] on Nov 1, 2023
  6. softwarecki commented on Nov 15, 2023

    @softwarecki
    Collaborator

    @fredoh9 Can you provide logs with ipc payloads?

  7. fredoh9 commented on Nov 15, 2023

    @fredoh9
    ContributorAuthor

    let me find how to capture logs with ipc payloads

  8. fredoh9 commented on Nov 15, 2023

    @fredoh9
    ContributorAuthor

    Here you are, this has IPC payloads
    dmesg-mtl-aioc.txt

    For your information and my memory, this is with LNLM_SDW_AIOC,
    cmd: TPLG=/lib/firmware/intel/sof-ace-tplg/sof-lnl-rt711-l0-rt1316-l23-rt714-l1.tplg MODEL=LNLM_SDW_AIOC SOF_TEST_INTERVAL=5 ~/sof-test/test-case/multiple-pipeline.sh -f p -l 50

    Intel internal test link:
    planresultdetail/34687?model=LNLM_SDW_AIOC&testcase=multiple-pipeline-playback-50

  9. 13 remaining items

  10. keqiaozhang commented on Dec 18, 2023

    @keqiaozhang
    Collaborator

    This issue can still be reproduced with multiple-pipeline testing. Inner test ID:36046.

  11. wszypelt commented on Dec 22, 2023

    @wszypelt

    @keqiaozhang does this still occur on main or is it different branch?

  12. keqiaozhang commented on Dec 25, 2023

    @keqiaozhang
    Collaborator

    @keqiaozhang does this still occur on main or is it different branch?

    This issue still exists on main branch, the reproduction rate is very high on LNL platform with external SDW codecs.

    WW52.2 https://sof-ci.ostc.intel.com/#/result/planresultdetail/36239
    WW52.4 https://sof-ci.ostc.intel.com/#/result/planresultdetail/36335

  13. keqiaozhang commented on Jan 3, 2024

    @keqiaozhang
    Collaborator

    Now this issue only happens on LNL-SDW platform now, No reproductions on LNL-NOCODEC for weeks.

  14. removed
    I2SApplies to I2S bus for codec connection
    on Jan 3, 2024
  15. plbossart commented on Jan 4, 2024

    @plbossart
    Member

    the logs for the SoundWire case looks very suspicious with a buffer id of either 0 or 65536?

    https://sof-ci.ostc.intel.com/#/result/planresultdetail/36335?model=LNLM_SDW_AIOC&testcase=multiple-pipeline-playback-50

    [   77.329001] <inf> ipc: ipc_cmd: rx	: 0x45020004|0x20006
    [   77.329018] <inf> ipc: buffer_new: buffer new size 0x300 id 2.0 flags 0x0
    [   77.329028] <inf> pipe: pipeline_connect: comp:2 0x20004 connect buffer 0 as sink
    [   77.329031] <inf> pipe: pipeline_connect: comp:2 0x20006 connect buffer 0 as source
    [   77.329496] <inf> ipc: ipc_cmd: rx	: 0x45020006|0x10002
    [   77.329506] <inf> ipc: buffer_new: buffer new size 0x300 id 2.0 flags 0x0
    [   77.329518] <inf> pipe: pipeline_connect: comp:2 0x20006 connect buffer 0 as sink
    [   77.329521] <inf> pipe: pipeline_connect: comp:2 0x10002 connect buffer 0 as source
    [   77.330241] <inf> ipc: ipc_cmd: rx	: 0x45010002|0x10003
    [   77.330251] <inf> ipc: buffer_new: buffer new size 0x300 id 2.0 flags 0x0
    [   77.330261] <inf> pipe: pipeline_connect: comp:2 0x10002 connect buffer 0 as sink
    [   77.330265] <inf> pipe: pipeline_connect: comp:3 0x10003 connect buffer 0 as source
    [   77.330748] <inf> ipc: ipc_cmd: rx	: 0x45010003|0x30006
    [   77.330758] <inf> ipc: buffer_new: buffer new size 0x300 id 3.0 flags 0x0
    [   77.330768] <inf> pipe: pipeline_connect: comp:3 0x10003 connect buffer 0 as sink
    [   77.330771] <inf> pipe: pipeline_connect: comp:3 0x30006 connect buffer 0 as source
    [   77.331203] <inf> ipc: ipc_cmd: rx	: 0x45030006|0x30004
    [   77.331211] <inf> ipc: buffer_new: buffer new size 0x300 id 3.0 flags 0x0
    [   77.331223] <inf> pipe: pipeline_connect: comp:3 0x30006 connect buffer 0 as sink
    [   77.331228] <inf> pipe: pipeline_connect: comp:3 0x30004 connect buffer 0 as source
    [   77.337043] <inf> ipc: ipc_cmd: rx	: 0x11040007|0x1
    [   77.337056] <inf> pipe: pipeline_new: pipeline new pipe_id 4 priority 0
    [   77.337440] <inf> ipc: ipc_cmd: rx	: 0x40040004|0x40015
    [   77.337481] <inf> dma: dma_get: dma_get() ID 0 sref = 3 busy channels 0
    [   77.338011] <inf> ipc: ipc_cmd: rx	: 0x40040006|0x40010
    [   77.338490] <inf> ipc: ipc_cmd: rx	: 0x44040006|0x30000018
    [   77.338975] <inf> ipc: ipc_cmd: rx	: 0x40020002|0x4000a
    [   77.339788] <inf> ipc: ipc_cmd: rx	: 0x13010003|0x0
    [   77.340111] <inf> ipc: ipc_cmd: rx	: 0x45040004|0x40006
    [   77.340121] <inf> ipc: buffer_new: buffer new size 0x300 id 4.0 flags 0x0
    [   77.340133] <inf> pipe: pipeline_connect: comp:4 0x40004 connect buffer 0 as sink
    [   77.340141] <inf> pipe: pipeline_connect: comp:4 0x40006 connect buffer 0 as source
    [   77.340513] <inf> ipc: ipc_cmd: rx	: 0x45040006|0x20002
    [   77.340525] <inf> ipc: buffer_new: buffer new size 0x300 id 4.0 flags 0x0
    [   77.340535] <inf> pipe: pipeline_connect: comp:4 0x40006 connect buffer 0 as sink
    [   77.340540] <inf> pipe: pipeline_connect: comp:4 0x20002 connect buffer 0 as source
    [   77.341125] <inf> ipc: ipc_cmd: rx	: 0x13010004|0x0
    [   77.341210] <inf> copier: copier_prepare: comp:1 0x10004 copier_prepare()
    [   77.341223] <inf> pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 7
    [   77.341230] <inf> ll_schedule: zephyr_ll_task_schedule_common: task add 0xa0106d40 0x20210U priority 0 flags 0x0
    [   77.341248] <inf> ll_schedule: zephyr_domain_register: zephyr_domain_register domain->type 1 domain->clk 5 domain->ticks_per_ms 38400 period 1000
    [   77.351933] <inf> ipc: ipc_cmd: rx	: 0x13000003|0x0
    [   77.351955] <wrn> ipc: ipc_pipeline_complete: ipc_pipeline_complete(): no scheduling component specified, use comp 2
    [   77.352415] <inf> ipc: ipc_cmd: rx	: 0x45020002|0x1010003
    [   77.352425] <inf> ipc: buffer_new: buffer new size 0x300 id 4.65536 flags 0x0
    [   77.352435] <inf> pipe: pipeline_connect: comp:4 0x20002 connect buffer 65536 as sink
    [   77.352445] <inf> pipe: pipeline_connect: comp:3 0x10003 connect buffer 65536 as source
    [   77.353413] <inf> ipc: ipc_cmd: rx	: 0x13000004|0x0
    [   77.353471] <inf> copier: copier_prepare: comp:0 0x4 copier_prepare()
    [   77.353496] <inf> mixer: mixin_prepare: comp:0 0x2 mixin_prepare()
    [   77.353513] <inf> pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 7
    [   77.353520] <inf> ll_schedule: zephyr_ll_task_schedule_common: task add 0xa0107ec0 0x20210U priority 0 flags 0x0
    [   77.354428] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
    [   77.355381] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
    [   77.356380] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
    [   77.357378] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
    [   77.358380] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
    [   77.359381] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
    [   77.360381] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
    [   77.361373] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
    [   77.362373] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
    [   77.363371] <inf> host_comp: host_get_copy_bytes_normal: comp:0 0x4 no bytes to copy, available samples: 0, free_samples: 192
    [   77.364413] <inf> ipc: ipc_cmd: rx	: 0x13030003|0x0
    [   77.364870] <inf> ipc: ipc_cmd: rx	: 0x13030004|0x0
    [   77.364958] <inf> copier: copier_prepare: comp:3 0x30004 copier_prepare()
    [   77.364968] <err> dai_comp: dai_common_config_prepare: comp:3 0x30004 dai_common_config_prepare(): dma_request_channel() failed
    [   77.364971] <err> module_adapter: module_prepare: comp:3 0x30004 module_prepare() error -5: module specific prepare failed, comp_id 196612
    [   77.364983] <err> module_adapter: module_adapter_prepare: comp:3 0x30004 module_adapter_prepare() error fffffffb: module prepare failed
    [   77.364986] <err> pipe: pipeline_prepare: pipe:3 0x0 pipeline_prepare(): ret = -5, dev->comp.id = 65539
    [   77.364991] <err> ipc: ipc4_pcm_params: ipc: pipe 3 comp 0 prepare failed -5
    [   77.365043] <inf> component: comp_set_state: comp:3 0x30004 comp_set_state(), state already set to 1
    [   77.365046] <err> ipc: ipc_cmd: ipc4: FW_GEN_MSG failed with err 7
    
  16. plbossart commented on Jan 4, 2024

    @plbossart
    Member

    @keqiaozhang I wouldn't be surprised if this is an issue with the mixer.

    2023-12-27 22:53:24 UTC [REMOTE_INFO] Testing: Speaker [hw:0,2]
    2023-12-27 22:53:24 UTC [REMOTE_COMMAND] aplay   -D hw:0,2 -c 2 -r 48000 -f S16_LE /dev/zero -q
    2023-12-27 22:53:24 UTC [REMOTE_INFO] Testing: Jack Out [hw:0,0]
    2023-12-27 22:53:24 UTC [REMOTE_COMMAND] aplay   -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
    2023-12-27 22:53:24 UTC [REMOTE_INFO] Testing: Deepbuffer Jack Out [hw:0,31]
    2023-12-27 22:53:24 UTC [REMOTE_COMMAND] aplay   -D hw:0,31 -c 2 -r 48000 -f S16_LE /dev/zero -q
    

    Can we try to put the "Deepbuffer Jack Out" in the deny list to see if independent pipelines work fine?

    TPLG_IGNORE_LST['pcm']='HDA Digital,Deepbuffer Jack Out' 
    

    should do the trick

  17. keqiaozhang commented on Jan 5, 2024

    @keqiaozhang
    Collaborator

    @plbossart , I tried to skip Deepbuffer pipeline, but it still failed:

    2024-01-05 03:05:11 UTC [REMOTE_INFO] Run command to get pipeline parameters
    2024-01-05 03:05:11 UTC [REMOTE_COMMAND] sof-tplgreader.py /usr/lib/firmware/intel/sof-ace-tplg/sof-lnl-rt711-l0-rt1316-l23-rt714-l1.tplg -f 'type:playback & ~pcm:Amplifier Reference & ~pcm:Deepbuffer Jack Out' -b ' pcm:HDA Digital' -s 0 -e
    2024-01-05 03:05:12 UTC [REMOTE_INFO] ===== Testing: (Loop: 1/50) =====
    2024-01-05 03:05:12 UTC [REMOTE_INFO] /home/ubuntu/sof-test/test-case/multiple-pipeline.sh will use topology /usr/lib/firmware/intel/sof-ace-tplg/sof-lnl-rt711-l0-rt1316-l23-rt714-l1.tplg to run the test case
    2024-01-05 03:05:12 UTC [REMOTE_INFO] Pipeline list to ignore is specified, will ignore 'pcm=HDA Digital' in test case
    2024-01-05 03:05:12 UTC [REMOTE_INFO] Run command to get pipeline parameters
    2024-01-05 03:05:12 UTC [REMOTE_COMMAND] sof-tplgreader.py /usr/lib/firmware/intel/sof-ace-tplg/sof-lnl-rt711-l0-rt1316-l23-rt714-l1.tplg -f 'type:playback ' -b ' pcm:HDA Digital' -s 0 -e
    2024-01-05 03:05:12 UTC [REMOTE_INFO] Testing: Speaker [hw:0,2]
    2024-01-05 03:05:12 UTC [REMOTE_COMMAND] aplay   -D hw:0,2 -c 2 -r 48000 -f S16_LE /dev/zero -q
    2024-01-05 03:05:12 UTC [REMOTE_INFO] Testing: Jack Out [hw:0,0]
    2024-01-05 03:05:12 UTC [REMOTE_INFO] wait 0.5s for aplay_opts()
    2024-01-05 03:05:12 UTC [REMOTE_COMMAND] aplay   -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
    aplay: pcm_write:2127: write error: Input/output error
    2024-01-05 03:05:13 UTC [REMOTE_INFO] checking pipeline status
    2024-01-05 03:05:13 UTC [REMOTE_ERROR] Running process count is 1, but 2 is expected
    4143 aplay -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q
    2024-01-05 03:05:13 UTC [REMOTE_INFO] Starting func_exit_handler(1)
    2024-01-05 03:05:13 UTC [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
    2024-01-05 03:05:13 UTC [REMOTE_ERROR]  func_error_exit()  @  /home/ubuntu/sof-test/test-case/multiple-pipeline.sh
    2024-01-05 03:05:13 UTC [REMOTE_ERROR]  ps_checks()  @  /home/ubuntu/sof-test/test-case/multiple-pipeline.sh:147
    2024-01-05 03:05:13 UTC [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/multiple-pipeline.sh:194
    /home/ubuntu/sof-test/test-case/../case-lib/lib.sh: line 723:  4143 Killed                  aplay $SOF_ALSA_OPTS $SOF_APLAY_OPTS "$@"
    2024-01-05 03:05:13 UTC [REMOTE_INFO] pkill -TERM -f mtrace-reader.py
    2024-01-05 03:05:13 UTC [REMOTE_INFO] nlines=177 /home/ubuntu/sof-test/logs/multiple-pipeline/2024-01-05-03:05:11-15024/mtrace.txt
    2024-01-05 03:05:13 UTC [REMOTE_INFO] ktime=2994 sof-test PID=3996: ending
    2024-01-05 03:05:13 UTC [REMOTE_INFO] Test Result: FAIL!
    
    

    This issue can be easily triggered by:

    aplay  -D hw:0,2 -c 2 -r 48000 -f S16_LE /dev/zero -q -d 10  & aplay -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q -d 10
    [1] 4396
    aplay: pcm_write:2127: write error: Input/output error
    
  18. plbossart commented on Jan 5, 2024

    @plbossart
    Member

    Thanks @keqiaozhang that's very useful, One last suggestion would be to try with a passthrough topology with simplified pipelines to see if this is the DSP IOs getting corrupted somehow, or really the DSP graph introducing issues.

  19. bardliao commented on Jan 25, 2024

    @bardliao
    Collaborator

    @plbossart @keqiaozhang I tested with #8361 and thesofproject/linux#4790 on LNL SDW. And the issue is not reproducible by aplay -D hw:0,2 -c 2 -r 48000 -f S16_LE /dev/zero -q -d 10 & aplay -D hw:0,0 -c 2 -r 48000 -f S16_LE /dev/zero -q -d 10 or TPLG=/lib/firmware/intel/sof-ipc4-tplg/sof-lnl-rt711-l0-rt1316-l23-rt714-l1.tplg MODEL=LNLM_SDW_AIOC SOF_TEST_INTERVAL=5 ~/sof-test/test-case/multiple-pipeline.sh -f p -l 50

  20. wszypelt commented on Jan 26, 2024

    @wszypelt

    root cause: #8361
    waiting for merge

  21. wszypelt commented on Jan 30, 2024

    @wszypelt

    Based on the report from Keqiao
    the issue does not reproduce

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

Metadata

Metadata

Labels

LNLApplies to Lunar Lake platformP1Blocker bugs or important featuresSDWSoundWirebugSomething isn't working as expected

Type

No type

Projects

No projects

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions