[BUG] [rt700] SDW Alert happens before codec is enumerated

Describe the bug
We can see sdw IO transfer timed out when we do suspend test. And the reason of sdw IO transfer timed out is that an alert is rised before the codec is enumerated.

To Reproduce

run sudo rtcwake -m mem -s 5.

Reproduce rate
more than 50%

Expected result
No issue on the suspend test.

Actual result
See IO transfer timed out errors in dmesg.

jf-cml-rvp-sdw-2 kernel: [ 7295.502075] rt700 sdw:1:25d:700:0: sdw_modify_slave_status: initializing completion for Slave 1
...
jf-cml-rvp-sdw-2 kernel: [ 7296.545696] intel-sdw intel-sdw.1: IO transfer timed out, cmd 2 device 1 addr 40 len 1
jf-cml-rvp-sdw-2 kernel: [ 7296.545702] soundwire sdw-master-0: trf on Slave 1 failed:-110
jf-cml-rvp-sdw-2 kernel: [ 7296.545706] soundwire sdw-master-0: SDW_SCP_INT1 read failed:-110
jf-cml-rvp-sdw-2 kernel: [ 7296.545708] soundwire sdw-master-0: Slave 1 alert handling failed: -110
jf-cml-rvp-sdw-2 kernel: [ 7296.545730] intel-sdw intel-sdw.1: Slave status change
jf-cml-rvp-sdw-2 kernel: [ 7296.545764] soundwire sdw-master-0: Slave attached, programming device number
...
jf-cml-rvp-sdw-2 kernel: [ 7296.546367] rt700 sdw:1:25d:700:0: sdw_modify_slave_status: signaling completion for Slave 1

dmesg_cml_rvp.txt

@plbossart

@plbossart Should we ignore the alert before codec is enumerated?
Does below change make sense?

