HANG/SLUGGISHNESS: IBSS mode on MT7612u on 64bit Raspberry Pi 4B

Setup:

• Single MT7612u Dongle from Alfa networks AWUS036ACM.
• Centos Stream 8 64 bit
• Kernel 5.10.37 - cannot yet move to 5.12 because of a USB Quirk fix in the XHCI driver for the VL805 PCIe<->USB3 chip
• Problem happens quite fast on CentOS + 5.10.39 kernel (minutes) (any kernel from 5.10.29 .. 33 and 39 t
• Single PI, NO other node advertising this SSID
• 'connection' not always happens between two nodes, but if they do connect then this problem doesn't happen. (but it will after one drops off)

Setup script:

batsetup.txt

After a few minutes with the pi being the single IBSS node, dmesg starts showing

[ 1088.628176] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[ 1120.149823] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[ 1156.307194] wlan1: No active IBSS STAs - trying to scan for other IBSS networks with same SSID (merge)
[ 1156.979268] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[ 1188.484350] brcmfmac: brcmf_cfg80211_set_power_mgmt: power save enabled
[ 1224.712315] wlan1: No active IBSS STAs - trying to scan for other IBSS networks with same SSID (merge)
[ 1450.996425] INFO: task kworker/u8:1:72 blocked for more than 120 seconds.
[ 1451.004028] Tainted: G C 5.10.39-v8.1.el8 #1
[ 1451.010928] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1451.019624] task:kworker/u8:1 state:D stack: 0 pid: 72 ppid: 2 flags:0x00000028
[ 1451.029090] Workqueue: phy0 ieee80211_iface_work [mac80211]
[ 1451.035572] Call trace:
[ 1451.038914] __switch_to+0x108/0x160
[ 1451.043376] __schedule+0x2d0/0x818
[ 1451.047703] schedule+0x48/0x100
[ 1451.051799] schedule_timeout+0x2e4/0x370
[ 1451.056675] wait_for_completion+0x88/0x118
[ 1451.061607] __flush_work.isra.48+0x10c/0x240
[ 1451.066677] __cancel_work_timer+0x148/0x1b8
[ 1451.071637] cancel_work_sync+0x1c/0x28
[ 1451.076151] mt76x02u_stop_pre_tbtt_timer+0x38/0x58 [mt76x02_usb]
[ 1451.082976] mt76x02u_pre_tbtt_enable+0x20/0x78 [mt76x02_usb]
[ 1451.089435] mt76x02_mac_set_beacon_enable+0x44/0x430 [mt76x02_lib]
[ 1451.096410] mt76x02_bss_info_changed+0xec/0x120 [mt76x02_lib]
[ 1451.103011] ieee80211_bss_info_change_notify+0x98/0x260 [mac80211]
[ 1451.110041] ieee80211_offchannel_stop_vifs+0x178/0x1a0 [mac80211]
[ 1451.116951] __ieee80211_start_scan+0x300/0x8f8 [mac80211]
[ 1451.123148] ieee80211_request_ibss_scan+0xf8/0x1e8 [mac80211]
[ 1451.129677] ieee80211_ibss_work+0x3f4/0x540 [mac80211]
[ 1451.135592] ieee80211_iface_work+0x228/0x360 [mac80211]
[ 1451.141534] process_one_work+0x1f4/0x4d8
[ 1451.146135] worker_thread+0x50/0x480
[ 1451.150385] kthread+0x148/0x158
[ 1451.154212] ret_from_fork+0x10/0x30
[ 1451.158383] INFO: task Schedule-1:725 blocked for more than 120 seconds.
[ 1451.165683] Tainted: G C 5.10.39-v8.1.el8 #1
[ 1451.172348] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1451.180783] task:Schedule-1 state:D stack: 0 pid: 725 ppid: 1 flags:0x00000200
[ 1451.189769] Call trace:
[ 1451.192732] __switch_to+0x108/0x160
[ 1451.196825] __schedule+0x2d0/0x818
[ 1451.200819] schedule+0x48/0x100
[ 1451.204552] schedule_preempt_disabled+0x20/0x38
[ 1451.209698] __mutex_lock.isra.11+0x16c/0x578
[ 1451.214577] __mutex_lock_slowpath+0x1c/0x28
[ 1451.219366] mutex_lock+0x40/0x58
[ 1451.223190] rtnl_lock+0x20/0x30
[ 1451.226918] sock_do_ioctl+0x214/0x2d0
[ 1451.231176] sock_ioctl+0x328/0x528
[ 1451.235176] __arm64_sys_ioctl+0xb0/0xf0
[ 1451.239611] el0_svc_common.constprop.2+0x9c/0x1a0
[ 1451.244922] do_el0_svc+0x2c/0x98
[ 1451.248731] el0_svc+0x20/0x30
[ 1451.252262] el0_sync_handler+0x90/0xb8
[ 1451.256592] el0_sync+0x160/0x180
[ 1451.260366] INFO: task Schedule-2:726 blocked for more than 121 seconds.
[ 1451.267594] Tainted: G C 5.10.39-v8.1.el8 #1
[ 1451.274209] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1451.282609] task:Schedule-2 state:D stack: 0 pid: 726 ppid: 1 flags:0x00000200
[ 1451.291611] Call trace:
[ 1451.294553] __switch_to+0x108/0x160
[ 1451.298639] __schedule+0x2d0/0x818
[ 1451.302647] schedule+0x48/0x100
[ 1451.306381] schedule_preempt_disabled+0x20/0x38
[ 1451.311524] __mutex_lock.isra.11+0x16c/0x578
[ 1451.316402] __mutex_lock_slowpath+0x1c/0x28
[ 1451.321166] mutex_lock+0x40/0x58
[ 1451.324941] rtnl_lock+0x20/0x30
[ 1451.328620] sock_do_ioctl+0x214/0x2d0
[ 1451.332822] sock_ioctl+0x328/0x528
[ 1451.336766] __arm64_sys_ioctl+0xb0/0xf0
[ 1451.341161] el0_svc_common.constprop.2+0x9c/0x1a0
[ 1451.346443] do_el0_svc+0x2c/0x98
[ 1451.350224] el0_svc+0x20/0x30
[ 1451.353724] el0_sync_handler+0x90/0xb8
[ 1451.358024] el0_sync+0x160/0x180
[ 1451.361795] INFO: task I/O Events:916 blocked for more than 121 seconds.
[ 1451.369016] Tainted: G C 5.10.39-v8.1.el8 #1
[ 1451.375628] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1451.384013] task:I/O Events state:D stack: 0 pid: 916 ppid: 1 flags:0x00000200
[ 1451.392957] Call trace:
[ 1451.395882] __switch_to+0x108/0x160
[ 1451.399980] __schedule+0x2d0/0x818
[ 1451.403989] schedule+0x48/0x100
[ 1451.407734] schedule_preempt_disabled+0x20/0x38
[ 1451.412905] __mutex_lock.isra.11+0x16c/0x578
[ 1451.417800] __mutex_lock_slowpath+0x1c/0x28
[ 1451.422564] mutex_lock+0x40/0x58
[ 1451.426340] rtnl_lock+0x20/0x30
[ 1451.430034] sock_do_ioctl+0x214/0x2d0
[ 1451.434248] sock_ioctl+0x328/0x528
[ 1451.438199] __arm64_sys_ioctl+0xb0/0xf0
[ 1451.442582] el0_svc_common.constprop.2+0x9c/0x1a0
[ 1451.447854] do_el0_svc+0x2c/0x98
[ 1451.451632] el0_svc+0x20/0x30
[ 1451.455150] el0_sync_handler+0x90/0xb8
[ 1451.459456] el0_sync+0x160/0x180
[ 1451.463251] INFO: task kworker/1:2H:12706 blocked for more than 121 seconds.
[ 1451.470821] Tainted: G C 5.10.39-v8.1.el8 #1
[ 1451.477434] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1451.485831] task:kworker/1:2H state:D stack: 0 pid:12706 ppid: 2 flags:0x00000228
[ 1451.494804] Workqueue: events_highpri mt76x02u_pre_tbtt_work [mt76x02_usb]
[ 1451.502265] Call trace:
[ 1451.505228] __switch_to+0x108/0x160
[ 1451.509347] __schedule+0x2d0/0x818
[ 1451.513379] schedule+0x48/0x100
[ 1451.517133] schedule_preempt_disabled+0x20/0x38
[ 1451.522298] __mutex_lock.isra.11+0x16c/0x578
[ 1451.527167] __mutex_lock_slowpath+0x1c/0x28
[ 1451.531935] mutex_lock+0x40/0x58
[ 1451.535828] ieee80211_iterate_interfaces+0x40/0x78 [mac80211]
[ 1451.542200] mt76x02u_pre_tbtt_work+0xe4/0x238 [mt76x02_usb]
[ 1451.548414] process_one_work+0x1f4/0x4d8
[ 1451.552931] worker_thread+0x50/0x480
[ 1451.557099] kthread+0x148/0x158
[ 1451.560823] ret_from_fork+0x10/0x30
[ 1451.564909] INFO: task kworker/0:1:24308 blocked for more than 121 seconds.
[ 1451.572446] Tainted: G C 5.10.39-v8.1.el8 #1
[ 1451.579132] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1451.587579] task:kworker/0:1 state:D stack: 0 pid:24308 ppid: 2 flags:0x00000228
[ 1451.596615] Workqueue: ipv6_addrconf addrconf_verify_work [ipv6]
[ 1451.603235] Call trace:
[ 1451.606239] __switch_to+0x108/0x160
[ 1451.610423] __schedule+0x2d0/0x818
[ 1451.614488] schedule+0x48/0x100
[ 1451.618275] schedule_preempt_disabled+0x20/0x38
[ 1451.623518] __mutex_lock.isra.11+0x16c/0x578
[ 1451.628460] __mutex_lock_slowpath+0x1c/0x28
[ 1451.633290] mutex_lock+0x40/0x58
[ 1451.637152] rtnl_lock+0x20/0x30
[ 1451.640912] addrconf_verify_work+0x18/0x30 [ipv6]
[ 1451.646246] process_one_work+0x1f4/0x4d8
[ 1451.650763] worker_thread+0x50/0x480
[ 1451.654925] kthread+0x148/0x158
[ 1451.658643] ret_from_fork+0x10/0x30
[ 1451.662734] INFO: task iw:24545 blocked for more than 121 seconds.
[ 1451.669463] Tainted: G C 5.10.39-v8.1.el8 #1
[ 1451.676151] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1451.684605] task:iw state:D stack: 0 pid:24545 ppid: 24544 flags:0x00000200
[ 1451.693603] Call trace:
[ 1451.696585] __switch_to+0x108/0x160
[ 1451.700712] __schedule+0x2d0/0x818
[ 1451.704735] schedule+0x48/0x100
[ 1451.708495] schedule_preempt_disabled+0x20/0x38
[ 1451.713664] __mutex_lock.isra.11+0x16c/0x578
[ 1451.718568] __mutex_lock_slowpath+0x1c/0x28
[ 1451.723371] mutex_lock+0x40/0x58
[ 1451.727298] nl80211_dump_scan+0x74/0x630 [cfg80211]
[ 1451.732795] netlink_dump+0x100/0x2c0
[ 1451.736941] __netlink_dump_start+0x1a0/0x270
[ 1451.741789] genl_family_rcv_msg_dumpit.isra.15+0x84/0x138
[ 1451.747770] genl_rcv_msg+0x1b0/0x228
[ 1451.751902] netlink_rcv_skb+0x64/0x128
[ 1451.756213] genl_rcv+0x40/0x58
[ 1451.759814] netlink_unicast+0x1c0/0x280
[ 1451.764218] netlink_sendmsg+0x1c0/0x3d0
[ 1451.768627] sock_sendmsg+0x54/0x60
[ 1451.772581] ____sys_sendmsg+0x270/0x2b0
[ 1451.776970] ___sys_sendmsg+0x8c/0xd0
[ 1451.781098] __sys_sendmsg+0x74/0xc8
[ 1451.785132] __arm64_sys_sendmsg+0x2c/0x38
[ 1451.789693] el0_svc_common.constprop.2+0x9c/0x1a0
[ 1451.794966] do_el0_svc+0x2c/0x98
[ 1451.798752] el0_svc+0x20/0x30
[ 1451.802250] el0_sync_handler+0x90/0xb8
[ 1451.806540] el0_sync+0x160/0x180
[ 1451.810289] INFO: task ip:24561 blocked for more than 121 seconds.
[ 1451.816947] Tainted: G C 5.10.39-v8.1.el8 #1
[ 1451.823511] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1451.831879] task:ip state:D stack: 0 pid:24561 ppid: 24560 flags:0x00000200
[ 1451.840775] Call trace:
[ 1451.843647] __switch_to+0x108/0x160
[ 1451.847682] __schedule+0x2d0/0x818
[ 1451.851627] schedule+0x48/0x100
[ 1451.855305] schedule_preempt_disabled+0x20/0x38
[ 1451.860414] __mutex_lock.isra.11+0x16c/0x578
[ 1451.865245] __mutex_lock_slowpath+0x1c/0x28
[ 1451.869976] mutex_lock+0x40/0x58
[ 1451.873737] __netlink_dump_start+0x98/0x270
[ 1451.878462] rtnetlink_rcv_msg+0x250/0x340
[ 1451.883012] netlink_rcv_skb+0x64/0x128
[ 1451.887291] rtnetlink_rcv+0x20/0x30
[ 1451.891314] netlink_unicast+0x1c0/0x280
[ 1451.895679] netlink_sendmsg+0x1c0/0x3d0
[ 1451.900045] sock_sendmsg+0x54/0x60
[ 1451.903969] __sys_sendto+0xdc/0x148
[ 1451.907981] __arm64_sys_sendto+0x30/0x40
[ 1451.912440] el0_svc_common.constprop.2+0x9c/0x1a0
[ 1451.917702] do_el0_svc+0x2c/0x98
[ 1451.921463] el0_svc+0x20/0x30
[ 1451.924947] el0_sync_handler+0x90/0xb8
[ 1451.929230] el0_sync+0x160/0x180
[ 1573.878792] INFO: task kworker/u8:1:72 blocked for more than 243 seconds.
[ 1573.886113] Tainted: G C 5.10.39-v8.1.el8 #1
[ 1573.892993] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1573.901393] task:kworker/u8:1 state:D stack: 0 pid: 72 ppid: 2 flags:0x00000028
[ 1573.910415] Workqueue: phy0 ieee80211_iface_work [mac80211]
[ 1573.916527] Call trace:
[ 1573.919452] __switch_to+0x108/0x160
[ 1573.923497] __schedule+0x2d0/0x818
[ 1573.927457] schedule+0x48/0x100
[ 1573.931149] schedule_timeout+0x2e4/0x370
[ 1573.935634] wait_for_completion+0x88/0x118
[ 1573.940284] __flush_work.isra.48+0x10c/0x240
[ 1573.945125] __cancel_work_timer+0x148/0x1b8
[ 1573.949864] cancel_work_sync+0x1c/0x28
[ 1573.954175] mt76x02u_stop_pre_tbtt_timer+0x38/0x58 [mt76x02_usb]
[ 1573.960787] mt76x02u_pre_tbtt_enable+0x20/0x78 [mt76x02_usb]
[ 1573.967056] mt76x02_mac_set_beacon_enable+0x44/0x430 [mt76x02_lib]
[ 1573.973858] mt76x02_bss_info_changed+0xec/0x120 [mt76x02_lib]
[ 1573.980267] ieee80211_bss_info_change_notify+0x98/0x260 [mac80211]
[ 1573.987125] ieee80211_offchannel_stop_vifs+0x178/0x1a0 [mac80211]
[ 1573.993889] __ieee80211_start_scan+0x300/0x8f8 [mac80211]
[ 1573.999962] ieee80211_request_ibss_scan+0xf8/0x1e8 [mac80211]
[ 1574.006391] ieee80211_ibss_work+0x3f4/0x540 [mac80211]
[ 1574.012208] ieee80211_iface_work+0x228/0x360 [mac80211]
[ 1574.018081] process_one_work+0x1f4/0x4d8
[ 1574.022623] worker_thread+0x50/0x480
[ 1574.026815] kthread+0x148/0x158
[ 1574.030557] ret_from_fork+0x10/0x30
[ 1574.034689] INFO: task Schedule-1:725 blocked for more than 243 seconds.
[ 1574.041998] Tainted: G C 5.10.39-v8.1.el8 #1
[ 1574.048674] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1574.057140] task:Schedule-1 state:D stack: 0 pid: 725 ppid: 1 flags:0x00000200
[ 1574.066145] Call trace:
[ 1574.069139] __switch_to+0x108/0x160
[ 1574.073257] __schedule+0x2d0/0x818
[ 1574.077256] schedule+0x48/0x100
[ 1574.080982] schedule_preempt_disabled+0x20/0x38
[ 1574.086130] __mutex_lock.isra.11+0x16c/0x578
[ 1574.091018] __mutex_lock_slowpath+0x1c/0x28
[ 1574.095810] mutex_lock+0x40/0x58
[ 1574.099635] rtnl_lock+0x20/0x30
[ 1574.103369] sock_do_ioctl+0x214/0x2d0
[ 1574.107632] sock_ioctl+0x328/0x528
[ 1574.111637] __arm64_sys_ioctl+0xb0/0xf0
[ 1574.116080] el0_svc_common.constprop.2+0x9c/0x1a0
[ 1574.121402] do_el0_svc+0x2c/0x98
[ 1574.125218] el0_svc+0x20/0x30
[ 1574.128761] el0_sync_handler+0x90/0xb8
[ 1574.133097] el0_sync+0x160/0x180

iw dev usually hangs after this, reboot doesn't work, and also I have had issues with sudo

This behavior happens as well with a Ubuntu 21.04 for the Raspberry Pi, but it takes MUCH (hours) longer. I have had a single IBSS node setup running on an AMD machine, and it doesn't happen ever, neither with Centos Stream nor Ubuntu on that machine.

I have not been able to compile a 5.12 kernel - nor the variant of this repo as there is a change which requires a 5.12 kernel...

Patch needed for VL805 on Pi

VL805.txt

Is this issue potentially fixed in the current tree?

Reproduce the issue using batsetup.txt on the stated Raspberry Pi and kernel setup, then inspect the IBSS path around ieee80211_ibss_work and mt76x02u_pre_tbtt_work in the reported trace. Done means identifying and resolving the cause of the prolonged blocked tasks during IBSS scanning without introducing regressions.