[BUG][alsabat] glitches happened on MTL-HDA when testing headset recording #7298

keqiaozhang · 2023-03-17T07:41:21Z

Describe the bug
I'm enabling alsabat test for headset recording and found some glitches on MTL-HDA. The reproduction rate is about 50% with all three test frequencies(599,821 and 997).

To Reproduce
~/sof-test/test-case/check-alsabat.sh -c hw:sofhdadsp,0 -p hw:CODEC,0 -C 2 -F 599
Need PR thesofproject/sof-test#1012

Reproduction Rate
50%

Environment

Branch name and commit hash of the 2 repositories: sof (firmware/topology) and linux (kernel driver).
- Kernel: tip sof-dev
- SOF: tip main
Name of the topology file
- Topology: sof-ace-tplg/sof-hda-generic-4ch.tplg
Name of the platform(s) on which the bug is observed.
- Platform: MTLP_RVP_HDA

lgirdwood · 2023-03-17T12:21:15Z

@keqiaozhang periodic issue with stream or just happens once in stream ? (if once when ?)

keqiaozhang · 2023-03-20T01:52:10Z

@keqiaozhang periodic issue with stream or just happens once in stream ? (if once when ?)

From my observation, this is not a periodic issue, it only occurs at the beginning.

lgirdwood · 2023-03-21T21:31:47Z

@keqiaozhang periodic issue with stream or just happens once in stream ? (if once when ?)

From my observation, this is not a periodic issue, it only occurs at the beginning.

@keqiaozhang Is the timing of the glitch from beginning always consistent ? @btian1 is copier clearing buffer at start ?

keqiaozhang · 2023-03-22T02:10:55Z

Is the timing of the glitch from beginning always consistent ?

Yes, it's consistent and occurs within the first 1-2 milliseconds.

juimonen · 2023-03-28T10:02:02Z

@keqiaozhang could you attach the mtrace also?

lgirdwood · 2023-03-29T11:40:39Z

@singalsu fyi - your glitch dtetector should be able to emit output if glitch is in initial periods (i.e. trigger start/release) errors.

singalsu · 2023-03-29T12:38:16Z

@singalsu fyi - your glitch dtetector should be able to emit output if glitch is in initial periods (i.e. trigger start/release) errors.

Currently it starts detect after stable signal level (waiting for ramp to complete) and analyze the FFTs after that. I would need to add a time domain glitch detector for the beginning part during ramp. The time domain is not as sensitive as FFT but it should work for glitches like this. I will try in next version for thesofproject/sof-test#1016

lgirdwood · 2023-03-29T14:29:33Z

@singalsu fyi - your glitch dtetector should be able to emit output if glitch is in initial periods (i.e. trigger start/release) errors.

Currently it starts detect after stable signal level (waiting for ramp to complete) and analyze the FFTs after that. I would need to add a time domain glitch detector for the beginning part during ramp. The time domain is not as sensitive as FFT but it should work for glitches like this. I will try in next version for thesofproject/sof-test#1016

Thanks - this will save some triage time as these are two quite different bugs with different solutions when they occur.

wszypelt · 2023-03-31T08:06:53Z

@keqiaozhang can you share the logs with payloads IPC logs.

keqiaozhang · 2023-04-03T08:23:31Z

@keqiaozhang could you attach the mtrace also?

mtrace

