Skip to content

Sdw/ack naks startup - #2559

Closed
plbossart wants to merge 6 commits into
thesofproject:topic/sof-devfrom
plbossart:sdw/ack-naks-startup
Closed

plbossart wants to merge 6 commits into
thesofproject:topic/sof-devfrom
plbossart:sdw/ack-naks-startup

Conversation

@plbossart

Copy link
Copy Markdown
Member

Draft pull request to try and address unexplained suspend-resume issues, with NAKs reported.

The existing code reports a NAK only when ACK=0
This is not aligned with the SoundWire 1.x specifications.

Table 32 in the SoundWire 1.2 specification shows that a Device shall
not set NAK=1 if ACK=1. But Table 33 shows the Combined Response
may very well be NAK=1/ACK=1, e.g. if another Device than the one
addressed reports a parity error.

NAK=1 signals a 'Command_Aborted', regardless of the ACK bit value.

Move the tests for NAK so that the NAK=1/ACK=1 combination is properly
detected according to the specification.

Fixes: 956baa1 ('soundwire: cdns: Add sdw_master_ops and IO transfer support')
Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
There are too many logs on startup, e.g.

[ 8811.851497] cdns_fill_msg_resp: 2 callbacks suppressed
[ 8811.851497] intel-sdw intel-sdw.0: Msg Ack not received
[ 8811.851498] intel-sdw intel-sdw.0: Msg Ack not received
[ 8811.851499] intel-sdw intel-sdw.0: Msg Ack not received
[ 8811.851499] intel-sdw intel-sdw.0: Msg Ack not received
[ 8811.851500] intel-sdw intel-sdw.0: Msg Ack not received
[ 8811.851500] intel-sdw intel-sdw.0: Msg Ack not received
[ 8811.851502] intel-sdw intel-sdw.0: Msg ignored for Slave 0
[ 8811.851503] soundwire sdw-master-0: No more devices to enumerate

We can skip the 'Msg Ack not received' since it's typical of the
enumeration end, and conversely add the information on which command
fails.

Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
We want to make sure the transactions don't start immediately and that
Slave events are not reported too early.

Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
Make sure we see ALL events for debug.

Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
@plbossart

Copy link
Copy Markdown
Member Author

We still have an odd error on TGL-Volteer

kernel: [ 5528.667698] intel-sdw intel-sdw.0: intel_resume: pm_runtime status was suspended, forcing active
kernel: [ 5528.667701] intel-sdw intel-sdw.0: intel_link_power_up: powering up all links
kernel: [ 5528.667701] intel-sdw intel-sdw.0: intel_link_power_up: first link up, programming SYNCPRD
kernel: [ 5528.668010] rt5682 sdw:0:25d:5682:0: sdw_modify_slave_status: initializing completion for Slave 1
kernel: [ 5528.668015] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
kernel: [ 5528.668023] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
kernel: [ 5528.668029] intel-sdw intel-sdw.0: system resume sync go start
kernel: [ 5528.668140] intel-sdw intel-sdw.0: sync go done
kernel: [ 5528.668334] max98373 sdw:1:19f:8373:0:7: sdw_modify_slave_status: initializing completion for Slave 1
kernel: [ 5528.668335] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: initializing completion for Slave 2
kernel: [ 5528.668359] intel-sdw intel-sdw.1: system resume sync go start
kernel: [ 5528.668469] intel-sdw intel-sdw.1: sync go done

420 us later Devices report as synchronized.

kernel: [ 5528.668885] intel-sdw intel-sdw.0: Slave status change
kernel: [ 5528.668891] soundwire sdw-master-0: Slave attached, programming device number
kernel: [ 5528.669054] soundwire sdw-master-0: SDW Slave Addr: 20025d568200
kernel: [ 5528.669056] soundwire sdw-master-0: SDW Slave class_id 0, part_id 5682, mfg_id 25d, unique_id 0, version 2
kernel: [ 5528.669057] soundwire sdw-master-0: Slave already registered, reusing dev_num:1
kernel: [ 5528.669283] intel-sdw intel-sdw.0: Msg ignored for Slave 0
kernel: [ 5528.669284] soundwire sdw-master-0: No more devices to enumerate
kernel: [ 5528.669310] intel-sdw intel-sdw.0: Slave status change
kernel: [ 5528.669315] rt5682 sdw:0:25d:5682:0: sdw_modify_slave_status: signaling completion for Slave 1
kernel: [ 5528.690993] intel-sdw intel-sdw.1: Slave status change
kernel: [ 5528.691007] soundwire sdw-master-1: Slave attached, programming device number
kernel: [ 5528.691295] soundwire sdw-master-1: SDW Slave Addr: 27019f837300
kernel: [ 5528.691298] soundwire sdw-master-1: SDW Slave class_id 0, part_id 8373, mfg_id 19f, unique_id 7, version 2
kernel: [ 5528.691300] soundwire sdw-master-1: Slave already registered, reusing dev_num:1
kernel: [ 5528.691533] soundwire sdw-master-1: SDW Slave Addr: 23019f837300
kernel: [ 5528.691535] soundwire sdw-master-1: SDW Slave class_id 0, part_id 8373, mfg_id 19f, unique_id 3, version 2
kernel: [ 5528.691536] soundwire sdw-master-1: Slave already registered, reusing dev_num:2
kernel: [ 5528.691762] intel-sdw intel-sdw.1: Msg ignored for Slave 0
kernel: [ 5528.691764] soundwire sdw-master-1: No more devices to enumerate
kernel: [ 5528.691787] intel-sdw intel-sdw.1: Slave status change
kernel: [ 5528.691793] max98373 sdw:1:19f:8373:0:7: sdw_modify_slave_status: signaling completion for Slave 1
kernel: [ 5528.691911] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: signaling completion for Slave 2

