[OpenWrt-Devel] atomic sleep bugs - 19.07 (and probably Master too)
Koen Vandeputte
koen.vandeputte at ncentric.com
Thu Aug 1 11:27:34 EDT 2019
Hi All,
I've been playing around the last few days stresstesting latest 19.07 on
different targets (ar71xx, cns3xxx, imx6, ...) with extra kernel debug
features enabled.
I'll post some results here as maybe somebody has a clue. :)
Some interesting splats already showed up, actually also *breaking* some
functionality while the board is running:
on Mikrotik RB2011 (ar71xx)
[ 16.885207] eth0: link down
[ 16.919752] BUG: sleeping function called from invalid context at
net/core/dev.c:5563
[ 17.013669] in_atomic(): 1, irqs_disabled(): 1, pid: 463, name: ip
[ 17.087839] 2 locks held by ip/463:
[ 17.129668] #0: (rtnl_mutex){....}, at: [<80378814>]
rtnetlink_rcv_msg+0x2d8/0x380
[ 17.222617] #1: (&(&ag->lock)->rlock){....}, at: [<80331900>]
ag71xx_hw_disable+0x24/0x94
[ 17.322878] CPU: 0 PID: 463 Comm: ip Not tainted 4.14.134 #0
[ 17.390782] Stack : 805e0000 8058aefc 80558ed0 876278ec 80610000
80610000 87d1b2fc 805b7367
[ 17.491032] 80552f04 000001cf 8061386c 87627ccc 87d5b180
00000001 876278a0 6ae07578
[ 17.591283] 00000000 00000000 80b00000 8762779c 0a55a891
00000000 00000007 00000000
[ 17.691535] 00000099 8f9b5648 00000098 00000000 80000000
87d6e58c 87d6e5b0 00000001
[ 17.791785] 8047095c 87627ccc 87d5b180 87d9ae10 00000003
802cfa54 00000000 80610000
[ 17.892036] ...
[ 17.921352] Call Trace:
[ 17.950676] [<8006cb0c>] show_stack+0x58/0x100
[ 18.003996] [<800aadf4>] ___might_sleep+0x100/0x120
[ 18.062512] [<8035d7f4>] napi_disable+0x30/0xd8
[ 18.116854] [<80331940>] ag71xx_hw_disable+0x64/0x94
[ 18.176421] [<80331994>] ag71xx_stop+0x24/0x38
[ 18.229729] [<8035b1f0>] __dev_close_many+0xcc/0x104
[ 18.289306] [<8036426c>] __dev_change_flags+0xc8/0x1ac
[ 18.350950] [<80364378>] dev_change_flags+0x28/0x70
[ 18.409473] [<80377c30>] do_setlink+0x31c/0x91c
[ 18.463826] [<8037a700>] rtnl_newlink+0x3ec/0x7f8
[ 18.520261] [<80378838>] rtnetlink_rcv_msg+0x2fc/0x380
[ 18.581938] [<8039bac4>] netlink_rcv_skb+0xd4/0x178
[ 18.640439] [<8039b0a0>] netlink_unicast+0x168/0x250
[ 18.700006] [<8039b664>] netlink_sendmsg+0x3d8/0x434
[ 18.759580] [<803404a4>] ___sys_sendmsg+0x1dc/0x290
[ 18.818098] [<80341500>] __sys_sendmsg+0x54/0x84
[ 18.873504] [<8007212c>] syscall_common+0x34/0x58
on Mikrotik RB-912 (ar71xx), using ath9k combined with a USB modem
together. When disabling ath9k or unplugging the modem, these bugs
don't appear
Here, the USB modem stops receiving data after a few seconds:
[ 37.165493] wlan0: Trigger new scan to find an IBSS to join
[ 37.171546] BUG: sleeping function called from invalid context at
kernel/irq/manage.c:112
[ 37.180006] in_atomic(): 1, irqs_disabled(): 1, pid: 9, name:
kworker/u2:1
[ 37.187110] 6 locks held by kworker/u2:1/9:
[ 37.191434] #0: ("%s"wiphy_name(local->hw.wiphy)){....}, at:
[<8009f89c>] process_one_work+0x250/0x4c0
[ 37.201298] #1: ((&sdata->work)){....}, at: [<8009f89c>]
process_one_work+0x250/0x4c0
[ 37.209604] #2: (&wdev->mtx){....}, at: [<82917130>]
ieee80211_ibss_work+0x40/0x5a4 [mac80211]
[ 37.219077] #3: (&local->mtx){....}, at: [<8290d914>]
ieee80211_request_ibss_scan+0x4c/0x2b8 [mac80211]
[ 37.229246] #4: (&sc->mutex){....}, at: [<82ae4878>]
ath9k_ps_restore+0xd54/0x11dc [ath9k]
[ 37.238159] #5: (&irq_desc_lock_class){....}, at: [<800c29d8>]
__irq_get_desc_lock+0x8c/0xb0
[ 37.247113] CPU: 0 PID: 9 Comm: kworker/u2:1 Tainted: G W
4.14.134 #0
[ 37.255282] Workqueue: phy0 ieee80211_ibss_leave [mac80211]
[ 37.261055] Stack : 82870080 82870158 82860d60 800c0fa0 80610000
00000000 00000001 805b0000
[ 37.269743] 80552e7c 8384db24 00000348 800c1e04 82860d60
00000000 8384db00 21bc325c
[ 37.278434] 00000000 00000000 00000006 8384d9d4 acbbbd0d
00000000 00000007 00000000
[ 37.287125] 00000132 805c0000 00000131 00000000 00000000
828626d8 828703c8 00000348
[ 37.295816] 82870080 82870158 82860d60 828703c8 00000002
802cfa54 00000000 80610000
[ 37.304508] ...
[ 37.307055] Call Trace:
[ 37.309601] [<8006cb0c>] show_stack+0x58/0x100
[ 37.314219] [<800aadf4>] ___might_sleep+0x100/0x120
[ 37.319280] [<800c3344>] synchronize_irq+0x3c/0xa0
[ 37.324245] [<800c6594>] __irq_disable+0x64/0xb4
[ 37.329024] [<800c35f4>] __disable_irq_nosync+0x3c/0x68
[ 37.334434] [<800c363c>] disable_irq+0x14/0x38
[ 37.339195] [<82ae5b48>] ath9k_calculate_summary_state+0x53c/0x6f4
[ath9k]
[ 37.357669] ttyS ttyS0: 1 input overrun(s)
[ 38.170588] BUG: sleeping function called from invalid context at
kernel/irq/manage.c:112
[ 38.179059] in_atomic(): 1, irqs_disabled(): 1, pid: 9, name:
kworker/u2:1
[ 38.186167] 5 locks held by kworker/u2:1/9:
[ 38.190492] #0: ("%s"wiphy_name(local->hw.wiphy)){....}, at:
[<8009f89c>] process_one_work+0x250/0x4c0
[ 38.200365] #1: ((&(&local->scan_work)->work)){....}, at:
[<8009f89c>] process_one_work+0x250/0x4c0
[ 38.209925] #2: (&local->mtx){....}, at: [<8290d338>]
ieee80211_scan_work+0x44/0x578 [mac80211]
[ 38.219497] #3: (&sc->mutex){....}, at: [<82ae4878>]
ath9k_ps_restore+0xd54/0x11dc [ath9k]
[ 38.228410] #4: (&irq_desc_lock_class){....}, at: [<800c29d8>]
__irq_get_desc_lock+0x8c/0xb0
[ 38.237363] CPU: 0 PID: 9 Comm: kworker/u2:1 Tainted: G W
4.14.134 #0
[ 38.245533] Workqueue: phy0 ieee80211_scan_work [mac80211]
[ 38.251224] Stack : 82870080 82870158 82860d60 800c0fa0 80610000
00000000 00000001 805b0000
[ 38.259912] 80552e7c 8384db94 000003c0 800c1e04 82860d60
00000000 8384db70 21bc325c
[ 38.268604] 00000000 00000000 00000005 8384da44 1c85fff7
00000000 00000007 00000000
[ 38.277295] 0000014b 805c0000 0000014a 00000000 00000000
828626d8 82870440 000003c0
[ 38.285986] 82870080 82870158 82860d60 82870440 00000001
802cfa54 00000000 80610000
[ 38.294677] ...
[ 38.297223] Call Trace:
[ 38.299762] [<8006cb0c>] show_stack+0x58/0x100
[ 38.304381] [<800aadf4>] ___might_sleep+0x100/0x120
[ 38.309440] [<800c3344>] synchronize_irq+0x3c/0xa0
[ 38.314406] [<800c6594>] __irq_disable+0x64/0xb4
[ 38.319184] [<800c35f4>] __disable_irq_nosync+0x3c/0x68
[ 38.324595] [<800c363c>] disable_irq+0x14/0x38
[ 38.329355] [<82ae5b48>] ath9k_calculate_summary_state+0x53c/0x6f4
[ath9k]
[ 39.210598] BUG: sleeping function called from invalid context at
kernel/irq/manage.c:112
[ 39.219073] in_atomic(): 1, irqs_disabled(): 1, pid: 9, name:
kworker/u2:1
[ 39.226182] 5 locks held by kworker/u2:1/9:
[ 39.230506] #0: ("%s"wiphy_name(local->hw.wiphy)){....}, at:
[<8009f89c>] process_one_work+0x250/0x4c0
[ 39.240379] #1: ((&(&local->scan_work)->work)){....}, at:
[<8009f89c>] process_one_work+0x250/0x4c0
[ 39.249940] #2: (&local->mtx){....}, at: [<8290d338>]
ieee80211_scan_work+0x44/0x578 [mac80211]
[ 39.259519] #3: (&sc->mutex){....}, at: [<82ae4878>]
ath9k_ps_restore+0xd54/0x11dc [ath9k]
[ 39.268434] #4: (&irq_desc_lock_class){....}, at: [<800c29d8>]
__irq_get_desc_lock+0x8c/0xb0
[ 39.277386] CPU: 0 PID: 9 Comm: kworker/u2:1 Tainted: G W
4.14.134 #0
[ 39.285555] Workqueue: phy0 ieee80211_scan_work [mac80211]
[ 39.291238] Stack : 82870080 82870158 82860d60 800c0fa0 80610000
00000000 00000001 805b0000
[ 39.299927] 80552e7c 8384db94 00000444 800c1e04 82860d60
00000000 8384db70 21bc325c
[ 39.308618] 00000000 00000000 00000005 8384da44 1c85fff7
00000000 00000007 00000000
[ 39.317309] 00000163 805c0000 00000162 00000000 00000000
828626d8 828704c4 00000444
[ 39.326000] 82870080 82870158 82860d60 828704c4 00000001
802cfa54 00000000 80610000
[ 39.334691] ...
[ 39.337238] Call Trace:
[ 39.339786] [<8006cb0c>] show_stack+0x58/0x100
[ 39.344404] [<800aadf4>] ___might_sleep+0x100/0x120
[ 39.349464] [<800c3344>] synchronize_irq+0x3c/0xa0
[ 39.354428] [<800c6594>] __irq_disable+0x64/0xb4
[ 39.359207] [<800c35f4>] __disable_irq_nosync+0x3c/0x68
[ 39.364618] [<800c363c>] disable_irq+0x14/0x38
[ 39.369377] [<82ae5b48>] ath9k_calculate_summary_state+0x53c/0x6f4
[ath9k]
[ 39.379637] ttyS ttyS0: 2 input overrun(s)
[ 44.124920] wlan0: Trigger new scan to find an IBSS to join
[ 44.130870] BUG: sleeping function called from invalid context at
kernel/irq/manage.c:112
[ 44.139328] in_atomic(): 1, irqs_disabled(): 1, pid: 5, name:
kworker/u2:0
[ 44.146431] 6 locks held by kworker/u2:0/5:
[ 44.150755] #0: ("%s"wiphy_name(local->hw.wiphy)){....}, at:
[<8009f89c>] process_one_work+0x250/0x4c0
[ 44.160620] #1: ((&sdata->work)){....}, at: [<8009f89c>]
process_one_work+0x250/0x4c0
[ 44.168925] #2: (&wdev->mtx){....}, at: [<82917130>]
ieee80211_ibss_work+0x40/0x5a4 [mac80211]
[ 44.178408] #3: (&local->mtx){....}, at: [<8290d914>]
ieee80211_request_ibss_scan+0x4c/0x2b8 [mac80211]
[ 44.188576] #4: (&sc->mutex){....}, at: [<82ae4878>]
ath9k_ps_restore+0xd54/0x11dc [ath9k]
[ 44.197490] #5: (&irq_desc_lock_class){....}, at: [<800c29d8>]
__irq_get_desc_lock+0x8c/0xb0
[ 44.206444] CPU: 0 PID: 5 Comm: kworker/u2:0 Tainted: G W
4.14.134 #0
[ 44.214616] Workqueue: phy0 ieee80211_ibss_leave [mac80211]
[ 44.220394] Stack : 82870080 82870158 82860d60 800c0fa0 80610000
00000000 00000001 805b0000
[ 44.229082] 80552e7c 83839b24 00000348 800c1e04 82860d60
00000000 83839b00 21802cc8
[ 44.237773] 00000000 00000000 00000006 838399d4 acbbbd0d
00000000 00000007 00000000
[ 44.246464] 0000017e 805c0000 0000017d 00000000 00000000
828626d8 828703c8 00000348
[ 44.255155] 82870080 82870158 82860d60 828703c8 00000002
802cfa54 00000000 80610000
[ 44.263847] ...
[ 44.266394] Call Trace:
[ 44.268940] [<8006cb0c>] show_stack+0x58/0x100
[ 44.273561] [<800aadf4>] ___might_sleep+0x100/0x120
[ 44.278620] [<800c3344>] synchronize_irq+0x3c/0xa0
[ 44.283584] [<800c6594>] __irq_disable+0x64/0xb4
[ 44.288362] [<800c35f4>] __disable_irq_nosync+0x3c/0x68
[ 44.293765] [<800c363c>] disable_irq+0x14/0x38
[ 44.298526] [<82ae5b48>] ath9k_calculate_summary_state+0x53c/0x6f4
[ath9k]
[ 44.315077] ttyS ttyS0: 1 input overrun(s)
[ 45.130588] BUG: sleeping function called from invalid context at
kernel/irq/manage.c:112
[ 45.139061] in_atomic(): 1, irqs_disabled(): 1, pid: 5, name:
kworker/u2:0
[ 45.146171] 5 locks held by kworker/u2:0/5:
[ 45.150495] #0: ("%s"wiphy_name(local->hw.wiphy)){....}, at:
[<8009f89c>] process_one_work+0x250/0x4c0
[ 45.160368] #1: ((&(&local->scan_work)->work)){....}, at:
[<8009f89c>] process_one_work+0x250/0x4c0
[ 45.169927] #2: (&local->mtx){....}, at: [<8290d338>]
ieee80211_scan_work+0x44/0x578 [mac80211]
[ 45.179499] #3: (&sc->mutex){....}, at: [<82ae4878>]
ath9k_ps_restore+0xd54/0x11dc [ath9k]
[ 45.188412] #4: (&irq_desc_lock_class){....}, at: [<800c29d8>]
__irq_get_desc_lock+0x8c/0xb0
[ 45.197366] CPU: 0 PID: 5 Comm: kworker/u2:0 Tainted: G W
4.14.134 #0
[ 45.205535] Workqueue: phy0 ieee80211_scan_work [mac80211]
[ 45.211226] Stack : 82870080 82870158 82860d60 800c0fa0 80610000
00000000 00000001 805b0000
[ 45.219914] 80552e7c 83839b94 000003c0 800c1e04 82860d60
00000000 83839b70 21802cc8
[ 45.228606] 00000000 00000000 00000005 83839a44 1c85fff7
00000000 00000007 00000000
[ 45.237297] 00000197 805c0000 00000196 00000000 00000000
828626d8 82870440 000003c0
[ 45.245988] 82870080 82870158 82860d60 82870440 00000001
802cfa54 00000000 80610000
[ 45.254680] ...
[ 45.257226] Call Trace:
[ 45.259764] [<8006cb0c>] show_stack+0x58/0x100
[ 45.264384] [<800aadf4>] ___might_sleep+0x100/0x120
[ 45.269444] [<800c3344>] synchronize_irq+0x3c/0xa0
[ 45.274408] [<800c6594>] __irq_disable+0x64/0xb4
[ 45.279187] [<800c35f4>] __disable_irq_nosync+0x3c/0x68
[ 45.284598] [<800c363c>] disable_irq+0x14/0x38
[ 45.289357] [<82ae5b48>] ath9k_calculate_summary_state+0x53c/0x6f4
[ath9k]
[ 46.170598] BUG: sleeping function called from invalid context at
kernel/irq/manage.c:112
[ 46.179076] in_atomic(): 1, irqs_disabled(): 1, pid: 5, name:
kworker/u2:0
[ 46.186184] 5 locks held by kworker/u2:0/5:
[ 46.190509] #0: ("%s"wiphy_name(local->hw.wiphy)){....}, at:
[<8009f89c>] process_one_work+0x250/0x4c0
[ 46.200382] #1: ((&(&local->scan_work)->work)){....}, at:
[<8009f89c>] process_one_work+0x250/0x4c0
[ 46.209942] #2: (&local->mtx){....}, at: [<8290d338>]
ieee80211_scan_work+0x44/0x578 [mac80211]
[ 46.219522] #3: (&sc->mutex){....}, at: [<82ae4878>]
ath9k_ps_restore+0xd54/0x11dc [ath9k]
[ 46.228435] #4: (&irq_desc_lock_class){....}, at: [<800c29d8>]
__irq_get_desc_lock+0x8c/0xb0
[ 46.237389] CPU: 0 PID: 5 Comm: kworker/u2:0 Tainted: G W
4.14.134 #0
[ 46.245559] Workqueue: phy0 ieee80211_scan_work [mac80211]
[ 46.251249] Stack : 82870080 82870158 82860d60 800c0fa0 80610000
00000000 00000001 805b0000
[ 46.259938] 80552e7c 83839b94 00000444 800c1e04 82860d60
00000000 83839b70 21802cc8
[ 46.268629] 00000000 00000000 00000005 83839a44 1c85fff7
00000000 00000007 00000000
[ 46.277320] 000001af 805c0000 000001ae 00000000 00000000
828626d8 828704c4 00000444
[ 46.286011] 82870080 82870158 82860d60 828704c4 00000001
802cfa54 00000000 80610000
[ 46.294702] ...
[ 46.297249] Call Trace:
[ 46.299787] [<8006cb0c>] show_stack+0x58/0x100
[ 46.304406] [<800aadf4>] ___might_sleep+0x100/0x120
[ 46.309466] [<800c3344>] synchronize_irq+0x3c/0xa0
[ 46.314431] [<800c6594>] __irq_disable+0x64/0xb4
[ 46.319209] [<800c35f4>] __disable_irq_nosync+0x3c/0x68
[ 46.324620] [<800c363c>] disable_irq+0x14/0x38
[ 46.329379] [<82ae5b48>] ath9k_calculate_summary_state+0x53c/0x6f4
[ath9k]
[ 46.339657] ttyS ttyS0: 2 input overrun(s)
[ 46.579616] wlan0: Creating new IBSS network, BSSID c8:a9:46:87:7d:ad
cns3xxx;
None so far ..
imx6:
None so far
Regards,
Koen
_______________________________________________
openwrt-devel mailing list
openwrt-devel at lists.openwrt.org
https://lists.openwrt.org/mailman/listinfo/openwrt-devel
More information about the openwrt-devel
mailing list