SoundWire: TGL: IO error in rt711_jack_detect_handler

@bardliao

@bardliao @shumingfan FYI, that's a new one.

https://sof-ci.01.org/linuxpr/PR3454/build7233/devicetest/?model=TGLU_RVP_SDW&testcase=check-suspend-resume-with-capture-5

[   29.522674] kernel: soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 3 device 1 addr b921 len 1
[   29.522680] kernel: soundwire sdw-master-0: trf on Slave 1 failed:-110 write addr b921 count 0
[   29.522741] kernel: IO error in rt711_jack_detect_handler, ret -110

dmesg.log

not sure if this is related to #3401

@bardliao

Not able to reproduce with short tests on Dell SKU 0A3E that uses RT711 on link1

TPLG=/lib/firmware/intel/sof-tplg/sof-tgl-rt715-rt711-rt1308-mono.tplg  ~/sof-test/test-case/check-suspend-resume-with-audio.sh -l 5 -m capture

@bardliao can you try to see if this bug can be reproduced on your TGL devices with IPC3?
Not sure why we see this consistently on TGLU_RVP_SDW now.

@bardliao

Not able to reproduce with short tests on Dell SKU 0A3E that uses RT711 on link1
TPLG=/lib/firmware/intel/sof-tplg/sof-tgl-rt715-rt711-rt1308-mono.tplg  ~/sof-test/test-case/check-suspend-resume-with-audio.sh -l 5 -m capture
@bardliao can you try to see if this bug can be reproduced on your TGL devices with IPC3? Not sure why we see this consistently on TGLU_RVP_SDW now.

@plbossart I tested it on my Dell SKU 0A3E and it passed. I run the test twice and both iterations are passed.

ASoC: rt711: fix race condition on suspend

P1 because it's happening consistently:

https://sof-ci.01.org/sofpr/PR5485/build12238/devicetest/?model=TGLU_RVP_SDW&testcase=check-suspend-resume-with-playback-5
https://sof-ci.01.org/softestpr/PR871/build1005/devicetest/?model=TGLU_RVP_SDW&testcase=check-suspend-resume-with-playback-5
https://sof-ci.01.org/sofpr/PR5475/build12242/devicetest/?model=TGLU_RVP_SDW&testcase=check-suspend-resume-with-playback-5

These test failures happened on different units.

What changed recently? Big kernel merge?

Interesting that searching for something as specific as rt711_jack_detect_handler returns 11 entries no less (8 closed)
https://github.com/thesofproject/linux/issues?q=rt711_jack_detect_handler

@marc-hb

@marc-hb can you help find the first report of a failure? I am down to a spurious pm_runtime resume after a system suspend, no sure what is happening.

I think this came with 5.17, maybe with

Merge/sound upstream 20220228 #3461 ?

According to the TCR database, the very first check-suspend-playback/capture failure on TGLU_RVP_SDW happened on January 29th:

This was with

linux/for-next/74cc53cf/linux-image-5.17.0-rc1-daily-default-20220128-0-13653-g74cc53cf59b6_5.17.0-rc1-linux-for-next-74cc53cf_amd64.deb
sof/main/40d2f6688367/fw/debug/sof-tgl.ri

