Bug 202103

Created attachment 280211 [details]
acpidump output

Can you attach similar lspci output (sudo lspci -vv) but from the whole system so we can see the root port as well?

Created attachment 280213 [details]
Full lspci output

If you just revert 0e157e528604 ("PCI/PME: Implement runtime PM callbacks") does it work as expected then?

Yes, reverting this commit brings back the expected behavior.

Can you following steps both with the commit reverted and without?

When the cable is disconnected and the NIC is in D3:

  # cat /sys/bus/pci/devices/0000:00:14.0/firmware_node/power_state
  # cat /sys/bus/pci/devices/0000:00:14.0/firmware_node/real_power_state
  # lspci -vv -s 00:14.0

then connect the cable back and run the same above commands.

Please attach also full dmesg of both cases. Thanks!

Created attachment 280217 [details]
dmesg with the commit

Created attachment 280219 [details]
dmesg with commit reverted

Created attachment 280221 [details]
lspci with commit

Created attachment 280223 [details]
lspci with commit reverted

I attached the requested output.
In sysfs I have neither power_state nor real_power_state under firmware_node.

As expected difference is that with the commit reverted PMEIntEna is enabled under RootCtl.

Right. AFAIK the root port cannot trigger PME itself (when it is in D3) so in this case it should actually generate GPE and looking at the acpidump there is GPE 9 associated to this root port via ACPI _PRW(). It is weird that the root port seems to be able to generate interrupts in D3.

Do you see any changes in /sys/firmware/acpi/interrupts/gpe_all and /sys/firmware/acpi/interrupts/gpe_09 when you plug back the ethernet cable (without the commit reverted)?

gpe_all:
Initially is 1. After re-pluging the cable with each read access the value increases: 1, 101837, 107665, ..

gpe09:
Has always value: 0 EN enabled unmasked

Just checked, the increasing number in gpe_all is caused by gpe03.

OK, thanks for trying.

I managed to find similar system here and can reproduce the issue now. Let me investigate and report back.

I read a little bit more about ACPI + PME, e.g. here: https://blog.linuxplumbersconf.org/2010/ocw/system/presentations/279/original/PCI_runtime_PM.pdf
Seems that ACPI can request to control wakeup but doesn't have to. Maybe we need a check whether srv has a related acpi_device which has flags.power_manageable set?
If not we'd go with the logic in pcie_pme_suspend.

For my understanding two further inquiries:

Commit message for adding the runtime PM callbacks says: "This prevents spurious wakeups immediately when the port is transitioned into D3cold."

- How is runtime PM different from system suspend here? If we have such spurious wakeups they could wake the system from system suspend as well, or?

- What's causing these spurious wakeups? Are the runtime PM callbacks more kind of a workaround for another issue?

Hi,

The problem the commit tried to solve is that when the PCIe hierarchy goes into D3cold it wakes up immediately due to PME/wakeup. Disabling the root port PME interrupt prevents that but it seems to cause other issues so it may be that it is not correct after all.

I'm currently investigating the issue as I can reproduce it easily and let you know once I have some resolution.

[regression] NIC doesn't wake up from suspend when LAN cable is plugged in,
in kernel stable 5.4.1 from here: https://git.kernel.org/pub/scm/linux/kernel/git/stable/linux.git/log/?h=linux-5.4.y
also in current git kernel.

bisect shows:
# first bad commit: [95fb8bb3181bbe1ee87c95e91dff94f74f148c33] net: phy: force phy suspend when calling phy_stop

Can confirm that reverting that commit returns things to normal.



