Skip to content

[BUG] HDA audio output garbled on MTL & cAVS2.5 with native Zephyr DMA+DAI #6709

Closed
#6823
Closed
[BUG] HDA audio output garbled on MTL & cAVS2.5 with native Zephyr DMA+DAI#6709
#6823
Assignees
abonislawski
Labels
HDAApplies to HD-Audio bus for codec connectionIPC4Issues observed with IPC4 (same IPC as Windows)MTLApplies to Meteor Lake platformP1Blocker bugs or important featuresTGLApplies to Tiger LakebugSomething isn't working as expected
Milestone
v2.4

Description

@kv2019i
kv2019i
opened on Dec 2, 2022

Describe the bug
Test audio playback to HDA headset codec.

To Reproduce
aplay file.wav

Reproduction Rate
100%

Expected behavior
Clean audio output

Impact
Showstopper

Environment

  1. Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
    • Kernel: c693d0caf6fa
    • SOF: f6f9b62
  2. Name of the topology file
    • Topology: sof-hda-generic-2ch.tplg
  3. Name of the platform(s) on which the bug is observed.
    • Platform: TGL

Screenshots or console output

Notes
Originally reported by @singalsu on UP i11.

Activity

  1. kv2019i
    added
    bugSomething isn't working as expected
    P1Blocker bugs or important features
    TGLApplies to Tiger Lake
    IPC4Issues observed with IPC4 (same IPC as Windows)
    on Dec 2, 2022

  2. kv2019i commented on Dec 2, 2022

    @kv2019i
    kv2019i
    on Dec 2, 2022
    CollaboratorAuthor

    FYI @mengdonglin @lgirdwood , this potentially affects sof-2.4 stable branch as well. Confirmed to happen also with sof-2.4.

  3. marc-hb commented on Dec 2, 2022

    @marc-hb
    marc-hb
    on Dec 2, 2022
    Collaborator

    @kv2019i , @singalsu is this too small for https://github.com/thesofproject/sof-test/blob/main/test-case/check-alsabat.sh to notice?

  4. kv2019i commented on Dec 3, 2022

    @kv2019i
    kv2019i
    on Dec 3, 2022
    CollaboratorAuthor

    @marc-hb alsabat should definitely pick this up.

  5. keqiaozhang commented on Dec 5, 2022

    @keqiaozhang
    keqiaozhang
    on Dec 5, 2022
    Collaborator

    @kv2019i I checked the alsabat on TGL-UP board with IPC4 fw/driver. it can pass the test and the audio wav looks perfect.

    ubuntu@sh-tglu-up-hda-04:/tmp$ ~/sof-test/test-case/check-alsabat.sh -p hw:sofhdadsp,0 -c hw:Device,0
2022-12-05 09:31:06 UTC [INFO] ktime=84160 sof-test PID=6883: starting
2022-12-05 09:31:06 UTC [WARNING] NO MODEL is defined. Please define MODEL to run alsa_settings/MODEL.sh
2022-12-05 09:31:06 UTC [INFO] Starting /home/ubuntu/.local/bin/mtrace-reader.py
2022-12-05 09:31:06 UTC [INFO] check the PCMs before alsabat test
2022-12-05 09:31:08 UTC [COMMAND] alsabat -Phw:sofhdadsp,0 --standalone -n 240000 -r 48000 -c 2 -F 997
alsa-utils version 1.2.2

Entering playback thread (ALSA).
Get period size: 2048  buffer size: 16384
Playing generated audio sine wave
2022-12-05 09:31:09 UTC [COMMAND] alsabat -Chw:Device,0 -c 1 -r 48000 -F 997
alsa-utils version 1.2.2

Entering capture thread (ALSA).
Get period size: 3000  buffer size: 24000
Recording ...
Capture completed.

BAT analysis: signal has 65536 frames at 48000 Hz, 1 channels, 2 bytes per sample.

Channel 1 - Checking for target frequency 997.00 Hz
Amplitude: 23524.8; Percentage: [71]
Detected peak at 996.83 Hz of 35.86 dB
 Total 42.0 dB from 983.64 to 1010.01 Hz
 PASS: Peak detected at target frequency
Detected at least 1 signal(s) in total

Return value is 0
Playback completed.

