[ 0.040506] init: print_version_banner: FW ABI 0x301b000 DBG ABI 0x5003000 tags SOF:v0.0-0-g0000 zephyr:v3.1.0-rc3-18211-g3c3e166d078c src hash 0x5686839f (ref hash 0x5686839f) *** Booting Zephyr OS build v3.1.0-rc3-18211-g3c3e166d078c *** [ 0.040695] main: main: SOF on intel_adsp_ace15_mtpm [ 0.040701] main: main: SOF initialized [ 0.040988] ipc: ipc_cmd: rx : 0x44000000|0x31400008 [ 0.041428] ipc: ipc_cmd: rx : 0x44000000|0x3060004c [ 0.042468] ipc: ipc_cmd: rx : 0x11000005|0x0 [ 0.042473] pipe: pipeline_new: pipeline new pipe_id 0 priority 0 [ 0.043071] ipc: ipc_cmd: rx : 0x40000004|0x15 [ 0.043113] dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0 [ 0.043528] ipc: ipc_cmd: rx : 0x40000006|0x10 [ 0.044003] ipc: ipc_cmd: rx : 0x44000006|0x30000018 [ 0.044423] ipc: ipc_cmd: rx : 0x40000002|0xa [ 0.044836] ipc: ipc_cmd: rx : 0x11010006|0x0 [ 0.044841] pipe: pipeline_new: pipeline new pipe_id 1 priority 0 [ 0.045256] ipc: ipc_cmd: rx : 0x40000003|0x1000a [ 0.045648] ipc: ipc_cmd: rx : 0x40010006|0x10010 [ 0.046078] ipc: ipc_cmd: rx : 0x44010006|0x30000018 [ 0.046523] ipc: ipc_cmd: rx : 0x40010004|0x1002f [ 0.046570] dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: dai_ssp_pm_runtime_en_ssp_power en_ssp_power index 0 [ 0.046575] dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: dai_ssp_pm_runtime_en_ssp_power I2SLCTL [ 0.046580] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 8, mask 80, value 80 [ 0.046598] dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0 [ 0.046601] ipc: dai_config: comp:1 0x40001 dai_config() dai type = 1 index = 0 dd 0x40107c80 [ 0.046613] dai_intel_ssp: dai_ssp_parse_aux_data: dai_ssp_parse_aux_data link clock_source 1 [ 0.046618] dai_intel_ssp: dai_ssp_set_reg_config: dai_ssp_set_reg_config sscr0 = 0xc1d0077f, sscr1 = 0xd0700004, ssto = 0x00000000, sspsp = 0x2200000 [ 0.046623] dai_intel_ssp: dai_ssp_set_reg_config: dai_ssp_set_reg_config sscr2 = 0x00004002, sspsp2 = 0x00000000, sscr3 = 0x07070000 [ 0.046626] dai_intel_ssp: dai_ssp_set_reg_config: dai_ssp_set_reg_config ssioc = 0x00000020, ssrsa = 0x00000003, sstsa = 0x00000003 [ 0.046631] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 4, mask 300000, value 300000 [ 0.046636] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 0, mask 80, value 80 [ 0.047030] ipc: ipc_cmd: rx : 0x45000004|0x6 [ 0.047036] ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0 [ 0.047050] pipe: pipeline_connect: comp:0 0x40000 connect buffer 0 as sink [ 0.047053] pipe: pipeline_connect: comp:0 0x60000 connect buffer 0 as source [ 0.047376] ipc: ipc_cmd: rx : 0x45000006|0x2 [ 0.047383] ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0 [ 0.047395] pipe: pipeline_connect: comp:0 0x60000 connect buffer 0 as sink [ 0.047400] pipe: pipeline_connect: comp:0 0x20000 connect buffer 0 as source [ 0.047861] ipc: ipc_cmd: rx : 0x45000002|0x3 [ 0.047868] ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0 [ 0.047881] pipe: pipeline_connect: comp:0 0x20000 connect buffer 0 as sink [ 0.047885] pipe: pipeline_connect: comp:1 0x30000 connect buffer 0 as source [ 0.048241] ipc: ipc_cmd: rx : 0x45000003|0x10006 [ 0.048248] ipc: buffer_new: buffer new size 0x300 id 1.0 flags 0x0 [ 0.048261] pipe: pipeline_connect: comp:1 0x30000 connect buffer 0 as sink [ 0.048265] pipe: pipeline_connect: comp:1 0x60001 connect buffer 0 as source [ 0.048465] ipc: ipc_cmd: rx : 0x45010006|0x10004 [ 0.048473] ipc: buffer_new: buffer new size 0x300 id 1.0 flags 0x0 [ 0.048485] pipe: pipeline_connect: comp:1 0x60001 connect buffer 0 as sink [ 0.048490] pipe: pipeline_connect: comp:1 0x40001 connect buffer 0 as source [ 0.049106] ipc: ipc_cmd: rx : 0x13000003|0x1 [ 0.049133] ipc: ipc_pipeline_complete: ipc_pipeline_complete(): no scheduling component specified, use comp 131072 [ 0.049276] ipc: ipc_cmd: rx : 0x13000004|0x1 [ 0.049358] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties dai_index 0 [ 0.049361] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties fifo 163856 [ 0.049366] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties handshake 2 [ 0.049371] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties init delay 0 [ 0.049375] dai_comp: dai_playback_params: comp:1 0x40001 dai_playback_params() dest_dev = 2 stream_id = 0 src_width = 4 dest_width = 4 [ 0.049380] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties dai_index 0 [ 0.049385] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties fifo 163856 [ 0.049388] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties handshake 2 [ 0.049393] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties init delay 0 [ 0.049410] copier: copier_prepare: comp:1 0x40001 copier_prepare() [ 0.049458] pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 7 [ 0.049461] pipe: add_pipeline_cps_consumption: Registering module: 0x30000 KCPS consumption: 2280, core: 0 [ 0.049468] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 12280, core: 0 [ 0.049478] pipe: add_pipeline_cps_consumption: Registering module: 0x60001 KCPS consumption: 10183, core: 0 [ 0.049483] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 22463, core: 0 [ 0.049486] pipe: add_pipeline_cps_consumption: Registering module: 0x40001 KCPS consumption: 6388, core: 0 [ 0.049493] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 28851, core: 0 [ 0.049501] ll_schedule: zephyr_ll_task_schedule_common: task add 0xa01098c0 0x201e0U priority 0 flags 0x0 [ 0.049516] ll_schedule: zephyr_domain_register: zephyr_domain_register domain->type 1 domain->clk 3 domain->ticks_per_ms 38400 period 1000 [ 0.049568] copier: copier_prepare: comp:0 0x40000 copier_prepare() [ 0.049618] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties dai_index 0 [ 0.049623] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties fifo 163856 [ 0.049628] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties handshake 2 [ 0.049631] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties init delay 0 [ 0.049640] dai_intel_ssp: dai_ssp_pre_start: dai_ssp_pre_start [ 0.049661] dma_intel_adsp_gpdma: intel_adsp_gpdma_power_on: intel_adsp_gpdma_power_on: dma dma@7c000 initialized [ 0.049678] dai_intel_ssp: dai_ssp_start: dai_ssp_start [ 0.049681] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 30, mask 100, value 100 [ 0.049776] mixer: mixin_prepare: comp:0 0x20000 mixin_prepare() [ 0.049793] pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 7 [ 0.049798] pipe: add_pipeline_cps_consumption: Registering module: 0x40000 KCPS consumption: 5272, core: 0 [ 0.049803] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 34123, core: 0 [ 0.049806] pipe: add_pipeline_cps_consumption: Registering module: 0x60000 KCPS consumption: 10183, core: 0 [ 0.049811] clock: clock_set_freq: clock 0 set freq 44306000Hz freq_idx 1 [ 0.049818] clock: clock_set_freq: clock 1 set freq 44306000Hz freq_idx 1 [ 0.049821] clock: clock_set_freq: clock 2 set freq 44306000Hz freq_idx 1 [ 0.049826] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 44306, core: 0 [ 0.049830] pipe: add_pipeline_cps_consumption: Registering module: 0x20000 KCPS consumption: 4996, core: 0 [ 0.049833] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 49302, core: 0 [ 0.049841] ll_schedule: zephyr_ll_task_schedule_common: task add 0xa010a6c0 0x201e0U priority 0 flags 0x0 [ 0.050711] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 0.051656] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 0.052655] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 0.053640] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 0.054676] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 0.055643] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 0.056643] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 0.057646] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 0.058643] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 0.059643] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 1.072643] ll_schedule: zephyr_domain_thread_fn: ll timer avg 1355, max 6011, overruns 0 [ 2.096641] ll_schedule: zephyr_domain_thread_fn: ll timer avg 1330, max 1560, overruns 0 [ 3.120641] ll_schedule: zephyr_domain_thread_fn: ll timer avg 1330, max 1357, overruns 0 [ 3.128035] ipc: ipc_cmd: rx : 0x13000003|0x1 [ 3.128040] pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 2 [ 3.128043] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x40000 KCPS consumption: 5272, core: 0 [ 3.128046] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 44030, core: 0 [ 3.128055] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x60000 KCPS consumption: 10183, core: 0 [ 3.128060] clock: clock_set_freq: clock 0 set freq 33847000Hz freq_idx 0 [ 3.128063] clock: clock_set_freq: clock 1 set freq 33847000Hz freq_idx 0 [ 3.128095] clock: clock_set_freq: clock 2 set freq 33847000Hz freq_idx 0 [ 3.128136] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 33847, core: 0 [ 3.128168] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x20000 KCPS consumption: 4996, core: 0 [ 3.128211] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 28851, core: 0 [ 3.128311] pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 2 [ 3.128340] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x30000 KCPS consumption: 2280, core: 0 [ 3.128383] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 26571, core: 0 [ 3.128416] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x60001 KCPS consumption: 10183, core: 0 [ 3.128460] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 16388, core: 0 [ 3.128493] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x40001 KCPS consumption: 6388, core: 0 [ 3.128536] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 10000, core: 0 [ 3.128833] dai_intel_ssp: dai_ssp_pause: dai_ssp_pause TX [ 3.128890] ll_schedule: zephyr_ll_task_done: task complete 0xa01098c0 0x201e0U [ 3.128915] ll_schedule: zephyr_ll_task_done: num_tasks 2 total_num_tasks 2 [ 3.129128] ll_schedule: zephyr_ll_task_done: task complete 0xa010a6c0 0x201e0U [ 3.129151] ll_schedule: zephyr_ll_task_done: num_tasks 1 total_num_tasks 1 [ 3.129193] ll_schedule: zephyr_domain_unregister: zephyr_domain_unregister domain->type 1 domain->clk 3 [ 3.130838] ipc: ipc_cmd: rx : 0x13000002|0x1 [ 3.130901] pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 0 [ 3.131055] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 30, mask 100, value 0 [ 3.131093] dai_intel_ssp: dai_ssp_stop: dai_ssp_stopTX stop [ 3.131130] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 4, mask 300000, value 0 --- 18 messages dropped --- [ 3.153141] ipc: ipc_cmd: rx : 0x40000006|0x10 [ 3.154768] ipc: ipc_cmd: rx : 0x44000006|0x30000018 [ 3.155980] ipc: ipc_cmd: rx : 0x40000002|0xa [ 3.157485] ipc: ipc_cmd: rx : 0x11010006|0x0 [ 3.157525] pipe: pipeline_new: pipeline new pipe_id 1 priority 0 [ 3.159125] ipc: ipc_cmd: rx : 0x40000003|0x1000a [ 3.160591] ipc: ipc_cmd: rx : 0x40010006|0x10010 [ 3.162083] ipc: ipc_cmd: rx : 0x44010006|0x30000018 [ 3.163643] ipc: ipc_cmd: rx : 0x40010004|0x1002f [ 3.164050] dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: dai_ssp_pm_runtime_en_ssp_power en_ssp_power index 0 [ 3.164223] dai_intel_ssp: dai_ssp_poll_for_register_delay: dai_ssp_poll_for_register_delay poll timeout reg 165892 mask 256 val 0 us 125 [ 3.164263] dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: dai_ssp_pm_runtime_en_ssp_power warning: timeout [ 3.164298] dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: dai_ssp_pm_runtime_en_ssp_power I2SLCTL [ 3.164336] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 8, mask 80, value 80 [ 3.164420] dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0 [ 3.164453] ipc: dai_config: comp:1 0x40001 dai_config() dai type = 1 index = 0 dd 0x40107c80 [ 3.164543] dai_intel_ssp: dai_ssp_parse_aux_data: dai_ssp_parse_aux_data link clock_source 1 [ 3.164591] dai_intel_ssp: dai_ssp_set_reg_config: dai_ssp_set_reg_config sscr0 = 0xc1d0077f, sscr1 = 0xd0700004, ssto = 0x00000000, sspsp = 0x2200000 [ 3.164628] dai_intel_ssp: dai_ssp_set_reg_config: dai_ssp_set_reg_config sscr2 = 0x00004002, sspsp2 = 0x00000000, sscr3 = 0x07070000 [ 3.164663] dai_intel_ssp: dai_ssp_set_reg_config: dai_ssp_set_reg_config ssioc = 0x00000020, ssrsa = 0x00000003, sstsa = 0x00000003 [ 3.164703] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 4, mask 300000, value 300000 [ 3.164748] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 0, mask 80, value 80 [ 3.165596] ipc: ipc_cmd: rx : 0x45000004|0x6 [ 3.165653] ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0 [ 3.165748] pipe: pipeline_connect: comp:0 0x40000 connect buffer 0 as sink [ 3.165785] pipe: pipeline_connect: comp:0 0x60000 connect buffer 0 as source [ 3.166565] ipc: ipc_cmd: rx : 0x45000006|0x2 [ 3.166621] ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0 [ 3.166715] pipe: pipeline_connect: comp:0 0x60000 connect buffer 0 as sink [ 3.166750] pipe: pipeline_connect: comp:0 0x20000 connect buffer 0 as source [ 3.167926] ipc: ipc_cmd: rx : 0x45000002|0x3 [ 3.167986] ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0 [ 3.168078] pipe: pipeline_connect: comp:0 0x20000 connect buffer 0 as sink [ 3.168115] pipe: pipeline_connect: comp:1 0x30000 connect buffer 0 as source [ 3.169155] ipc: ipc_cmd: rx : 0x45000003|0x10006 [ 3.169218] ipc: buffer_new: buffer new size 0x300 id 1.0 flags 0x0 [ 3.169310] pipe: pipeline_connect: comp:1 0x30000 connect buffer 0 as sink [ 3.169346] pipe: pipeline_connect: [ 3.170498] pipe: pipeline_connect: comp:1 0x60001 connect buffer 0 as sink [ 3.170535] pipe: pipeline_connect: comp:1 0x40001 connect buffer 0 as source [ 3.171650] ipc: ipc_cmd: rx : 0x13000003|0x1 [ 3.171873] ipc: ipc_pipeline_complete: ipc_pipeline_complete(): no scheduling component specified, use comp 131072 [ 3.173428] ipc: ipc_cmd: rx : 0x13000004|0x1 [ 3.174096] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties dai_index 0 [ 3.174136] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties fifo 163856 [ 3.174173] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties handshake 2 [ 3.174210] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties init delay 0 [ 3.174241] dai_comp: dai_playback_params: comp:1 0x40001 dai_playback_params() dest_dev = 2 stream_id = 0 src_width = 4 dest_width = 4 [ 3.174283] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties dai_index 0 [ 3.174321] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties fifo 163856 [ 3.174358] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties handshake 2 [ 3.174395] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties init delay 0 [ 3.174523] copier: copier_prepare: comp:1 0x40001 copier_prepare() [ 3.174676] pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 7 [ 3.174705] pipe: add_pipeline_cps_consumption: Registering module: 0x30000 KCPS consumption: 2280, core: 0 [ 3.174750] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 12280, core: 0 [ 3.174783] pipe: add_pipeline_cps_consumption: Registering module: 0x60001 KCPS consumption: 10183, core: 0 [ 3.174828] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 22463, core: 0 [ 3.174861] pipe: add_pipeline_cps_consumption: Registering module: 0x40001 KCPS consumption: 6388, core: 0 [ 3.174905] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 28851, core: 0 [ 3.174971] ll_schedule: zephyr_ll_task_schedule_common: task add 0xa01098c0 0x201e0U priority 0 flags 0x0 [ 3.175095] ll_schedule: zephyr_domain_register: zephyr_domain_register domain->type 1 domain->clk 3 domain->ticks_per_ms 38400 period 1000 [ 3.175328] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties dai_index 0 [ 3.175366] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties fifo 163856 [ 3.175403] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties handshake 2 [ 3.175471] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties init delay 0 [ 3.175550] dai_intel_ssp: dai_ssp_pre_start: dai_ssp_pre_start [ 3.175730] dma_intel_adsp_gpdma: intel_adsp_gpdma_power_on: intel_adsp_gpdma_power_on: dma dma@7c000 initialized [ 3.175871] dai_intel_ssp: dai_ssp_start: dai_ssp_start [ 3.175926] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 30, mask 100, value 100 [ 3.177751] copier: copier_prepare: comp:0 0x40000 copier_prepare() [ 3.178005] mixer: mixin_prepare: comp:0 0x20000 mixin_prepare() [ 3.178690] pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 7 [ 3.178736] pipe: add_pipeline_cps_consumption: Registering module: 0x40000 KCPS consumption: 6388, core: 0 [ 3.178796] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 35239, core: 0 [ 3.178848] pipe: add_pipeline_cps_consumption: Registering module: 0x60000 KCPS consumption: 10183, core: 0 [ 3.178900] clock: clock_set_freq: clock 0 set freq 45422000Hz freq_idx 1 [ 3.178921] clock: clock_set_freq: clock 1 set freq 45422000Hz freq_idx 1 [ 3.178928] clock: clock_set_freq: clock 2 set freq 45422000Hz freq_idx 1 [ 3.178933] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 45422, core: 0 [ 3.178938] pipe: add_pipeline_cps_consumption: Registering module: 0x20000 KCPS consumption: 4996, core: 0 [ 3.178945] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 50418, core: 0 [ 3.178953] ll_schedule: zephyr_ll_task_schedule_common: task add 0xa010a6c0 0x201e0U priority 0 flags 0x0 [ 3.179201] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 3.180143] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 3.181156] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 3.182141] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 3.183153] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 3.184146] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 3.185185] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 3.186171] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 3.187155] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 3.188190] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 3.189143] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 4.198141] ll_schedule: zephyr_domain_thread_fn: ll timer avg 1387, max 46270, overruns 1 [ 5.222141] ll_schedule: zephyr_domain_thread_fn: ll timer avg 1290, max 1505, overruns 0 [ 6.215548] ipc: ipc_cmd: rx : 0x13000003|0x1 [ 6.215556] pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 2 [ 6.215560] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x40000 KCPS consumption: 6388, core: 0 [ 6.215563] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 44030, core: 0 [ 6.215566] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x60000 KCPS consumption: 10183, core: 0 [ 6.215575] clock: clock_set_freq: clock 0 set freq 33847000Hz freq_idx 0 [ 6.215580] clock: clock_set_freq: clock 1 set freq 33847000Hz freq_idx 0 [ 6.215618] clock: clock_set_freq: clock 2 set freq 33847000Hz freq_idx 0 [ 6.215660] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 33847, core: 0 [ 6.215693] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x20000 KCPS consumption: 4996, core: 0 [ 6.215736] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 28851, core: 0 [ 6.215836] pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 2 [ 6.215865] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x30000 KCPS consumption: 2280, core: 0 [ 6.215908] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 26571, core: 0 [ 6.215941] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x60001 KCPS consumption: 10183, core: 0 [ 6.215985] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 16388, core: 0 [ 6.216018] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x40001 KCPS consumption: 6388, core: 0 [ 6.216061] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 10000, core: 0 [ 6.216590] ll_schedule: zephyr_ll_task_done: task complete 0xa010a6c0 0x201e0U [ 6.216615] ll_schedule: zephyr_ll_task_done: num_tasks 2 total_num_tasks 2 [ 6.217733] dai_intel_ssp: dai_ssp_pause: dai_ssp_pause TX [ 6.217790] ll_schedule: zephyr_ll_task_done: task complete 0xa01098c0 0x201e0U [ 6.217815] ll_schedule: zephyr_ll_task_done: num_tasks 1 total_num_tasks 1 [ 6.217855] ll_schedule: zephyr_domain_unregister: zephyr_domain_unregister domain->type 1 domain->clk 3 [ 6.228793] ipc: ipc_cmd: rx : 0x13000002|0x1 [ 6.228858] pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 0 [ 6.229010] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 30, mask 100, value 0 [ 6.229046] dai_intel_ssp: dai_ssp_stop: dai_ssp_stopTX stop [ 6.229085] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 4, mask 300000, value 0 [ 6.229120] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 0, mask 80, value 0 [ 6.229156] dai_intel_ssp: dai_ssp_stop: dai_ssp_stop SSE clear SSP0 [ 6.229235] dma_intel_adsp_gpdma: intel_adsp_gpdma_power_off: intel_adsp_gpdma_power_off: dma dma@7c000 power off [ 6.229713] pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 0 [ 6.229910] copier: copier_comp_trigger: comp:0 0x40000 dai is not ready [ 6.231776] ipc: ipc_cmd: rx : 0x46000002|0x3 [ 6.233375] ipc: ipc_cmd: rx : 0x12000000|0x0 [ 6.233468] dma: dma_put: dma_put(), dma = 0x400ebc58, sref = 0 [ 6.235701] ipc: ipc_cmd: rx : 0x12010000|0x0 [ 6.236311] dma: dma_put: dma_put(), dma = 0x400ebb80, sref = 0 [ 6.236376] dai_intel_ssp: dai_ssp_pm_runtime_dis_ssp_power: dai_ssp_pm_runtime_dis_ssp_power index 0 --- 6 messages dropped --- [ 6.248895] dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0 [ 6.250495] ipc: ipc_cmd: rx : 0x40000006|0x10 [ 6.252251] ipc: ipc_cmd: rx : 0x44000006|0x30000018 [ 6.253560] ipc: ipc_cmd: rx : 0x40000002|0xa [ 6.255280] ipc: ipc_cmd: rx : 0x11010006|0x0 [ 6.255320] pipe: pipeline_new: pipeline new pipe_id 1 priority 0 [ 6.256541] ipc: ipc_cmd: rx : 0x40000003|0x1000a [ 6.257988] ipc: ipc_cmd: rx : 0x40010006|0x10010 [ 6.259288] ipc: ipc_cmd: rx : 0x44010006|0x30000018 [ 6.260481] ipc: ipc_cmd: rx : 0x40010004|0x1002f [ 6.260851] dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: dai_ssp_pm_runtime_en_ssp_power en_ssp_power index 0 [ 6.261025] dai_intel_ssp: dai_ssp_poll_for_register_delay: dai_ssp_poll_for_register_delay poll timeout reg 165892 mask 256 val 0 us 125 [ 6.261063] dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: dai_ssp_pm_runtime_en_ssp_power warning: timeout [ 6.261100] dai_intel_ssp: dai_ssp_pm_runtime_en_ssp_power: dai_ssp_pm_runtime_en_ssp_power I2SLCTL [ 6.261136] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 8, mask 80, value 80 [ 6.261221] dma: dma_get: dma_get() ID 0 sref = 1 busy channels 0 [ 6.261253] ipc: dai_config: comp:1 0x40001 dai_config() dai type = 1 index = 0 dd 0x40107c80 [ 6.261343] dai_intel_ssp: dai_ssp_parse_aux_data: dai_ssp_parse_aux_data link clock_source 1 [ 6.261391] dai_intel_ssp: dai_ssp_set_reg_config: dai_ssp_set_reg_config sscr0 = 0xc1d0077f, sscr1 = 0xd0700004, ssto = 0x00000000, sspsp = 0x2200000 [ 6.261428] dai_intel_ssp: dai_ssp_set_reg_config: dai_ssp_set_reg_config sscr2 = 0x00004002, sspsp2 = 0x00000000, sscr3 = 0x07070000 [ 6.261463] dai_intel_ssp: dai_ssp_set_reg_config: dai_ssp_set_reg_config ssioc = 0x00000020, ssrsa = 0x00000003, sstsa = 0x00000003 [ 6.261503] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 4, mask 300000, value 300000 [ 6.261540] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 0, mask 80, value 80 [ 6.262428] ipc: ipc_cmd: rx : 0x45000004|0x6 [ 6.262485] ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0 [ 6.262578] pipe: pipeline_connect: comp:0 0x40000 connect buffer 0 as sink [ 6.262615] pipe: pipeline_connect: comp:0 0x60000 connect buffer 0 as source [ 6.263450] ipc: ipc_cmd: rx : 0x45000006|0x2 [ 6.263508] ipc: [ 6.263600] pipe: pipeline_connect: comp:0 0x60000 connect buffer 0 as sink [ 6.263636] pipe: pipeline_connect: comp:0 0x20000 connect buffer 0 as source [ 6.264451] ipc: ipc_cmd: rx : 0x45000002|0x3 [ 6.264511] ipc: buffer_new: buffer new size 0x300 id 0.0 flags 0x0 [ 6.264603] pipe: pipeline_connect: comp:0 0x20000 connect buffer 0 as sink [ 6.264640] pipe: pipeline_connect: comp:1 0x30000 connect buffer 0 as source [ 6.265435] ipc: ipc_cmd: rx : 0x45000003|0x10006 [ 6.265496] ipc: buffer_new: buffer new size 0x300 id 1.0 flags 0x0 [ 6.265590] pipe: pipeline_connect: comp:1 0x30000 connect buffer 0 as sink [ 6.265625] pipe: pipeline_connect: comp:1 0x60001 connect buffer 0 as source [ 6.266483] ipc: ipc_cmd: rx : 0x45010006|0x10004 [ 6.266548] ipc: buffer_new: buffer new size 0x300 id 1.0 flags 0x0 [ 6.266640] pipe: pipeline_connect: comp:1 0x60001 connect buffer 0 as sink [ 6.266676] pipe: pipeline_connect: comp:1 0x40001 connect buffer 0 as source [ 6.268003] ipc: ipc_cmd: rx : 0x13000003|0x1 [ 6.268225] ipc: ipc_pipeline_complete: ipc_pipeline_complete(): no scheduling component specified, use comp 131072 [ 6.269215] ipc: ipc_cmd: rx : 0x13000004|0x1 [ 6.269885] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties dai_index 0 [ 6.269923] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties fifo 163856 [ 6.269968] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties handshake 2 [ 6.270005] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties init delay 0 [ 6.270036] dai_comp: dai_playback_params: comp:1 0x40001 dai_playback_params() dest_dev = 2 stream_id = 0 src_width = 4 dest_width = 4 [ 6.270078] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties dai_index 0 [ 6.270116] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties fifo 163856 [ 6.270153] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties handshake 2 [ 6.270190] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties init delay 0 [ 6.270318] copier: copier_prepare: comp:1 0x40001 copier_prepare() [ 6.270471] pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 7 [ 6.270500] pipe: add_pipeline_cps_consumption: Registering module: 0x30000 KCPS consumption: 2280, core: 0 [ 6.270545] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 12280, core: 0 [ 6.270580] pipe: add_pipeline_cps_consumption: Registering module: 0x60001 KCPS consumption: 10183, core: 0 [ 6.270623] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 22463, core: 0 [ 6.270656] pipe: add_pipeline_cps_consumption: Registering module: 0x40001 KCPS consumption: 6388, core: 0 [ 6.270700] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 28851, core: 0 [ 6.270766] ll_schedule: zephyr_ll_task_schedule_common: task add 0xa01098c0 0x201e0U priority 0 flags 0x0 [ 6.270891] ll_schedule: zephyr_domain_register: zephyr_domain_register domain->type 1 domain->clk 3 domain->ticks_per_ms 38400 period 1000 [ 6.271143] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties dai_index 0 [ 6.271181] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties fifo 163856 [ 6.271218] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties handshake 2 [ 6.271255] dai_intel_ssp: dai_ssp_get_properties: dai_ssp_get_properties init delay 0 [ 6.271316] dai_intel_ssp: dai_ssp_pre_start: dai_ssp_pre_start [ 6.271478] dma_intel_adsp_gpdma: intel_adsp_gpdma_power_on: intel_adsp_gpdma_power_on: dma dma@7c000 initialized [ 6.271603] dai_intel_ssp: dai_ssp_start: dai_ssp_start [ 6.271643] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 30, mask 100, value 100 [ 6.272911] copier: copier_prepare: comp:0 0x40000 copier_prepare() [ 6.273683] mixer: mixin_prepare: comp:0 0x20000 mixin_prepare() [ 6.273825] pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 7 [ 6.273853] pipe: add_pipeline_cps_consumption: Registering module: 0x40000 KCPS consumption: 6388, core: 0 [ 6.273898] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 35239, core: 0 [ 6.274460] pipe: add_pipeline_cps_consumption: Registering module: 0x60000 KCPS consumption: 10183, core: 0 [ 6.274500] clock: clock_set_freq: clock 0 set freq 45422000Hz freq_idx 1 [ 6.274523] clock: clock_set_freq: clock 1 set freq 45422000Hz freq_idx 1 [ 6.274528] clock: clock_set_freq: clock 2 set freq 45422000Hz freq_idx 1 [ 6.274535] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 45422, core: 0 [ 6.274540] pipe: add_pipeline_cps_consumption: Registering module: 0x20000 KCPS consumption: 4996, core: 0 [ 6.274545] pipe: add_pipeline_cps_consumption: Sum of KCPS consumption: 50418, core: 0 [ 6.274555] ll_schedule: zephyr_ll_task_schedule_common: task add 0xa010a6c0 0x201e0U priority 0 flags 0x0 [ 6.275050] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 6.275976] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 6.276998] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 6.277991] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 6.279011] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 6.279980] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 6.280986] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 6.282010] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 6.283001] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 6.284038] host_comp: host_get_copy_bytes_normal: comp:0 0x40000 no bytes to copy, available samples: 0, free_samples: 192 [ 7.293976] ll_schedule: zephyr_domain_thread_fn: ll timer avg 1384, max 42606, overruns 1 [ 8.317975] ll_schedule: zephyr_domain_thread_fn: ll timer avg 1293, max 1532, overruns 0 [ 9.310360] ipc: ipc_cmd: rx : 0x13000003|0x1 [ 9.310368] pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 2 [ 9.310371] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x40000 KCPS consumption: 6388, core: 0 [ 9.310376] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 44030, core: 0 [ 9.310380] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x60000 KCPS consumption: 10183, core: 0 [ 9.310388] clock: clock_set_freq: clock 0 set freq 33847000Hz freq_idx 0 [ 9.310391] clock: clock_set_freq: clock 1 set freq 33847000Hz freq_idx 0 [ 9.310423] clock: clock_set_freq: clock 2 set freq 33847000Hz freq_idx 0 [ 9.310465] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 33847, core: 0 [ 9.310498] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x20000 KCPS consumption: 4996, core: 0 [ 9.310541] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 28851, core: 0 [ 9.310641] pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 2 [ 9.310670] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x30000 KCPS consumption: 2280, core: 0 [ 9.310713] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 26571, core: 0 [ 9.310746] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x60001 KCPS consumption: 10183, core: 0 [ 9.310790] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 16388, core: 0 [ 9.310823] pipe: remove_pipeline_cps_consumption: Unregistering module: 0x40001 KCPS consumption: 6388, core: 0 [ 9.310866] pipe: remove_pipeline_cps_consumption: Sum of KCPS consumption: 10000, core: 0 [ 9.311176] dai_intel_ssp: dai_ssp_pause: dai_ssp_pause TX [ 9.311233] ll_schedule: zephyr_ll_task_done: task complete 0xa01098c0 0x201e0U [ 9.311258] ll_schedule: zephyr_ll_task_done: num_tasks 2 total_num_tasks 2 [ 9.311470] ll_schedule: zephyr_ll_task_done: task complete 0xa010a6c0 0x201e0U [ 9.311495] ll_schedule: zephyr_ll_task_done: num_tasks 1 total_num_tasks 1 [ 9.311536] ll_schedule: zephyr_domain_unregister: zephyr_domain_unregister domain->type 1 domain->clk 3 [ 9.323533] ipc: ipc_cmd: rx : 0x13000002|0x1 [ 9.323598] pipe: pipeline_trigger: pipe:1 0x0 pipe trigger cmd 0 [ 9.323750] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 30, mask 100, value 0 [ 9.323788] dai_intel_ssp: dai_ssp_stop: dai_ssp_stopTX stop [ 9.323825] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 4, mask 300000, value 0 [ 9.323861] dai_intel_ssp: dai_ssp_update_bits: dai_ssp_update_bits base 28000, reg 0, mask 80, value 0 [ 9.323898] dai_intel_ssp: dai_ssp_stop: dai_ssp_stop SSE clear SSP0 [ 9.323976] dma_intel_adsp_gpdma: intel_adsp_gpdma_power_off: intel_adsp_gpdma_power_off: dma dma@7c000 power off [ 9.324453] pipe: pipeline_trigger: pipe:0 0x0 pipe trigger cmd 0 [ 9.324650] copier: copier_comp_trigger: comp:0 0x40000 dai is not ready [ 9.326385] ipc: ipc_cmd: rx : 0x46000002|0x3 [ 9.328066] ipc: ipc_cmd: rx : 0x12000000|0x0 [ 9.328168] dma: dma_put: dma_put(), dma = 0x400ebc58, sref = 0 [ 9.330318] ipc: ipc_cmd: rx : 0x12010000|0x0 [ 9.330928] dma: dma_put: dma_put(), dma = 0x400ebb80, sref = 0 [ 9.330993] dai_intel_ssp: dai_ssp_pm_runtime_dis_ssp_power: dai_ssp_pm_runtime_dis_ssp_power index 0 [ 9.331166] dai_intel_ssp: dai_ssp_poll_for_register_delay: dai_ssp_poll_for_register_delay poll timeout reg 165892 mask 256 val 256 us 125 [ 9.331205] dai_intel_ssp: dai_ssp_pm_runtime_dis_ssp_power: dai_ssp_pm_runtime_dis_ssp_power warning: timeout [ 9.331240] dai_intel_ssp: dai_ssp_pm_runtime_dis_ssp_power: dai_ssp_pm_runtime_dis_ssp_power I2SLCTL [ 9.350276] ipc: ipc_cmd: rx : 0x47000000|0x0Terminated