Skip to content

volume pipeline copy failure with HDMI playback on APL-UP2-pcm512x. #1114

Closed
Closed
volume pipeline copy failure with HDMI playback on APL-UP2-pcm512x.#1114
Assignees
tlauda
Labels
APLApplies to Apollolake platformWHLApplies to WhiskeyLake platformbugSomething isn't working as expected
Milestone
1.3

Description

@Jiangxinx
Jiangxinx
opened on Mar 12, 2019

Summary:
Fail to check HDMI aplay function on APL-UP2-pcm512x.

Step：
1.aplay -Dhw:0,2 -fS16_LE -c2 -r48000 /dev/zero

Output:

Playing raw data '/dev/zero' : Signed 16 bit Little Endian, Rate 48000 Hz, Stereo
aplay: pcm_write:2011: write error: Input/output error

Dmesg:

[    4.477053] sof-audio-pci 0000:00:0e.0: link dma channel 1 for playback
[    4.477065] sof-audio-pci 0000:00:0e.0: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[    4.477124] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[    4.477134] sof-audio-pci 0000:00:0e.0: link dma channel 2 for playback
[    4.477145] sof-audio-pci 0000:00:0e.0: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
[    4.477204] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x80010000: GLB_DAI_MSG: CONFIG
[    4.477209] sof-audio-pci 0000:00:0e.0: ASoC: Parent card not yet available, widget card binding deferred
[    4.477212] sof-audio-pci 0000:00:0e.0: tplg: complete pipeline PIPELINE.4.HDA2.OUT id 23
[    4.477219] sof-audio-pci 0000:00:0e.0: ipc tx: 0x30130000: GLB_TPLG_MSG: PIPE_COMPLETE
[    4.477327] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x30130000: GLB_TPLG_MSG: PIPE_COMPLETE
[    4.477333] sof-audio-pci 0000:00:0e.0: tplg: complete pipeline PIPELINE.3.HDA1.OUT id 17
[    4.477339] sof-audio-pci 0000:00:0e.0: ipc tx: 0x30130000: GLB_TPLG_MSG: PIPE_COMPLETE
[    4.477391] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x30130000: GLB_TPLG_MSG: PIPE_COMPLETE
[    4.477396] sof-audio-pci 0000:00:0e.0: tplg: complete pipeline PIPELINE.2.HDA0.OUT id 11
[    4.477401] sof-audio-pci 0000:00:0e.0: ipc tx: 0x30130000: GLB_TPLG_MSG: PIPE_COMPLETE
[    4.477451] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x30130000: GLB_TPLG_MSG: PIPE_COMPLETE
[    4.477458] sof-audio-pci 0000:00:0e.0: tplg: complete pipeline PIPELINE.1.SSP5.OUT id 5
[    4.477463] sof-audio-pci 0000:00:0e.0: ipc tx: 0x30130000: GLB_TPLG_MSG: PIPE_COMPLETE
[    4.477763] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x30130000: GLB_TPLG_MSG: PIPE_COMPLETE
[    4.478974] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 5:0
[    4.479149] HDMI HDA Codec ehdaudio0D2: hdac_hdmi_present_sense: disconnect for pin:port 7:0
[    4.483877] sof-audio-pci 0000:00:0e.0: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[    4.483954] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
[    4.483983] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1010303 successful
[    4.484993] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x303 successful
[    4.484996] sof-audio-pci 0000:00:0e.0: DSP core(s) enabled? 0 : core_mask 3
[    4.485016] sof-audio-pci 0000:00:0e.0: Debug PCIR: 00000000 at  00000044
[    4.485019] sof-audio-pci 0000:00:0e.0: Debug PCIW: 00000010 at  00000044
[    4.486134] bxt-pcm512x bxt-pcm512x: pcm512x-hifi <-> SSP5 Pin mapping ok
[    4.486152] bxt-pcm512x bxt-pcm512x: intel-hdmi-hifi1 <-> iDisp1 Pin mapping ok
[    4.486164] bxt-pcm512x bxt-pcm512x: intel-hdmi-hifi2 <-> iDisp2 Pin mapping ok
[    4.486174] bxt-pcm512x bxt-pcm512x: intel-hdmi-hifi3 <-> iDisp3 Pin mapping ok
[    4.486222] sof-audio-pci 0000:00:0e.0: creating new PCM Port5
[    4.486225] sof-audio-pci 0000:00:0e.0: spcm: allocate Passthro