Return value is 0
2022-12-05 09:31:14 UTC [INFO] pkill -TERM -f mtrace-reader.py
2022-12-05 09:31:14 UTC [INFO] ktime=84168 sof-test PID=6883: ending
2022-12-05 09:31:14 UTC [INFO] Test Result: PASS!

    image

  6. kv2019i commented on Dec 5, 2022

    @kv2019i
    kv2019i
    on Dec 5, 2022
    CollaboratorAuthor

    Hmm, something is off here. @singalsu , @ujfalusi both got the audio problem. I just retried building kernel (sof-dev of today 41f9d4fe31be334ece6ec0a1829b730342f9c900), rebuild tplg (main of today 7029fb7) and rebuild FW (main of today 7029fb7) and I still get the garbled audio.

    Dmic seems to be ok, so at least some of the DMAs are running as expected. The FW log also seems ok, performance is at expected level and no xruns are reported.

  7. mengdonglin commented on Dec 5, 2022

    @mengdonglin
    mengdonglin
    on Dec 5, 2022
    Collaborator

    @kv2019i @singalsu @ujfalusi @keqiaozhang Do you have PulseAudio or Pipewire enabled during your test?

  8. kv2019i commented on Dec 5, 2022

    @kv2019i
    kv2019i
    on Dec 5, 2022
    CollaboratorAuthor

    @mengdonglin Not enabled, this happens with plain aplay to native PCM, so audio servers should not interfere.

    Also tested today:

    • forcing DMI-L1 off (-> no impact)
    • older test branch for native drivers: SOF c04b406fd0a1085ba5b1dee888c2bbcf0c601ba0 , Zephyr bd60b9289a635aedf80fc997e6b2a2de56fe5786 (-> issue still seen)

  9. lgirdwood commented on Dec 5, 2022

    @lgirdwood
    lgirdwood
    on Dec 5, 2022
    Member

    Do FW logs show any issues re underruns ?
    Is audio garbled with less gain i.e. overall gain at -3dB or -6dB
    Is there a wav capture to append ?

  10. ujfalusi commented on Dec 5, 2022

    @ujfalusi
    ujfalusi
    on Dec 5, 2022
    Contributor

    @lgirdwood, this is what I have in firmware log when playing audio to HDMI. The audio is garbled and it is playing in slow motion (1.5 times slower):

    [    0.000000] <inf> dma_intel_adsp_gpdma: intel_adsp_gpdma_init: dma dma@7d000 initialized