This is the start of the error sequence, Slave2 seems to have a problem
kernel: [ 5528.692051] intel-sdw intel-sdw.1: Slave status change
kernel: [ 5528.692055] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: initializing completion for Slave 2
kernel: [ 5528.692197] max98373 sdw:1:19f:8373:0:7: Bus clash detected

???

kernel: [ 5528.692425] intel-sdw intel-sdw.1: Slave status change
kernel: [ 5529.168272] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
kernel: [ 5529.168285] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
kernel: [ 5530.726160] max98373 sdw:1:19f:8373:0:3: Initialization not complete, timed out
kernel: [ 5530.726172] PM: dpm_run_callback(): max98373_resume+0x0/0x70 [snd_soc_max98373_sdw] returns -110
kernel: [ 5530.726176] PM: Device sdw:1:19f:8373:0:3 failed to resume: error -110

Something goes wrong when a device loses sync

Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
Not sure what happens, add code to get a trace

Signed-off-by: Pierre-Louis Bossart <pierre-louis.bossart@linux.intel.com>
@RanderWang

Copy link
Copy Markdown

@plbossart no multi-link for 98373 on volteer. I doubt we lost one interrupt since two 98373 may trigger interrupt at the same time at rare chance, so it is difficult to reproduce it.

@RanderWang

Copy link
Copy Markdown

Actually we never did stress test with two slaves on single link case before 98373 coming since we don't have such device without any rework. I tested two 1308s on single link but we need to rework tgl, use external 3-in-1 board and change machine driver, so QA can't test it easily.

@RanderWang

Copy link
Copy Markdown

I have a interesting idea: what will happen if more than two slaves are on single link ? With Up extreme or tgl rvp (reworked), we can connect one rt711, two rt1308s, one rt715 to one header with 3-in-1 board. Maybe we can get more interrupt to reproduce bug.

@bardliao

Copy link
Copy Markdown
Collaborator

kernel: [ 5528.691787] intel-sdw intel-sdw.1: Slave status change
kernel: [ 5528.691793] max98373 sdw:1:19f:8373:0:7: sdw_modify_slave_status: signaling completion for Slave 1
kernel: [ 5528.691911] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: signaling completion for Slave 2

This is the start of the error sequence, Slave2 seems to have a problem
kernel: [ 5528.692051] intel-sdw intel-sdw.1: Slave status change
kernel: [ 5528.692055] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: initializing completion for Slave 2
kernel: [ 5528.692197] max98373 sdw:1:19f:8373:0:7: Bus clash detected

???

kernel: [ 5528.692425] intel-sdw intel-sdw.1: Slave status change
kernel: [ 5529.168272] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
kernel: [ 5529.168285] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
kernel: [ 5530.726160] max98373 sdw:1:19f:8373:0:3: Initialization not complete, timed out
kernel: [ 5530.726172] PM: dpm_run_callback(): max98373_resume+0x0/0x70 [snd_soc_max98373_sdw] returns -110
kernel: [ 5530.726176] PM: Device sdw:1:19f:8373:0:3 failed to resume: error -110

@plbossart It looks like somehow Slave 2 is unattached shortly after attached. I don't even see max98373_update_status start in the log.

@plbossart

Copy link
Copy Markdown
Member Author