sof-logger:

CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1       VOLUME           1678634.791667   1678634.750000   src/audio/volume.c:493 	volume_copy() error: sink component buffer has not enough free bytes for copy
    0      1         PIPE           1678670.989583        36.197918 src/audio/pipeline.c:658 	pipeline_copy() error: ret = -5, start->comp.id = 16, dir = 1
    0      1         PIPE 3.17      1678677.031250         6.041667 src/audio/pipeline.c:766 	pipeline_xrun_recover()
    0      1       VOLUME           1679634.791667       957.760437   src/audio/volume.c:493 	volume_copy() error: sink component buffer has not enough free bytes for copy
    0      1         PIPE           1679671.406250        36.614582 src/audio/pipeline.c:658 	pipeline_copy() error: ret = -5, start->comp.id = 16, dir = 1
    0      1         PIPE 3.17      1679677.343750         5.937500 src/audio/pipeline.c:766 	pipeline_xrun_recover()
    0      1       VOLUME           1680634.791667       957.447937   src/audio/volume.c:493 	volume_copy() error: sink component buffer has not enough free bytes for copy
    0      1         PIPE           1680670.989583        36.197918 src/audio/pipeline.c:658 	pipeline_copy() error: ret = -5, start->comp.id = 16, dir = 1
    0      1         PIPE 3.17      1680677.031250         6.041667 src/audio/pipeline.c:766 	pipeline_xrun_recover()
    0      1       VOLUME           1681634.791667       957.760437   src/audio/volume.c:493 	volume_copy() error: sink component buffer has not enough free bytes for copy
    0      1         PIPE           1681671.354167        36.562500 src/audio/pipeline.c:658 	pipeline_copy() error: ret = -5, start->comp.id = 16, dir = 1
    0      1         PIPE 3.17      1681677.343750         5.989583 src/audio/pipeline.c:766 	pipeline_xrun_recover()
    0      1       VOLUME           1682634.739583       957.395813   src/audio/volume.c:493 	volume_copy() error: sink component buffer has not enough free bytes for copy
    0      1         PIPE           1682671.093750        36.354168 src/audio/pipeline.c:658 	pipeline_copy() error: ret = -5, start->comp.id = 16, dir = 1
    0      1         PIPE 3.17      1682677.135417         6.041667 src/audio/pipeline.c:766 	pipeline_xrun_recover()
    0      1       VOLUME           1683634.791667       957.656250   src/audio/volume.c:493 	volume_copy() error: sink component buffer has not enough free bytes for copy
    0      1         PIPE           1683669.531250        34.739582 src/audio/pipeline.c:658 	pipeline_copy() error: ret = -5, start->comp.id = 16, dir = 1
    0      1         PIPE 3.17      1683675.468750         5.937500 src/audio/pipeline.c:766 	pipeline_xrun_recover()
    0      1       VOLUME           1684679.270833      1003.802063   src/audio/volume.c:493 	volume_copy() error: sink component buffer has not enough free bytes for copy
    0      1         PIPE           1684715.781250        36.510418 src/audio/pipeline.c:658 	pipeline_copy() error: ret = -5, start->comp.id = 16, dir = 1
    0      1         PIPE 3.17      1684722.083333         6.302083 src/audio/pipeline.c:766 	pipeline_xrun_recover()
    0      1       VOLUME           1684823.593750       101.510414   src/audio/volume.c:493 	volume_copy() error: sink component buffer has not enough free bytes for copy
    0      1         PIPE           1684859.791667        36.197918 src/audio/pipeline.c:658 	pipeline_copy() error: ret = -5, start->comp.id = 16, dir = 1
    0      1         PIPE 3.17      1684865.885417         6.093750 src/audio/pipeline.c:766 	pipeline_xrun_recover()
    0      1       VOLUME           1685634.843750       768.958313   src/audio/volume.c:493 	volume_copy() error: sink component buffer has not enough free bytes for copy
    0      1         PIPE           1685671.406250        36.562500 src/audio/pipeline.c:658 	pipeline_copy() error: ret = -5, start->comp.id = 16, dir = 1
    0      1         PIPE 3.17      1685677.604167         6.197917 src/audio/pipeline.c:766 	pipeline_xrun_recover()

Env:
sof master: 2dbe69e
kernel sof-dev: facd448
tplg: sof-apl-pcm512x.tplg

Log file:
dmesg.log
logger.log

Activity

  1. Jiangxinx
    added
    bugSomething isn't working as expected
    APLApplies to Apollolake platform
    on Mar 12, 2019
  2. lgirdwood
    changed the title [-]Fail to check HDMI aplay function on APL-UP2-pcm512x.[/-] [+]volume pipeline copy failure with HDMI playback on APL-UP2-pcm512x.[/+] on Mar 12, 2019
  3. lgirdwood
    assigned
    tlauda
    on Mar 12, 2019

  4. lgirdwood commented on Mar 12, 2019

    @lgirdwood
    lgirdwood
    on Mar 12, 2019
    Member

    @tlauda I guess HDMI playback is working at your end ?
    @Jiangxinx can you describe the pipeline this is failing on ?

  5. tlauda commented on Mar 12, 2019

    @tlauda
    tlauda
    on Mar 12, 2019
    Contributor

    @lgirdwood Last time I've checked it worked. Anyway HDMI playback works on work_queue, so it's basically timer driven scheduling. During next two weeks we should have schedule refactor ready along with timer scheduling enabled, so limitation will need to be introduced for scheduling HDA-Link pipelines. We should allow only timer scheduling for them.

  6. lgirdwood commented on Mar 12, 2019

    @lgirdwood
    lgirdwood
    on Mar 12, 2019
    Member

    @mengdonglin, @xiulipan @keyonjie can someone check timer scheduling for HDMI is enabled for this test. Thanks

  7. mengdonglin
    added
    WHLApplies to WhiskeyLake platform
    on Mar 13, 2019

  8. mengdonglin commented on Mar 13, 2019

    @mengdonglin
    mengdonglin
    on Mar 13, 2019
    Collaborator

    @lgirdwood @tlauda We haven't revise, so the time_delay is still 0 by default, I think. Could you share more info about how to "allow only timer scheduling" for HDA-link pipelines?

  9. tlauda commented on Mar 13, 2019

    @tlauda
    tlauda
    on Mar 13, 2019
    Contributor

    @mengdonglin Timer scheduling is not yet ready, but we're getting there. We need to have #1089 and #1116 merged first and after that one more small PR from my side. I think I could also modify topology files and enable timer for HDA based pipelines to avoid synchronization problems between FW and Topology updates.
    I wouldn't like to spend much time on this issue, because current implementation of HDA Link is very faulty and everything should work fine after we switch to timer scheduling.

  10. tlauda commented on Mar 14, 2019

    @tlauda
    tlauda
    on Mar 14, 2019
    Contributor

    @mengdonglin PRs that will resolve the issue: #1089, #1125, #1130, #1131.

  11. keqiaozhang commented on Mar 15, 2019

    @keqiaozhang
    keqiaozhang
    on Mar 15, 2019
    Collaborator

    @tlauda
    These patch series have some conflicts, please have a check.
    Or what the right order to apply these patches?

  12. keqiaozhang
    added
    GLKApplies to Gemini Lake platform
    on Mar 15, 2019

  13. RanderWang commented on Mar 15, 2019

    @RanderWang
    RanderWang
    on Mar 15, 2019
    Collaborator

    I also created a bug: #1133 and I got the reason.

  14. RanderWang commented on Mar 20, 2019

    @RanderWang
    RanderWang
    on Mar 20, 2019
    Collaborator

    Now the error is: hda-dmac: %d channel %d HDA Link DMA doesn't support irq scheduling.
    I submitted #1153 to fix this error msg.

  15. 2 remaining items

  16. tlauda commented on Mar 27, 2019

    @tlauda
    tlauda
    on Mar 27, 2019
    Contributor

    @wenqingfu Yes.

  17. wenqingfu commented on Mar 27, 2019

    @wenqingfu
    wenqingfu
    on Mar 27, 2019

    Close. Please reopen if it still fails in your daily regression. @Jiangxinx @stevyan

  18. wenqingfu
    closed this as completedon Mar 27, 2019

  19. Jiangxinx commented on Mar 28, 2019

    @Jiangxinx
    Jiangxinx
    on Mar 28, 2019
    ContributorAuthor

    This issue can still be reproduced in daily regression on APL-UP2-pcm512x.
    sof-logger:

    CORE  LEVEL      COMP_ID                TIMESTAMP            DELTA                FILE_NAME	CONTENT
    0      1          DMA             50141.302083     50141.300781 intel/cavs/hda-dma.c:716 	hda-dmac: 7 channel 1 HDA Link DMA doesn't support irq scheduling
    0      1         PIPE             50148.072917         6.770833 src/audio/pipeline.c:365 	pipeline_prepare() error: ret = -22,dev->comp.id = 12
    0      1          IPC             50154.062500         5.989583    src/ipc/handler.c:325 	ipc: pipe 3 comp 12 prepare failed -22
    0      1          DMA             50289.843750       135.781250 intel/cavs/hda-dma.c:634 	hda-dmac: 5 invalid channel -1

    Dmesg:

    [11897.947068] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x50010000: GLB_COMP_MSG: SET_VALUE: SET_VALUE
[11897.947080] sof-audio-pci 0000:00:0e.0: ipc tx: 0x50010000: GLB_COMP_MSG: SET_VALUE: SET_VALUE
[11897.947156] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x50010000: GLB_COMP_MSG: SET_VALUE: SET_VALUE
[11897.947166] sof-audio-pci 0000:00:0e.0: ipc tx: 0x40020000: GLB_PM_MSG: CTX_RESTORE
[11897.947241] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x40020000: GLB_PM_MSG: CTX_RESTORE
[11897.952949] sof-audio-pci 0000:00:0e.0: pcm: open stream 2 dir 0
[11897.952953] sof-audio-pci 0000:00:0e.0: period min 192 max 16384 bytes
[11897.952956] sof-audio-pci 0000:00:0e.0: period count 2 max 16
[11897.952958] sof-audio-pci 0000:00:0e.0: buffer max 65536 bytes
[11897.953510] sof-audio-pci 0000:00:0e.0: format_val=49, rate=48000, ch=2, format=10
[11897.953519] sof-audio-pci 0000:00:0e.0: pcm: hw params stream 2 dir 0
[11897.953525] sof-audio-pci 0000:00:0e.0: generating page table for 0000000031ee6cd8 size 0xff00 pages 16
[11897.953545] sof-audio-pci 0000:00:0e.0: period_bytes:0xfc0
[11897.953547] sof-audio-pci 0000:00:0e.0: periods:16
[11897.953558] sof-audio-pci 0000:00:0e.0: stream_tag 1
[11897.953565] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60010000: GLB_STREAM_MSG: PCM_PARAMS
[11897.953750] sof-audio-pci 0000:00:0e.0: error: ipc error for 0x60010000 size 20
[11897.953760] sof-audio-pci 0000:00:0e.0: error: hw params ipc failed for stream 1
[11897.953764] sof-audio-pci 0000:00:0e.0: ASoC: 0000:00:0e.0 hw params failed: -22
[11897.953768]  HDMI2: ASoC: hw_params FE failed -22
[11897.953779] sof-audio-pci 0000:00:0e.0: pcm: free stream 2 dir 0
[11897.953783] sof-audio-pci 0000:00:0e.0: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[11897.953859] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x60030000: GLB_STREAM_MSG: PCM_FREE
[11897.954590] sof-audio-pci 0000:00:0e.0: pcm: close stream 2 dir 0
[11898.448553] sof-audio-pci 0000:00:0e.0: ipc rx: 0x90020000: GLB_TRACE_MSG
[11898.448567] sof-audio-pci 0000:00:0e.0: ipc rx done: 0x90020000: GLB_TRACE_MSG
[11898.948537] sof-audio-pci 0000:00:0e.0: ipc rx: 0x90020000: GLB_TRACE_MSG
[11898.948551] sof-audio-pci 0000:00:0e.0: ipc rx done: 0x90020000: GLB_TRACE_MSG
[11899.992367] sof-audio-pci 0000:00:0e.0: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[11899.992474] sof-audio-pci 0000:00:0e.0: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
[11899.992498] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x1010303 successful
[11899.993553] sof-audio-pci 0000:00:0e.0: FW Poll Status: reg=0x303 successful
[11899.993561] sof-audio-pci 0000:00:0e.0: DSP core(s) enabled? 0 : core_mask 3
[11899.993589] sof-audio-pci 0000:00:0e.0: Debug PCIR: 00000010 at  00000044

    Env:
    sof master: 44705df
    kernel sof-dev: 0367002
    tplg: sof-apl-pcm512x.tplg

  20. Jiangxinx
    reopened this on Mar 28, 2019

  21. tlauda commented on Mar 28, 2019

    @tlauda
    tlauda
    on Mar 28, 2019
    Contributor

    @Jiangxinx Error due to the timer not set for HDA pipeline. It looks like you haven't used the latest topology.

    Edit: You have used the wrong FW. Fix was introduced in 6a0dcb3.

  22. RanderWang commented on Mar 28, 2019

    @RanderWang
    RanderWang
    on Mar 28, 2019
    Collaborator

    I validated it on HDA codec and found the issue has been fixed.

  23. mengdonglin commented on Mar 28, 2019

    @mengdonglin
    mengdonglin
    on Mar 28, 2019
    Collaborator

    @Jiangxinx @DarrenxWang @stevyan Please help to check if the sof-apl-pcm512x.tplg used by daily test has been update to latest for all HDA pipelines to use timer as scheduling source:
    6a0dcb3

  24. lgirdwood
    added this to the 1.3 milestone on Mar 28, 2019

  25. lgirdwood commented on Mar 28, 2019

    @lgirdwood
    lgirdwood
    on Mar 28, 2019
    Member

    @mengdonglin blocker for 1.3-rc1

  26. wenqingfu commented on Mar 28, 2019

    @wenqingfu
    wenqingfu
    on Mar 28, 2019

    @Jiangxinx @RanderWang can you please help to do a cross checking and come to a conclusion of the testing status?

  27. keqiaozhang commented on Mar 29, 2019

    @keqiaozhang
    keqiaozhang
    on Mar 29, 2019
    Collaborator

    This issue is fixed on GLK, HDMI playback works well.
    sof/tplg:glk-011-drop-stable/55ae67b5c
    kernel:cros-sof-v4.14-rebase/d4d2c3b8

  28. keqiaozhang
    removed
    GLKApplies to Gemini Lake platform
    on Mar 29, 2019

  29. stevyan commented on Mar 29, 2019

    @stevyan
    stevyan
    on Mar 29, 2019

    Summary
    This issue is fixed on APL UP2 PCM512x, HDMI playback works well.

    Test Env
    sof master: 742f83b
    kernel sof-dev: e29122d
    tplg: sof-apl-pcm512x.tplg

  30. stevyan
    closed this as completedon Mar 29, 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 platformWHLApplies 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