Full bisect log:
$ git bisect log
git bisect start
# bad: [81b6b96475ac7a4ebfceae9f16fb3758327adbfe] Merge branch 'master' of git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux; tag 'dma-mapping-5.5' of git://git.infradead.org/users/hch/dma-mapping
git bisect bad 81b6b96475ac7a4ebfceae9f16fb3758327adbfe
# good: [4d856f72c10ecb060868ed10ff1b1453943fc6c8] Linux 5.3
git bisect good 4d856f72c10ecb060868ed10ff1b1453943fc6c8
# skip: [351c8a09b00b5c51c8f58b016fffe51f87e2d820] Merge branch 'i2c/for-5.4' of git://git.kernel.org/pub/scm/linux/kernel/git/wsa/linux
git bisect skip 351c8a09b00b5c51c8f58b016fffe51f87e2d820
# skip: [351c8a09b00b5c51c8f58b016fffe51f87e2d820] Merge branch 'i2c/for-5.4' of git://git.kernel.org/pub/scm/linux/kernel/git/wsa/linux
git bisect skip 351c8a09b00b5c51c8f58b016fffe51f87e2d820
# bad: [b31333298087f8ee3559bd62bcbd1638f232cac0] samples/bpf: Add missing option to xdpsock usage
git bisect bad b31333298087f8ee3559bd62bcbd1638f232cac0
# bad: [32b90daf5cafdda62b1ce62d0b7445fa9107babf] Merge tag 'tag-chrome-platform-for-v5.4' of git://git.kernel.org/pub/scm/linux/kernel/git/chrome-platform/linux
git bisect bad 32b90daf5cafdda62b1ce62d0b7445fa9107babf
# good: [1f7d290a7275edb270dbee13212c37cb59940221] Merge tag 'driver-core-5.4-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/gregkh/driver-core
git bisect good 1f7d290a7275edb270dbee13212c37cb59940221
# bad: [35c7ff349a2d1df1b59909f67ba4ddcd84ad934e] mlx4: Split restart_one into two functions
git bisect bad 35c7ff349a2d1df1b59909f67ba4ddcd84ad934e
# good: [1216ce9d4a740bed88393177174fef275069a560] net/mlx5e: Extend neigh hash entry with rcu
git bisect good 1216ce9d4a740bed88393177174fef275069a560
# bad: [67e974c3ae21c8ced474eae3ce9261a6f827e95c] Merge tag 'iwlwifi-next-for-kalle-2019-09-06' of git://git.kernel.org/pub/scm/linux/kernel/git/iwlwifi/iwlwifi-next
git bisect bad 67e974c3ae21c8ced474eae3ce9261a6f827e95c
# bad: [657a33c8a0a2342e91259b28356838dc89216b19] bnxt_en: Add devlink health reset reporter.
git bisect bad 657a33c8a0a2342e91259b28356838dc89216b19
# good: [99122836d26a366847f92f9a211602a44a038c61] net: stmmac: add EHL SGMII 1Gbps PCI info and PCI ID
git bisect good 99122836d26a366847f92f9a211602a44a038c61
# bad: [42aa15cf05c0a47cc5807c21c7ff471b80cad371] net: dsa: mv88e6xxx: fix freeing unused SERDES IRQ
git bisect bad 42aa15cf05c0a47cc5807c21c7ff471b80cad371
# good: [8e4a2adcedac01c4269ae104824b9078870000b1] Merge branch '100GbE' of git://git.kernel.org/pub/scm/linux/kernel/git/jkirsher/next-queue
git bisect good 8e4a2adcedac01c4269ae104824b9078870000b1
# bad: [6125b52d2641497228e806c60b906769ab4b2c19] net: hns3: modify base parameter of kstrtouint in hclge_dbg_dump_tm_map
git bisect bad 6125b52d2641497228e806c60b906769ab4b2c19
# bad: [198836fdff09f45d09fd6d291e0ebda25d393bf4] Merge branch 'mlxsw-Various-updates'
git bisect bad 198836fdff09f45d09fd6d291e0ebda25d393bf4
# bad: [3f61967f4197547fb1888642d5178a64ca9fb191] mlxsw: spectrum: Prevent auto negotiation on number of lanes
git bisect bad 3f61967f4197547fb1888642d5178a64ca9fb191
# bad: [95fb8bb3181bbe1ee87c95e91dff94f74f148c33] net: phy: force phy suspend when calling phy_stop
git bisect bad 95fb8bb3181bbe1ee87c95e91dff94f74f148c33
# first bad commit: [95fb8bb3181bbe1ee87c95e91dff94f74f148c33] net: phy: force phy suspend when calling phy_stop

Maybe something else is also at play here because I'm getting the following WARN_ONCE even after reverting the bad commit:

[    9.865044] ------------[ cut here ]------------
[    9.874822] read_page callback not available, PHY driver not loaded?
[    9.874851] WARNING: CPU: 3 PID: 617 at __phy_read_page+0x37/0x40
[    9.874981] systemd[1]: kdump.service: Succeeded.
[    9.875605] systemd[1]: Started Load dump capture kernel.
[    9.884107] Modules linked in: xt_TCPMSS iptable_mangle iptable_security iptable_nat nf_nat iptable_raw nf_log_ipv4 nf_log_common xt_c
onntrack ipt_REJECT nf_reject_ipv4 xt_LOG xt_connlimit nf_conncount xt_hashlimit xt_multiport xt_owner xt_addrtype xt_tcpudp iptable_filt
er rtsx_usb mfd_core input_leds snd_hda_codec_realtek led_class pcspkr snd_hda_codec_hdmi snd_hda_codec_generic mq_deadline snd_hda_intel
 snd_intel_dspcfg snd_hda_codec snd_hwdep snd_hda_core i2c_piix4 snd_pcm snd_timer snd soundcore ip_tables x_tables autofs4 hid_generic s
erio_raw ohci_pci [last unloaded: msr]
[    9.884107] CPU: 3 PID: 617 Comm: ip Kdump: loaded Tainted: G          I       5.4.0-g81b6b96475ac #137
[    9.884107] Hardware name: LENOVO Sabine/Torpedo, BIOS 54CN18WW 07/20/2011
[    9.884107] RIP: 0010:__phy_read_page+0x37/0x40
[    9.884107] Code: 00 48 85 c0 74 02 ff e0 80 3d d8 c6 bb 00 00 74 06 b8 a1 ff ff ff c3 c6 05 c9 c6 bb 00 01 48 c7 c7 a0 e3 13 85 e8 99
 b0 97 ff <0f> 0b eb e3 0f 1f 44 00 00 55 48 89 fd 48 8b 87 a8 02 00 00 48 8d
[    9.884107] RSP: 0018:ffff9ee30196f4c8 EFLAGS: 00010282
[    9.884107] RAX: 0000000000000000 RBX: 0000000000000000 RCX: 0000000000000006
[    9.884107] RDX: 0000000000000007 RSI: 0000000000000002 RDI: ffff8b238e393ad0
[    9.884107] RBP: ffff8b238e34a800 R08: 000000024c95d43f R09: 0000000000000710
[    9.884107] R10: 0000000000000000 R11: 0000000000fd62f8 R12: ffff8b2087cd4800
[    9.884107] R13: 0000000000000005 R14: ffff8b216b3650b0 R15: 0000000000000001
[    9.884107] FS:  00007f8ec75196c0(0000) GS:ffff8b238e380000(0000) knlGS:0000000000000000
[    9.884107] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[    9.884107] CR2: 000055e7b3782f10 CR3: 00000003d4636000 CR4: 00000000000006e0
[    9.936108] Call Trace:
[    9.936108]  ? phy_select_page+0x23/0x60
[    9.936108]  ? phy_write_paged+0x13/0x60
[    9.936108]  ? rtl8105e_hw_phy_config+0x57/0xa0
[    9.936108]  ? rtl8169_init_phy+0x20/0x80
[    9.936108]  ? rtl_open+0x3a7/0x560
[    9.936108]  ? __dev_open+0xc9/0x160
[    9.936108]  ? __dev_change_flags+0x16f/0x1e0
[    9.936108]  ? dev_change_flags+0x1e/0x60
[    9.936108]  ? do_setlink+0x6e7/0xe80
[    9.936108]  ? __nla_validate_parse+0x51/0x780
[    9.936108]  ? __rtnl_newlink+0x59c/0x920
[    9.936108]  ? __nla_validate_parse+0x51/0x780
[    9.936108]  ? prep_new_page+0x6e/0x100
[    9.936108]  ? get_page_from_freelist+0xcda/0x1000
[    9.936108]  ? __nla_reserve+0x38/0x60
[    9.936108]  ? __nla_put+0xc/0x20
[    9.936108]  ? rtnl_xdp_prog_skb+0x10/0x60
[    9.936108]  ? __nla_reserve+0x38/0x60
[    9.936108]  ? __nla_put+0xc/0x20
[    9.936108]  ? sk_filter_trim_cap+0xba/0x200
[    9.936108]  ? netlink_attachskb+0x1c3/0x220
[    9.936108]  ? skb_queue_tail+0x16/0x40
[    9.936108]  ? __rtnl_unlock+0x1f/0x40
[    9.936108]  ? rtnl_newlink+0x3a/0x60
[   10.012109]  ? rtnetlink_rcv_msg+0x2c7/0x3a0
[   10.012109]  ? copyout+0x29/0x40
[   10.012109]  ? rtnl_calcit.isra.0+0x100/0x100
[   10.012109]  ? netlink_rcv_skb+0x41/0x120
[   10.012109]  ? netlink_unicast+0x18b/0x260
[   10.012109]  ? netlink_sendmsg+0x218/0x440
[   10.012109]  ? netlink_unicast+0x260/0x260
[   10.012109]  ? ____sys_sendmsg+0x244/0x280
[   10.012109]  ? copy_msghdr_from_user+0xcf/0x160
[   10.012109]  ? ___sys_sendmsg+0x7d/0xe0
[   10.012109]  ? __wake_up_common_lock+0x85/0xc0
[   10.012109]  ? __inode_wait_for_writeback+0x79/0xe0
[   10.012109]  ? fsnotify_destroy_marks+0x1d/0xf0
[   10.012109]  ? __sys_sendmsg+0x54/0xa0
[   10.012109]  ? do_syscall_64+0x3d/0x120
[   10.012109]  ? entry_SYSCALL_64_after_hwframe+0x44/0xa9
[   10.012109] ---[ end trace d7f0a93700207a3e ]---

A separate bug ticket would have been better because the issue is different.

1. When talking about suspend, do you refer to runtime suspend or to S3 (suspend to RAM)?
2. What's the PHY ID of the chip (check attribute phy_id in sysfs)?
3. Is the Realtek PHY driver (realtek.ko) loaded?

I looked at the description (Comment #0) and it matched, which is why I opted to not make a new issue.

1. I refer to:
cat /sys/bus/pci/devices/0000:01:00.0/power/runtime_status
which returns 'suspended'
and it doesn't change to 'resuming' then 'active' when LAN cable is plugged in, unless I revert that commit, of course.

not anything like suspend to RAM.(never tried that)

2. phy id is "0x001cc882", according to:
$ find /sys/devices/pci0000:00/0000:00:04.0/0000:01:00.0 -iname \*phy\* -exec grep -nH . "{}" \;
grep: /sys/devices/pci0000:00/0000:00:04.0/0000:01:00.0/net/net0/phydev: Is a directory
grep: /sys/devices/pci0000:00/0000:00:04.0/0000:01:00.0/net/net0/phys_switch_id: Operation not supported
grep: /sys/devices/pci0000:00/0000:00:04.0/0000:01:00.0/net/net0/phys_port_name: Operation not supported
grep: /sys/devices/pci0000:00/0000:00:04.0/0000:01:00.0/net/net0/phys_port_id: Operation not supported
/sys/devices/pci0000:00/0000:00:04.0/0000:01:00.0/mdio_bus/r8169-100/r8169-100:00/phy_interface:1:mii
/sys/devices/pci0000:00/0000:00:04.0/0000:01:00.0/mdio_bus/r8169-100/r8169-100:00/phy_id:1:0x001cc882
/sys/devices/pci0000:00/0000:00:04.0/0000:01:00.0/mdio_bus/r8169-100/r8169-100:00/phy_has_fixups:1:0

3. I don't know? probably not.

$ lspci -vvv|grep -i kernel
	Kernel driver in use: radeon
	Kernel driver in use: snd_hda_intel
	Kernel modules: snd_hda_intel
	Kernel driver in use: pcieport
	Kernel driver in use: ahci
	Kernel driver in use: ohci-pci
	Kernel modules: ohci_pci
	Kernel driver in use: ehci-pci
	Kernel driver in use: ohci-pci
	Kernel modules: ohci_pci
	Kernel driver in use: ehci-pci
	Kernel modules: i2c_piix4
	Kernel driver in use: snd_hda_intel
	Kernel modules: snd_hda_intel
	Kernel driver in use: k10temp
	Kernel driver in use: r8169

$ lsmod|grep -i realtek
snd_hda_codec_realtek   118784  1
snd_hda_codec_generic    69632  1 snd_hda_codec_realtek
snd_hda_codec         106496  4 snd_hda_codec_generic,snd_hda_codec_hdmi,snd_hda_intel,snd_hda_codec_realtek
snd_hda_core           61440  5 snd_hda_codec_generic,snd_hda_codec_hdmi,snd_hda_intel,snd_hda_codec,snd_hda_codec_realtek
snd                    73728  14 snd_hda_codec_generic,snd_hda_codec_hdmi,snd_hwdep,snd_hda_intel,snd_hda_codec,snd_hda_codec_realtek,snd_timer,snd_pcm

$ sudo modprobe realtek
doesn't say anything but exit code is 0, but the above lsmod/lspci doesn't change its output.

Maybe it's already built into kernel?

nothing interesting in dmesg about realtek (except unrelated stuff), here's some phy stuff:
[    3.167423] libphy: r8169: probed
[   10.519409] Generic PHY r8169-100:00: attached PHY driver [Generic PHY] (mii_bus:phy_addr=r8169-100:00, irq=IGNORE)
and the "cut here" dump from above, that's it.

Here come two patches, first one is supposed to fix the cable plug-in detection, the second one fixes the warning regarding the missing paged operations.
You should see RTL8208 as detected PHY type in the "attached PHY driver" message. Could you please give these patches a try? Thanks.


diff --git a/drivers/net/ethernet/realtek/r8169_main.c b/drivers/net/ethernet/realtek/r8169_main.c
index d47a038cb..0b47db2ff 100644
--- a/drivers/net/ethernet/realtek/r8169_main.c
+++ b/drivers/net/ethernet/realtek/r8169_main.c
@@ -1542,6 +1542,7 @@ static void __rtl8169_set_wol(struct rtl8169_private *tp, u32 wolopts)
 	rtl_lock_config_regs(tp);
 
 	device_set_wakeup_enable(tp_to_dev(tp), wolopts);
+	tp->dev->wol_enabled = wolopts ? 1 : 0;
 }
 
 static int rtl8169_set_wol(struct net_device *dev, struct ethtool_wolinfo *wol)
-- 
2.24.0



diff --git a/drivers/net/phy/realtek.c b/drivers/net/phy/realtek.c
index 677c45985..476db5345 100644
--- a/drivers/net/phy/realtek.c
+++ b/drivers/net/phy/realtek.c
@@ -439,6 +439,15 @@ static struct phy_driver realtek_drvs[] = {
 		.resume		= genphy_resume,
 		.read_page	= rtl821x_read_page,
 		.write_page	= rtl821x_write_page,
+	}, {
+		PHY_ID_MATCH_MODEL(0x001cc880),
+		.name		= "RTL8208 Fast Ethernet",
+		.read_mmd	= genphy_read_mmd_unsupported,
+		.write_mmd	= genphy_write_mmd_unsupported,
+		.suspend	= genphy_suspend,
+		.resume		= genphy_resume,
+		.read_page	= rtl821x_read_page,
+		.write_page	= rtl821x_write_page,
 	}, {
 		PHY_ID_MATCH_EXACT(0x001cc910),
 		.name		= "RTL8211 Gigabit Ethernet",
-- 
2.24.0

Both patches work as expected(I've applied them on top of the same linux git commit 81b6b96475ac7a4ebfceae9f16fb3758327adbfe as my latest test(s), without reverting the bad commit).
Thank you very much for your work!

[   10.287013] RTL8208 Fast Ethernet r8169-100:00: attached PHY driver [RTL8208 Fast Ethernet] (mii_bus:phy_addr=r8169-100:00, irq=IGNORE)


I realized I haven't shown this before, so here's `$ lspci -vvv` now:

01:00.0 Ethernet controller: Realtek Semiconductor Co., Ltd. RTL810xE PCI Express Fast Ethernet controller (rev 05)
	Subsystem: Lenovo RTL810xE PCI Express Fast Ethernet controller
	Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx+
	Status: Cap+ 66MHz- UDF- FastB2B- ParErr- DEVSEL=fast >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
	Latency: 0, Cache Line Size: 32 bytes
	Interrupt: pin A routed to IRQ 16
	Region 0: I/O ports at 1000 [size=256]
	Region 2: Memory at f0004000 (64-bit, prefetchable) [size=4K]
	Region 4: Memory at f0000000 (64-bit, prefetchable) [size=16K]
	Capabilities: <access denied>
	Kernel driver in use: r8169

Really, much appreciated. Cheers!