kernel: [ 5528.691787] intel-sdw intel-sdw.1: Slave status change
kernel: [ 5528.691793] max98373 sdw:1:19f:8373:0:7: sdw_modify_slave_status: signaling completion for Slave 1
kernel: [ 5528.691911] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: signaling completion for Slave 2
This is the start of the error sequence, Slave2 seems to have a problem
kernel: [ 5528.692051] intel-sdw intel-sdw.1: Slave status change
kernel: [ 5528.692055] max98373 sdw:1:19f:8373:0:3: sdw_modify_slave_status: initializing completion for Slave 2
kernel: [ 5528.692197] max98373 sdw:1:19f:8373:0:7: Bus clash detected
???
kernel: [ 5528.692425] intel-sdw intel-sdw.1: Slave status change
kernel: [ 5529.168272] sof-audio-pci 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG
kernel: [ 5529.168285] sof-audio-pci 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG
kernel: [ 5530.726160] max98373 sdw:1:19f:8373:0:3: Initialization not complete, timed out
kernel: [ 5530.726172] PM: dpm_run_callback(): max98373_resume+0x0/0x70 [snd_soc_max98373_sdw] returns -110
kernel: [ 5530.726176] PM: Device sdw:1:19f:8373:0:3 failed to resume: error -110

@plbossart It looks like somehow Slave 2 is unattached shortly after attached. I don't even see max98373_update_status start in the log.

This looks like a real bus conflict/electrical issue:

  1. both devices attach and start their initialization
  2. Slave 2 (device:3) becomes unattached, reattaches and starts its initialization again
  3. Slave 1 (device:7) detects a bus clash.
  4. Slave 2 (device:3) does not complete its initialization.

The bus clash tells us the Slave 2 (device:3) somehow drives bits that are owned by Slave 1 (device :7). That doesn't sound good at all.

@RanderWang yes we could try to reproduce the issue by putting two max98373 on the same link with an RVP+eval boards, but keep in mind it would be a different electrical configuration (trace length, damping resistors, etc). SoundWire requires a careful hardware design, it's not expected to work without paying attention to the low-level electrical parameters.

@RanderWang

Copy link
Copy Markdown

@RanderWang yes we could try to reproduce the issue by putting two max98373 on the same link with an RVP+eval boards, but keep in mind it would be a different electrical configuration (trace length, damping resistors, etc). SoundWire requires a careful hardware design, it's not expected to work without paying attention to the low-level electrical parameters.

Thanks. your idea goes far more than mine. I just want to test on tgl-rvp with 3-in-1. I connected 3 slave to link0 today. Good news is everything works well, bad news is the failure rate doesn't increase immediately

[15890.942971] soundwire sdw-master-0: SDW Slave Addr: 22025d130800
[15890.942973] soundwire sdw-master-0: SDW Slave class_id 0, part_id 1308, mfg_id 25d, unique_id 2, version 2
[15890.942974] soundwire sdw-master-0: Slave already registered, reusing dev_num:1
[15890.943233] soundwire sdw-master-0: SDW Slave Addr: 21025d071100
[15890.943234] soundwire sdw-master-0: SDW Slave class_id 0, part_id 711, mfg_id 25d, unique_id 1, version 2
[15890.943234] soundwire sdw-master-0: Slave already registered, reusing dev_num:2
[15890.943480] soundwire sdw-master-0: SDW Slave Addr: 20025d130800
[15890.943481] soundwire sdw-master-0: SDW Slave class_id 0, part_id 1308, mfg_id 25d, unique_id 0, version 2
[15890.943488] soundwire sdw-master-0: Slave already registered, reusing dev_num:3
[15890.943727] cdns_fill_msg_resp: 2 callbacks suppressed
[15890.943728] intel-sdw intel-sdw.0: Msg Ack not received
[15890.943728] intel-sdw intel-sdw.0: Msg Ack not received
[15890.943729] intel-sdw intel-sdw.0: Msg Ack not received
[15890.943729] intel-sdw intel-sdw.0: Msg Ack not received
[15890.943730] intel-sdw intel-sdw.0: Msg Ack not received
[15890.943730] intel-sdw intel-sdw.0: Msg Ack not received
[15890.943731] intel-sdw intel-sdw.0: Msg ignored for Slave 0
[15890.943732] soundwire sdw-master-0: No more devices to enumerate
[15890.943756] intel-sdw intel-sdw.0: Slave status change
[15890.943760] rt1308 sdw:0:25d:1308:0:2: sdw_modify_slave_status: signaling completion for Slave 1
[15890.943891] rt711 sdw:0:25d:711:0: sdw_modify_slave_status: signaling completion for Slave 2
[15890.943984] rt1308 sdw:0:25d:1308:0:0: sdw_modify_slave_status: signaling completion for Slave 3
[15890.975720] intel-sdw intel-sdw.0: Slave status change
[15890.975725] rt711 sdw:0:25d:711:0: sdw_modify_slave_status: initializing completion for Slave 2
[15890.975727] rt1308 sdw:0:25d:1308:0:0: sdw_modify_slave_status: initializing completion for Slave 3

@RanderWang

RanderWang commented Nov 17, 2020 •

Copy link
Copy Markdown

I caught one error. Since 1308 is in external board, maybe the connection was unstable, but this error happens rarely

 tgl-08 kernel: [93109.267104] rt1308 sdw:0:25d:1308:0:2: sdw_modify_slave_status: signaling completion for Slave 1
tgl-08 kernel: [93109.267240] rt711 sdw:0:25d:711:0: sdw_modify_slave_status: signaling completion for Slave 2
tgl-08 kernel: [93109.267395] rt1308 sdw:0:25d:1308:0:0: sdw_modify_slave_status: signaling completion for Slave 3
tgl-08 kernel: [93109.267523] intel-sdw intel-sdw.0: Slave status change
tgl-08 kernel: [93109.292031] intel-sdw intel-sdw.0: Slave status change
tgl-08 kernel: [93110.874899] intel-sdw intel-sdw.0: Bus clash for data word
tgl-08 kernel: [93110.874935] intel-sdw intel-sdw.0: Slave status change
tgl-08 kernel: [93110.875029] intel-sdw intel-sdw.0: Msg Ack not received
tgl-08 kernel: [93110.875031] intel-sdw intel-sdw.0: Msg NACK received
tgl-08 kernel: [93110.875035] intel-sdw intel-sdw.0: Msg NACKed for Slave 1
tgl-08 kernel: [93110.875040] CPU: 5 PID: 1355564 Comm: kworker/5:0 Not tainted 5.10.0-rc1+ #419
tgl-08 kernel: [93110.875043] Hardware name: Intel Corporation Tiger Lake Client Platform/TigerLake U DDR4 SODIMM RVP, BIOS TGLSFWI1.R00.2321.A09.1909250234 09/25/2019
tgl-08 kernel: [93110.875053] Workqueue: events cdns_update_slave_status_work [soundwire_cadence]
tgl-08 kernel: [93110.875056] Call Trace:
tgl-08 kernel: [93110.875070]  dump_stack+0x57/0x6a     // I add dump_stack to trace call stack
tgl-08 kernel: [93110.875074]  cdns_fill_msg_resp.isra.0.cold+0x40/0x4a [soundwire_cadence]
tgl-08 kernel: [93110.875079]  cdns_xfer_msg+0xca/0xe0 [soundwire_cadence]
tgl-08 kernel: [93110.875086]  sdw_transfer_unlocked+0x54/0xb0 [soundwire_bus]
tgl-08 kernel: [93110.875092]  sdw_transfer+0x22/0x40 [soundwire_bus]
tgl-08 kernel: [93110.875097]  sdw_nread_no_pm+0x4a/0x70 [soundwire_bus]
tgl-08 kernel: [93110.875102]  sdw_handle_slave_status+0x214/0xce0 [soundwire_bus]
tgl-08 kernel: [93110.875110]  ? sched_clock_cpu+0xc/0xa0
tgl-08 kernel: [93110.875114]  cdns_update_slave_status_work+0x214/0x220 [soundwire_cadence]
tgl-08 kernel: [93110.875121]  process_one_work+0x1cf/0x360
tgl-08 kernel: [93110.875125]  worker_thread+0x45/0x3b0
tgl-08 kernel: [93110.875128]  ? process_one_work+0x360/0x360
tgl-08 kernel: [93110.875132]  kthread+0xf9/0x130
tgl-08 kernel: [93110.875136]  ? kthread_park+0x80/0x80
tgl-08 kernel: [93110.875140]  ret_from_fork+0x1f/0x30
tgl-08 kernel: [93110.875146] soundwire sdw-master-0: trf on Slave 1 failed:-5
tgl-08 kernel: [93110.875151] rt1308 sdw:0:25d:1308:0:2: SDW_SCP_INT1 read failed:-5
tgl-08 kernel: [93110.875155] rt1308 sdw:0:25d:1308:0:2: Slave 1 alert handling failed: -5
tgl-08 kernel: [93110.875312] rt711 sdw:0:25d:711:0: Parity error detected
tgl-08 kernel: [93110.875933] rt1308 sdw:0:25d:1308:0:0: Parity error detected
tgl-08 kernel: [93110.875936] rt1308 sdw:0:25d:1308:0:0: Bus clash detected
tgl-08 kernel: [93110.876381] rt1308 sdw:0:25d:1308:0:0: Parity error detected