mtrace 
[00:00:00.000,000]  dma_intel_adsp_gpdma: intel_adsp_gpdma_init: intel_adsp_gpdma_init: dma dma@7c000 initialized
[00:00:00.000,000]  dma_intel_adsp_gpdma: intel_adsp_gpdma_init: intel_adsp_gpdma_init: dma dma@7d000 initialized
[00:00:00.000,000]  dma_intel_adsp_gpdma: intel_adsp_gpdma_init: intel_adsp_gpdma_init: dma dma@7e000 initialized
[00:00:00.116,326]  init: print_version_banner: FW ABI 0x301a000 DBG ABI 0x5003000 tags SOF:v2.5-stable-branch-85-g362a0781f20b zephyr:zephyr-v3.3.0-1778-g1851950977d5 src hash 0x17f5bfd1 (ref hash 0x17f5bfd1)
[00:00:00.116,350]  clock: clock_set_freq: clock 0 set freq 400000000Hz freq_idx 2
*** Booting Zephyr OS build zephyr-v3.3.0-1778-g1851950977d5 ***
[00:00:00.116,593]  main: main: SOF on intel_adsp_ace15_mtpm
[00:00:00.116,606]  main: main: SOF initialized
[00:00:00.117,673]  ipc: ipc_cmd: rx       : 0x44000000|0x31400008
[00:00:00.118,443]  ipc: ipc_cmd: rx       : 0x44000000|0x3060004c
[00:00:00.407,810]  ipc: ipc_cmd: rx       : 0x11000004|0x0
[00:00:00.407,836]  pipe: pipeline_new: pipeline new pipe_id 0 priority 0
[00:00:00.408,430]  ipc: ipc_cmd: rx       : 0x40000004|0x15
[00:00:00.408,471]  ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0
[00:00:00.408,531]  dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0
[00:00:00.408,548]  ipc: dai_config: comp:0 0x40000 dai_config() dai type = 3 index = 0 dd 0x40112100
[00:00:00.408,581]  pipe: pipeline_connect: comp:0 0x40000 connect buffer 0 as sink
[00:00:00.409,208]  ipc: ipc_cmd: rx       : 0x40000010|0xa
[00:00:00.409,255]  eq_iir: eq_iir_init: comp:0 0x100000 eq_iir_init()
[00:00:00.409,740]  ipc: ipc_cmd: rx       : 0x44000010|0x30000058
[00:00:00.409,760]  eq_iir: eq_iir_set_config: comp:0 0x100000 eq_iir_set_config()
[00:00:00.410,343]  ipc: ipc_cmd: rx       : 0x11010002|0x0
[00:00:00.410,368]  pipe: pipeline_new: pipeline new pipe_id 1 priority 0
[00:00:00.410,851]  ipc: ipc_cmd: rx       : 0x40010004|0x10015
[00:00:00.410,905]  dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0
[00:00:00.411,516]  ipc: ipc_cmd: rx       : 0x45000010|0x10004
[00:00:00.411,533]  ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0
[00:00:00.411,556]  pipe: pipeline_connect: comp:0 0x100000 connect buffer 0 as sink
[00:00:00.411,571]  pipe: pipeline_connect: comp:1 0x40001 connect buffer 0 as source
[00:00:00.412,271]  ipc: ipc_cmd: rx       : 0x45000004|0x10
[00:00:00.412,288]  ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0
[00:00:00.412,311]  pipe: pipeline_connect: comp:0 0x40000 connect buffer 0 as sink
[00:00:00.412,325]  pipe: pipeline_connect: comp:0 0x100000 connect buffer 0 as source
[00:00:00.417,631]  ipc: ipc_cmd: rx       : 0x13010003|0x0
[00:00:00.417,668]  ipc: ipc_pipeline_complete(): no scheduling component specified, use comp 262145
[00:00:00.418,251]  ipc: ipc_cmd: rx       : 0x13010004|0x0
[00:00:00.418,318]  pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 7
[00:00:00.418,335]  ll_schedule: zephyr_ll_task_schedule_common: task add 0xa0113f40 0x201b0U priority 0 flags 0x0
[00:00:00.418,376]  ll_schedule: zephyr_domain_register: zephyr_domain_register domain->type 1 domain->clk 3 domain->ticks_per_ms 38400 period 1000
[00:00:00.418,480]  host_comp: host_get_copy_bytes_normal: comp:1 0x40001 no bytes to copy, available bytes: 0, free_bytes: 768
[00:00:00.419,456]  host_comp: host_get_copy_bytes_normal: comp:1 0x40001 no bytes to copy, available bytes: 0, free_bytes: 768
[00:00:00.419,485]  ipc: ipc_cmd: rx       : 0x13000003|0x0
[00:00:00.420,436]  host_comp: host_get_copy_bytes_normal: comp:1 0x40001 no bytes to copy, available bytes: 0, free_bytes: 768
[00:00:00.420,925]  ipc: ipc_cmd: rx       : 0x13000004|0x0
[00:00:00.420,981]  dai_comp: dai_capture_params: comp:0 0x40000 dai_capture_params() src_dev = 0 stream_id = 0 src_width = 4 dest_width = 4
[00:00:00.421,031]  eq_iir: eq_iir_prepare: comp:0 0x100000 eq_iir_prepare(), source_format=2, sink_format=2
[00:00:00.421,048]  eq_iir: eq_iir_init_coef: comp:0 0x100000 eq_iir_init_coef(): 1 responses, 2 channels, stream 2 channels
[00:00:00.421,065]  eq_iir: eq_iir_init_coef: comp:0 0x100000 eq_iir_init_coef(), ch 0 is set to response 0
[00:00:00.421,095]  eq_iir: eq_iir_init_coef: comp:0 0x100000 eq_iir_init_coef(), ch 1 is set to response 0
[00:00:00.421,135]  pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 7
[00:00:00.421,151]  ll_schedule: zephyr_ll_task_schedule_common: task add 0xa0114940 0x201b0U priority 0 flags 0x0
[00:00:00.421,475]  host_comp: host_get_copy_bytes_normal: comp:1 0x40001 no bytes to copy, available bytes: 0, free_bytes: 768
[00:00:00.421,531]  dai_comp: comp:0 0x40000 dai_copy(): nothing to copy
[00:00:00.422,436]  host_comp: host_get_copy_bytes_normal: comp:1 0x40001 no bytes to copy, available bytes: 0, free_bytes: 768
[00:00:01.441,486]  ll_schedule: zephyr_domain_thread_fn: ll timer avg 2429, max 4480, overruns 0
[00:00:01.448,515]  ipc: ipc_cmd: rx       : 0x13000003|0x0
[00:00:01.448,530]  pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 2
[00:00:01.449,461]  ll_schedule: zephyr_ll_task_done: task complete 0xa0114940 0x201b0U
[00:00:01.449,473]  ll_schedule: zephyr_ll_task_done: num_tasks 2 total_num_tasks 2
[00:00:01.450,185]  ipc: ipc_cmd: rx       : 0x13000002|0x0
[00:00:01.450,215]  pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 0
[00:00:01.450,236]  eq_iir: eq_iir_reset: comp:0 0x100000 eq_iir_reset()
[00:00:01.451,235]  ipc: ipc_cmd: rx       : 0x13010003|0x0
[00:00:01.451,250]  pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 2
[00:00:01.451,436]  ll_schedule: zephyr_ll_task_done: task complete 0xa0113f40 0x201b0U
[00:00:01.451,446]  ll_schedule: zephyr_ll_task_done: num_tasks 1 total_num_tasks 1
[00:00:01.451,466]  ll_schedule: zephyr_domain_unregister: zephyr_domain_unregister domain->type 1 domain->clk 3
[00:00:01.452,276]  ipc: ipc_cmd: rx       : 0x13010002|0x0
[00:00:01.452,291]  pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 0
[00:00:01.452,785]  ipc: ipc_cmd: rx       : 0x46000010|0x10004
[00:00:01.453,585]  ipc: ipc_cmd: rx       : 0x12000000|0x0
[00:00:01.453,620]  dma: dma_put: dma_put(), dma = 0x400f6420, sref = 0
[00:00:01.453,713]  eq_iir: eq_iir_free: comp:0 0x100000 eq_iir_free()
[00:00:01.454,508]  ipc: ipc_cmd: rx       : 0x12010000|0x0
[00:00:01.454,530]  dma: dma_put: dma_put(), dma = 0x400f6380, sref = 0
[00:00:02.481,976]  ipc: ipc_cmd: rx       : 0x11000004|0x0
[00:00:02.482,001]  pipe: pipeline_new: pipeline new pipe_id 0 priority 0
[00:00:02.482,608]  ipc: ipc_cmd: rx       : 0x40000004|0x15
[00:00:02.482,643]  ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0
[00:00:02.482,703]  dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0
[00:00:02.482,720]  ipc: dai_config: comp:0 0x40000 dai_config() dai type = 3 index = 0 dd 0x40112100
[00:00:02.482,753]  pipe: pipeline_connect: comp:0 0x40000 connect buffer 0 as sink
[00:00:02.483,823]  ipc: ipc_cmd: rx       : 0x40000010|0xa
[00:00:02.483,870]  eq_iir: eq_iir_init: comp:0 0x100000 eq_iir_init()
[00:00:02.484,555]  ipc: ipc_cmd: rx       : 0x44000010|0x30000058
[00:00:02.484,575]  eq_iir: eq_iir_set_config: comp:0 0x100000 eq_iir_set_config()
[00:00:02.484,995]  ipc: ipc_cmd: rx       : 0x11010002|0x0
[00:00:02.485,008]  pipe: pipeline_new: pipeline new pipe_id 1 priority 0
[00:00:02.485,801]  ipc: ipc_cmd: rx       : 0x40010004|0x10015
[00:00:02.485,856]  dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0
[00:00:02.486,668]  ipc: ipc_cmd: rx       : 0x45000010|0x10004
[00:00:02.486,696]  ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0
[00:00:02.486,720]  pipe: pipeline_connect: comp:0 0x100000 connect buffer 0 as sink
[00:00:02.486,735]  pipe: pipeline_connect: comp:1 0x40001 connect buffer 0 as source
[00:00:02.487,528]  ipc: ipc_cmd: rx       : 0x45000004|0x10
[00:00:02.487,545]  ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0
[00:00:02.487,581]  pipe: pipeline_connect: comp:0 0x40000 connect buffer 0 as sink
[00:00:02.487,596]  pipe: pipeline_connect: comp:0 0x100000 connect buffer 0 as source
[00:00:02.489,108]  ipc: ipc_cmd: rx       : 0x13010003|0x0
[00:00:02.489,145]  ipc: ipc_pipeline_complete(): no scheduling component specified, use comp 262145
[00:00:02.489,648]  ipc: ipc_cmd: rx       : 0x13010004|0x0
[00:00:02.489,713]  pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 7
[00:00:02.489,730]  ll_schedule: zephyr_ll_task_schedule_common: task add 0xa0113f40 0x201b0U priority 0 flags 0x0
[00:00:02.489,773]  ll_schedule: zephyr_domain_register: zephyr_domain_register domain->type 1 domain->clk 3 domain->ticks_per_ms 38400 period 1000
[00:00:02.489,873]  host_comp: host_get_copy_bytes_normal: comp:1 0x40001 no bytes to copy, available bytes: 0, free_bytes: 768
[00:00:02.490,736]  ipc: ipc_cmd: rx       : 0x13000003|0x0
[00:00:02.490,943]  host_comp: host_get_copy_bytes_normal: comp:1 0x40001 no bytes to copy, available bytes: 0, free_bytes: 768
[00:00:02.491,621]  ipc: ipc_cmd: rx       : 0x13000004|0x0
[00:00:02.491,695]  dai_comp: dai_capture_params: comp:0 0x40000 dai_capture_params() src_dev = 0 stream_id = 0 src_width = 4 dest_width = 4
[00:00:02.491,743]  eq_iir: eq_iir_prepare: comp:0 0x100000 eq_iir_prepare(), source_format=2, sink_format=2
[00:00:02.491,761]  eq_iir: eq_iir_init_coef: comp:0 0x100000 eq_iir_init_coef(): 1 responses, 2 channels, stream 2 channels
[00:00:02.491,778]  eq_iir: eq_iir_init_coef: comp:0 0x100000 eq_iir_init_coef(), ch 0 is set to response 0
[00:00:02.491,848]  host_comp: host_get_copy_bytes_normal: comp:1 0x40001 no bytes to copy, available bytes: 0, free_bytes: 768
[00:00:02.491,883]  eq_iir: eq_iir_init_coef: comp:0 0x100000 eq_iir_init_coef(), ch 1 is set to response 0
[00:00:02.491,923]  pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 7
[00:00:02.491,941]  ll_schedule: zephyr_ll_task_schedule_common: task add 0xa0114940 0x201b0U priority 0 flags 0x0
[00:00:02.492,946]  host_comp: host_get_copy_bytes_normal: comp:1 0x40001 no bytes to copy, available bytes: 0, free_bytes: 768
[00:00:02.493,003]  dai_comp: comp:0 0x40000 dai_copy(): nothing to copy
[00:00:02.494,008]  host_comp: host_get_copy_bytes_normal: comp:1 0x40001 no bytes to copy, available bytes: 0, free_bytes: 768
[00:00:03.512,903]  ll_schedule: zephyr_domain_thread_fn: ll timer avg 2429, max 3968, overruns 0
[00:00:04.372,616]  ipc: ipc_cmd: rx       : 0x13000003|0x0
[00:00:04.372,638]  pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 2
[00:00:04.372,878]  ll_schedule: zephyr_ll_task_done: task complete 0xa0114940 0x201b0U
[00:00:04.372,890]  ll_schedule: zephyr_ll_task_done: num_tasks 2 total_num_tasks 2
[00:00:04.373,766]  ipc: ipc_cmd: rx       : 0x13000002|0x0
[00:00:04.373,781]  pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 0
[00:00:04.373,891]  eq_iir: eq_iir_reset: comp:0 0x100000 eq_iir_reset()
[00:00:04.374,873]  host_comp: host_get_copy_bytes_normal: comp:1 0x40001 no bytes to copy, available bytes: 0, free_bytes: 768
[00:00:04.375,128]  ipc: ipc_cmd: rx       : 0x13010003|0x0
[00:00:04.375,150]  pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 2
[00:00:04.375,846]  ll_schedule: zephyr_ll_task_done: task complete 0xa0113f40 0x201b0U
[00:00:04.375,865]  ll_schedule: zephyr_ll_task_done: num_tasks 1 total_num_tasks 1
[00:00:04.375,883]  ll_schedule: zephyr_domain_unregister: zephyr_domain_unregister domain->type 1 domain->clk 3
[00:00:05.108,555]  ipc: ipc_cmd: rx       : 0x13010002|0x0
Terminated108,580]  pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 0

keqiaozhang · 2023-04-03T08:40:13Z

@keqiaozhang can you share the logs with payloads IPC logs.

payloads IPC logs

mtrace 
[  791.642352] snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: Debug PCIR: 00000000 at  00000044
[  791.642370] snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: Debug PCIR: 00000000 at  00000048
[  791.645914] snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: Debug PCIR: 00000000 at  00000048
[  791.645934] snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: Debug PCIW: 00000040 at  00000048
[  791.645985] snd_sof_intel_hda_common:hda_dsp_state_log: sof-audio-pci-intel-mtl 0000:00:1f.3: Current DSP power state: D0I0
[  791.645997] snd_sof:sof_set_fw_state: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state change: 0 -> 2
[  791.646008] snd_sof:snd_sof_load_firmware: sof-audio-pci-intel-mtl 0000:00:1f.3: loading firmware
[  791.646017] snd_sof:sof_set_fw_state: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state change: 2 -> 3
[  791.647071] snd_sof_intel_hda_common:mtl_dsp_pre_fw_run: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1000]=0x1010000 successful
[  791.648144] snd_sof_intel_hda_common:mtl_dsp_pre_fw_run: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1d1c]=0x8151 successful
[  791.648171] snd_sof:snd_sof_run_firmware: sof-audio-pci-intel-mtl 0000:00:1f.3: booting DSP firmware
[  791.648185] snd_sof_intel_hda_common:hda_dsp_cl_boot_firmware: sof-audio-pci-intel-mtl 0000:00:1f.3: IMR restore supported, booting from IMR directly
[  791.649237] snd_sof_intel_hda_common:mtl_dsp_core_power_up: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x178d04]=0x2000101 successful
[  791.649252] snd_sof_intel_hda_common:mtl_dsp_cl_init: sof-audio-pci-intel-mtl 0000:00:1f.3: Primary core power up successful
[  791.649264] snd_sof_intel_hda_common:mtl_dsp_cl_init: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x73214]=0x80000000 successful
[  791.649275] snd_sof_intel_hda_common:mtl_enable_interrupts: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1800]=0x41 successful
[  791.649284] snd_sof_intel_hda_common:mtl_enable_interrupts: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x1140]=0x1 successful
[  791.763677] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc rx      : 0x1b080000|0x0: GLB_NOTIFICATION|FW_READY
[  791.763700] snd_sof:sof_set_fw_state: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state change: 3 -> 6
[  791.763717] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc rx done : 0x1b080000|0x0: GLB_NOTIFICATION|FW_READY
[  791.763968] snd_sof:snd_sof_run_firmware: sof-audio-pci-intel-mtl 0000:00:1f.3: firmware boot complete
[  791.763988] snd_sof:sof_set_fw_state: sof-audio-pci-intel-mtl 0000:00:1f.3: fw_state change: 6 -> 7
[  791.764005] snd_sof_intel_hda_common:mtl_enable_sdw_irq: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x114c]=0xf successful
[  791.764019] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x44000000|0x31400008: MOD_LARGE_CONFIG_SET [data size: 8]
[  791.764497] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x64000000|0x31400008: MOD_LARGE_CONFIG_SET
[  791.764674] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x44000000|0x31400008: MOD_LARGE_CONFIG_SET [data size: 8]
[  791.764689] Message payload: 00000000: 772861e4 ffedcdc9
[  791.764698] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x44000000|0x3060004c: MOD_LARGE_CONFIG_SET [data size: 76]
[  791.765180] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x64000000|0x3060004c: MOD_LARGE_CONFIG_SET
[  791.765367] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x44000000|0x3060004c: MOD_LARGE_CONFIG_SET [data size: 76]
[  791.765382] Message payload: 00000000: 00000100 00001000 00000001 000001ef
[  791.765388] Message payload: 00000010: 00000000 00000000 00000000 00000000
[  791.765392] Message payload: 00000020: 00000000 00000000 00000000 00000000
[  791.765396] Message payload: 00000030: 00000000 00000000 00000000 00000000
[  791.765399] Message payload: 00000040: 00000000 00000000 00000000
[  792.049739] snd_sof:sof_pcm_open: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: open stream 0 dir 1
[  792.049751] snd_sof:sof_pcm_open: sof-audio-pci-intel-mtl 0000:00:1f.3: period min 192 max 16384 bytes
[  792.049756] snd_sof:sof_pcm_open: sof-audio-pci-intel-mtl 0000:00:1f.3: period count 2 max 16
[  792.049760] snd_sof:sof_pcm_open: sof-audio-pci-intel-mtl 0000:00:1f.3: buffer max 65536 bytes
[  792.050117] snd_sof_intel_hda_common:hda_calc_stream_format: sof-audio-pci-intel-mtl 0000:00:1f.3: format_val=0x11, rate=48000, ch=2, format=2
[  792.050132] snd_sof:sof_pcm_hw_params: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: hw params stream 0 dir 1
[  792.050143] snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x80]=0x40000 successful
[  792.050165] snd_sof_intel_hda_common:hda_dsp_stream_hw_params: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x80]=0x40000 successful
[  792.050172] snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-mtl 0000:00:1f.3: period_bytes:0x2000
[  792.050175] snd_sof_intel_hda_common:hda_dsp_stream_setup_bdl: sof-audio-pci-intel-mtl 0000:00:1f.3: periods:8
[  792.050201] snd_sof:sof_ipc4_prepare_copier_module: sof-audio-pci-intel-mtl 0000:00:1f.3: copier copier.HDA.4.1, type 28
[  792.050206] snd_sof:sof_ipc4_init_audio_fmt: sof-audio-pci-intel-mtl 0000:00:1f.3: matched audio format index for 48000Hz, 32bit, 2 channels: 0
[  792.050212] snd_sof:sof_ipc4_init_audio_fmt: sof-audio-pci-intel-mtl 0000:00:1f.3: Init input audio formats for copier.HDA.4.1
[  792.050216] snd_sof:sof_ipc4_dbg_audio_format: sof-audio-pci-intel-mtl 0000:00:1f.3: Pin index #0: 48000Hz, 32bit (ch_map 0xffffff10 ch_cfg 1 interleaving_style 0 fmt_cfg 0x2002) buffer size 384
[  792.050223] snd_sof:sof_ipc4_prepare_copier_module: sof-audio-pci-intel-mtl 0000:00:1f.3: Output audio format for copier.HDA.4.1
[  792.050226] snd_sof:sof_ipc4_dbg_audio_format: sof-audio-pci-intel-mtl 0000:00:1f.3: Pin index #0: 48000Hz, 32bit (ch_map 0xffffff10 ch_cfg 1 interleaving_style 0 fmt_cfg 0x2002) buffer size 384
[  792.050231] snd_sof:sof_ipc4_prepare_copier_module: sof-audio-pci-intel-mtl 0000:00:1f.3: copier copier.HDA.4.1, IPC size is 84
[  792.050237] snd_sof:sof_ipc4_init_audio_fmt: sof-audio-pci-intel-mtl 0000:00:1f.3: matched audio format index for 48000Hz, 32bit, 2 channels: 0
[  792.050241] snd_sof:sof_ipc4_init_audio_fmt: sof-audio-pci-intel-mtl 0000:00:1f.3: Init input audio formats for eqiir.4.1
[  792.050244] snd_sof:sof_ipc4_dbg_audio_format: sof-audio-pci-intel-mtl 0000:00:1f.3: Pin index #0: 48000Hz, 32bit (ch_map 0xffffff10 ch_cfg 1 interleaving_style 0 fmt_cfg 0x2002) buffer size 384
[  792.050250] snd_sof:sof_ipc4_prepare_copier_module: sof-audio-pci-intel-mtl 0000:00:1f.3: copier copier.host.3.1, type 24
[  792.050255] snd_sof:sof_ipc4_init_audio_fmt: sof-audio-pci-intel-mtl 0000:00:1f.3: matched audio format index for 48000Hz, 16bit, 2 channels: 0
[  792.050259] snd_sof:sof_ipc4_init_audio_fmt: sof-audio-pci-intel-mtl 0000:00:1f.3: Init input audio formats for copier.host.3.1
[  792.050263] snd_sof:sof_ipc4_dbg_audio_format: sof-audio-pci-intel-mtl 0000:00:1f.3: Pin index #0: 48000Hz, 32bit (ch_map 0xffffff10 ch_cfg 1 interleaving_style 0 fmt_cfg 0x2002) buffer size 384
[  792.050267] snd_sof:sof_ipc4_prepare_copier_module: sof-audio-pci-intel-mtl 0000:00:1f.3: Output audio format for copier.host.3.1
[  792.050271] snd_sof:sof_ipc4_dbg_audio_format: sof-audio-pci-intel-mtl 0000:00:1f.3: Pin index #0: 48000Hz, 16bit (ch_map 0xffffff10 ch_cfg 1 interleaving_style 0 fmt_cfg 0x1002) buffer size 192
[  792.050276] snd_sof:sof_ipc4_prepare_copier_module: sof-audio-pci-intel-mtl 0000:00:1f.3: copier copier.host.3.1, IPC size is 84
[  792.050281] snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-mtl 0000:00:1f.3: pipeline: 4 memory pages: 4
[  792.050288] snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-mtl 0000:00:1f.3: Create widget pipeline.4 instance 0 - pipe 4 - core 0
[  792.050296] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x11000004|0x0: GLB_CREATE_PIPELINE
[  792.050784] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x31000000|0x0: GLB_CREATE_PIPELINE
[  792.050836] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x11000004|0x0: GLB_CREATE_PIPELINE
[  792.050858] snd_sof:sof_widget_setup_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget pipeline.4 setup complete
[  792.050874] snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-mtl 0000:00:1f.3: Create widget copier.HDA.4.1 instance 0 - pipe 4 - core 0
[  792.050889] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x40000004|0x15: MOD_INIT_INSTANCE [data size: 84]
[  792.051439] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x60000000|0x15: MOD_INIT_INSTANCE
[  792.051615] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x40000004|0x15: MOD_INIT_INSTANCE [data size: 84]
[  792.051646] Message payload: 00000000: 0000066f 00000180 00000180 00000001
[  792.051653] Message payload: 00000010: 0000bb80 00000020 ffffff10 00000001
[  792.051657] Message payload: 00000020: 00000000 00002002 0000bb80 00000020
[  792.051661] Message payload: 00000030: ffffff10 00000001 00000000 00002002
[  792.051665] Message payload: 00000040: 00000000 00000900 00000300 00000001
[  792.051668] Message payload: 00000050: 00000000
[  792.051674] snd_sof:sof_widget_setup_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget copier.HDA.4.1 setup complete
[  792.051683] snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-mtl 0000:00:1f.3: Create widget eqiir.4.1 instance 0 - pipe 4 - core 0
[  792.051691] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x40000010|0xa: MOD_INIT_INSTANCE [data size: 40]
[  792.052179] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x60000000|0xa: MOD_INIT_INSTANCE
[  792.052398] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x40000010|0xa: MOD_INIT_INSTANCE [data size: 40]
[  792.052411] Message payload: 00000000: 00000000 00000180 00000180 00000000
[  792.052417] Message payload: 00000010: 0000bb80 00000020 ffffff10 00000001
[  792.052420] Message payload: 00000020: 00000000 00002002
[  792.052437] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x44000010|0x30000058: MOD_LARGE_CONFIG_SET [data size: 88]
[  792.052775] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x64000000|0x30000058: MOD_LARGE_CONFIG_SET
[  792.052850] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x44000010|0x30000058: MOD_LARGE_CONFIG_SET [data size: 88]
[  792.052882] Message payload: 00000000: 00000058 00000002 00000001 00000000
[  792.052889] Message payload: 00000010: 00000000 00000000 00000000 00000000
[  792.052893] Message payload: 00000020: 00000000 00000001 00000001 00000000
[  792.052897] Message payload: 00000030: 00000000 00000000 00000000 c078df4c
[  792.052900] Message payload: 00000040: 7f86ae23 1ff51b12 c015c9db 1ff51b12
[  792.052903] Message payload: 00000050: 00000000 00007fb2
[  792.052907] snd_sof:sof_widget_setup_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget eqiir.4.1 setup complete
[  792.052914] snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-mtl 0000:00:1f.3: pipeline: 3 memory pages: 2
[  792.052920] snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-mtl 0000:00:1f.3: Create widget pipeline.3 instance 1 - pipe 3 - core 0
[  792.052926] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x11010002|0x0: GLB_CREATE_PIPELINE
[  792.053409] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x31000000|0x0: GLB_CREATE_PIPELINE
[  792.053450] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x11010002|0x0: GLB_CREATE_PIPELINE
[  792.053465] snd_sof:sof_widget_setup_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget pipeline.3 setup complete
[  792.053477] snd_sof:sof_ipc4_widget_setup: sof-audio-pci-intel-mtl 0000:00:1f.3: Create widget copier.host.3.1 instance 1 - pipe 3 - core 0
[  792.053482] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x40010004|0x10015: MOD_INIT_INSTANCE [data size: 84]
[  792.053866] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x60000000|0x10015: MOD_INIT_INSTANCE
[  792.054091] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x40010004|0x10015: MOD_INIT_INSTANCE [data size: 84]
[  792.054105] Message payload: 00000000: 0000066f 00000180 000000c0 00000001
[  792.054111] Message payload: 00000010: 0000bb80 00000020 ffffff10 00000001
[  792.054115] Message payload: 00000020: 00000000 00002002 0000bb80 00000010
[  792.054119] Message payload: 00000030: ffffff10 00000001 00000000 00001002
[  792.054122] Message payload: 00000040: 00000000 00000100 00000180 00000001
[  792.054125] Message payload: 00000050: 00000000
[  792.054130] snd_sof:sof_widget_setup_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget copier.host.3.1 setup complete
[  792.054138] snd_sof:sof_ipc4_route_setup: sof-audio-pci-intel-mtl 0000:00:1f.3: bind eqiir.4.1:0 -> copier.host.3.1:0
[  792.054146] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x45000010|0x10004: MOD_BIND
[  792.054535] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x65000000|0x10004: MOD_BIND
[  792.054583] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x45000010|0x10004: MOD_BIND
[  792.054602] snd_sof:sof_ipc4_route_setup: sof-audio-pci-intel-mtl 0000:00:1f.3: bind copier.HDA.4.1:0 -> eqiir.4.1:0
[  792.054610] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x45000004|0x10: MOD_BIND
[  792.055173] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x65000000|0x10: MOD_BIND
[  792.055369] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x45000004|0x10: MOD_BIND
[  792.055617] sof-audio-pci-intel-mtl 0000:00:1f.3: no llp found, fall back to default HDA path
[  792.060328] snd_sof:sof_pcm_trigger: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: trigger stream 0 dir 1 cmd 1
[  792.060344] snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-mtl 0000:00:1f.3: trigger cmd: 1 state: 4
[  792.060358] snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc4 set pipeline 1 state 3
[  792.060370] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13010003|0x0: GLB_SET_PIPELINE_STATE
[  792.061005] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x33000000|0x0: GLB_SET_PIPELINE_STATE
[  792.061212] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x13010003|0x0: GLB_SET_PIPELINE_STATE
[  792.061236] snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc4 set pipeline 1 state 4
[  792.061249] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13010004|0x0: GLB_SET_PIPELINE_STATE
[  792.062085] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x33000000|0x0: GLB_SET_PIPELINE_STATE
[  792.062269] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x13010004|0x0: GLB_SET_PIPELINE_STATE
[  792.063017] snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x80]=0x2014001e successful
[  792.063040] snd_sof_intel_hda_common:hda_dai_trigger: sof-audio-pci-intel-mtl 0000:00:1f.3: cmd=1 dai Analog CPU DAI direction 1
[  792.063057] snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc4 set pipeline 0 state 3
[  792.063071] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13000003|0x0: GLB_SET_PIPELINE_STATE
[  792.063402] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x33000000|0x0: GLB_SET_PIPELINE_STATE
[  792.063636] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x13000003|0x0: GLB_SET_PIPELINE_STATE
[  792.063655] snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc4 set pipeline 0 state 4
[  792.063670] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13000004|0x0: GLB_SET_PIPELINE_STATE
[  792.065132] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x33000000|0x0: GLB_SET_PIPELINE_STATE
[  792.065321] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x13000004|0x0: GLB_SET_PIPELINE_STATE
[  793.944391] snd_sof_intel_hda_common:hda_dai_trigger: sof-audio-pci-intel-mtl 0000:00:1f.3: cmd=0 dai Analog CPU DAI direction 1
[  793.944408] snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc4 set pipeline 0 state 3
[  793.944418] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13000003|0x0: GLB_SET_PIPELINE_STATE
[  793.945954] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x33000000|0x0: GLB_SET_PIPELINE_STATE
[  793.946183] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x13000003|0x0: GLB_SET_PIPELINE_STATE
[  793.946205] snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc4 set pipeline 0 state 2
[  793.946215] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13000002|0x0: GLB_SET_PIPELINE_STATE
[  793.946961] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x33000000|0x0: GLB_SET_PIPELINE_STATE
[  793.947148] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x13000002|0x0: GLB_SET_PIPELINE_STATE
[  793.947181] snd_sof:sof_pcm_trigger: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: trigger stream 0 dir 1 cmd 0
[  793.947188] snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-mtl 0000:00:1f.3: trigger cmd: 0 state: 3
[  793.947196] snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc4 set pipeline 1 state 3
[  793.947201] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13010003|0x0: GLB_SET_PIPELINE_STATE
[  793.948818] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x33000000|0x0: GLB_SET_PIPELINE_STATE
[  793.948955] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x13010003|0x0: GLB_SET_PIPELINE_STATE
[  794.680677] snd_sof:sof_pcm_hw_free: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: free stream 0 dir 1
[  794.680700] snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-mtl 0000:00:1f.3: FW Poll Status: reg[0x80]=0x20140000 successful
[  794.680707] snd_sof:sof_ipc4_trigger_pipelines: sof-audio-pci-intel-mtl 0000:00:1f.3: trigger cmd: 0 state: 2
[  794.680711] snd_sof:sof_ipc4_set_pipeline_state: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc4 set pipeline 1 state 2
[  794.680715] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x13010002|0x0: GLB_SET_PIPELINE_STATE
[  794.681101] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x33000000|0x0: GLB_SET_PIPELINE_STATE
[  794.681293] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x13010002|0x0: GLB_SET_PIPELINE_STATE
[  794.681327] snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-mtl 0000:00:1f.3: unbind modules copier.HDA.4.1:0 -> eqiir.4.1:0
[  794.681335] snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget copier.HDA.4.1 freed
[  794.681340] snd_sof:sof_ipc4_route_free: sof-audio-pci-intel-mtl 0000:00:1f.3: unbind modules eqiir.4.1:0 -> copier.host.3.1:0
[  794.681344] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x46000010|0x10004: MOD_UNBIND
[  794.681832] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x66000000|0x10004: MOD_UNBIND
[  794.682078] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x46000010|0x10004: MOD_UNBIND
[  794.682102] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x12000000|0x0: GLB_DELETE_PIPELINE
[  794.682883] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x32000000|0x0: GLB_DELETE_PIPELINE
[  794.683117] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x12000000|0x0: GLB_DELETE_PIPELINE
[  794.683126] snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget pipeline.4 freed
[  794.683129] snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget eqiir.4.1 freed
[  794.683134] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx      : 0x12010000|0x0: GLB_DELETE_PIPELINE
[  794.683528] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx reply: 0x32000000|0x0: GLB_DELETE_PIPELINE
[  794.683567] snd_sof:sof_ipc4_log_header: sof-audio-pci-intel-mtl 0000:00:1f.3: ipc tx done : 0x12010000|0x0: GLB_DELETE_PIPELINE
[  794.683582] snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget pipeline.3 freed
[  794.683598] snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-mtl 0000:00:1f.3: widget copier.host.3.1 freed
[  794.683993] snd_sof:sof_pcm_close: sof-audio-pci-intel-mtl 0000:00:1f.3: pcm: close stream 0 dir 1

fredoh9 · 2023-04-12T21:42:01Z

From today's daily(planresultdetail/23418), sh-mtlp-rvp-hda-04 is used

check-alsabat-headset-capture-599.sh : pass
check-alsabat-headset-capture-821.sh : failed
check-alsabat-headset-capture-997.sh : failed

821 Hz has an (or a few) imperfection in waveform

However I tried same build with another device, jf-mtlp-rvp-hda-2, all alsabat capture tests are passed.

fredoh9 · 2023-04-13T17:40:03Z

For today's daily test(planresultdetail/23512), sh-mtlp-rvp-hda-02 was used.

check-alsabat-headset-capture-599.sh : failed
check-alsabat-headset-capture-821.sh : pass
check-alsabat-headset-capture-997.sh : pass

fredoh9 · 2023-04-14T17:22:30Z

daily test(planresultdetail/23549), jf-mtlp-rvp-hda-2 was used,
all 3 alsabat capture was passed

check-alsabat-headset-capture-599.sh : pass
check-alsabat-headset-capture-821.sh : pass
check-alsabat-headset-capture-997.sh : pass

First of all, it might be possibly device specific now.
2nd, do we have any fix for this merged already?

fredoh9 · 2023-04-14T20:29:50Z

today's daily test failed on sh-mtlp-rvp-hda-03.

tested on sh-mtlp-rvp-hda-03 with same alsa settings with jf-mtlp-rvp-hda-2
check-alsabat-headset-capture-599.sh failed 3 out of 5. not 100% failure. At least it's not alsa settings issue.

bat_failed_sh-hda03.wav.gz

fredoh9 · 2023-04-17T17:54:21Z

For today's daily test(planresultdetail/23660), device is sh-mtlp-rvp-hda-04, 599Hz pass, 821/998Hz failed

fredoh9 · 2023-04-18T17:08:49Z

Yesterday @keqiaozhang checked on the device,

It’s not a device configuration issue, there’re some distortions in the waveform. This issue also can be reproduced on other devices, the reproduction rate is about ~20%.

fredoh9 · 2023-04-20T17:43:14Z

Removed P1 as some of devices have not reported the issue recently. The other devices (multiple) have ~20% failure rate though.

fredoh9 · 2023-04-21T20:05:49Z

After compiling test results of +1 week, we have 5 devices for this model.

These two devices are solid pass for all,

jf-mtlp-rvp-hda-2.jf.intel.com
jf-mtlp-rvp-hda-3.jf.intel.com

Below 3 has ~20% failure, I don't see any failure pattern,

sh-mtlp-rvp-hda-04.sh.intel.com
sh-mtlp-rvp-hda-02.sh.intel.com
sh-mtlp-rvp-hda-03.sh.intel.com

keqiaozhang · 2023-04-24T01:28:42Z

After compiling test results of +1 week, we have 5 devices for this model.

Thanks Fred for debugging, I will try to figure it out.

lgirdwood · 2023-04-25T09:01:38Z

@keqiaozhang @fredoh9 I wonder if it's the capture HW that has the glitch ? i.e. as the 2 DUTs that pass are a similar config to the DUTs that fail. Have you tried swapping capture/testing HW between DUTs ?

keqiaozhang · 2023-05-15T02:17:34Z

Confirmed that this is a Hardware specific issue and only happens on SH DUTs. I'm debugging it.

keqiaozhang · 2023-05-16T02:09:43Z

Issue fixed after connecting the stereo USB sound card to other USB port on MB. It seems that using USB HUB to power up the stereo sound card is not very stable.

keqiaozhang added bug Something isn't working as expected HDA Applies to HD-Audio bus for codec connection area:alsa-bat MTL Applies to Meteor Lake platform labels Mar 17, 2023

keqiaozhang mentioned this issue Mar 17, 2023

Amixer setting for ipc4 platforms thesofproject/sof-test#1012

Merged

lgirdwood added this to the v2.6 milestone Mar 17, 2023

kfrydryx added the P1 Blocker bugs or important features label Mar 28, 2023

singalsu mentioned this issue Mar 29, 2023

Test-case: Add to check-alsabat.sh additional audio test thesofproject/sof-test#1016

Open

fredoh9 removed the P1 Blocker bugs or important features label Apr 20, 2023

lgirdwood modified the milestones: v2.6, v2.7 May 10, 2023

keqiaozhang closed this as completed May 16, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[BUG][alsabat] glitches happened on MTL-HDA when testing headset recording #7298

[BUG][alsabat] glitches happened on MTL-HDA when testing headset recording #7298

keqiaozhang commented Mar 17, 2023

lgirdwood commented Mar 17, 2023

keqiaozhang commented Mar 20, 2023

lgirdwood commented Mar 21, 2023

keqiaozhang commented Mar 22, 2023

juimonen commented Mar 28, 2023

lgirdwood commented Mar 29, 2023 •

edited

Loading

singalsu commented Mar 29, 2023

lgirdwood commented Mar 29, 2023

wszypelt commented Mar 31, 2023

keqiaozhang commented Apr 3, 2023

keqiaozhang commented Apr 3, 2023

fredoh9 commented Apr 12, 2023 •

edited

Loading

fredoh9 commented Apr 13, 2023 •

edited

Loading

fredoh9 commented Apr 14, 2023

fredoh9 commented Apr 14, 2023 •

edited

Loading

fredoh9 commented Apr 17, 2023

fredoh9 commented Apr 18, 2023

fredoh9 commented Apr 20, 2023

fredoh9 commented Apr 21, 2023

keqiaozhang commented Apr 24, 2023

lgirdwood commented Apr 25, 2023

keqiaozhang commented May 15, 2023

keqiaozhang commented May 16, 2023

[BUG][alsabat] glitches happened on MTL-HDA when testing headset recording #7298

[BUG][alsabat] glitches happened on MTL-HDA when testing headset recording #7298

Comments

keqiaozhang commented Mar 17, 2023

lgirdwood commented Mar 17, 2023

keqiaozhang commented Mar 20, 2023

lgirdwood commented Mar 21, 2023

keqiaozhang commented Mar 22, 2023

juimonen commented Mar 28, 2023

lgirdwood commented Mar 29, 2023 • edited Loading

singalsu commented Mar 29, 2023

lgirdwood commented Mar 29, 2023

wszypelt commented Mar 31, 2023

keqiaozhang commented Apr 3, 2023

keqiaozhang commented Apr 3, 2023

fredoh9 commented Apr 12, 2023 • edited Loading

fredoh9 commented Apr 13, 2023 • edited Loading

fredoh9 commented Apr 14, 2023

fredoh9 commented Apr 14, 2023 • edited Loading

fredoh9 commented Apr 17, 2023

fredoh9 commented Apr 18, 2023

fredoh9 commented Apr 20, 2023

fredoh9 commented Apr 21, 2023

keqiaozhang commented Apr 24, 2023

lgirdwood commented Apr 25, 2023

keqiaozhang commented May 15, 2023

keqiaozhang commented May 16, 2023

lgirdwood commented Mar 29, 2023 •

edited

Loading

fredoh9 commented Apr 12, 2023 •

edited

Loading

fredoh9 commented Apr 13, 2023 •

edited

Loading

fredoh9 commented Apr 14, 2023 •

edited

Loading