Re: [Intel-wired-lan] [RFC PATCH] net: ethtool: do runtime PM outside RTNL

[Johannes Berg <johannes@sipsolutions.net>]

On Mon, 2023-12-04 at 12:36 -0800, Marc MERLIN wrote:
> 
> So, ipc is not a module for me
> sauron:/usr/src/linux-6.6.4-amd64-preempt-sysrq-20231203# lsmod | grep ipc

I think the driver is "igc", not "ipc".

> sauron:/usr/src/linux-6.6.4-amd64-preempt-sysrq-20231203# 
> 
> Is that a build config option I can reaonably turn off without breaking
> networking altogether?
> 
> Previous boot, before your patch that I just compiled and will test now, 
> it ended with this. I also see ethtool lower down, maybe run randomly by network manager
> but isn't the hang happening before in these loglines, or the order of the logs is not
> the actual sequence order of the problem?

The order of this doesn't tell us much, I believe.

> [ 4230.596282] INFO: task kworker/0:2:132 blocked for more than 120 seconds.
> [ 4230.596288]       Tainted: G     U             6.6.4-amd64-preempt-sysrq-20231203 #5
> [ 4230.596289] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 4230.596291] task:kworker/0:2     state:D stack:0     pid:132   ppid:2      flags:0x00004000
> [ 4230.596294] Workqueue: ipv6_addrconf addrconf_verify_work
> [ 4230.596305] Call Trace:
> [ 4230.596310]  <TASK>
> [ 4230.596317]  __schedule+0x6c3/0x727
> [ 4230.596330]  ? update_load_avg+0x43/0x3ba
> [ 4230.596340]  schedule+0x8b/0xbc
> [ 4230.596349]  schedule_preempt_disabled+0x11/0x1d
> [ 4230.596359]  __mutex_lock.constprop.0+0x18b/0x291
> [ 4230.596367]  addrconf_verify_work+0xe/0x20

This is just a worker trying to acquire RTNL.

> [ 4230.596506] INFO: task NetworkManager:3153 blocked for more than 120 seconds.
> [ 4230.596507]       Tainted: G     U             6.6.4-amd64-preempt-sysrq-20231203 #5
> [ 4230.596508] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 4230.596509] task:NetworkManager  state:D stack:0     pid:3153  ppid:1      flags:0x00000002
> [ 4230.596511] Call Trace:
> [ 4230.596512]  <TASK>
> [ 4230.596513]  __schedule+0x6c3/0x727
> [ 4230.596515]  schedule+0x8b/0xbc
> [ 4230.596517]  schedule_preempt_disabled+0x11/0x1d
> [ 4230.596519]  __mutex_lock.constprop.0+0x18b/0x291
> [ 4230.596521]  nl80211_prepare_wdev_dump+0x8b/0x19f [cfg80211 7e4322db9148b7482d4806580d3e58073444690f]

This is just wireless trying to acquire the RTNL on behalf of NM.

> [ 4230.596743] INFO: task ThreadPoolForeg:9425 blocked for more than 120 seconds.
> [ 4230.596745]       Tainted: G     U             6.6.4-amd64-preempt-sysrq-20231203 #5
> [ 4230.596745] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 4230.596746] task:ThreadPoolForeg state:D stack:0     pid:9425  ppid:9416   flags:0x00000002
> [ 4230.596748] Call Trace:
> [ 4230.596749]  <TASK>
> [ 4230.596750]  __schedule+0x6c3/0x727
> [ 4230.596752]  schedule+0x8b/0xbc
> [ 4230.596754]  schedule_preempt_disabled+0x11/0x1d
> [ 4230.596756]  __mutex_lock.constprop.0+0x18b/0x291
> [ 4230.596758]  ? __pfx_ioctl_standard_call+0x40/0x40
> [ 4230.596760]  ? __pfx_ioctl_private_call+0x40/0x40
> [ 4230.596762]  wext_ioctl_dispatch+0x4b/0x1a7

I don't know why something should be using wireless extensions, but same
thing. Also wext is going away for WiFi7 devices. ;)

> [ 4230.596890] INFO: task ethtool:20272 blocked for more than 120 seconds.
> [ 4230.596891]       Tainted: G     U             6.6.4-amd64-preempt-sysrq-20231203 #5
> [ 4230.596892] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> [ 4230.596893] task:ethtool         state:D stack:0     pid:20272 ppid:1      flags:0x00004006
> [ 4230.596894] Call Trace:
> [ 4230.596895]  <TASK>
> [ 4230.596896]  __schedule+0x6c3/0x727
> [ 4230.596899]  schedule+0x8b/0xbc
> [ 4230.596900]  schedule_preempt_disabled+0x11/0x1d
> [ 4230.596902]  __mutex_lock.constprop.0+0x18b/0x291
> [ 4230.596904]  ? __pfx_pci_pm_runtime_resume+0x40/0x40
> [ 4230.596908]  igc_resume+0x18b/0x1ca [igc 33cdaa7f35d000f01945bed5e87cab1e358c8327]
> [ 4230.596916]  __rpm_callback+0x7a/0xe7
> [ 4230.596919]  rpm_callback+0x35/0x64
> [ 4230.596921]  ? __pfx_pci_pm_runtime_resume+0x40/0x40
> [ 4230.596922]  rpm_resume+0x342/0x44a
> [ 4230.596924]  ? dev_get_by_name_rcu+0x25/0x41
> [ 4230.596926]  ? dev_get_by_name+0x3c/0x4a
> [ 4230.596928]  __pm_runtime_resume+0x5a/0x7a
> [ 4230.596930]  ethnl_ops_begin+0x2c/0x8d

This one's still the problem, so I guess my 2-line hack didn't do
anything.

[snip rest, they're all just waiting for RTNL]

johannes
_______________________________________________
Intel-wired-lan mailing list
Intel-wired-lan@osuosl.org
https://lists.osuosl.org/mailman/listinfo/intel-wired-lan