@plbossart

Copy link
Copy Markdown
Member Author

replaced by PR #2565

@plbossart plbossart closed this Nov 17, 2020
@plbossart

Copy link
Copy Markdown
Member Author

I caught one error. Since 1308 is in external board, maybe the connection was unstable, but this error happens rarely

 tgl-08 kernel: [93109.267104] rt1308 sdw:0:25d:1308:0:2: sdw_modify_slave_status: signaling completion for Slave 1
tgl-08 kernel: [93109.267240] rt711 sdw:0:25d:711:0: sdw_modify_slave_status: signaling completion for Slave 2
tgl-08 kernel: [93109.267395] rt1308 sdw:0:25d:1308:0:0: sdw_modify_slave_status: signaling completion for Slave 3
tgl-08 kernel: [93109.267523] intel-sdw intel-sdw.0: Slave status change
tgl-08 kernel: [93109.292031] intel-sdw intel-sdw.0: Slave status change
tgl-08 kernel: [93110.874899] intel-sdw intel-sdw.0: Bus clash for data word
tgl-08 kernel: [93110.874935] intel-sdw intel-sdw.0: Slave status change
tgl-08 kernel: [93110.875029] intel-sdw intel-sdw.0: Msg Ack not received
tgl-08 kernel: [93110.875031] intel-sdw intel-sdw.0: Msg NACK received
tgl-08 kernel: [93110.875035] intel-sdw intel-sdw.0: Msg NACKed for Slave 1
tgl-08 kernel: [93110.875040] CPU: 5 PID: 1355564 Comm: kworker/5:0 Not tainted 5.10.0-rc1+ #419
tgl-08 kernel: [93110.875043] Hardware name: Intel Corporation Tiger Lake Client Platform/TigerLake U DDR4 SODIMM RVP, BIOS TGLSFWI1.R00.2321.A09.1909250234 09/25/2019
tgl-08 kernel: [93110.875053] Workqueue: events cdns_update_slave_status_work [soundwire_cadence]
tgl-08 kernel: [93110.875056] Call Trace:
tgl-08 kernel: [93110.875070]  dump_stack+0x57/0x6a     // I add dump_stack to trace call stack
tgl-08 kernel: [93110.875074]  cdns_fill_msg_resp.isra.0.cold+0x40/0x4a [soundwire_cadence]
tgl-08 kernel: [93110.875079]  cdns_xfer_msg+0xca/0xe0 [soundwire_cadence]
tgl-08 kernel: [93110.875086]  sdw_transfer_unlocked+0x54/0xb0 [soundwire_bus]
tgl-08 kernel: [93110.875092]  sdw_transfer+0x22/0x40 [soundwire_bus]
tgl-08 kernel: [93110.875097]  sdw_nread_no_pm+0x4a/0x70 [soundwire_bus]
tgl-08 kernel: [93110.875102]  sdw_handle_slave_status+0x214/0xce0 [soundwire_bus]
tgl-08 kernel: [93110.875110]  ? sched_clock_cpu+0xc/0xa0
tgl-08 kernel: [93110.875114]  cdns_update_slave_status_work+0x214/0x220 [soundwire_cadence]
tgl-08 kernel: [93110.875121]  process_one_work+0x1cf/0x360
tgl-08 kernel: [93110.875125]  worker_thread+0x45/0x3b0
tgl-08 kernel: [93110.875128]  ? process_one_work+0x360/0x360
tgl-08 kernel: [93110.875132]  kthread+0xf9/0x130
tgl-08 kernel: [93110.875136]  ? kthread_park+0x80/0x80
tgl-08 kernel: [93110.875140]  ret_from_fork+0x1f/0x30
tgl-08 kernel: [93110.875146] soundwire sdw-master-0: trf on Slave 1 failed:-5
tgl-08 kernel: [93110.875151] rt1308 sdw:0:25d:1308:0:2: SDW_SCP_INT1 read failed:-5
tgl-08 kernel: [93110.875155] rt1308 sdw:0:25d:1308:0:2: Slave 1 alert handling failed: -5
tgl-08 kernel: [93110.875312] rt711 sdw:0:25d:711:0: Parity error detected
tgl-08 kernel: [93110.875933] rt1308 sdw:0:25d:1308:0:0: Parity error detected
tgl-08 kernel: [93110.875936] rt1308 sdw:0:25d:1308:0:0: Bus clash detected
tgl-08 kernel: [93110.876381] rt1308 sdw:0:25d:1308:0:0: Parity error detected

This looks like a complete fail at the electrical level.... Not sure how we can do anything at the software level when commands are NAKed and parity/bus clashes are reported.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants