Bug 217343 - WARNING "thunderbolt 0000:34:00.6: interrupt for TX ring 0 is already enabled" at S4 resume
Summary: WARNING "thunderbolt 0000:34:00.6: interrupt for TX ring 0 is already enabled...
Status: RESOLVED CODE_FIX
Alias: None
Product: Drivers
Classification: Unclassified
Component: Other (show other bugs)
Hardware: All Linux
: P3 normal
Assignee: drivers_other
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2023-04-15 09:43 UTC by Takashi Iwai
Modified: 2023-05-22 21:03 UTC (History)
2 users (show)

See Also:
Kernel Version:
Subsystem:
Regression: No
Bisected commit-id:


Attachments
possible patch (3.19 KB, patch)
2023-04-21 01:59 UTC, Mario Limonciello (AMD)
Details | Diff

Description Takashi Iwai 2023-04-15 09:43:14 UTC
When resuming from the hibernation on Lenovo Thinkpad T14s Gen 3 with AMD Ryzen, the kernel spews the warnings like:

[   13.774391] WARNING: CPU: 13 PID: 111 at drivers/thunderbolt/nhi.c:125 ring_interrupt_active+0x216/0x270
[   13.774399] Modules linked in: bnep(E) btusb(E) btrtl(E) btbcm(E) btintel(E) btmtk(E) bluetooth(E) ecdh_generic(E) qrtr_mhi(E) cdc_mbim(E) cdc_wdm(E) cdc_ncm(E) cdc_ether(E) usbnet(E) mii(E) dmi_sysfs(E) qrtr(E) mhi(E) snd_ctl_led(E) intel_rapl_msr(E) nls_iso8859_1(E) intel_rapl_common(E) nls_cp437(E) snd_hda_codec_realtek(E) snd_hda_codec_generic(E) vfat(E) snd_hda_codec_hdmi(E) kvm_amd(E) think_lmi(E) fat(E) firmware_attributes_class(E) wmi_bmof(E) snd_hda_intel(E) snd_intel_dspcfg(E) kvm(E) snd_hda_codec(E) snd_hwdep(E) irqbypass(E) snd_hda_core(E) thinkpad_acpi(E) snd_pcm(E) ledtrig_audio(E) video(E) platform_profile(E) snd_timer(E) snd_rn_pci_acp3x(E) i2c_piix4(E) snd(E) snd_acp_config(E) snd_soc_acpi(E) snd_pci_acp3x(E) ucsi_acpi(E) soundcore(E) typec_ucsi(E) roles(E) typec(E) thermal(E) rfkill(E) fan(E) battery(E) ac(E) wmi(E) acpi_cpufreq(E) amd_pmc(E) acpi_tad(E) button(E) drm(E) fuse(E) configfs(E) efi_pstore(E) ip_tables(E) x_tables(E) ext4(E) crc16(E) mbcache(E) jbd2(E) crc32_pclmul(E) crc32c_intel(E)
[   13.774456]  ghash_clmulni_intel(E) xhci_pci(E) aesni_intel(E) xhci_pci_renesas(E) nvme(E) crypto_simd(E) cryptd(E) xhci_hcd(E) nvme_core(E) serio_raw(E) t10_pi(E) sp5100_tco(E) crc64_rocksoft_generic(E) usbcore(E) ccp(E) crc64_rocksoft(E) crc64(E) i2c_hid_acpi(E) i2c_hid(E) sg(E) dm_multipath(E) dm_mod(E) scsi_dh_rdac(E) scsi_dh_emc(E) scsi_dh_alua(E) scsi_mod(E) scsi_common(E) msr(E) efivarfs(E) [last unloaded: qmi_helpers(E)]
[   13.774478] CPU: 13 PID: 111 Comm: kworker/u32:1 Tainted: G            E      6.3.0-rc6-xtest5-dirty #11 334ee2e65583e46a1a254d52b14ac04857fddcf8
[   13.774481] Hardware name: LENOVO 21CRS0K63E/21CRS0K63E, BIOS R22ET60W (1.30 ) 02/09/2023
[   13.774483] Workqueue: events_unbound async_run_entry_fn
[   13.774489] RIP: 0010:ring_interrupt_active+0x216/0x270
[   13.774492] Code: c7 d0 00 00 00 48 89 14 24 e8 96 f4 f1 ff 48 8b 14 24 4d 89 f9 45 89 f0 4c 89 e1 48 89 c6 48 c7 c7 b8 a5 50 98 e8 1a 7b 79 ff <0f> 0b e9 3c ff ff ff 0f b6 43 78 d3 e0 09 c7 e9 d4 fe ff ff 03 56
[   13.774494] RSP: 0018:ffffa801c0553d78 EFLAGS: 00010082
[   13.774496] RAX: 0000000000000000 RBX: ffff90dac11ab5c0 RCX: 0000000000000027
[   13.774497] RDX: 0000000000000000 RSI: 00000000ffff7fff RDI: ffff90ddef1624c8
[   13.774499] RBP: 0000000000000009 R08: 0000000000000000 R09: c0000000ffff7fff
[   13.774500] R10: 0000000000000006 R11: ffffa801c0553c10 R12: ffffffff9850a3af
[   13.774501] R13: 0000000000038200 R14: 0000000000000000 R15: ffffffff98486ff5
[   13.774502] FS:  0000000000000000(0000) GS:ffff90ddef140000(0000) knlGS:0000000000000000
[   13.774504] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[   13.774505] CR2: 0000000000000000 CR3: 000000014dc34000 CR4: 0000000000750ee0
[   13.774506] PKRU: 55555554
[   13.774507] Call Trace:
[   13.774510]  <TASK>
[   13.774514]  tb_ring_start+0x14e/0x240
[   13.774518]  tb_ctl_start+0x22/0x80
[   13.774522]  ? __pfx_pci_pm_restore_noirq+0x10/0x10
[   13.774526]  tb_domain_resume_noirq+0x25/0x60
[   13.774531]  dpm_run_callback+0x46/0x190
[   13.774535]  device_resume_noirq+0xe0/0x1e0
[   13.774538]  async_resume_noirq+0x1a/0x60
[   13.774541]  async_run_entry_fn+0x2e/0x110
[   13.774543]  process_one_work+0x226/0x440
[   13.774547]  worker_thread+0x2a/0x3b0
[   13.774550]  ? __pfx_worker_thread+0x10/0x10
[   13.774552]  kthread+0xd9/0x100
[   13.774556]  ? __pfx_kthread+0x10/0x10
[   13.774559]  ret_from_fork+0x2c/0x50
[   13.774565]  </TASK>
[   13.774566] ---[ end trace 0000000000000000 ]---

And once again for RX:
[   13.774605] thunderbolt 0000:34:00.6: interrupt for RX ring 0 is already enabled
[   13.774611] WARNING: CPU: 13 PID: 111 at drivers/thunderbolt/nhi.c:125 ring_interrupt_active+0x216/0x270
....

And, this seems to be happening only when the Thunderbolt driver is configured as built-in (CONFIG_USB4=y).  On the kernel with TB as a module (CONFIG_USB4=m), this bug isn't triggered.

My wild guess is that the TB stuff gets initialized on the kernel that does restore the image, and the irq setup is taken over at resuming from the image.
Adding some debug prints and enabling the debug output, the kernel shows like below just before the warning:

[   13.774312] thunderbolt 0000:34:00.6: XXX nhi_restore_noirq
[   13.774338] thunderbolt 0000:34:00.6: XXX nhi_resume_noirq
[   13.774362] thunderbolt 0000:34:00.6: enabling interrupt at register 0x38200 bit 0 (0x9 -> 0x9)

So, this is happening at the restore_noirq call, and the irqs have been already set up.

The symptom is found from 5.15 to the latest Linus tree (6.3-rc6).
(The reason starting from 5.15 is that AMD TB got fixed on that version.)

Except for the ugly interrupts, there is no other problem.
Comment 1 Takashi Iwai 2023-04-20 14:34:21 UTC
I suspect rather that this might be an AMD-specific problem.  Adding Mario to Cc.

During the debug, I noticed that the interrupt bit flip in ring_interrupt_active() isn't taken immediately on the machine.
Namely, even after the iowrite32() on REG_RING_INTERRUPT_BASE + idx, reading the same register returns the old value.

That is, the suspend / freeze ops does turn off the interrupt by writing on that register, but this alone doesn't suffice.  At the hibernation (with TB built-in), the device has been already initialized.  Even if it's (runtime-)suspended, the irq bit on the register isn't actually cleared, and at the hibernation resume, the driver checks it by reading the register, hence it complains the inconsistency, as it seems.
Comment 2 Mario Limonciello (AMD) 2023-04-20 15:02:07 UTC
My knee jerk reaction is "What is the value to this warning message?".

> Namely, even after the iowrite32() on REG_RING_INTERRUPT_BASE + idx, reading
> the same register returns the old value.

It sounds like by having it as a module it changes the timing and it takes some time for the hardware to enable (or disable) the interrupt.

If the warning should stay one option is that we can poll `REG_RING_INTERRUPT_BASE + idx` after the write to ensure it's settled.  Can you have a try with that perhaps?
Comment 3 Takashi Iwai 2023-04-20 15:08:30 UTC
(In reply to Mario Limonciello (AMD) from comment #2)
> My knee jerk reaction is "What is the value to this warning message?".
> 
> > Namely, even after the iowrite32() on REG_RING_INTERRUPT_BASE + idx,
> reading
> > the same register returns the old value.
> 
> It sounds like by having it as a module it changes the timing and it takes
> some time for the hardware to enable (or disable) the interrupt.

Right, if the TB is a module, it's not loaded on the kernel that does restore the hibernation image, hence at the hibernation resume, TB device is still in the uninitialized state.  OTOH, when it's built-in, the TB device was already initialized at hibernation resume, and it triggers the bug.

> If the warning should stay one option is that we can poll
> `REG_RING_INTERRUPT_BASE + idx` after the write to ensure it's settled.  Can
> you have a try with that perhaps?

I tried to add the 1000 times reads, but this didn't seem help, and the value persisted.  But I need to double-check.
Comment 4 Takashi Iwai 2023-04-20 15:25:17 UTC
(In reply to Takashi Iwai from comment #3)
> (In reply to Mario Limonciello (AMD) from comment #2)
> > If the warning should stay one option is that we can poll
> > `REG_RING_INTERRUPT_BASE + idx` after the write to ensure it's settled. 
> Can
> > you have a try with that perhaps?
> 
> I tried to add the 1000 times reads, but this didn't seem help, and the
> value persisted.  But I need to double-check.

I confirmed that the old value persists even after 1 second.  HOWEVER: this happens only when you turn off the bit.  Turning on the bit is effective immediately, as it seems.
Comment 5 Mario Limonciello (AMD) 2023-04-21 01:59:15 UTC
Created attachment 304168 [details]
possible patch

Can you have a try with this patch?
Comment 6 Takashi Iwai 2023-04-21 07:13:50 UTC
Yes, the patch works fine!
Comment 7 Takashi Iwai 2023-04-21 07:14:50 UTC
So feel free to take:
Tested-by: Takashi Iwai <tiwai@suse.de>

Will be looking forward to seeing your upstream submission :)
Comment 8 Mario Limonciello (AMD) 2023-05-22 21:03:50 UTC
It's part of 6.4-rc3 and trickling into stable kernels.

c4af8e3fecd0 ("thunderbolt: Clear registers properly when auto clear isn't in use")

Note You need to log in before you can comment on or make changes to this bug.