[2022-01-29T20:15:10.418Z] 2022-01-29 20:15:09 UTC Sub-Test: [REMOTE_COMMAND] Run the command: rtcwake -m mem -s 5
[2022-01-29T20:15:10.418Z] rtcwake: wakeup from "mem" using /dev/rtc0 at Sat Jan 29 20:15:15 2022
[2022-01-29T20:15:22.710Z] 2022-01-29 20:15:16 UTC Sub-Test: [REMOTE_COMMAND] sleep for 5
[2022-01-29T20:15:22.710Z] 2022-01-29 20:15:21 UTC Sub-Test: [REMOTE_INFO] Check for the kernel log status
[2022-01-29T20:15:22.710Z] declare -- cmd="journalctl_cmd --since=@1643487301"
[2022-01-29T20:15:22.710Z] 2022-01-29 20:15:21 UTC [ERROR] Caught kernel log error
[2022-01-29T20:15:22.710Z] ===========================>>
[2022-01-29T20:15:22.710Z] [ 8113.494143] kernel: soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 3 device 1 addr b921 len 1
[2022-01-29T20:15:22.710Z] [ 8113.494149] kernel: soundwire sdw-master-0: trf on Slave 1 failed:-110 write addr b921 count 0
[2022-01-29T20:15:22.710Z] [ 8113.494221] kernel: IO error in rt711_jack_detect_handler, ret -110
[2022-01-29T20:15:22.710Z] <<===========================
[2022-01-29T20:15:22.710Z] 2022-01-29 20:15:21 UTC Sub-Test: [REMOTE_ERROR] Caught error in kernel log
[2022-01-29T20:15:22.710Z] 2022-01-29 20:15:21 UTC Sub-Test: [REMOTE_ERROR] Starting func_exit_handler(), exit status=1, FUNCNAME stack:
[2022-01-29T20:15:22.710Z] 2022-01-29 20:15:21 UTC Sub-Test: [REMOTE_ERROR]  die()  @  /home/ubuntu/sof-test/test-case/../case-lib/lib.sh
[2022-01-29T20:15:22.710Z] 2022-01-29 20:15:21 UTC Sub-Test: [REMOTE_ERROR]  main()  @  /home/ubuntu/sof-test/test-case/check-suspend-resume.sh:91

Starting from January 29th I see one of two daily-tests failing: PASS, FAIL, PASS, FAIL,... There's no branch information in the TCR database but it looks like the topic/sof-dev daily was the one passing and the for-next daily was the one failing.

From February 2nd to February 24th, daily tests are consistently passing again.

After February 24th, daily tests are consistently failing except this one (which was on 5.16):

topic/sof-dev/96221091-2/linux-image-5.16.0-rc1-daily-default-20220227-0_5.16.0-rc1-topic-sof-dev-96221091-2_amd64.deb
ab715d8/fw/zephyr_debug_key/sof-tgl.ri

The first SOF Pull Requests started failing these two tests on TGLU_RVP_SDW on March 1st and then they almost never passed. #3461 was merged on Feb 28th

@marc-hb

@marc-hb, @bardliao, @plbossart, I think the reason for the error is:
https://sof-ci.01.org/linuxpr/PR3461/build7243/devicetest/?model=TGLU_RVP_SDW&testcase=check-suspend-resume-with-playback-5
When it works the log looks like this:

[ 1398.567313] kernel: rt711 sdw:0:025d:0711:00: rt711_calibration calibration complete, ret=0
[ 1398.568250] kernel: rt711 sdw:0:025d:0711:00: in rt711_jack_init enable
[ 1398.568332] kernel: rt711 sdw:0:025d:0711:00: [rt711_sdw_write] 3501 <= 0003
[ 1398.568335] kernel: rt711 sdw:0:025d:0711:00: rt711_io_init hw_init complete
[ 1398.568337] kernel: rt711 sdw:0:025d:0711:00: sdw_handle_slave_status: signaling initialization completion for Slave 1
...
[ 1398.577647] kernel: rt711 sdw:0:025d:0711:00: rt711_interrupt_callback control_port_stat=4
[ 1398.577977] kernel: soundwire_intel soundwire_intel.link.0: Slave status change: 0x20
[ 1398.818037] kernel: soundwire_intel soundwire_intel.link.0: Slave status change: 0x40
[ 1398.818252] kernel: rt711 sdw:0:025d:0711:00: Slave impl defined interrupt
[ 1398.818254] kernel: rt711 sdw:0:025d:0711:00: rt711_interrupt_callback control_port_stat=4
[ 1398.818658] kernel: soundwire_intel soundwire_intel.link.0: Slave status change: 0x20
[ 1399.072288] kernel: rt711 sdw:0:025d:0711:00: [rt711_sdw_read] b921 0000 => 80000000
[ 1399.073103] kernel: rt711 sdw:0:025d:0711:00: [rt711_sdw_read] 7520 85a0 9c20 aca0 => 00000800
[ 1399.073916] kernel: rt711 sdw:0:025d:0711:00: [rt711_sdw_read] 7520 85a0 9c20 aca0 => 00000030
[ 1399.073919] kernel: rt711 sdw:0:025d:0711:00: in rt711_jack_detect_handler, jack_type=0x3
[ 1399.073922] kernel: rt711 sdw:0:025d:0711:00: in rt711_jack_detect_handler, btn_type=0x0

[ 1401.551250] kernel: soundwire sdw-master-1: clock stop prep/de-prep done slave:15
[ 1401.966736] kernel: soundwire sdw-master-0: clock stop prep/de-prep done slave:15
[ 1401.966958] kernel: soundwire_intel soundwire_intel.link.0: intel_link_power_down: powering down all links

When it fails:

[ 1404.335718] kernel: rt711 sdw:0:025d:0711:00: in rt711_jack_init enable
[ 1404.335858] kernel: rt711 sdw:0:025d:0711:00: [rt711_sdw_write] 3501 <= 0003
[ 1404.335863] kernel: rt711 sdw:0:025d:0711:00: rt711_io_init hw_init complete
[ 1404.335865] kernel: rt711 sdw:0:025d:0711:00: sdw_handle_slave_status: signaling initialization completion for Slave 1
[ 1404.336071] kernel: soundwire_intel soundwire_intel.link.0: intel_link_power_down: powering down all links
...
[ 1404.785030] kernel: ACPI: EC: interrupt blocked
[ 1409.162488] kernel: ACPI: EC: interrupt unblocked
[ 1409.316458] kernel: soundwire_intel soundwire_intel.link.0: IO transfer timed out, cmd 3 device 1 addr b921 len 1
[ 1409.316466] kernel: soundwire sdw-master-0: trf on Slave 1 failed:-110 write addr b921 count 0
[ 1409.316538] kernel: IO error in rt711_jack_detect_handler, ret -110

...

[ 1410.107908] kernel: soundwire_intel soundwire_intel.link.0: intel_link_power_up: powering up all links
[ 1410.107914] kernel: soundwire_intel soundwire_intel.link.0: intel_link_power_up: first link up, programming SYNCPRD
[ 1410.108260] kernel: rt711 sdw:0:025d:0711:00: sdw_modify_slave_status: initializing enumeration and init completion for Slave 1
[ 1410.109150] kernel: soundwire_intel soundwire_intel.link.0: Slave status change: 0x2
[ 1410.109156] kernel: soundwire sdw-master-0: Slave attached, programming device number
[ 1410.109384] kernel: soundwire sdw-master-0: SDW Slave Addr: 20025d071100
[ 1410.109385] kernel: soundwire sdw-master-0: SDW Slave class_id 0x00, mfg_id 0x025d, part_id 0x0711, unique_id 0x0, version 0x2
[ 1410.109387] kernel: soundwire sdw-master-0: Slave already registered, reusing dev_num:1
...
[ 1410.576437] kernel: rt711 sdw:0:025d:0711:00: in rt711_jack_init enable
[ 1410.576540] kernel: rt711 sdw:0:025d:0711:00: [rt711_sdw_write] 3501 <= 0003
[ 1410.576542] kernel: rt711 sdw:0:025d:0711:00: rt711_io_init hw_init complete
[ 1410.576544] kernel: rt711 sdw:0:025d:0711:00: sdw_handle_slave_status: signaling initialization completion for Slave 1
...
[ 1410.586529] kernel: rt711 sdw:0:025d:0711:00: rt711_interrupt_callback control_port_stat=4
[ 1410.586872] kernel: soundwire_intel soundwire_intel.link.0: Slave status change: 0x20
[ 1410.606525] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 1410.606581] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
[ 1410.814363] kernel: rt711 sdw:0:025d:0711:00: Slave impl defined interrupt
[ 1410.814366] kernel: rt711 sdw:0:025d:0711:00: rt711_interrupt_callback control_port_stat=4
[ 1411.069309] kernel: rt711 sdw:0:025d:0711:00: [rt711_sdw_read] b921 0000 => 80000000
[ 1411.070401] kernel: rt711 sdw:0:025d:0711:00: [rt711_sdw_read] 7520 85a0 9c20 aca0 => 00000800
[ 1411.071528] kernel: rt711 sdw:0:025d:0711:00: [rt711_sdw_read] 7520 85a0 9c20 aca0 => 00000030
[ 1411.071534] kernel: rt711 sdw:0:025d:0711:00: in rt711_jack_detect_handler, jack_type=0x3
[ 1411.071538] kernel: rt711 sdw:0:025d:0711:00: in rt711_jack_detect_handler, btn_type=0x0
[ 1414.140735] kernel: soundwire sdw-master-0: clock stop prep/de-prep done slave:15
[ 1414.140987] kernel: soundwire sdw-master-1: clock stop prep/de-prep done slave:15
[ 1414.141163] kernel: soundwire_intel soundwire_intel.link.1: intel_link_power_down: powering down all links

So in case of error print the in rt711_jack_init enable means that jack_detect_work is scheduled to run in ~250ms, the sdw core got power off and the rt711_jack_detect_handler() tries to read 0xb921 register, which is volatile, so it must reach out to the bus, but it is down, so we get -ETIMEDOUT back as error code.
Note that later on the jack detect works again when the sequence is correct (the sdw links are not powered down right away).

When there is no error we also receive interrupt, which is expected or not, I don't know.

We might be missing a cancel work calls in case the sdw is disabling the link or we need a check if the link is up at all?

@plbossart

@plbossart @marc-hb @ujfalusi It took me more than 6 hours to bisect this issue, lucky me, I found the bad commit:
e38f9ff

diff --git a/drivers/acpi/scan.c b/drivers/acpi/scan.c
index 2c80765670bc..5991dddbc9ce 100644
--- a/drivers/acpi/scan.c
+++ b/drivers/acpi/scan.c
@@ -1340,11 +1340,11 @@ static void acpi_set_pnp_ids(acpi_handle handle, struct acpi_device_pnp *pnp,
                if (info->valid & ACPI_VALID_HID) {
                        acpi_add_id(pnp, info->hardware_id.string);
                        pnp->type.platform_id = 1;
-               }
-               if (info->valid & ACPI_VALID_CID) {
-                       cid_list = &info->compatible_id_list;
-                       for (i = 0; i < cid_list->count; i++)
-                               acpi_add_id(pnp, cid_list->ids[i].string);
+                       if (info->valid & ACPI_VALID_CID) {
+                               cid_list = &info->compatible_id_list;
+                               for (i = 0; i < cid_list->count; i++)
+                                       acpi_add_id(pnp, cid_list->ids[i].string);

I tried to revert this commit on tip of sof-dev and verified this issue again, 3*30 iterations passed, no reproductions.

@keqiaozhang

@keqiaozhang, wow!

What I have found that the issue is really easy to reproduce on tglu-rvp-sdw:

aplay -Dplughw:0,2 -fdat /dev/urandom &
sleep 1
sudo rtcwake -m mem -s 5

Don't forget to killall aplay

# aplay -l
**** List of PLAYBACK Hardware Devices ****
card 0: sofsoundwire [sof-soundwire], device 0: Jack Out (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: sofsoundwire [sof-soundwire], device 2: Speaker (*) []
  Subdevices: 0/1
  Subdevice #0: subdevice #0
card 0: sofsoundwire [sof-soundwire], device 5: HDMI 1 (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: sofsoundwire [sof-soundwire], device 6: HDMI 2 (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: sofsoundwire [sof-soundwire], device 7: HDMI 3 (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 0: sofsoundwire [sof-soundwire], device 8: HDMI 4 (*) []
  Subdevices: 1/1
  Subdevice #0: subdevice #0
card 1: Device [USB Audio Device], device 0: USB Audio [USB Audio]
  Subdevices: 1/1
  Subdevice #0: subdevice #0

If you would try plughw:0,0, it never happens, only if you use a PCM which does not have the rt711 in path.

Can you see if this is working as well? For me this is 100% reproduction rate.

@ujfalusi

@ujfalusi , I changed test script and only test hw:0,2 with suspend/resume. I did a lot of test, no reproductions after reverting e38f9ff. I'm pretty sure about the result.

soundwire: intel: prevent pm_runtime resume prior to system suspend

Navigation Menu

Repository navigation

SoundWire: TGL: IO error in rt711_jack_detect_handler #3459

158 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

SoundWire: TGL: IO error in rt711_jack_detect_handler #3459

Description

Activity

plbossart commented on Feb 25, 2022

plbossart commented on Feb 28, 2022

bardliao commented on Mar 1, 2022

marc-hb commented on Mar 8, 2022

plbossart commented on Mar 9, 2022

marc-hb commented on Mar 10, 2022

ujfalusi commented on Mar 10, 2022

keqiaozhang commented on Mar 10, 2022

ujfalusi commented on Mar 10, 2022

keqiaozhang commented on Mar 10, 2022

158 remaining items

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions