search

thesofproject / linux

Linux kernel source tree
Other
91 stars 133 forks source link

CML controller bank switch timeout #5079

Closed plbossart closed 4 months ago

plbossart commented 5 months ago

initially reported in https://github.com/thesofproject/linux/issues/4823#issuecomment-2183427729

stable-v2.2 daily test run 43002?model=CML_SKU0983_SDW-ipc3&testcase=multiple-pipeline-playback-50

Linux Branch: topic/sof-dev Linux Commit: e9eea140a1d9 KConfig Branch: master KConfig Commit: c3171afedc63

Jun 21 17:14:29 jf-cml-sku0983-sdw-1 kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
Jun 21 17:14:29 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_hw_free: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: free stream 5 dir 0
Jun 21 17:14:29 jf-cml-sku0983-sdw-1 kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x80010000: GLB_DAI_MSG: CONFIG
Jun 21 17:14:29 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_close: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: close stream 5 dir 0
Jun 21 17:14:29 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_hw_free: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: free stream 6 dir 0
Jun 21 17:14:29 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_close: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: close stream 6 dir 0
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-1: Controller Timed out on bank switch
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-0: Controller Timed out on bank switch
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-1: multi link bank switch failed: -110
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-0: multi link bank switch failed: -110
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel: _sdw_disable_stream: do_bank_switch failed: -110
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel: _sdw_disable_stream: do_bank_switch failed: -110
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel:  SDW1-Playback: sdw_trigger trigger 0 failed: -110
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel:  SDW0-Playback: sdw_trigger trigger 0 failed: -110
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel:  SDW1-Playback: ASoC: error at soc_link_trigger on SDW1-Playback: -110
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel:  SDW0-Playback: ASoC: error at soc_link_trigger on SDW0-Playback: -110
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel:  Speaker: ASoC: error at dpcm_be_dai_trigger on Speaker: -110
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel:  Jack Out: ASoC: error at dpcm_be_dai_trigger on Jack Out: -110
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel:  Speaker: ASoC: trigger FE cmd: 0 failed: -110
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel:  Jack Out: ASoC: trigger FE cmd: 0 failed: -110
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_hw_free: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: free stream 2 dir 0
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x90040000: GLB_TRACE_MSG: FILTER_UPDATE
Jun 21 17:14:30 jf-cml-sku0983-sdw-1 kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x90040000: GLB_TRACE_MSG: FILTER_UPDATE
Jun 21 17:14:31 jf-cml-sku0983-sdw-1 kernel: soundwire_intel soundwire_intel.link.1: SCP Msg trf timed out
Jun 21 17:14:31 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-1: trf on Slave 1 failed:-5 write addr c103 count 0
Jun 21 17:14:31 jf-cml-sku0983-sdw-1 kernel: rt1308 sdw:0:1:025d:1308:00: ASoC: error at snd_soc_component_update_bits on sdw:0:1:025d:1308:00 for register: [0x0000c103] -5
Jun 21 17:14:31 jf-cml-sku0983-sdw-1 kernel: soundwire_intel soundwire_intel.link.1: SCP Msg trf timed out
Jun 21 17:14:31 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-1: trf on Slave 1 failed:-5 write addr c360 count 0
Jun 21 17:14:31 jf-cml-sku0983-sdw-1 kernel: rt1308 sdw:0:1:025d:1308:00: ASoC: error at snd_soc_component_update_bits on sdw:0:1:025d:1308:00 for register: [0x0000c360] -5
Jun 21 17:14:32 jf-cml-sku0983-sdw-1 kernel: soundwire_intel soundwire_intel.link.1: SCP Msg trf timed out
Jun 21 17:14:32 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-1: trf on Slave 1 failed:-5 write addr c320 count 0
Jun 21 17:14:32 jf-cml-sku0983-sdw-1 kernel: rt1308 sdw:0:1:025d:1308:00: ASoC: error at snd_soc_component_update_bits on sdw:0:1:025d:1308:00 for register: [0x0000c320] -5
Jun 21 17:14:33 jf-cml-sku0983-sdw-1 kernel: soundwire_intel soundwire_intel.link.1: SCP Msg trf timed out
Jun 21 17:14:33 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-1: trf on Slave 1 failed:-5 read addr c321 count 0
Jun 21 17:14:33 jf-cml-sku0983-sdw-1 kernel: rt1308 sdw:0:1:025d:1308:00: ASoC: error at snd_soc_component_update_bits on sdw:0:1:025d:1308:00 for register: [0x0000c321] -5
Jun 21 17:14:33 jf-cml-sku0983-sdw-1 kernel: soundwire_intel soundwire_intel.link.1: SCP Msg trf timed out
Jun 21 17:14:33 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-1: trf on Slave 1 failed:-5 write addr c322 count 0
Jun 21 17:14:33 jf-cml-sku0983-sdw-1 kernel: rt1308 sdw:0:1:025d:1308:00: ASoC: error at snd_soc_component_update_bits on sdw:0:1:025d:1308:00 for register: [0x0000c322] -5
Jun 21 17:14:33 jf-cml-sku0983-sdw-1 kernel: soundwire_generic_allocation:sdw_compute_master_ports: soundwire sdw-master-0-1: sdw_compute_master_ports p_rt->lane 0
Jun 21 17:14:33 jf-cml-sku0983-sdw-1 kernel: soundwire_generic_allocation:sdw_compute_slave_ports: rt1308 sdw:0:1:025d:1308:00: sdw_compute_slave_ports p_rt->lane 0
Jun 21 17:14:34 jf-cml-sku0983-sdw-1 kernel: soundwire_intel soundwire_intel.link.1: IO transfer timed out, cmd 2 device 1 addr 102 len 1
Jun 21 17:14:34 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-1: trf on Slave 1 failed:-110 read addr 102 count 0
Jun 21 17:14:34 jf-cml-sku0983-sdw-1 kernel: rt1308 sdw:0:1:025d:1308:00: DPN_PortCtrl register write failed for port 1
Jun 21 17:14:34 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-1: Program transport params failed: -110
Jun 21 17:14:34 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-1: _sdw_deprepare_stream: Program params failed: -110
Jun 21 17:14:34 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_close: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: close stream 2 dir 0
Jun 21 17:14:34 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_hw_free: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: free stream 0 dir 0
Jun 21 17:14:34 jf-cml-sku0983-sdw-1 kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x60030000: GLB_STREAM_MSG: PCM_FREE
Jun 21 17:14:34 jf-cml-sku0983-sdw-1 kernel: soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 3 device 6 addr 7321 len 1
Jun 21 17:14:34 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-0: trf on Slave 6 failed:-110 write addr 7321 count 0
Jun 21 17:14:35 jf-cml-sku0983-sdw-1 kernel: soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 3 device 6 addr 3603 len 1
Jun 21 17:14:35 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-0: trf on Slave 6 failed:-110 write addr 3603 count 0
Jun 21 17:14:35 jf-cml-sku0983-sdw-1 kernel: soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 3 device 6 addr 3501 len 1
Jun 21 17:14:35 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-0: trf on Slave 6 failed:-110 write addr 3501 count 0
Jun 21 17:14:35 jf-cml-sku0983-sdw-1 kernel: soundwire_generic_allocation:sdw_compute_master_ports: soundwire sdw-master-0-0: sdw_compute_master_ports p_rt->lane 0
Jun 21 17:14:35 jf-cml-sku0983-sdw-1 kernel: soundwire_generic_allocation:sdw_compute_slave_ports: rt711 sdw:0:0:025d:0711:00: sdw_compute_slave_ports p_rt->lane 0
Jun 21 17:14:36 jf-cml-sku0983-sdw-1 kernel: soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 2 device 6 addr 302 len 1
Jun 21 17:14:36 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-0: trf on Slave 6 failed:-110 read addr 302 count 0
Jun 21 17:14:36 jf-cml-sku0983-sdw-1 kernel: rt711 sdw:0:0:025d:0711:00: DPN_PortCtrl register write failed for port 3
Jun 21 17:14:36 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-0: Program transport params failed: -110
Jun 21 17:14:36 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-0: _sdw_deprepare_stream: Program params failed: -110
Jun 21 17:14:36 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_close: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: close stream 0 dir 0
Jun 21 17:14:36 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_open: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: open stream 2 dir 0
Jun 21 17:14:36 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_open: sof-audio-pci-intel-cnl 0000:00:1f.3: period min 192 max 16384 bytes
Jun 21 17:14:36 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_open: sof-audio-pci-intel-cnl 0000:00:1f.3: period count 2 max 16
Jun 21 17:14:36 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_open: sof-audio-pci-intel-cnl 0000:00:1f.3: buffer max 65536 bytes
Jun 21 17:14:36 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_open: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: open stream 0 dir 0
Jun 21 17:14:36 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_open: sof-audio-pci-intel-cnl 0000:00:1f.3: period min 192 max 16384 bytes
Jun 21 17:14:36 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_open: sof-audio-pci-intel-cnl 0000:00:1f.3: period count 2 max 16
Jun 21 17:14:36 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_open: sof-audio-pci-intel-cnl 0000:00:1f.3: buffer max 65536 bytes
Jun 21 17:14:36 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_close: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: close stream 2 dir 0
Jun 21 17:14:36 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_pcm_close: sof-audio-pci-intel-cnl 0000:00:1f.3: pcm: close stream 0 dir 0
Jun 21 17:14:39 jf-cml-sku0983-sdw-1 kernel: soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 3 device 6 addr 45 len 1
Jun 21 17:14:39 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-0: trf on Slave 6 failed:-110 write addr 45 count 0
Jun 21 17:14:39 jf-cml-sku0983-sdw-1 kernel: rt711 sdw:0:0:025d:0711:00: SDW_SCP_SYSTEMCTRL write failed:-110
Jun 21 17:14:39 jf-cml-sku0983-sdw-1 kernel: rt711 sdw:0:0:025d:0711:00: clock stop prepare failed:-110
Jun 21 17:14:39 jf-cml-sku0983-sdw-1 kernel: soundwire_intel soundwire_intel.link.0: prepare clock stop failed -110
Jun 21 17:14:39 jf-cml-sku0983-sdw-1 kernel: soundwire_intel soundwire_intel.link.0: intel_stop_bus: cannot stop clock: -110
Jun 21 17:14:40 jf-cml-sku0983-sdw-1 kernel: soundwire_intel soundwire_intel.link.1: IO transfer timed out, cmd 3 device 1 addr 45 len 1
Jun 21 17:14:40 jf-cml-sku0983-sdw-1 kernel: soundwire sdw-master-0-1: trf on Slave 1 failed:-110 write addr 45 count 0
Jun 21 17:14:40 jf-cml-sku0983-sdw-1 kernel: rt1308 sdw:0:1:025d:1308:00: SDW_SCP_SYSTEMCTRL write failed:-110
Jun 21 17:14:40 jf-cml-sku0983-sdw-1 kernel: rt1308 sdw:0:1:025d:1308:00: clock stop prepare failed:-110
Jun 21 17:14:40 jf-cml-sku0983-sdw-1 kernel: soundwire_intel soundwire_intel.link.1: prepare clock stop failed -110
Jun 21 17:14:40 jf-cml-sku0983-sdw-1 kernel: soundwire_intel soundwire_intel.link.1: intel_stop_bus: cannot stop clock: -110
Jun 21 17:14:40 jf-cml-sku0983-sdw-1 kernel: soundwire_intel:intel_link_power_down: soundwire_intel soundwire_intel.link.1: powering down all links
Jun 21 17:14:40 jf-cml-sku0983-sdw-1 kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x30210000: GLB_TPLG_MSG: BUFFER_FREE
Jun 21 17:14:40 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-cnl 0000:00:1f.3: widget BUF30.1 freed
Jun 21 17:14:40 jf-cml-sku0983-sdw-1 kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x30210000: GLB_TPLG_MSG: BUFFER_FREE
Jun 21 17:14:40 jf-cml-sku0983-sdw-1 kernel: snd_sof:sof_widget_free_unlocked: sof-audio-pci-intel-cnl 0000:00:1f.3: widget BUF30.0 freed
Jun 21 17:14:40 jf-cml-sku0983-sdw-1 kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-cnl 0000:00:1f.3: ipc tx: 0x30020000: GLB_TPLG_MSG: COMP_FREE
plbossart commented 5 months ago

@marc-hb it looks like this run 43002 is the FIRST test result we had on this device, I only see 'not tested' before. And the more recent test 43016 does not show the error so that's definitively not 100% reproducible.

plbossart commented 4 months ago

@marc-hb @fredoh9 I haven't seen this error happen again so I am tempted to close this issue as a random one-off.

marc-hb commented 4 months ago

I don't remember seeing this again on CML...