diff --git a/drivers/soundwire/bus.c b/drivers/soundwire/bus.c
index d0aecf995c4f..219592cfee6f 100644
--- a/drivers/soundwire/bus.c
+++ b/drivers/soundwire/bus.c
@@ -1711,11 +1711,20 @@ int sdw_handle_slave_status(struct sdw_bus *bus,
                        break;

                case SDW_SLAVE_ALERT:
+                       if (!completion_done(&slave->slave->initialization_complete))
+                               break;
                        ret = sdw_handle_slave_alerts(slave);

@bardliao

@bardliao it's not possible to have an alert if the DeviceNumber is zero and the interrupt masks are not initialized. I wonder if this is a codec problem where on hard reset the interrupt masks are not reset.

Edit: the master driver should first go through the sdw_clear_slave_status() to mark the status as UNATTACHED on resume. Then we would first deal with enumeration. I think we have a race condition here where the codec resumes before the link is reset and its status marked as UNACTTACHED.

@plbossart

@plbossart I think I know the reason of IO transfer timed out now. We got an interrupt immediately after rt700 is enumerated. However, rt700 go into suspend right after that. See log below

[  820.942039] soundwire sdw-master-0: bard: sdw_clear_slave_status 1
[  820.942043] rt700 sdw:1:25d:700:0: sdw_modify_slave_status: initializing completion for Slave 1
[  820.942274] rt700 sdw:1:25d:700:0: bard: rt700_dev_resume
[  820.961605] intel-sdw intel-sdw.1: Slave status change
[  820.961622] soundwire sdw-master-0: Slave attached, programming device number
[  820.961924] soundwire sdw-master-0: SDW Slave Addr: 10025d070000
[  820.961929] soundwire sdw-master-0: SDW Slave class_id 0, part_id 700, mfg_id 25d, unique_id 0, version 1
[  820.961931] soundwire sdw-master-0: Slave already registered, reusing dev_num:1
[  820.962166] intel-sdw intel-sdw.1: Msg Ack not received
[  820.962167] intel-sdw intel-sdw.1: Msg Ack not received
[  820.962168] intel-sdw intel-sdw.1: Msg Ack not received
[  820.962170] intel-sdw intel-sdw.1: Msg Ack not received
[  820.962171] intel-sdw intel-sdw.1: Msg Ack not received
[  820.962172] intel-sdw intel-sdw.1: Msg Ack not received
[  820.962174] intel-sdw intel-sdw.1: Msg ignored for Slave 0
[  820.962176] soundwire sdw-master-0: No more devices to enumerate
[  820.962204] intel-sdw intel-sdw.1: Slave status change
[  820.962212] rt700 sdw:1:25d:700:0: sdw_modify_slave_status: signaling completion for Slave 1
[  820.962450] intel-sdw intel-sdw.1: Slave status change
[  820.962458] soundwire sdw-master-0: bard: Slave 1 status 1
[  820.962485] rt700 sdw:1:25d:700:0: bard: rt700_dev_resume cache sync start
[  820.967985] rt700 sdw:1:25d:700:0: bard: rt700_dev_resume cache sync end
[  820.967992] rt700 sdw:1:25d:700:0: bard: rt700_dev_suspend

Now see sdw_handle_slave_alerts(). We call pm_runtime_get_sync() while rt700 is just suspended.
I don't think rt700 is already resumed when pm_runtime_get_sync returned and then sdw_read(slave, SDW_SCP_INT1); is called while rt700 is suspended. So IO transfer timed out happens.

[  820.962450] intel-sdw intel-sdw.1: Slave status change
[  820.962458] soundwire sdw-master-0: bard: Slave 1 status 1
[  820.962485] rt700 sdw:1:25d:700:0: bard: rt700_dev_resume cache sync start
[  820.967985] rt700 sdw:1:25d:700:0: bard: rt700_dev_resume cache sync end
[  820.967992] rt700 sdw:1:25d:700:0: bard: rt700_dev_suspend
[  820.967998] rt700 sdw:1:25d:700:0: bard: sdw_handle_slave_alerts pm_runtime_get_sync ret 1
...
[  821.933210] intel-sdw intel-sdw.1: bard: intel_resume
[  821.933211] intel-sdw intel-sdw.1: intel_link_power_up: powering up all links
[  821.933212] intel-sdw intel-sdw.1: intel_link_power_up: first link up, programming SYNCPRD
[  821.933466] soundwire sdw-master-0: bard: sdw_clear_slave_status 1
[  821.933468] rt700 sdw:1:25d:700:0: sdw_modify_slave_status: initializing completion for Slave 1
[  821.933811] rt700 sdw:1:25d:700:0: bard: rt700_dev_resume
...
[  822.991662] intel-sdw intel-sdw.1: IO transfer timed out, cmd 2 device 1 addr 40 len 1
[  822.991669] soundwire sdw-master-0: trf on Slave 1 failed:-110
[  822.991673] rt700 sdw:1:25d:700:0: bard: sdw_handle_slave_alerts sdw_read ret -110
[  822.991675] soundwire sdw-master-0: SDW_SCP_INT1 read failed:-110
[  822.991678] soundwire sdw-master-0: Slave 1 alert handling failed: -110

dmesg_cml_rvp_2.txt

log_diff.txt

@bardliao

Great work @bardliao

[  820.962485] rt700 sdw:1:25d:700:0: bard: rt700_dev_resume cache sync start
[  820.967985] rt700 sdw:1:25d:700:0: bard: rt700_dev_resume cache sync end
[  820.967992] rt700 sdw:1:25d:700:0: bard: rt700_dev_suspend

I think the last suspend is a system suspend.

it looks like we have a race condition with a system suspend happening immediately while we are still dealing with a device interrupt and we have a pending transaction. On the next system resume, there is a timeout and an error, but that doesn't seem to be a real problem. The error happens in a workqueue.

I think we should use cancel_work_sync() on the master level to make sure current transactions are completed, and no alert can be handled while the master suspends.

soundwire: cadence: fix race condition between suspend and Slave devi…

@bardliao

@bardliao can you try #2354, not sure if this helps?

soundwire: cadence: fix race condition between suspend and Slave devi…

@bardliao

@bardliao can you try #2354, not sure if this helps?

Thanks, @plbossart it works. But it should be if (cdns->interrupt_enable) below. We need to schedule the workqueue if interrupt is enabled.

/* if the interrupt disable is in process, don't schedule a workqueue */
		if (!cdns->interrupt_enable)
			schedule_work(&cdns->work);

soundwire: cadence: fix race condition between suspend and Slave devi…

Bluetooth: Fix alt settings for incoming SCO with transparent coding …

soundwire: cadence: fix race condition between suspend and Slave devi…

Navigation Menu

Repository navigation

[BUG] [rt700] SDW Alert happens before codec is enumerated #2344

11 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[BUG] [rt700] SDW Alert happens before codec is enumerated #2344

Description

Activity

bardliao commented on Aug 5, 2020

plbossart commented on Aug 5, 2020

bardliao commented on Aug 11, 2020

plbossart commented on Aug 11, 2020

plbossart commented on Aug 11, 2020

bardliao commented on Aug 12, 2020

11 remaining items

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions