SoundWire: TGL: IO error in rt711_jack_detect_handler

[plbossart]

@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

[plbossart]

not sure if this is related to #3401

[plbossart]

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.

[marc-hb]

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

[plbossart]

@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.

[marc-hb]

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

[ujfalusi]

@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?