[    0.000000] <inf> dma_intel_adsp_gpdma: intel_adsp_gpdma_init: dma dma@7c000 initialized
*** Booting Zephyr OS build ffed8388e7cb ***
[    0.000000] <inf> main: SOF on intel_adsp_cavs25
[    0.015530] <inf> init: FW ABI 0x301a000 DBG ABI 0x5003000 tags SOF:v2.0-rc1-1798-g8c16ce371dbf zephyr:ffed8388e7cb src hash 0xdeb39d20 (ref hash 0xdeb39d20)
[    0.015550] <inf> power: pm_runtime_enable_dsp dsp_d0_sref 1
[    0.015648] <inf> ll_schedule: dma_single_chan_domain_init(): num_dma 2, clk 4
[    0.015668] <inf> ipc: ipc_init()
[    0.015686] <inf> idc: idc_init()
[    0.015701] <inf> dma_trace: dma_trace_init_complete()
[    0.015713] <inf> dma: dma_get() ID 4 sref = 1 busy channels 0
[    0.015845] <inf> main: SOF initialized
[    0.015921] <inf> idc: idc_init()
[    0.016133] <inf> ipc: rx    : 0x44000000|0x31400008
[    0.016295] <inf> ipc: rx    : 0x44000000|0x3060004c
[    0.046951] <inf> ipc: rx    : 0xe070000|0x180
[    0.046963] <inf> pipe: pipeline new pipe_id 8388608 priority 0
[    0.047005] <inf> dma: dma_get() ID 5 sref = 1 busy channels 0
[    0.047063] <inf> dma: dma_get() ID 7 sref = 1 busy channels 0
[    0.047066] <inf> ipc: comp:8388608 0x800002 dai_config() dai type = 3 index = 15 dd 0x9e080bc0
[    0.047081] <inf> ipc: buffer new size 0x180 id 8388608.8388611 flags 0x0
[    0.047105] <inf> pipe: comp:8388608 0x800001 connect buffer 8388611 as sink
[    0.047110] <inf> pipe: comp:8388608 0x800002 connect buffer 8388611 as source
[    0.047118] <inf> pipe: pipe:8388608 0x0 pipeline complete, clock freq 400000000Hz
[    0.047151] <inf> ipc: comp:8388608 0x800002 dai_data_config() dai type = 3 index = 15 dd 0x9e080bc0
[    0.047170] <inf> dai_comp: comp:8388608 0x800002 dai_playback_params() dest_dev = 0 stream_id = 0 src_width = 2 dest_width = 2
[    0.047175] <inf> dai_comp: comp:8388608 0x800002 dai_playback_params() fifo 0x0
[    0.047193] <inf> pipe: pipe:8388608 0x0 pipe prepare
[    0.047211] <inf> dai_comp: comp:8388608 0x800002 dai_prepare()
[    0.047215] <inf> dai_comp: comp:8388608 0x800002 dai_config_prepare(), channel = 0
[    0.047220] <inf> dai_comp: comp:8388608 0x800002 dai_config_prepare(): new configured dma channel index 0
[    0.047235] <inf> pipe: pipe:8388608 0x0 pipe trigger cmd 7
[    0.047241] <inf> ll_schedule: task add 0xbe081a40 0x20180U priority 0 flags 0x0
[    0.047261] <inf> ll_schedule: zephyr_domain_register domain->type 1 domain->clk 4 domain->ticks_per_ms 38400 period 1000
[    0.047400] <inf> host_comp: comp:8388608 0x800001 no bytes to copy, 384 free in buffer, 0 available in DMA
[    0.047406] <wrn> dai_comp: comp:8388608 0x800002 dai_copy(): Copy_bytes 0 + avail bytes 16 < period bytes 192, possible glitch
[    0.047411] <wrn> dai_comp: comp:8388608 0x800002 dai_copy(): nothing to copy
[    0.048380] <wrn> dai_comp: comp:8388608 0x800002 dai_copy(): Copy_bytes 128 + avail bytes 0 < period bytes 192, possible glitch
[    0.049353] <wrn> dai_comp: comp:8388608 0x800002 dai_copy(): Copy_bytes 128 + avail bytes 0 < period bytes 192, possible glitch
[    0.050350] <wrn> dai_comp: comp:8388608 0x800002 dai_copy(): Copy_bytes 128 + avail bytes 0 < period bytes 192, possible glitch
[    0.051350] <wrn> dai_comp: comp:8388608 0x800002 dai_copy(): Copy_bytes 128 + avail bytes 0 < period bytes 192, possible glitch
[    0.052350] <wrn> dai_comp: comp:8388608 0x800002 dai_copy(): Copy_bytes 128 + avail bytes 0 < period bytes 192, possible glitch
[    0.053350] <wrn> dai_comp: comp:8388608 0x800002 dai_copy(): Copy_bytes 128 + avail bytes 0 < period bytes 192, possible glitch

    The <wrn> lines are flooding the log ^

    Analog playback (garbled, distorted, but correct speed):

    [    0.000000] <inf> dma_intel_adsp_gpdma: intel_adsp_gpdma_init: dma dma@7d000 initialized
[    0.000000] <inf> dma_intel_adsp_gpdma: intel_adsp_gpdma_init: dma dma@7c000 initialized
*** Booting Zephyr OS build ffed8388e7cb ***
[    0.000000] <inf> main: SOF on intel_adsp_cavs25
[    0.015351] <inf> init: FW ABI 0x301a000 DBG ABI 0x5003000 tags SOF:v2.0-rc1-1798-g8c16ce371dbf zephyr:ffed8388e7cb src hash 0xdeb39d20 (ref hash 0xdeb39d20)
[    0.015371] <inf> power: pm_runtime_enable_dsp dsp_d0_sref 1
[    0.015471] <inf> ll_schedule: dma_single_chan_domain_init(): num_dma 2, clk 4
[    0.015491] <inf> ipc: ipc_init()
[    0.015508] <inf> idc: idc_init()
[    0.015523] <inf> dma_trace: dma_trace_init_complete()
[    0.015536] <inf> dma: dma_get() ID 4 sref = 1 busy channels 0
[    0.015668] <inf> main: SOF initialized
[    0.015743] <inf> idc: idc_init()
[    0.015803] <inf> ipc: rx    : 0x44000000|0x31400008
[    0.015905] <inf> ipc: rx    : 0x44000000|0x3060004c
[    0.184833] <inf> ipc: rx    : 0x11000005|0x0
[    0.184843] <inf> pipe: pipeline new pipe_id 0 priority 0
[    0.185081] <inf> ipc: rx    : 0x40000004|0x15
[    0.185115] <inf> ipc: buffer new size 0x180 id 0.0 flags 0x0
[    0.185148] <inf> dma: dma_get() ID 5 sref = 1 busy channels 0
[    0.185161] <inf> pipe: comp:0 0x40000 connect buffer 0 as sink
[    0.185341] <inf> ipc: rx    : 0x40000006|0x10
[    0.185370] <inf> module_adapter: comp:0 0x60000 module_init() start
[    0.185385] <inf> module_adapter: comp:0 0x60000 module_init() done
[    0.185616] <inf> ipc: rx    : 0x44000006|0x30000018
[    0.186163] <inf> ipc: rx    : 0x40000002|0xa
[    0.186371] <inf> ipc: rx    : 0x11010006|0x0
[    0.186378] <inf> pipe: pipeline new pipe_id 1 priority 0
[    0.186555] <inf> ipc: rx    : 0x40000003|0x1000a
[    0.186788] <inf> ipc: rx    : 0x40010006|0x10010
[    0.186811] <inf> module_adapter: comp:1 0x60001 module_init() start
[    0.186833] <inf> module_adapter: comp:1 0x60001 module_init() done
[    0.187238] <inf> ipc: rx    : 0x44010006|0x30000018
[    0.187456] <inf> ipc: rx    : 0x40010004|0x10015
[    0.187485] <inf> ipc: buffer new size 0x300 id 1.0 flags 0x0
[    0.187530] <inf> dma: dma_get() ID 7 sref = 1 busy channels 0
[    0.187533] <inf> ipc: comp:1 0x40001 dai_config() dai type = 3 index = 0 dd 0x9e082580
[    0.187543] <inf> pipe: comp:1 0x40001 connect buffer 0 as source
[    0.187801] <inf> ipc: rx    : 0x45000004|0x6
[    0.187816] <inf> ipc: buffer new size 0x300 id 0.0 flags 0x0
[    0.187850] <inf> pipe: comp:0 0x40000 connect buffer 0 as sink
[    0.187853] <inf> pipe: comp:0 0x60000 connect buffer 0 as source
[    0.188558] <inf> ipc: rx    : 0x45000006|0x2
[    0.188570] <inf> ipc: buffer new size 0x300 id 0.0 flags 0x0
[    0.188585] <inf> pipe: comp:0 0x60000 connect buffer 0 as sink
[    0.188590] <inf> pipe: comp:0 0x20000 connect buffer 0 as source
[    0.188708] <inf> ipc: rx    : 0x45000002|0x3
[    0.188716] <inf> ipc: buffer new size 0x300 id 0.0 flags 0x0
[    0.188738] <inf> pipe: comp:0 0x20000 connect buffer 0 as sink
[    0.188743] <inf> pipe: comp:1 0x30000 connect buffer 0 as source
[    0.188886] <inf> ipc: rx    : 0x45000003|0x10006
[    0.188895] <inf> ipc: buffer new size 0x300 id 1.0 flags 0x0
[    0.188910] <inf> pipe: comp:1 0x30000 connect buffer 0 as sink
[    0.188915] <inf> pipe: comp:1 0x60001 connect buffer 0 as source
[    0.189421] <inf> ipc: rx    : 0x45010006|0x10004
[    0.189431] <inf> ipc: buffer new size 0x300 id 1.0 flags 0x0
[    0.189446] <inf> pipe: comp:1 0x60001 connect buffer 0 as sink
[    0.189450] <inf> pipe: comp:1 0x40001 connect buffer 0 as source
[    0.191803] <inf> ipc: rx    : 0x13010003|0x0
[    0.191823] <inf> pipe: pipe:1 0x0 pipeline complete, clock freq 400000000Hz
[    0.191918] <inf> ipc: rx    : 0x13010004|0x0
[    0.191941] <inf> ipc: comp:1 0x40001 dai_data_config() dai type = 3 index = 0 dd 0x9e082580
[    0.191961] <inf> dai_comp: comp:1 0x40001 dai_playback_params() dest_dev = 0 stream_id = 0 src_width = 4 dest_width = 4
[    0.191966] <inf> dai_comp: comp:1 0x40001 dai_playback_params() fifo 0x0
[    0.191993] <inf> pipe: pipe:1 0x0 pipe prepare
[    0.192033] <inf> dai_comp: comp:1 0x40001 dai_prepare()
[    0.192038] <inf> dai_comp: comp:1 0x40001 dai_config_prepare(), channel = 0
[    0.192043] <inf> dai_comp: comp:1 0x40001 dai_config_prepare(): new configured dma channel index 0
[    0.192056] <inf> pipe: pipe:1 0x0 pipe trigger cmd 7
[    0.192066] <inf> ll_schedule: task add 0xbe084480 0x20180U priority 0 flags 0x0
[    0.192086] <inf> ll_schedule: zephyr_domain_register domain->type 1 domain->clk 4 domain->ticks_per_ms 38400 period 1000
[    0.192971] <inf> ipc: rx    : 0x13000003|0x0
[    0.192986] <wrn> ipc: ipc_pipeline_complete(): no scheduling component specified, use comp 131072
[    0.192991] <inf> pipe: pipe:0 0x0 pipeline complete, clock freq 400000000Hz
[    0.193068] <inf> ipc: rx    : 0x13000004|0x0
[    0.193118] <inf> pipe: pipe:0 0x0 pipe prepare
[    0.193221] <inf> pipe: pipe:0 0x0 pipe trigger cmd 7
[    0.193231] <inf> ll_schedule: task add 0xbe084b00 0x20180U priority 0 flags 0x0
[    0.194213] <err> copier: comp:0 0x40000 failed to find dai comp or sink pipeline not running.
[    0.194235] <err> copier: comp:0 0x40000 failed to find dai comp or sink pipeline not running.
[    0.194250] <inf> host_comp: comp:0 0x40000 no bytes to copy, 384 free in buffer, 0 available in DMA
[    1.215231] <inf> ll_schedule: ll timer avg 2666, max 3992, overruns 0
[    2.239231] <inf> ll_schedule: ll timer avg 2666, max 3088, overruns 0
[    3.263231] <inf> ll_schedule: ll timer avg 2666, max 3069, overruns 0
[    4.287231] <inf> ll_schedule: ll timer avg 2664, max 3081, overruns 0

    Nothing special to my eyes in the log.

  11. bardliao commented on Dec 6, 2022

    @bardliao
    bardliao
    on Dec 6, 2022
    Collaborator

    I can reproduce the issue on my Up Xtreme board (TGL) with the specific recipe
    Kernel: c693d0caf6fa
    SOF: f6f9b62

  12. mengdonglin
    added
    HDAApplies to HD-Audio bus for codec connection
    on Dec 6, 2022

  13. 14 remaining items

  14. kv2019i
    assigned
    juimonen
    and
    kv2019i
    on Dec 7, 2022

  15. singalsu commented on Dec 7, 2022

    @singalsu
    singalsu
    on Dec 7, 2022
    Collaborator

    @keqiaozhang If there are other tests with 1000 Hz it's a good idea to replace in all of them the frequency. When the frequency is a prime it will ensure all possible PCM codes are exercised in the test over time. With 1 kHz @ 48 kHz only 25 different PCM code values are used.

  16. marc-hb
    added a commit that references this issue on Dec 7, 2022

    check-alsabat.sh: use 821Hz as default test frequency

    55e337d

  17. keqiaozhang commented on Dec 19, 2022

    @keqiaozhang
    keqiaozhang
    on Dec 19, 2022
    Collaborator

    @kv2019i this issue is still reproducible on main branch, any Zephyr change missed on main branch?

  18. kv2019i commented on Dec 19, 2022

    @kv2019i
    kv2019i
    on Dec 19, 2022
    CollaboratorAuthor

    @keqiaozhang This bug will be fixed with this fix, which is still in review:

  19. kv2019i
    assigned
    abonislawski
    and unassigned
    juimonen
    and
    kv2019i
    on Dec 19, 2022
  20. mengdonglin
    changed the title [-][BUG] HDA audio output garbled on cAVS2.5 with native Zephyr DMA+DAI[/-] [+][BUG] HDA audio output garbled on MTL & cAVS2.5 with native Zephyr DMA+DAI[/+] on Jan 4, 2023
  21. kv2019i
    closed this as completedin #6823on Jan 4, 2023

  22. marc-hb commented on Jan 4, 2023

    @marc-hb
    marc-hb
    on Jan 4, 2023
    Collaborator

    Stupid Github auto-close not waiting for daily tests results.

  23. marc-hb
    reopened this on Jan 4, 2023

  24. keqiaozhang commented on Jan 9, 2023

    @keqiaozhang
    keqiaozhang
    on Jan 9, 2023
    Collaborator

    Confirmed that this issue is fixed by #6823

  25. keqiaozhang
    closed this as completedon Jan 9, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Labels

HDAApplies to HD-Audio bus for codec connectionIPC4Issues observed with IPC4 (same IPC as Windows)MTLApplies to Meteor Lake platformP1Blocker bugs or important featuresTGLApplies to Tiger LakebugSomething isn't working as expected

Type

No type

Projects

No projects

    Milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions