netdev - Re: [RFC PATCH] net: ethtool: do runtime PM outside RTNL

lists.openwall.net		lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC
Open Source and information security mailing list archives

Hash Suite: Windows password security audit tool. GUI, reports in PDF.

[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]

Message-ID: <24577c9b8b4d398fe34bd756354c33b80cf67720.camel@sipsolutions.net>
Date: Mon, 04 Dec 2023 21:40:08 +0100
From: Johannes Berg <johannes@...solutions.net>
To: Marc MERLIN <marc@...lins.org>
Cc: netdev@...r.kernel.org, Jesse Brandeburg <jesse.brandeburg@...el.com>, 
 Tony Nguyen <anthony.l.nguyen@...el.com>, intel-wired-lan@...ts.osuosl.org,
 Heiner Kallweit <hkallweit1@...il.com>
Subject: Re: [RFC PATCH] net: ethtool: do runtime PM outside RTNL

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