rex-rev1 ~ # mtrace-reader.py [00:00:00.055,931] init: print_version_banner: FW ABI 0x301a000 DBG ABI 0x5003000 tags SOF:v2.5-stable-branch-262-gb3b414f9a458-dirty zephyr:v3.1.0-rc3-13361-gc31e683295eb src hash 0x99272281 (ref hash 0x99272281) *** Booting Zephyr OS build v3.1.0-rc3-13361-gc31e683295eb *** [00:00:00.056,128] main: main: SOF on intel_adsp_ace15_mtpm [00:00:00.056,140] main: main: SOF initialized [00:00:00.056,281] ipc: ipc_cmd: rx : 0x43000000|0x20701000 [00:00:00.069,631] ipc: ipc_cmd: rx : 0x44000000|0x31400008 [00:00:00.069,943] ipc: ipc_cmd: rx : 0x44000000|0x3060004c [00:00:04.686,316] ipc: ipc_cmd: rx : 0x44000000|0x3060004c [00:00:04.686,805] ipc: ipc_cmd: rx : 0x47000000|0x0 [00:00:00.152,868] ipc: ipc_cmd: rx : 0x44000000|0x31400008 [00:00:00.153,175] ipc: ipc_cmd: rx : 0x44000000|0x3060004c [00:00:00.154,790] ipc: ipc_cmd: rx : 0x11000005|0x0 [00:00:00.154,806] pipe: pipeline_new: pipeline new pipe_id 0 priority 0 [00:00:00.155,520] ipc: ipc_cmd: rx : 0x40000004|0x15 [00:00:00.155,570] dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0 [00:00:00.156,043] ipc: ipc_cmd: rx : 0x40000006|0x10 [00:00:00.156,441] ipc: ipc_cmd: rx : 0x44000006|0x30000018 [00:00:00.156,763] ipc: ipc_cmd: rx : 0x40000002|0xa [00:00:00.157,086] ipc: ipc_cmd: rx : 0x11010006|0x0 [00:00:00.157,108] pipe: pipeline_new: pipeline new pipe_id 1 priority 0 [00:00:00.157,430] ipc: ipc_cmd: rx : 0x40000003|0x1000a [00:00:00.157,766] ipc: ipc_cmd: rx : 0x40010006|0x10010 [00:00:00.158,123] ipc: ipc_cmd: rx : 0x44010006|0x30000018 [00:00:00.158,436] ipc: ipc_cmd: rx : 0x40010004|0x1002f [00:00:00.158,498] dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: dai_ssp_pm_runtime_en_ssp_power en_ssp_power index 0 [00:00:00.158,508] dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: dai_ssp_pm_runtime_en_ssp_power I2SLCTL [00:00:00.158,521] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 8, mask 80, value 80 [00:00:00.158,546] dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0 [00:00:00.158,566] ipc: dai_config: comp:1 0x40001 dai_config() dai type = 1 index = 0 dd 0x40109cc0 [00:00:00.158,590] dai_intel_ssp: dai_ssp_parse_aux_data: dai_ssp_parse_aux_data link clock_source 1 [00:00:00.158,611] dai_intel_ssp: dai_ssp_set_reg_config: dai_ssp_set_reg_config sscr0 = 0xc1d0077f, sscr1 = 0xd0700004, ssto = 0x00000000, sspsp = 0x2200000 [00:00:00.158,628] dai_intel_ssp: dai_ssp_set_reg_config: dai_ssp_set_reg_config sscr2 = 0x00004002, sspsp2 = 0x00000000, sscr3 = 0x07070000 [00:00:00.158,645] dai_intel_ssp: dai_ssp_set_reg_config: dai_ssp_set_reg_config ssioc = 0x00000020, ssrsa = 0x00000003, sstsa = 0x00000003 [00:00:00.158,660] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 4, mask 300000, value 300000 [00:00:00.158,673] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 0, mask 80, value 80 [00:00:00.159,070] ipc: ipc_cmd: rx : 0x45000004|0x6 [00:00:00.159,088] ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0 [00:00:00.159,113] pipe: pipeline_connect: comp:0 0x40000 connect buffer 0 as sink [00:00:00.159,128] pipe: pipeline_connect: comp:0 0x60000 connect buffer 0 as source [00:00:00.161,490] ipc: ipc_cmd: rx : 0x45000006|0x2 [00:00:00.161,516] ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0 [00:00:00.161,540] pipe: pipeline_connect: comp:0 0x60000 connect buffer 0 as sink [00:00:00.161,555] pipe: pipeline_connect: comp:0 0x20000 connect buffer 0 as source [00:00:00.161,833] ipc: ipc_cmd: rx : 0x45000002|0x3 [00:00:00.161,851] ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0 [00:00:00.161,881] pipe: pipeline_connect: comp:0 0x20000 connect buffer 0 as sink [00:00:00.161,896] pipe: pipeline_connect: comp:1 0x30000 connect buffer 0 as source [00:00:00.163,158[00:00:00.168,745] ipc: ipc_cmd: rx : 0x40000004|0x15 [00:00:00.168,800] dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0 [00:00:00.169,103] ipc: ipc_cmd: rx : 0x40000006|0x10 [00:00:00.169,585] ipc: ipc_cmd: rx : 0x44000006|0x30000018 [00:00:00.170,023] ipc: ipc_cmd: rx : 0x40000002|0xa [00:00:00.170,343] ipc: ipc_cmd: rx : 0x11010006|0x0 [00:00:00.170,365] pipe: pipeline_new: pipeline new pipe_id 1 priority 0 [00:00:00.170,683] ipc: ipc_cmd: rx : 0x40000003|0x1000a [00:00:00.171,015] ipc: ipc_cmd: rx : 0x40010006|0x10010 [00:00:00.171,365] ipc: ipc_cmd: rx : 0x44010006|0x30000018 [00:00:00.171,691] ipc: ipc_cmd: rx : 0x40010004|0x1002f [00:00:00.171,748] dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: dai_ssp_pm_runtime_en_ssp_power en_ssp_power index 0 [00:00:00.171,758] dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: dai_ssp_pm_runtime_en_ssp_power I2SLCTL [00:00:00.171,771] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 8, mask 80, value 80 [00:00:00.171,796] dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0 [00:00:00.171,816] ipc: dai_config: comp:1 0x40001 dai_config() dai type = 1 index = 0 dd 0x40109cc0 [00:00:00.171,840] dai_intel_ssp: dai_ssp_parse_aux_data: dai_ssp_parse_aux_data link clock_source 1 [00:00:00.171,861] dai_intel_ssp: dai_ssp_set_reg_config: dai_ssp_set_reg_config sscr0 = 0xc1d0077f, sscr1 = 0xd0700004, ssto = 0x00000000, sspsp = 0x2200000 [00:00:00.171,878] dai_intel_ssp: dai_ssp_set_reg_config: dai_ssp_set_reg_config sscr2 = 0x00004002, sspsp2 = 0x00000000, sscr3 = 0x07070000 [00:00:00.171,895] dai_intel_ssp: dai_ssp_set_reg_config: dai_ssp_set_reg_config ssioc = 0x00000020, ssrsa = 0x00000003, sstsa = 0x00000003 [00:00:00.171,910] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 4, mask 300000, value 300000 [00:00:00.171,923] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 0, mask 80, value 80 [00:00:00.172,328] ipc: ipc_cmd: rx : 0x45000004|0x6 [00:00:00.172,346] ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0 [00:00:00.172,370] pipe: pipeline_connect: comp:0 0x40000 connect buffer 0 as sink [00:00:00.172,386] pipe: pipeline_connect: comp:0 0x60000 connect buffer 0 as source [00:00:00.172,738] ipc: ipc_cmd: rx : 0x45000006|0x2 [00:00:00.172,758] ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0 [00:00:00.172,781] pipe: pipeline_connect: comp:0 0x60000 connect buffer 0 as sink [00:00:00.172,796] pipe: pipeline_connect: comp:0 0x20000 connect buffer 0 as source [00:00:00.173,221] ipc: ipc_cmd: rx : 0x45000002|0x3 [00:00:00.173,241] ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0 [00:00:00.173,265] pipe: pipeline_connect: comp:0 0x20000 connect buffer 0 as sink [00:00:00.173,280] pipe: pipeline_connect: comp:1 0x30000 connect buffer 0 as source [00:00:00.173,643] ipc: ipc_cmd: rx : 0x45000003|0x10006 [00:00:00.173,663] ipc: buffer_new: buffer new size 0x300 id 1.0 flags 0x0 [00:00:00.173,686] pipe: pipeline_connect: comp:1 0x30000 connect buffer 0 as sink [00:00:00.173,701] pipe: pipeline_connect: comp:1 0x60001 connect buffer 0 as source [00:00:00.174,058] ipc: ipc_cmd: rx : 0x45010006|0x10004 [00:00:00.174,078] ipc: buffer_new: buffer new size 0x300 id 1.0 flags 0x0 [00:00:00.174,101] pipe: pipeline_connect: comp:1 0x60001 connect buffer 0 as sink [00:00:00.174,116] pipe: pipeline_connect: comp:1 0x40001 connect buffer 0 as source [00:00:00.180,295] ipc: ipc_cmd: rx : 0x13000003|0x1 [00:00:00.180,351] ipc: ipc_pipeline_complete(): no scheduling component specified, use comp 131072 [00:00:00.180,741] ipc: ipc_cmd: rx : 0x13000004|0x1 [00:00:00.180,790] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties dai_index 0 [00:00:00.180,796] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties fifo 163856 [00:00:00.180,806] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties handshake 2 [00:00:00.180,820] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties init delay 0 [00:00:00.180,848] dai_comp: dai_playback_params: comp:1 0x40001 dai_playback_params() dest_dev = 2 stream_id = 0 src_width = 4 dest_width = 4 [00:00:00.180,858] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties dai_index 0 [00:00:00.180,865] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties fifo 163856 [00:00:00.180,873] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties handshake 2 [00:00:00.180,883] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties init delay 0 [00:00:00.180,973] pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 7 [00:00:00.180,990] pipe: add_pipeline_cps_consumption: Registering KCPS consumption: 2280, core: 0 [00:00:00.181,006] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 12280, core: 0 [00:00:00.181,023] pipe: add_pipeline_cps_consumption: Registering KCPS consumption: 10183, core: 0 [00:00:00.181,038] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 22463, core: 0 [00:00:00.181,055] pipe: add_pipeline_cps_consumption: Registering KCPS consumption: 6388, core: 0 [00:00:00.181,071] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 28851, core: 0 [00:00:00.181,093] ll_schedule: zephyr_ll_task_schedule_common: task add 0xa010bfc0 0x201b0U priority 0 flags 0x0 [00:00:00.181,133] ll_schedule: zephyr_domain_register: zephyr_domain_register domain->type 1 domain->clk 3 domain->ticks_per_ms 38400 period 1000 [00:00:00.181,218] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties dai_index 0 [00:00:00.181,225] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties fifo 163856 [00:00:00.181,235] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties handshake 2 [00:00:00.181,243] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties init delay 0 [00:00:00.181,253] dai_intel_ssp: dai_ssp_pre_start: dai_ssp_pre_start [00:00:00.181,281] dma_intel_adsp_gpdma: intel_adsp_gpdma_power_on: intel_adsp_gpdma_power_on: dma dma@7c000 initialized [00:00:00.181,306] dai_intel_ssp: dai_ssp_start: dai_ssp_start [00:00:00.181,320] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 30, mask 100, value 100 [00:00:00.181,470] mixer: mixin_prepare: comp:0 0x20000 mixin_prepare() [00:00:00.181,500] pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 7 [00:00:00.181,516] pipe: add_pipeline_cps_consumption: Registering KCPS consumption: 5272, core: 0 [00:00:00.181,533] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 34123, core: 0 [00:00:00.181,550] pipe: add_pipeline_cps_consumption: Registering KCPS consumption: 10183, core: 0 [00:00:00.181,565] clock: clock_set_freq: clock 0 set freq 44306000Hz freq_idx 1 [00:00:00.181,580] clock: clock_set_freq: clock 1 set freq 44306000Hz freq_idx 1 [00:00:00.181,595] clock: clock_set_freq: clock 2 set freq 44306000Hz freq_idx 1 [00:00:00.181,610] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 44306, core: 0 [00:00:00.181,625] pipe: add_pipeline_cps_consumption: Registering KCPS consumption: 4996, core: 0 [00:00:00.181,640] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 49302, core: 0 [00:00:00.181,663] ll_schedule: zephyr_ll_task_schedule_common: task add 0xa010c8c0 0x201b0U priority 0 flags 0x0 [00:00:00.182,336] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [00:00:01.204,273] ll_schedule: zephyr_domain_thread_fn: ll timer avg 2448, max 8534, overruns 0 [00:00:02.228,273] ll_schedule: zephyr_domain_thread_fn: ll timer avg 2411, max 2464, overruns 0 [00:00:02.250,115] ipc: ipc_cmd: rx : 0x11020004|0x0 [00:00:02.250,130] pipe: pipeline_new: pipeline new pipe_id 2 priority 0 [00:00:02.250,538] ipc: ipc_cmd: rx : 0x40020004|0x2002f [00:00:02.250,590] dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0 [00:00:02.250,608] ipc: dai_config: comp:2 0x40002 dai_config() dai type = 1 index = 0 dd 0x4010ce00 [00:00:02.251,361] ipc: ipc_cmd: rx : 0x40030004|0x20015 [00:00:02.251,696] ipc: ipc_cmd: rx : 0x11030002|0x0 [00:00:02.251,711] pipe: pipeline_new: pipeline new pipe_id 3 priority 0 [00:00:02.252,263] ipc: ipc_cmd: rx : 0x40040004|0x30015 [00:00:02.252,300] dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0 [00:00:02.252,588] ipc: ipc_cmd: rx : 0x45030004|0x40004 [00:00:02.252,611] ipc: buffer_new: buffer new size 0x300 id 2.0 flags 0x0 [00:00:02.252,633] pipe: pipeline_connect: comp:2 0x40003 connect buffer 0 as sink [00:00:02.252,646] pipe: pipeline_connect: comp:3 0x40004 connect buffer 0 as source [00:00:02.252,985] ipc: ipc_cmd: rx : 0x45020004|0x30004 [00:00:02.253,005] ipc: buffer_new: buffer new size 0x300 id 2.0 flags 0x0 [00:00:02.253,026] pipe: pipeline_connect: comp:2 0x40002 connect buffer 0 as sink [00:00:02.253,041] pipe: pipeline_connect: comp:2 0x40003 connect buffer 0 as source [00:00:02.269,466] ipc: ipc_cmd: rx : 0x13000003|0x1 [00:00:02.269,505] ipc: ipc_pipeline_complete(): no scheduling component specified, use comp 262148 [00:00:02.270,056] ipc: ipc_cmd: rx : 0x13000004|0x1 [00:00:02.270,106] pipe: pipeline_trigger: pipe:3 0x0 pipe trigger cmd 7 [00:00:02.270,121] pipe: add_pipeline_cps_consumption: Registering KCPS consumption: 6388, core: 0 [00:00:02.270,136] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 55690, core: 0 [00:00:02.270,160] ll_schedule: zephyr_ll_task_schedule_common: task add 0xa010ec40 0x201b0U priority 0 flags 0x0 [00:00:02.270,298] host_comp: host_get_copy_bytes_normal: comp:3 0x40004 no bytes to copy, available samples: 0, free_samples: 384 [00:00:02.270,320] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties dai_index 0 [00:00:02.270,326] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties fifo 163856 [00:00:02.270,335] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties handshake 3 [00:00:02.270,343] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties init delay 0 [00:00:02.270,368] dai_comp: dai_capture_params: comp:2 0x40002 dai_capture_params() src_dev = 3 stream_id = 0 src_width = 4 dest_width = 4 [00:00:02.270,378] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties dai_index 0 [00:00:02.270,385] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties fifo 163856 [00:00:02.270,393] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties handshake 3 [00:00:02.270,401] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties init delay 0 [00:00:02.270,446] pipe: pipeline_trigger: pipe:2 0x0 pipe trigger cmd 7 [00:00:02.270,461] pipe: add_pipeline_cps_consumption: Registering KCPS consumption: 6388, core: 0 [00:00:02.270,476] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 62078, core: 0 [00:00:02.270,491] pipe: add_pipeline_cps_consumption: Registering KCPS consumption: 6388, core: 0 [00:00:02.270,506] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 68466, core: 0 [00:00:02.270,526] ll_schedule: zephyr_ll_task_schedule_common: task add 0xa010f600 0x201b0U priority 0 flags 0x0 [00:00:02.271,320] host_comp: host_get_copy_bytes_normal: comp:3 0x40004 no bytes to copy, available samples: 0, free_samples: 384 [00:00:02.271,335] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties dai_index 0 [00:00:02.271,341] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties fifo 163856 [00:00:02.271,350] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties handshake 2 [00:00:02.271,358] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties init delay 0 [00:00:02.271,366] dai_intel_ssp: dai_ssp_pre_start: dai_ssp_pre_start [00:00:02.271,388] dma_intel_adsp_gpdma: intel_adsp_gpdma_power_on: intel_adsp_gpdma_power_on: dma dma@7d000 initialized [00:00:02.271,408] dai_intel_ssp: dai_ssp_start: dai_ssp_start [00:00:02.271,421] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 34, mask 100, value 100 [00:00:02.271,485] dai_comp: comp:2 0x40002 dai_zephyr_copy(): nothing to copy [00:00:02.272,288] host_comp: host_get_copy_bytes_normal: comp:3 0x40004 no bytes to copy, available samples: 0, free_samples: 384 [00:00:03.252,306] ll_schedule: zephyr_domain_thread_fn: ll timer avg 3646, max 10079, overruns 0 [00:00:04.276,306] ll_schedule: zephyr_domain_thread_fn: ll timer avg 3689, max 4146, overruns 0 [00:00:04.430,810] ipc: ipc_cmd: rx : 0x11040006|0x0 [00:00:04.430,828] pipe: pipeline_new: pipeline new pipe_id 4 priority 0 [00:00:04.431,548] ipc: ipc_cmd: rx : 0x40050004|0x40306 [00:00:04.431,591] dai_intel_dmic: dai_dmic_probe: dmic_probe() [00:00:04.431,610] dma: dma_get: dma_get() ID 0 sref = 2 busy channels 0 [00:00:04.431,628] ipc: dai_config: comp:4 0x40005 dai_config() dai type = 2 index = 0 dd 0x4010fa00 [00:00:04.431,646] dai_intel_dmic: dai_dmic_set_config: dmic_set_config() [00:00:04.431,661] dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: dmic_set_config_nhlt(): OUTCONTROL0 = 00390843 [00:00:04.431,673] dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: tie=0, sip=0, finit=0, fci=0 [00:00:04.431,685] dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: bfth=3, of=2, ipm=2, th=3 [00:00:04.431,698] dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: ipms1=0, ipms2=1, ipms3=0, ipms4=0 [00:00:04.431,706] dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: ipms_mode=1 [00:00:04.431,721] dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: dmic_set_config_nhlt(): OUTCONTROL1 = 00390843 [00:00:04.431,733] dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: tie=0, sip=0, finit=0, fci=0 [00:00:04.431,745] dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: bfth=3, of=2, ipm=2, th=3 [00:00:04.431,758] dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: ipms1=0, ipms2=1, ipms3=0, ipms4=0 [00:00:04.431,766] dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: ipms_mode=1 [00:00:04.431,780] dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: dmic_set_config_nhlt(): OUTCONTROL0 = 02390843 [00:00:04.431,801] dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: dmic_set_config_nhlt(): clkdiv = 16, mcic = 25, mfir_a = 2, len = 101 [00:00:04.431,828] dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: dmic_set_config_nhlt(): clkdiv = 16, mcic = 25, mfir_a = 2, len = 101 [00:00:04.431,853] dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: dmic_set_config_nhlt(): rate = 48000, channels = 4, format = 2 [00:00:04.431,868] dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: dmic_set_config_nhlt(): io_clk 38400000, rate_div 800 [00:00:04.431,883] dai_intel_dmic_nhlt: dai_dmic_set_config_nhlt: dmic_set_config_nhlt(): enable0 3, enable1 3 [00:00:04.432,415] ipc: ipc_cmd: rx : 0x40000010|0x4000a [00:00:04.432,450] eq_iir: eq_iir_init: comp:4 0x100000 eq_iir_init() [00:00:04.432,796] ipc: ipc_cmd: rx : 0x44000010|0x30000058 [00:00:04.432,815] eq_iir: eq_iir_set_config: comp:4 0x100000 eq_iir_set_config() [00:00:04.433,368] ipc: ipc_cmd: rx : 0x40060004|0x40015 [00:00:04.433,695] ipc: ipc_cmd: rx : 0x11050004|0x0 [00:00:04.433,711] pipe: pipeline_new: pipeline new pipe_id 5 priority 0 [00:00:04.434,055] ipc: ipc_cmd: rx : 0x40070004|0x50015 [00:00:04.434,410] ipc: ipc_cmd: rx : 0x40000013|0x10050026 [00:00:04.434,435] google_rtc_audio_processing: google_rtc_audio_processing_create: google_rtc_audio_processing_create() [00:00:04.436,088] ipc: ipc_cmd: rx : 0x44000013|0x30000034 [00:00:04.436,420] ipc: ipc_cmd: rx : 0x40080004|0x50015 [00:00:04.436,748] ipc: ipc_cmd: rx : 0x11060002|0x0 [00:00:04.436,763] pipe: pipeline_new: pipeline new pipe_id 6 priority 0 [00:00:04.437,085] ipc: ipc_cmd: rx : 0x40090004|0x60015 [00:00:04.437,118] dma: dma_get: dma_get() ID 0 sref = 2 busy channels 0 [00:00:04.437,443] ipc: ipc_cmd: rx : 0x45080004|0x90004 [00:00:04.437,463] ipc: buffer_new: buffer new size 0x300 id 5.0 flags 0x0 [00:00:04.437,486] pipe: pipeline_connect: comp:5 0x40008 connect buffer 0 as sink [00:00:04.437,501] pipe: pipeline_connect: comp:6 0x40009 connect buffer 0 as source [00:00:04.437,768] ipc: ipc_cmd: rx : 0x45000013|0x80004 [00:00:04.437,790] ipc: buffer_new: buffer new size 0x180 id 5.0 flags 0x0 [00:00:04.437,811] pipe: pipeline_connect: comp:5 0x130000 connect buffer 0 as sink [00:00:04.437,826] pipe: pipeline_connect: comp:5 0x40008 connect buffer 0 as source [00:00:04.438,111] ipc: ipc_cmd: rx : 0x45070004|0x13 [00:00:04.438,131] ipc: buffer_new: buffer new size 0x180 id 5.0 flags 0x0 [00:00:04.438,151] pipe: pipeline_connect: comp:5 0x40007 connect buffer 0 as sink [00:00:04.438,166] pipe: pipeline_connect: comp:5 0x130000 connect buffer 0 as source [00:00:04.438,470] ipc: ipc_cmd: rx : 0x44030004|0x30200034 [00:00:04.438,773] ipc: ipc_cmd: rx : 0x45030004|0x9000013 [00:00:04.438,791] ipc: buffer_new: buffer new size 0x300 id 2.65537 flags 0x0 [00:00:04.438,811] pipe: pipeline_connect: comp:2 0x40003 connect buffer 65537 as sink [00:00:04.438,826] pipe: pipeline_connect: comp:5 0x130000 connect buffer 65537 as source [00:00:04.439,123] ipc: ipc_cmd: rx : 0x45060004|0x70004 [00:00:04.439,141] ipc: buffer_new: buffer new size 0x600 id 4.0 flags 0x0 [00:00:04.439,163] pipe: pipeline_connect: comp:4 0x40006 connect buffer 0 as sink [00:00:04.439,178] pipe: pipeline_connect: comp:5 0x40007 connect buffer 0 as source [00:00:04.439,606] ipc: ipc_cmd: rx : 0x45000010|0x60004 [00:00:04.439,626] ipc: buffer_new: buffer new size 0x600 id 4.0 flags 0x0 [00:00:04.439,646] pipe: pipeline_connect: comp:4 0x100000 connect buffer 0 as sink [00:00:04.439,661] pipe: pipeline_connect: comp:4 0x40006 connect buffer 0 as source [00:00:04.439,956] ipc: ipc_cmd: rx : 0x45050004|0x10 [00:00:04.439,975] ipc: buffer_new: buffer new size 0x600 id 4.0 flags 0x0 [00:00:04.439,996] pipe: pipeline_connect: comp:4 0x40005 connect buffer 0 as sink [00:00:04.440,011] pipe: pipeline_connect: comp:4 0x100000 connect buffer 0 as source [00:00:04.441,361] ipc: ipc_cmd: rx : 0x13000003|0x1 [00:00:04.441,411] ipc: ipc_pipeline_complete(): no scheduling component specified, use comp 262153 [00:00:04.441,453] ipc: ipc_pipeline_complete(): no scheduling component specified, use comp 262152 [00:00:04.442,025] ipc: ipc_cmd: rx : 0x13000004|0x1 [00:00:04.442,083] pipe: pipeline_trigger: pipe:6 0x0 pipe trigger cmd 7 [00:00:04.442,101] pipe: 0 CPS requested for module: 0x40009, core: 0 using safe max CPC: 400000 [00:00:04.442,116] pipe: add_pipeline_cps_consumption: Registering KCPS consumption: 400000, core: 0 [00:00:04.442,130] clock: clock_set_freq: clock 0 set freq 468466000Hz freq_idx 2 [00:00:04.442,145] clock: clock_set_freq: clock 1 set freq 468466000Hz freq_idx 2 [00:00:04.442,166] clock: clock_set_freq: clock 2 set freq 468466000Hz freq_idx 2 [00:00:04.442,331] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 468466, core: 0 [00:00:04.442,350] ll_schedule: zephyr_ll_task_schedule_common: task add 0xa0146240 0x201b0U priority 0 flags 0x0 [00:00:04.442,425] pipe: pipeline_trigger: pipe:5 0x0 pipe trigger cmd 7 [00:00:04.442,443] pipe: 0 CPS requested for module: 0x40007, core: 0 using safe max CPC: 400000 [00:00:04.442,458] pipe: add_pipeline_cps_consumption: Registering KCPS consumption: 400000, core: 0 [00:00:04.442,473] clock: clock_set_freq: clock 0 set freq 868466000Hz freq_idx 2 [00:00:04.442,490] clock: clock_set_freq: clock 1 set freq 868466000Hz freq_idx 2 [00:00:04.442,506] clock: clock_set_freq: clock 2 set freq 868466000Hz freq_idx 2 [00:00:04.442,523] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 868466, core: 0 [00:00:04.442,543] pipe: 0 CPS requested for module: 0x130000, core: 0 using safe max CPC: 400000 [00:00:04.442,558] pipe: add_pipeline_cps_consumption: Registering KCPS consumption: 400000, core: 0 [00:00:04.442,573] clock: clock_set_freq: clock 0 set freq 1268466000Hz freq_idx 2 [00:00:04.442,588] clock: clock_set_freq: clock 1 set freq 1268466000Hz freq_idx 2 [00:00:04.442,605] clock: clock_set_freq: clock 2 set freq 1268466000Hz freq_idx 2 [00:00:04.442,620] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 1268466, core: 0 [00:00:04.442,636] pipe: add_pipeline_cps_consumption: Registering KCPS consumption: 5272, core: 0 [00:00:04.442,651] clock: clock_set_freq: clock 0 set freq 1273738000Hz freq_idx 2 [00:00:04.442,668] clock: clock_set_freq: clock 1 set freq 1273738000Hz freq_idx 2 [00:00:04.442,683] clock: clock_set_freq: clock 2 set freq 1273738000Hz freq_idx 2 [00:00:04.442,700] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 1273738, core: 0 [00:00:04.442,726] ll_schedule: zephyr_ll_task_schedule_common: task add 0xa0146300 0x201b0U priority 0 flags 0x0 [00:00:04.442,791] dai_comp: dai_capture_params: comp:4 0x40005 dai_capture_params() src_dev = 0 stream_id = 0 src_width = 4 dest_width = 4 [00:00:04.442,843] eq_iir: eq_iir_prepare: comp:4 0x100000 eq_iir_prepare(), source_format=2, sink_format=2 [00:00:04.442,866] eq_iir: eq_iir_init_coef: comp:4 0x100000 eq_iir_init_coef(): 1 responses, 2 channels, stream 4 channels [00:00:04.442,886] eq_iir: eq_iir_init_coef: comp:4 0x100000 eq_iir_init_coef(), ch 0 is set to response 0 [00:00:04.442,906] eq_iir: eq_iir_init_coef: comp:4 0x100000 eq_iir_init_coef(), ch 1 is set to response 0 [00:00:04.442,925] eq_iir: eq_iir_init_coef: comp:4 0x100000 eq_iir_init_coef(), ch 2 is set to response 0 [00:00:04.442,943] eq_iir: eq_iir_init_coef: comp:4 0x100000 eq_iir_init_coef(), ch 3 is set to response 0 [00:00:04.442,991] pipe: pipeline_trigger: pipe:4 0x0 pipe trigger cmd 7 [00:00:04.443,008] pipe: add_pipeline_cps_consumption: Registering KCPS consumption: 7116, core: 0 [00:00:04.443,023] clock: clock_set_freq: clock 0 set freq 1280854000Hz freq_idx 2 [00:00:04.443,040] clock: clock_set_freq: clock 1 set freq 1280854000Hz freq_idx 2 [00:00:04.443,055] clock: clock_set_freq: clock 2 set freq 1280854000Hz freq_idx 2 [00:00:04.443,071] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 1280854, core: 0 [00:00:04.443,088] pipe: add_pipeline_cps_consumption: Registering KCPS consumption: 20663, core: 0 [00:00:04.443,103] clock: clock_set_freq: clock 0 set freq 1301517000Hz freq_idx 2 [00:00:04.443,118] clock: clock_set_freq: clock 1 set freq 1301517000Hz freq_idx 2 [00:00:04.443,135] clock: clock_set_freq: clock 2 set freq 1301517000Hz freq_idx 2 [00:00:04.443,151] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 1301517, core: 0 [00:00:04.443,168] pipe: add_pipeline_cps_consumption: Registering KCPS consumption: 7116, core: 0 [00:00:04.443,181] clock: clock_set_freq: clock 0 set freq 1308633000Hz freq_idx 2 [00:00:04.443,198] clock: clock_set_freq: clock 1 set freq 1308633000Hz freq_idx 2 [00:00:04.443,215] clock: clock_set_freq: clock 2 set freq 1308633000Hz freq_idx 2 [00:00:04.443,401] host_comp: host_get_copy_bytes_normal: comp:6 0x40009 no bytes to copy, available samples: 0, free_samples: 384 [00:00:04.443,465] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 1308633, core: 0 [00:00:04.443,490] ll_schedule: zephyr_ll_task_schedule_common: task add 0xa0149540 0x201b0U priority 0 flags 0x0 [00:00:04.444,388] host_comp: host_get_copy_bytes_normal: comp:6 0x40009 no bytes to copy, available samples: 0, free_samples: 384 [00:00:04.444,461] dai_intel_dmic: dai_dmic_start: dmic_start(), dmic->fifo_a [00:00:04.444,475] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 0, mask 6000000, value 4000000 [00:00:04.444,490] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 1000, mask 10000, value 0 [00:00:04.444,500] dai_intel_dmic: dai_dmic_start: dmic_start(), cic 0x00000001 [00:00:04.444,515] dai_intel_dmic: dai_dmic_start: dmic_start(), pdm0 mic_a = 1, mic_b = 1 [00:00:04.444,528] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 1000, mask c000, value c000 [00:00:04.444,543] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 100c, mask 3, value 3 [00:00:04.444,556] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 1020, mask 80, value 80 [00:00:04.444,570] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 2000, mask 10000, value 0 [00:00:04.444,581] dai_intel_dmic: dai_dmic_start: dmic_start(), cic 0x00000001 [00:00:04.444,596] dai_intel_dmic: dai_dmic_start: dmic_start(), pdm1 mic_a = 1, mic_b = 1 [00:00:04.444,610] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 2000, mask c000, value c000 [00:00:04.444,623] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 200c, mask 3, value 3 [00:00:04.444,638] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 2020, mask 80, value 80 [00:00:04.444,925] dai_intel_dmic: dai_dmic_start: dmic_start(), dmic_active_fifos_mask = 0x1 [00:00:04.444,961] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 1000, mask 2, value 0 [00:00:04.444,975] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 2000, mask 2, value 0 [00:00:04.445,380] host_comp: host_get_copy_bytes_normal: comp:6 0x40009 no bytes to copy, available samples: 0, free_samples: 384 [00:00:04.445,418] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 1020, mask 2, value 0 [00:00:04.445,431] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 2020, mask 2, value 0 [00:00:04.446,401] host_comp: host_get_copy_bytes_normal: comp:6 0x40009 no bytes to copy, available samples: 0, free_samples: 384 [00:00:04.447,376] host_comp: host_get_copy_bytes_normal: comp:6 0x40009 no bytes to copy, available samples: 0, free_samples: 384 [00:00:04.450,373] host_comp: host_get_copy_bytes_normal: comp:6 0x40009 no bytes to copy, available samples: 0, free_samples: 384 [00:00:04.451,360] host_comp: host_get_copy_bytes_normal: comp:6 0x40009 no bytes to copy, available samples: 0, free_samples: 384 [00:00:05.300,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 7824, max 29897, overruns 0 [00:00:06.324,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8585, max 9146, overruns 0 [00:00:07.348,440] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8585, max 8915, overruns 0 [00:00:08.372,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8582, max 9243, overruns 0 [00:00:09.396,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8578, max 8907, overruns 0 [00:00:10.420,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8580, max 8901, overruns 0 [00:00:11.444,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8585, max 8934, overruns 0 [00:00:12.468,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8585, max 8934, overruns 0 [00:00:13.492,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8585, max 8939, overruns 0 [00:00:14.516,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8586, max 8935, overruns 0 [00:00:15.540,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8589, max 9118, overruns 0 [00:00:16.564,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8588, max 8944, overruns 0 [00:00:17.588,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8586, max 9275, overruns 0 [00:00:18.612,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8582, max 8967, overruns 0 [00:00:19.636,440] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8583, max 8948, overruns 0 [00:00:20.660,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8594, max 8862, overruns 0 [00:00:21.684,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8594, max 8928, overruns 0 [00:00:22.708,440] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8595, max 8938, overruns 0 [00:00:23.732,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8595, max 8747, overruns 0 [00:00:24.756,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8596, max 9171, overruns 0 [00:00:25.780,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8595, max 8919, overruns 0 [00:00:26.804,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8595, max 9261, overruns 0 [00:00:27.828,440] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8591, max 8925, overruns 0 [00:00:28.852,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8587, max 8944, overruns 0 [00:00:29.876,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8596, max 8975, overruns 0 [00:00:30.900,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8597, max 8969, overruns 0 [00:00:31.924,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8595, max 8967, overruns 0 [00:00:32.948,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8596, max 8989, overruns 0 [00:00:33.972,436] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8601, max 9149, overruns 0 [00:00:34.996,436] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8599, max 8975, overruns 0 [00:00:36.020,436] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8601, max 9282, overruns 0 [00:00:37.044,438] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8598, max 8965, overruns 0 [00:00:38.068,440] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8592, max 8974, overruns 0 [00:00:39.005,843] ipc: ipc_cmd: rx : 0x13000003|0x1 [00:00:39.005,865] pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 2 [00:00:39.005,881] clock: clock_set_freq: clock 0 set freq 1303361000Hz freq_idx 2 [00:00:39.005,896] clock: clock_set_freq: clock 1 set freq 1303361000Hz freq_idx 2 [00:00:39.005,913] clock: clock_set_freq: clock 2 set freq 1303361000Hz freq_idx 2 [00:00:39.005,930] pipe: remove_pipeline_cps_consumption: Unregistering KCPS consumption: 5272, core: 0 [00:00:39.005,951] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 1303361, core: 0 [00:00:39.005,968] clock: clock_set_freq: clock 0 set freq 1293178000Hz freq_idx 2 [00:00:39.005,983] clock: clock_set_freq: clock 1 set freq 1293178000Hz freq_idx 2 [00:00:39.006,000] clock: clock_set_freq: clock 2 set freq 1293178000Hz freq_idx 2 [00:00:39.006,018] pipe: remove_pipeline_cps_consumption: Unregistering KCPS consumption: 10183, core: 0 [00:00:39.006,031] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 1293178, core: 0 [00:00:39.006,048] clock: clock_set_freq: clock 0 set freq 1288182000Hz freq_idx 2 [00:00:39.006,065] clock: clock_set_freq: clock 1 set freq 1288182000Hz freq_idx 2 [00:00:39.006,081] clock: clock_set_freq: clock 2 set freq 1288182000Hz freq_idx 2 [00:00:39.006,098] pipe: remove_pipeline_cps_consumption: Unregistering KCPS consumption: 4996, core: 0 [00:00:39.006,111] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 1288182, core: 0 [00:00:39.006,138] pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 2 [00:00:39.006,153] clock: clock_set_freq: clock 0 set freq 1285902000Hz freq_idx 2 [00:00:39.006,170] clock: clock_set_freq: clock 1 set freq 1285902000Hz freq_idx 2 [00:00:39.006,185] clock: clock_set_freq: clock 2 set freq 1285902000Hz freq_idx 2 [00:00:39.006,288] ll_schedule: zephyr_ll_task_done: task complete 0xa010c8c0 0x201b0U [00:00:39.006,301] ll_schedule: zephyr_ll_task_done: num_tasks 7 total_num_tasks 7 [00:00:39.006,475] pipe: remove_pipeline_cps_consumption: Unregistering KCPS consumption: 2280, core: 0 [00:00:39.006,488] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 1285902, core: 0 [00:00:39.006,506] clock: clock_set_freq: clock 0 set freq 1275719000Hz freq_idx 2 [00:00:39.006,521] clock: clock_set_freq: clock 1 set freq 1275719000Hz freq_idx 2 [00:00:39.006,538] clock: clock_set_freq: clock 2 set freq 1275719000Hz freq_idx 2 [00:00:39.006,555] pipe: remove_pipeline_cps_consumption: Unregistering KCPS consumption: 10183, core: 0 [00:00:39.006,570] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 1275719, core: 0 [00:00:39.006,586] clock: clock_set_freq: clock 0 set freq 1269331000Hz freq_idx 2 [00:00:39.006,601] clock: clock_set_freq: clock 1 set freq 1269331000Hz freq_idx 2 [00:00:39.006,618] clock: clock_set_freq: clock 2 set freq 1269331000Hz freq_idx 2 [00:00:39.006,635] pipe: remove_pipeline_cps_consumption: Unregistering KCPS consumption: 6388, core: 0 [00:00:39.006,650] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 1269331, core: 0 [00:00:39.007,245] dai_intel_ssp: dai_ssp_pause: dai_ssp_pause TX [00:00:39.007,260] ll_schedule: zephyr_ll_task_done: task complete 0xa010bfc0 0x201b0U [00:00:39.007,273] ll_schedule: zephyr_ll_task_done: num_tasks 6 total_num_tasks 6 [00:00:39.008,391] ipc: ipc_cmd: rx : 0x13000002|0x1 [00:00:39.008,410] pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 0 [00:00:39.008,478] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 30, mask 100, value 0 [00:00:39.008,486] dai_intel_ssp: dai_ssp_stop: dai_ssp_stopTX stop [00:00:39.008,568] pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 0 [00:00:39.008,596] copier: comp:0 0x40000 dai is not ready [00:00:39.009,070] ipc: ipc_cmd: rx : 0x46000002|0x3 [00:00:39.009,680] ipc: ipc_cmd: rx : 0x12000000|0x0 [00:00:39.009,701] dma: dma_put: dma_put(), dma = 0x400ec378, sref = 0 [00:00:39.010,418] ipc: ipc_cmd: rx : 0x12010000|0x0 [00:00:39.010,506] dma: dma_put: dma_put(), dma = 0x400ec2a0, sref = 1 [00:00:39.092,365] ll_schedule: zephyr_domain_thread_fn: ll timer avg 8368, max 9365, overruns 0 [00:00:40.116,365] ll_schedule: zephyr_domain_thread_fn: ll timer avg 5752, max 6307, overruns 0 [00:00:41.140,365] ll_schedule: zephyr_domain_thread_fn: ll timer avg 5752, max 6305, overruns 0 [00:00:42.164,365] ll_schedule: zephyr_domain_thread_fn: ll timer avg 5753, max 6308, overruns 0 [00:00:43.188,365] ll_schedule: zephyr_domain_thread_fn: ll timer avg 5754, max 6351, overruns 0 [00:00:44.212,365] ll_schedule: zephyr_domain_thread_fn: ll timer avg 5754, max 6315, overruns 0 [00:00:44.472,015] ipc: ipc_cmd: rx : 0x13000003|0x1 [00:00:44.472,040] pipe: pipeline_trigger: pipe:4 0x0 pipe trigger cmd 2 [00:00:44.472,056] clock: clock_set_freq: clock 0 set freq 1262215000Hz freq_idx 2 [00:00:44.472,073] clock: clock_set_freq: clock 1 set freq 1262215000Hz freq_idx 2 [00:00:44.472,088] clock: clock_set_freq: clock 2 set freq 1262215000Hz freq_idx 2 [00:00:44.472,106] pipe: remove_pipeline_cps_consumption: Unregistering KCPS consumption: 7116, core: 0 [00:00:44.472,126] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 1262215, core: 0 [00:00:44.472,143] clock: clock_set_freq: clock 0 set freq 1241552000Hz freq_idx 2 [00:00:44.472,160] clock: clock_set_freq: clock 1 set freq 1241552000Hz freq_idx 2 [00:00:44.472,175] clock: clock_set_freq: clock 2 set freq 1241552000Hz freq_idx 2 [00:00:44.472,320] pipe: remove_pipeline_cps_consumption: Unregistering KCPS consumption: 20663, core: 0 [00:00:44.472,335] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 1241552, core: 0 [00:00:44.472,351] clock: clock_set_freq: clock 0 set freq 1234436000Hz freq_idx 2 [00:00:44.472,368] clock: clock_set_freq: clock 1 set freq 1234436000Hz freq_idx 2 [00:00:44.472,383] clock: clock_set_freq: clock 2 set freq 1234436000Hz freq_idx 2 [00:00:44.472,401] pipe: remove_pipeline_cps_consumption: Unregistering KCPS consumption: 7116, core: 0 [00:00:44.472,415] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 1234436, core: 0 [00:00:44.472,441] pipe: pipeline_trigger: pipe:5 0x0 pipe trigger cmd 2 [00:00:44.472,456] clock: clock_set_freq: clock 0 set freq 834436000Hz freq_idx 2 [00:00:44.472,473] clock: clock_set_freq: clock 1 set freq 834436000Hz freq_idx 2 [00:00:44.472,488] clock: clock_set_freq: clock 2 set freq 834436000Hz freq_idx 2 [00:00:44.472,506] pipe: remove_pipeline_cps_consumption: Unregistering KCPS consumption: 400000, core: 0 [00:00:44.472,520] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 834436, core: 0 [00:00:44.472,536] clock: clock_set_freq: clock 0 set freq 434436000Hz freq_idx 2 [00:00:44.472,553] clock: clock_set_freq: clock 1 set freq 434436000Hz freq_idx 2 [00:00:44.472,568] clock: clock_set_freq: clock 2 set freq 434436000Hz freq_idx 2 [00:00:44.472,585] pipe: remove_pipeline_cps_consumption: Unregistering KCPS consumption: 400000, core: 0 [00:00:44.472,600] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 434436, core: 0 [00:00:44.472,616] clock: clock_set_freq: clock 0 set freq 429164000Hz freq_idx 2 [00:00:44.472,631] clock: clock_set_freq: clock 1 set freq 429164000Hz freq_idx 2 [00:00:44.472,648] clock: clock_set_freq: clock 2 set freq 429164000Hz freq_idx 2 [00:00:44.472,665] pipe: remove_pipeline_cps_consumption: Unregistering KCPS consumption: 5272, core: 0 [00:00:44.472,680] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 429164, core: 0 [00:00:44.472,708] pipe: pipeline_trigger: pipe:6 0x0 pipe trigger cmd 2 [00:00:44.472,725] clock: clock_set_freq: clock 0 set freq 29164000Hz freq_idx 0 [00:00:44.472,831] clock: clock_set_freq: clock 1 set freq 29164000Hz freq_idx 0 [00:00:44.472,980] clock: clock_set_freq: clock 2 set freq 29164000Hz freq_idx 0 [00:00:44.474,090] ll_schedule: zephyr_ll_task_done: task complete 0xa0146300 0x201b0U [00:00:44.474,215] ll_schedule: zephyr_ll_task_done: num_tasks 5 total_num_tasks 5 [00:00:44.474,566] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 0, mask 6000000, value 2000000 [00:00:44.474,713] dai_intel_dmic: dai_dmic_stop: dmic_stop(), dmic_active_fifos_mask = 0x1 [00:00:44.474,855] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 1000, mask 10002, value 10002 [00:00:44.474,990] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 1020, mask 2, value 2 [00:00:44.475,125] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 2000, mask 10002, value 10002 [00:00:44.475,260] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 2020, mask 2, value 2 [00:00:44.475,513] ll_schedule: zephyr_ll_task_done: task complete 0xa0149540 0x201b0U [00:00:44.475,638] ll_schedule: zephyr_ll_task_done: num_tasks 4 total_num_tasks 4 [00:00:44.476,870] host_comp: host_get_copy_bytes_normal: comp:6 0x40009 no bytes to copy, available samples: 0, free_samples: 384 [00:00:44.477,635] host_comp: host_get_copy_bytes_normal: comp:6 0x40009 no bytes to copy, available samples: 0, free_samples: 384 [00:00:44.478,398] host_comp: host_get_copy_bytes_normal: comp:6 0x40009 no bytes to copy, available samples: 0, free_samples: 384 [00:00:44.479,045] host_comp: host_get_copy_bytes_normal: comp:6 0x40009 no bytes to copy, available samples: 0, free_samples: 384 [00:00:44.480,026] pipe: remove_pipeline_cps_consumption: Unregistering KCPS consumption: 400000, core: 0 [00:00:44.479,933] host_comp: host_get_copy_bytes_normal: comp:6 0x40009 no bytes to copy, available samples: 0, free_samples: 384 [00:00:44.480,168] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 29164, core: 0 [00:00:44.480,935] host_comp: host_get_copy_bytes_normal: comp:6 0x40009 no bytes to copy, available samples: 0, free_samples: 384 [00:00:44.482,151] ll_schedule: zephyr_ll_task_done: task complete 0xa0146240 0x201b0U [00:00:44.482,278] ll_schedule: zephyr_ll_task_done: num_tasks 3 total_num_tasks 3 [00:00:44.484,955] ipc: ipc_cmd: rx : 0x13000002|0x1 [00:00:44.485,161] pipe: pipeline_trigger: pipe:6 0x0 pipe trigger cmd 0 [00:00:44.486,803] pipe: pipeline_trigger: pipe:5 0x0 pipe trigger cmd 0 [00:00:44.487,170] pipe: pipeline_trigger: pipe:4 0x0 pipe trigger cmd 0 [00:00:44.487,980] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 0, mask 6000000, value 2000000 [00:00:44.488,126] dai_intel_dmic: dai_dmic_stop: dmic_stop(), dmic_active_fifos_mask = 0x0 [00:00:44.488,261] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 1000, mask 10002, value 10002 [00:00:44.488,396] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 1020, mask 2, value 2 [00:00:44.488,531] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 2000, mask 10002, value 10002 [00:00:44.488,665] dai_intel_dmic: dai_dmic_update_bits: dai_dmic_update_bits base 10000, reg 2020, mask 2, value 2 [00:00:44.489,885] dma_intel_adsp_gpdma: intel_adsp_gpdma_power_off: intel_adsp_gpdma_power_off: dma dma@7c000 power off [00:00:44.490,088] eq_iir: eq_iir_reset: comp:4 0x100000 eq_iir_reset() [00:00:44.493,933] ipc: ipc_cmd: rx : 0x46060004|0x70004 [00:00:44.496,823] ipc: ipc_cmd: rx : 0x12040000|0x0 [00:00:44.497,045] dma: dma_put: dma_put(), dma = 0x400ec2a0, sref = 0 [00:00:44.497,151] dai_intel_dmic: dai_dmic_remove: dmic_remove() [00:00:44.497,361] dai_intel_dmic: dai_dmic_remove: dmic_remove(), dmic_active_fifos_mask = 0x0, dmic_pause_mask = 0x0 [00:00:44.499,018] eq_iir: eq_iir_free: comp:4 0x100000 eq_iir_free() [00:00:44.502,810] ipc: ipc_cmd: rx : 0x46030004|0x9000013 [00:00:44.506,015] ipc: ipc_cmd: rx : 0x46080004|0x90004 [00:00:44.509,840] ipc: ipc_cmd: rx : 0x12050000|0x0 [00:00:44.516,043] ipc: ipc_cmd: rx : 0x12060000|0x0 [00:00:44.516,223] dma: dma_put: dma_put(), dma = 0x400ec330, sref = 1 [00:00:45.236,825] ll_schedule: zephyr_domain_thread_fn: ll timer avg 12052, max 89708, overruns 16 [00:00:46.260,825] ll_schedule: zephyr_domain_thread_fn: ll timer avg 13807, max 22347, overruns 1 [00:00:47.284,825] ll_schedule: zephyr_domain_thread_fn: ll timer avg 13785, max 22161, overruns 1 [00:00:48.273,888] ipc: ipc_cmd: rx : 0x13000003|0x1 [00:00:48.274,075] pipe: pipeline_trigger: pipe:2 0x0 pipe trigger cmd 2 [00:00:48.274,826] pipe: remove_pipeline_cps_consumption: Unregistering KCPS consumption: 6388, core: 0 [00:00:48.274,965] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 22776, core: 0 [00:00:48.275,148] pipe: remove_pipeline_cps_consumption: Unregistering KCPS consumption: 6388, core: 0 [00:00:48.275,780] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 16388, core: 0 [00:00:48.276,031] pipe: pipeline_trigger: pipe:3 0x0 pipe trigger cmd 2 [00:00:48.276,581] host_comp: host_get_copy_bytes_normal: comp:3 0x40004 no bytes to copy, available samples: 0, free_samples: 384 [00:00:48.276,718] dai_intel_ssp: dai_ssp_pause: dai_ssp_pause RX [00:00:48.276,850] ll_schedule: zephyr_ll_task_done: task complete 0xa010f600 0x201b0U [00:00:48.276,973] ll_schedule: zephyr_ll_task_done: num_tasks 2 total_num_tasks 2 [00:00:48.277,076] pipe: remove_pipeline_cps_consumption: Unregistering KCPS consumption: 6388, core: 0 [00:00:48.277,580] host_comp: host_get_copy_bytes_normal: comp:3 0x40004 no bytes to copy, available samples: 0, free_samples: 384 [00:00:48.277,700] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 10000, core: 0 [00:00:48.278,570] ll_schedule: zephyr_ll_task_done: task complete 0xa010ec40 0x201b0U [00:00:48.278,695] ll_schedule: zephyr_ll_task_done: num_tasks 1 total_num_tasks 1 [00:00:48.278,893] ll_schedule: zephyr_domain_unregister: zephyr_domain_unregister domain->type 1 domain->clk 3 [00:00:48.280,851] ipc: ipc_cmd: rx : 0x13000002|0x1 [00:00:48.281,015] pipe: pipeline_trigger: pipe:3 0x0 pipe trigger cmd 0 [00:00:48.281,431] pipe: pipeline_trigger: pipe:2 0x0 pipe trigger cmd 0 [00:00:48.281,670] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 34, mask 100, value 0 [00:00:48.281,871] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 8, mask 80, value 80 [00:00:48.281,943] dai_intel_ssp: dai_ssp_stop: dai_ssp_stop RX stop [00:00:48.282,078] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 4, mask 300000, value 0 [00:00:48.282,213] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 0, mask 80, value 0 [00:00:48.282,305] dai_intel_ssp: dai_ssp_stop: dai_ssp_stop SSE clear SSP0 [00:00:48.282,436] dma_intel_adsp_gpdma: intel_adsp_gpdma_power_off: intel_adsp_gpdma_power_off: dma dma@7d000 power off [00:00:48.284,801] ipc: ipc_cmd: rx : 0x46030004|0x40004 [00:00:48.287,005] ipc: ipc_cmd: rx : 0x12020000|0x0 [00:00:48.287,206] dma: dma_put: dma_put(), dma = 0x400ec2e8, sref = 0 [00:00:48.287,315] dai_intel_ssp: dai_ssp_pm_runtime_dis_ssp_power: dai_ssp_pm_runtime_dis_ssp_power index 0 [00:00:48.287,588] dai_intel_ssp: dai_ssp_poll_for_register_delay poll timeout reg 165892 mask 256 val 256 us 125 [00:00:48.287,671] dai_intel_ssp: dai_ssp_pm_runtime_dis_ssp_power warning: timeout [00:00:48.287,741] dai_intel_ssp: dai_ssp_pm_runtime_dis_ssp_power: dai_ssp_pm_runtime_dis_ssp_power I2SLCTL [00:00:48.289,751] ipc: ipc_cmd: rx : 0x12030000|0x0 [00:00:48.289,935] dma: dma_put: dma_put(), dma = 0x400ec330, sref = 0