diff mbox

AMPDU stalls with brcmfmac4366b-pcie.bin triggering WARNINGs

Message ID 20160915114836.12364-1-zajec5@gmail.com (mailing list archive)
State Not Applicable
Delegated to: Kalle Valo
Headers show

Commit Message

Rafał Miłecki Sept. 15, 2016, 11:48 a.m. UTC
On 09/14/2016 08:28 PM, Arend Van Spriel wrote:
> On 14-9-2016 7:45, Rafał Miłecki wrote:
>> Even with the most recent brcmfmac code ppl keep seeing WARNINGs from
>> brcmf_netdev_wait_pend8021x [0].
>>
>> Hante suggested using CONSOLE for debugging some firmware crash so I
>> decided to see I it could also help understanding WARNINGs. I believe it
>> did.
>>
>> First of all, I can't reproduce these problems reliably. One evening I
>> got WARNINGs one by one and I could work on my debugging patch easily.
>> Yesterday when I got my patch complete, it took me 10+ hours to get a
>> single WARNING.
>>
>> Anyway, it seems to me that sometimes AMPDU stalls in the firmware. It
>> seems firmware has some AMPDU watchdog that notices the problem and
>> kicks in. It prints some debugging info and starts cleaning up process.
>>
>> If brcmf_netdev_wait_pend8021x gets called shortly after that (I set
>> wpa_group_rekey=30 in hostapd to get brcmf_cfg80211_add_key called more
>> often) it results in a WARNING.
>>
>> For better debugging I wrote brcmfmac patch that:
>> 1) Keeps track of every 802.1x skb submitted to the device
>> 2) During WARNING it prints skbs and marks them as timedout
>> 3) It informs when timedout skb gets finally reported as sent
>>
>> Enough talking, please take a look at my debugging log. Does it give you
>> enough hint? Could you review/debug firmware's code responsible for
>> AMPDU? FWIW Merlin users (so no brcmfmac invovled) also saw this [1].
>>
>> [  913.569121] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c7369480 brcmf_ifname(ifp):wlan1
>> [  913.579521] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c70cd480 brcmf_ifname(ifp):wlan0
>> [  913.627346] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c71a1480 brcmf_ifname(ifp):wlan1-1
>> [  913.839833] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6464c80 brcmf_ifname(ifp):wlan0-1
>> [  914.179775] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64cac80 brcmf_ifname(ifp):wlan0-2
>> [  914.191129] brcmfmac: CONSOLE: 027644.261 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.198474] brcmfmac: CONSOLE: 027644.266 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.206020] brcmfmac: CONSOLE: 027644.273 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.215243] brcmfmac: CONSOLE: 027644.284 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.224521] brcmfmac: CONSOLE: 027644.294 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.231878] brcmfmac: CONSOLE: 027644.298 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.239425] brcmfmac: CONSOLE: 027644.307 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.248444] brcmfmac: CONSOLE: 027644.318 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.257163] brcmfmac: CONSOLE: 027644.326 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.266616] brcmfmac: CONSOLE: 027644.336 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.274072] brcmfmac: CONSOLE: 027644.341 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.284716] brcmfmac: CONSOLE: 027644.354 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.291962] brcmfmac: CONSOLE: 027644.359 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.299172] brcmfmac: CONSOLE: 027644.364 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.306646] brcmfmac: CONSOLE: 027644.371 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.314058] brcmfmac: CONSOLE: 027644.380 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.323193] brcmfmac: CONSOLE: 027644.393 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.330640] brcmfmac: CONSOLE: 027644.400 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.340886] brcmfmac: CONSOLE: 027644.410 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.352975] brcmfmac: CONSOLE: 027644.422 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.365365] brcmfmac: CONSOLE: 027644.434 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.372790] brcmfmac: CONSOLE: 027644.440 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.384982] brcmfmac: CONSOLE: 027644.454 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.395488] brcmfmac: CONSOLE: 027644.465 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.402977] brcmfmac: CONSOLE: 027644.471 wl0.3: wlc_send_bar: seq 0x3 tid 0
>> [  914.701404] brcmfmac: CONSOLE: 027644.771 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.710513] brcmfmac: CONSOLE: 027644.780 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.717731] brcmfmac: CONSOLE: 027644.787 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.728099] brcmfmac: CONSOLE: 027644.798 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.737616] brcmfmac: CONSOLE: 027644.807 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.745320] brcmfmac: CONSOLE: 027644.815 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.757985] brcmfmac: CONSOLE: 027644.827 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.765457] brcmfmac: CONSOLE: 027644.833 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.772729] brcmfmac: CONSOLE: 027644.841 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.781407] brcmfmac: CONSOLE: 027644.851 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.789268] brcmfmac: CONSOLE: 027644.859 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.796754] brcmfmac: CONSOLE: 027644.866 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.808174] brcmfmac: CONSOLE: 027644.878 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  914.818975] brcmfmac: CONSOLE: 027644.888 wl0.3: wlc_send_bar: seq 0x4 tid 0
>> [  917.077991] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: wl0.3 scb:00347c74 tid:0 
>> [  917.085368] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: wl0.3 dead_cnt 2 tx_in_transit 1 psm_mux 0xfff0 aqmqmap 0x0x101 aqmfifo_status 0x0x4000 fifordy 0x0 cpbusy 0x0
>> [  917.100070] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: ifsstat 0xaf nav_stat 0x0 txop 30788
>> [  917.108303] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: pktpend: 0 2 0 0 0 ap 1
>> [  917.115434] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: txall 5901 txbcn 0 txrts 0 rxcts 0 rsptmout 0 rxstrt 0
>> [  917.125265] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: cwcur0-3 f f 7 3 bslots cur/0-3 9 0 9 0 0 ifs_boff 0
>> [  917.134907] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: again1 ifsstat 0xaf nav_stat 0x0
>> [  917.142806] brcmfmac: CONSOLE: 027647.149 ampdu_dbg: again2 ifsstat 0xaf nav_stat 0x0
>> [  917.150739] brcmfmac: CONSOLE: 027647.149 wl0: wlc_ampdu_watchdog: cleaning up ini tid 0 due to no progress for 2 secs tx_in_transit 1
>> [  917.162912] brcmfmac: CONSOLE: 027647.149 wl0: wlc_ampdu_tx_send_delba: tid 0 initiator 1 reason 39
>> [  917.718723] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6518c80 brcmf_ifname(ifp):wlan1-2
>> [  918.678558] ------------[ cut here ]------------
>> [  918.683329] WARNING: CPU: 1 PID: 1145 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1219 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
>> [  918.699599] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
>> [  918.771954] CPU: 1 PID: 1145 Comm: hostapd Not tainted 4.4.19 #0
>> [  918.777971] Hardware name: BCM5301X
>> [  918.781461] Backtrace: 
>> [  918.783938] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
>> [  918.791523]  r7:000004c3 r6:bf1d0e9c r5:60000013 r4:00000000
>> [  918.797240] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
>> [  918.804480] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
>> [  918.812587]  r5:00000009 r4:00000000
>> [  918.816184] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
>> [  918.824981]  r8:c72f10a4 r7:00000001 r6:c64f7b3c r5:00000000 r4:c6518c80
>> [  918.831764] [<c002153c>] (warn_slowpath_null) from [<bf1be578>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
>> [  918.842243] [<bf1be4bc>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
>> [  918.854870]  r8:c72f10a4 r7:bf1c8613 r6:c6518c80 r5:c04903c8 r4:c72f1394
>> [  918.861641] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad740>] (brcmf_cfg80211_add_key+0x2e0/0x3dc [brcmfmac])
>> [  918.873836]  r7:00000000 r6:c6518c80 r5:c72f10a4 r4:00000004
>> [  918.879578] [<bf1ad460>] (brcmf_cfg80211_add_key [brcmfmac]) from [<bf160b48>] (nl80211_new_key+0xfc/0x128 [cfg80211])
>> [  918.890296]  r10:00000014 r9:c7250800 r8:c64f7ca0 r7:c72de000 r6:c6518800 r5:00000000
>> [  918.898181]  r4:bf1ad460
>> [  918.900751] [<bf160a4c>] (nl80211_new_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
>> [  918.909723]  r8:c5d50300 r7:c658b614 r6:bf170540 r5:bf1787d0 r4:00000000
>> [  918.916482] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
>> [  918.924328]  r10:c5d50300 r9:00000000 r8:c64f7d84 r7:c6b0e400 r6:c0286ce0 r5:c5d50300
>> [  918.932214]  r4:c658b600
>> [  918.934761] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
>> [  918.942258]  r7:c6b0e400 r6:c5d50300 r5:c5d50300 r4:c04a42a0
>> [  918.947965] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
>> [  918.955637]  r5:00000048 r4:c7952000
>> [  918.959236] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
>> [  918.967517]  r9:00000008 r8:00000000 r7:00000048 r6:c64f7f4c r5:c6b0e400 r4:00000000
>> [  918.975324] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
>> [  918.983167]  r10:00000000 r9:00000000 r8:00000000 r7:c7544900 r6:c64f7e64 r5:00000000
>> [  918.991053]  r4:c64f7f4c
>> [  918.993598] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
>> [  919.001529] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
>> [  919.009375]  r10:00000000 r9:c64f6000 r8:c00098c4 r7:00000128 r6:00000000 r5:bee617c0
>> [  919.017260]  r4:c7544900
>> [  919.019807] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
>> [  919.027393]  r6:00003000 r5:00000000 r4:00000000
>> [  919.032046] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
>> [  919.039829] ---[ end trace ab86393507c49518 ]---
>> [  919.044467] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c6518c80 brcmf_ifname(ifp):wlan1-2 brcmf_get_pend_8021x_cnt(ifp):2
>> [  919.055542] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
>> [  919.062956] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c7269780 skb->dev:c6518800 skb->dev->name:wlan1-2
>> [  919.072547] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c72693c0 skb->dev:c6518800 skb->dev->name:wlan1-2
> 
> Hi Rafal,
> 
> Surprised to see those ampdu_dbg messages in official firmware release.

Well, I'm somehow glad they make it into the official firmware. It at least
allowed understanding what causes these delays (A-MPDU issue). They indeed don't
seem to be present in 43602a1 firmware so I can only guess it suffers from the
same problem.


> It would be great to have a timestamp for these skb when they arrive in
> brcmfmac or transferred to firmware (or both).

You ask and you have it :) I saved kernel's local time and printed it the same
way print_time function does it. Let me paste the most important lines:
[ 1876.496770] brcmfmac: CONSOLE: 028605.731 wl0: wlc_ampdu_watchdog: cleaning up ini tid 0 due to no progress for 2 secs tx_in_transit 1
[ 1877.958898] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1
[ 1878.923359] WARNING: CPU: 1 PID: 1140 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1256 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 1880.659840] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1 brcmf_get_pend_8021x_cnt(ifp):3
[ 1880.670922] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 1880.678333] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b18d80 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1880.687935] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b18900 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1880.697530] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c721fc00 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1881.439614] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6b18d80 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1874.928858]; commit_time:[ 1874.928994])
[ 1881.457852] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6b18900 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1875.938806]; commit_time:[ 1875.938858])
[ 1881.476074] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c721fc00 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1876.948805]; commit_time:[ 1876.948855])

For the first skb brcmf_netdev_start_xmit was called at 1874.928858.
It was commited to firmware with brcmf_msgbuf_txflow at 1874.928994.
Then there was A-MPDU hang in firmware.
Finally brcmf_msgbuf_process_txstatus was called and it called
brcmf_txfinalize and this one logged everything at 1881.439614.

You'll find full log at the end.


> The obvious solution would be to increase the pend8021x timeout in
> brcmfmac. Probably another solution would be to exclude EAPOL frames
> from A-MPDU in firmware. That still does not solve the A-MPDU stall.

For me the most obvious solution would be to fix A-MPDU problem in the firmware.
Of course that would require releasing updated firmware and ppl switching to it.
It still sounds like a desired long term solution.

I don't think we want few second stalls in communication with AP. Moreover Hante
seemed to be worried clients can get totally disconnected which would make
things even worse:
> This waiting uses a timeout (950ms) and in this case the timeout expired. It
> will most likely result in a situation where client and AP wont have the same
> keys anymore and eventually the client will disconnect en reconnect.

If xmit of skb was started at 1874.928858 and we got TX status at 1881.439614
that's 6-7 seconds of delay. Quite a lot so I really would prefer a *fix*
instead of workaround hiding the problem.


[ 1874.409157] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6970c80 brcmf_ifname(ifp):wlan1
[ 1874.499840] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c79d5480 brcmf_ifname(ifp):wlan0
[ 1874.579199] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64b0480 brcmf_ifname(ifp):wlan1-2
[ 1874.599201] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c79d0c80 brcmf_ifname(ifp):wlan0-1
[ 1874.719154] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6aac480 brcmf_ifname(ifp):wlan0-2
[ 1876.423494] brcmfmac: CONSOLE: 028605.731 ampdu_dbg: wl0.2 scb:00345ba8 tid:0 
[ 1876.430873] brcmfmac: CONSOLE: 028605.731 ampdu_dbg: wl0.2 dead_cnt 2 tx_in_transit 1 psm_mux 0xfff0 aqmqmap 0x0x101 aqmfifo_status 0x0x4000 fifordy 0x0 cpbusy 0x0
[ 1876.445571] brcmfmac: CONSOLE: 028605.731 ampdu_dbg: ifsstat 0x1d80 nav_stat 0x0 txop 31893
[ 1876.453990] brcmfmac: CONSOLE: 028605.731 ampdu_dbg: pktpend: 0 0 0 0 0 ap 1
[ 1876.461122] brcmfmac: CONSOLE: 028605.731 ampdu_dbg: txall 5836 txbcn 0 txrts 0 rxcts 0 rsptmout 0 rxstrt 0
[ 1876.470948] brcmfmac: CONSOLE: 028605.731 ampdu_dbg: cwcur0-3 f f 7 3 bslots cur/0-3 6 0 0 0 0 ifs_boff 0
[ 1876.480586] brcmfmac: CONSOLE: 028605.731 ampdu_dbg: again1 ifsstat 0x1ea0 nav_stat 0x0
[ 1876.488657] brcmfmac: CONSOLE: 028605.731 ampdu_dbg: again2 ifsstat 0x1ea0 nav_stat 0x0
[ 1876.496770] brcmfmac: CONSOLE: 028605.731 wl0: wlc_ampdu_watchdog: cleaning up ini tid 0 due to no progress for 2 secs tx_in_transit 1
[ 1876.508943] brcmfmac: CONSOLE: 028605.731 wl0: wlc_ampdu_tx_send_delba: tid 0 initiator 1 reason 39
[ 1877.958898] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1
[ 1878.918681] ------------[ cut here ]------------
[ 1878.923359] WARNING: CPU: 1 PID: 1140 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1256 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 1878.939505] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[ 1879.011922] CPU: 1 PID: 1140 Comm: hostapd Tainted: G        W       4.4.19 #0
[ 1879.019157] Hardware name: BCM5301X
[ 1879.022647] Backtrace: 
[ 1879.025124] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[ 1879.032710]  r7:000004e8 r6:bf1d12cf r5:60000013 r4:00000000
[ 1879.038428] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[ 1879.045667] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[ 1879.053773]  r5:00000009 r4:00000000
[ 1879.057371] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[ 1879.066176]  r8:c79050a4 r7:00000001 r6:c6471b3c r5:00000000 r4:c71c5480
[ 1879.072960] [<c002153c>] (warn_slowpath_null) from [<bf1be784>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[ 1879.083444] [<bf1be6c8>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[ 1879.096075]  r8:c79050a4 r7:bf1c8927 r6:c71c5480 r5:c04903c8 r4:c7905394
[ 1879.102848] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad740>] (brcmf_cfg80211_add_key+0x2e0/0x3dc [brcmfmac])
[ 1879.115050]  r7:00000000 r6:c71c5480 r5:c79050a4 r4:00000004
[ 1879.120793] [<bf1ad460>] (brcmf_cfg80211_add_key [brcmfmac]) from [<bf160b48>] (nl80211_new_key+0xfc/0x128 [cfg80211])
[ 1879.131509]  r10:00000014 r9:c79da800 r8:c6471ca0 r7:c7306000 r6:c71c5000 r5:00000000
[ 1879.139394]  r4:bf1ad460
[ 1879.141976] [<bf160a4c>] (nl80211_new_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[ 1879.150953]  r8:c721f780 r7:c695e414 r6:bf170540 r5:bf1787d0 r4:00000000
[ 1879.157716] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[ 1879.165558]  r10:c721f780 r9:00000000 r8:c6471d84 r7:c72e0800 r6:c0286ce0 r5:c721f780
[ 1879.173444]  r4:c695e400
[ 1879.175991] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[ 1879.183489]  r7:c72e0800 r6:c721f780 r5:c721f780 r4:c04a42a0
[ 1879.189194] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[ 1879.196866]  r5:00000048 r4:c7952000
[ 1879.200467] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[ 1879.208747]  r9:00000008 r8:00000000 r7:00000048 r6:c6471f4c r5:c72e0800 r4:00000000
[ 1879.216554] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[ 1879.224396]  r10:00000000 r9:00000000 r8:00000000 r7:c7507c80 r6:c6471e64 r5:00000000
[ 1879.232283]  r4:c6471f4c
[ 1879.234829] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[ 1879.242767] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[ 1879.250613]  r10:00000000 r9:c6470000 r8:c00098c4 r7:00000128 r6:00000000 r5:beb207c0
[ 1879.258499]  r4:c7507c80
[ 1879.261046] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[ 1879.268630]  r6:b6f6b1c8 r5:00000000 r4:00000000
[ 1879.273285] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[ 1879.281100] ---[ end trace 86e59c15931392ff ]---
[ 1879.285743] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1 brcmf_get_pend_8021x_cnt(ifp):3
[ 1879.296836] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 1879.304264] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b18d80 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1879.313856] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b18900 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1879.323447] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c721fc00 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1879.336774] brcmfmac: [brcmf_cfg80211_del_key -> __send_key_to_dongle] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1
[ 1880.298704] ------------[ cut here ]------------
[ 1880.303383] WARNING: CPU: 1 PID: 1140 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1256 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
[ 1880.319629] Modules linked in: pppoe ppp_async iptable_nat brcmfmac pppox ppp_generic nf_nat_ipv4 nf_conntrack_ipv6 nf_conntrack_ipv4 ipt_REJECT ipt_MASQUERADE cfg80211 xt_time xt_tcpudp xt_state xt_nat xt_multiport xt_mark xt_mac xt_limit xt_id xt_conntrack xt_commed
[ 1880.391985] CPU: 1 PID: 1140 Comm: hostapd Tainted: G        W       4.4.19 #0
[ 1880.399220] Hardware name: BCM5301X
[ 1880.402711] Backtrace: 
[ 1880.405186] [<c001708c>] (dump_backtrace) from [<c0017288>] (show_stack+0x18/0x1c)
[ 1880.412774]  r7:000004e8 r6:bf1d12cf r5:60000013 r4:00000000
[ 1880.418490] [<c0017270>] (show_stack) from [<c017c210>] (dump_stack+0x84/0xa4)
[ 1880.425729] [<c017c18c>] (dump_stack) from [<c0021490>] (warn_slowpath_common+0x8c/0xb8)
[ 1880.433835]  r5:00000009 r4:00000000
[ 1880.437434] [<c0021404>] (warn_slowpath_common) from [<c0021560>] (warn_slowpath_null+0x24/0x2c)
[ 1880.446238]  r8:c646be40 r7:00000001 r6:c6471b74 r5:00000000 r4:c71c5480
[ 1880.453029] [<c002153c>] (warn_slowpath_null) from [<bf1be784>] (brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac])
[ 1880.463514] [<bf1be6c8>] (brcmf_netdev_wait_pend8021x [brcmfmac]) from [<bf1ab200>] (brcmf_cfg80211_sched_scan_start+0x460/0x6c0 [brcmfmac])
[ 1880.476145]  r8:c646be40 r7:bf1c8910 r6:c71c5480 r5:c04903c8 r4:c79052f0
[ 1880.482918] [<bf1ab13c>] (brcmf_cfg80211_sched_scan_start [brcmfmac]) from [<bf1ad420>] (brcmf_cfg80211_del_key+0xb0/0xf0 [brcmfmac])
[ 1880.494938]  r7:c71c5480 r6:00000002 r5:c7905254 r4:c7905000
[ 1880.500682] [<bf1ad370>] (brcmf_cfg80211_del_key [brcmfmac]) from [<bf1608b8>] (nl80211_del_key+0xf4/0x148 [cfg80211])
[ 1880.511396]  r7:c7306000 r6:c71c5000 r5:c659b420 r4:bf1ad370
[ 1880.517138] [<bf1607c4>] (nl80211_del_key [cfg80211]) from [<c0286f40>] (genl_rcv_msg+0x260/0x2e4)
[ 1880.526115]  r7:c659b414 r6:bf170554 r5:bf1787d0 r4:00000000
[ 1880.531824] [<c0286ce0>] (genl_rcv_msg) from [<c0286260>] (netlink_rcv_skb+0x60/0xbc)
[ 1880.539667]  r10:c646be40 r9:00000000 r8:c6471d84 r7:c72e0800 r6:c0286ce0 r5:c646be40
[ 1880.547553]  r4:c659b400
[ 1880.550100] [<c0286200>] (netlink_rcv_skb) from [<c0286ccc>] (genl_rcv+0x28/0x3c)
[ 1880.557597]  r7:c72e0800 r6:c646be40 r5:c646be40 r4:c04a42a0
[ 1880.563304] [<c0286ca4>] (genl_rcv) from [<c0285c48>] (netlink_unicast+0x138/0x1f4)
[ 1880.570975]  r5:00000030 r4:c7952000
[ 1880.574575] [<c0285b10>] (netlink_unicast) from [<c02860c8>] (netlink_sendmsg+0x300/0x320)
[ 1880.582856]  r9:00000008 r8:00000000 r7:00000030 r6:c6471f4c r5:c72e0800 r4:00000000
[ 1880.590663] [<c0285dc8>] (netlink_sendmsg) from [<c0248de4>] (sock_sendmsg+0x1c/0x2c)
[ 1880.598506]  r10:00000000 r9:00000000 r8:00000000 r7:c7507c80 r6:c6471e64 r5:00000000
[ 1880.606392]  r4:c6471f4c
[ 1880.608938] [<c0248dc8>] (sock_sendmsg) from [<c0249398>] (___sys_sendmsg+0x198/0x228)
[ 1880.616876] [<c0249200>] (___sys_sendmsg) from [<c024a1ec>] (__sys_sendmsg+0x44/0x68)
[ 1880.624722]  r10:00000000 r9:c6470000 r8:c00098c4 r7:00000128 r6:00000000 r5:beb20790
[ 1880.632608]  r4:c7507c80
[ 1880.635155] [<c024a1a8>] (__sys_sendmsg) from [<c024a220>] (SyS_sendmsg+0x10/0x14)
[ 1880.642741]  r6:b6f6b1c8 r5:00000000 r4:00000000
[ 1880.647394] [<c024a210>] (SyS_sendmsg) from [<c0009700>] (ret_fast_syscall+0x0/0x3c)
[ 1880.655195] ---[ end trace 86e59c1593139300 ]---
[ 1880.659840] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1 brcmf_get_pend_8021x_cnt(ifp):3
[ 1880.670922] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
[ 1880.678333] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b18d80 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1880.687935] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b18900 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1880.697530] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c721fc00 skb->dev:c71c5000 skb->dev->name:wlan1-1
[ 1881.439614] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6b18d80 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1874.928858]; commit_time:[ 1874.928994])
[ 1881.457852] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6b18900 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1875.938806]; commit_time:[ 1875.938858])
[ 1881.476074] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c721fc00 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1876.948805]; commit_time:[ 1876.948855])
[ 1881.494440] brcmfmac: CONSOLE: 028610.749 wl0: Proxy STA 78:d6:f0:9b:ba:bc link is already gone !!??
[ 1888.235520] brcmfmac: CONSOLE: 028617.545 wl0.2: wlc_send_bar: seq 0x1 tid 0
[ 1888.331718] brcmfmac: CONSOLE: 028617.642 wl0.2: wlc_send_bar: seq 0x2 tid 0
[ 1888.339244] brcmfmac: CONSOLE: 028617.649 wl0.2: wlc_send_bar: seq 0x2 tid 0
[ 1888.346526] brcmfmac: CONSOLE: 028617.653 wl0.2: wlc_send_bar: seq 0x2 tid 0
[ 1889.340149] brcmfmac: CONSOLE: 028618.650 wl0.2: wlc_send_bar: seq 0x3 tid 0
[ 1889.347986] brcmfmac: CONSOLE: 028618.658 wl0.2: wlc_send_bar: seq 0x3 tid 0
[ 1889.356389] brcmfmac: CONSOLE: 028618.666 wl0.2: wlc_send_bar: seq 0x3 tid 0
[ 1889.365376] brcmfmac: CONSOLE: 028618.675 wl0.2: wlc_send_bar: seq 0x3 tid 0
[ 1889.820256] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1
[ 1891.234796] brcmfmac: CONSOLE: 028620.545 wl0.2: wlc_send_bar: seq 0x5 tid 0
[ 1891.450654] brcmfmac: CONSOLE: 028620.761 wl0.2: wlc_send_bar: seq 0x1 tid 6
[ 1896.459074] brcmfmac: CONSOLE: 028625.769 wl0.2: wlc_send_bar: seq 0xb tid 0
[ 1896.466714] brcmfmac: CONSOLE: 028625.777 wl0.2: wlc_send_bar: seq 0xb tid 0
[ 1899.466112] brcmfmac: CONSOLE: 028628.776 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.477359] brcmfmac: CONSOLE: 028628.787 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.485109] brcmfmac: CONSOLE: 028628.795 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.493678] brcmfmac: CONSOLE: 028628.804 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.502530] brcmfmac: CONSOLE: 028628.812 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.512932] brcmfmac: CONSOLE: 028628.823 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.521532] brcmfmac: CONSOLE: 028628.832 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.533614] brcmfmac: CONSOLE: 028628.843 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.542998] brcmfmac: CONSOLE: 028628.853 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.550675] brcmfmac: CONSOLE: 028628.857 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.558172] brcmfmac: CONSOLE: 028628.865 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1899.567218] brcmfmac: CONSOLE: 028628.877 wl0.2: wlc_send_bar: seq 0x11 tid 0
[ 1900.541469] brcmfmac: CONSOLE: 028629.852 wl0.2: wlc_send_bar: seq 0x12 tid 0
[ 1900.562295] brcmfmac: CONSOLE: 028629.872 wl0.2: wlc_send_bar: seq 0x13 tid 0
[ 1901.357401] brcmfmac: CONSOLE: 028630.667 wl0: Proxy STA 78:d6:f0:9b:ba:bc link is already gone !!??
[ 1901.367534] brcmfmac: [brcmf_cfg80211_del_key -> __send_key_to_dongle] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1
[ 1902.823503] brcmfmac: CONSOLE: 028632.131 wl0.3: wlc_send_bar: seq 0x3 tid 0
[ 1904.429210] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6970c80 brcmf_ifname(ifp):wlan1
[ 1904.519856] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c79d5480 brcmf_ifname(ifp):wlan0
[ 1904.599225] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c64b0480 brcmf_ifname(ifp):wlan1-2
[ 1904.619978] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c79d0c80 brcmf_ifname(ifp):wlan0-1
[ 1904.654979] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1
[ 1904.739199] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c6aac480 brcmf_ifname(ifp):wlan0-2
---
 .../broadcom/brcm80211/brcmfmac/cfg80211.c         |  4 +-
 .../wireless/broadcom/brcm80211/brcmfmac/core.c    | 94 +++++++++++++++++++++-
 .../wireless/broadcom/brcm80211/brcmfmac/core.h    | 17 +++-
 .../broadcom/brcm80211/brcmfmac/flowring.c         |  2 +
 .../broadcom/brcm80211/brcmfmac/fwsignal.c         | 30 ++++++-
 .../wireless/broadcom/brcm80211/brcmfmac/msgbuf.c  | 21 +++++
 .../net/wireless/broadcom/brcm80211/brcmfmac/usb.c |  3 +
 .../wireless/broadcom/brcm80211/brcmutil/utils.c   |  2 +-
 .../broadcom/brcm80211/include/brcmu_utils.h       |  2 +-
 9 files changed, 167 insertions(+), 8 deletions(-)

Comments

Rafał Miłecki Sept. 15, 2016, 2:27 p.m. UTC | #1
On 09/15/2016 01:48 PM, Rafał Miłecki wrote:
> On 09/14/2016 08:28 PM, Arend Van Spriel wrote:
>> It would be great to have a timestamp for these skb when they arrive in
>> brcmfmac or transferred to firmware (or both).
>
> You ask and you have it :) I saved kernel's local time and printed it the same
> way print_time function does it. Let me paste the most important lines:
> [ 1876.496770] brcmfmac: CONSOLE: 028605.731 wl0: wlc_ampdu_watchdog: cleaning up ini tid 0 due to no progress for 2 secs tx_in_transit 1
> [ 1877.958898] brcmfmac: [brcmf_cfg80211_add_key -> __send_key_to_dongle] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1
> [ 1878.923359] WARNING: CPU: 1 PID: 1140 at compat-wireless-2016-06-20/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c:1256 brcmf_netdev_wait_pend8021x+0xbc/0x184 [brcmfmac]()
> [ 1880.659840] brcmfmac: [brcmf_netdev_wait_pend8021x] ifp:c71c5480 brcmf_ifname(ifp):wlan1-1 brcmf_get_pend_8021x_cnt(ifp):3
> [ 1880.670922] brcmfmac: [brcmf_netdev_wait_pend8021x] List of pending 802.1x skbs:
> [ 1880.678333] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b18d80 skb->dev:c71c5000 skb->dev->name:wlan1-1
> [ 1880.687935] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c6b18900 skb->dev:c71c5000 skb->dev->name:wlan1-1
> [ 1880.697530] brcmfmac: [brcmf_netdev_wait_pend8021x] skb:c721fc00 skb->dev:c71c5000 skb->dev->name:wlan1-1
> [ 1881.439614] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6b18d80 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1874.928858]; commit_time:[ 1874.928994])
> [ 1881.457852] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c6b18900 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1875.938806]; commit_time:[ 1875.938858])
> [ 1881.476074] brcmfmac: [brcmf_msgbuf_process_txstatus -> __brcmf_txfinalize] Finally finalizing skb:c721fc00 skb->dev:c71c5000 skb->dev->name:wlan1-1 (start_time:[ 1876.948805]; commit_time:[ 1876.948855])
>
> For the first skb brcmf_netdev_start_xmit was called at 1874.928858.
> It was commited to firmware with brcmf_msgbuf_txflow at 1874.928994.
> Then there was A-MPDU hang in firmware.
> Finally brcmf_msgbuf_process_txstatus was called and it called
> brcmf_txfinalize and this one logged everything at 1881.439614.
>
> You'll find full log at the end.

I kept thinking about this. Some more timing info:
1) wlc_ampdu_watchdog probably started with ampdu_dbg, so we can assume the
    beginning was about 1876.423494.
2) brcmf_netdev_wait_pend8021x waits for 950 ms, so it probably started about
    1877.973359

So the closest timeline I can guess/restore is:
1874.423494: A-MPDU stalls
1874.928994: Passing 802.1x packet #1 to the firmware
1875.938858: Passing 802.1x packet #2 to the firmware
1876.423494: A-MPDU stall detected
1876.508943: Firmware sends DELBA
1876.948855: Passing 802.1x packet #3 to the firmware
1877.973359: brcmf_netdev_wait_pend8021x starts waiting
1881.439614: TX status of 802.1x packet #1
1881.457852: TX status of 802.1x packet #2
1881.476074: TX status of 802.1x packet #3

Now I'm more thinking about this, maybe this A-MPDU stall wasn't any firmware
bug at all? Could it be firmware wasn't getting BA reply e.g. because STA simply
lost the signal?
5 seconds of firmware delay between noticing A-MPDU stall and finally sending
802.1x packets still sound like a big one, but maybe it's not *that* critical?

What's the real problem then is brcmfmac waiting for too long in
brcmf_netdev_wait_pend8021x. It prevents keys from updating and current timeout
of 950 ms sounds like quite a lot. Increasing it to few seconds would stop
WARNINGs from appearing, but would make keys update take even more time.

I guess ideally we should:
1) Have firmware quickly recover from A-MPDU stall (currently: 2 + 5 seconds)
2) Don't have to wait for so long to update keys
diff mbox

Patch

diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c
index 201a980..c7ccea5 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c
@@ -464,11 +464,12 @@  static void convert_key_from_CPU(struct brcmf_wsec_key *key,
 }
 
 static int
-send_key_to_dongle(struct brcmf_if *ifp, struct brcmf_wsec_key *key)
+__send_key_to_dongle(const char *c0, struct brcmf_if *ifp, struct brcmf_wsec_key *key)
 {
 	int err;
 	struct brcmf_wsec_key_le key_le;
 
+	pr_info("[%s -> %s] ifp:%p brcmf_ifname(ifp):%s\n", c0, __func__, ifp, brcmf_ifname(ifp));
 	convert_key_from_CPU(key, &key_le);
 
 	brcmf_netdev_wait_pend8021x(ifp);
@@ -480,6 +481,7 @@  send_key_to_dongle(struct brcmf_if *ifp, struct brcmf_wsec_key *key)
 		brcmf_err("wsec_key error (%d)\n", err);
 	return err;
 }
+#define send_key_to_dongle(ifp, key)	__send_key_to_dongle(__func__, ifp, key)
 
 static s32
 brcmf_configure_arp_nd_offload(struct brcmf_if *ifp, bool enable)
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c
index 8d16f02..67f2623 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.c
@@ -38,6 +38,46 @@ 
 #include "pcie.h"
 #include "common.h"
 
+#include <linux/sched.h>
+
+static size_t print_time(u64 ts, char *buf)
+{
+	unsigned long rem_nsec;
+
+	rem_nsec = do_div(ts, 1000000000);
+
+	if (!buf)
+		return snprintf(NULL, 0, "[%5lu.000000]", (unsigned long)ts);
+
+	return sprintf(buf, "[%5lu.%06lu]",
+		       (unsigned long)ts, rem_nsec / 1000);
+}
+
+/* Free the driver packet. Free the tag if present */
+void __brcmu_pkt_buf_free_skb(const char *c0, struct brcmf_if *ifp, struct sk_buff *skb)
+{
+	if (!skb)
+		return;
+
+	if (ifp) {
+		struct pend_skb *e;
+
+		mutex_lock(&ifp->pend_8021x_mutex);
+		list_for_each_entry(e, &ifp->pend_8021x_skbs, list) {
+			if (e->skb == skb) {
+				pr_info("[%s -> %s] [ifp:%p] ***BUG*** skb:%p skb->dev:%p skb->dev->name:%s\n", c0, __func__, ifp, e->skb, e->skb->dev, e->skb->dev ? e->skb->dev->name : "---");
+				break;
+			}
+		}
+		mutex_unlock(&ifp->pend_8021x_mutex);
+	} else if (strcmp(c0, "brcmf_msgbuf_query_dcmd")) {
+		pr_info("[%s -> %s] [ifp:%p] Freeing skb:%p skb->dev:%p skb->dev->name:%s\n", c0, __func__, ifp, skb, skb->dev, skb->dev ? skb->dev->name : "---");
+	}
+
+	WARN_ON(skb->next);
+	dev_kfree_skb_any(skb);
+}
+
 #define MAX_WAIT_FOR_8021X_TX			msecs_to_jiffies(950)
 
 #define BRCMF_BSSIDX_INVALID			-1
@@ -247,8 +287,18 @@  static netdev_tx_t brcmf_netdev_start_xmit(struct sk_buff *skb,
 		goto done;
 	}
 
-	if (eh->h_proto == htons(ETH_P_PAE))
+	if (eh->h_proto == htons(ETH_P_PAE)) {
+		struct pend_skb *e;
+
+		e = kzalloc(sizeof(*e), GFP_KERNEL);
+		e->skb = skb;
+		e->start_time = local_clock();
+
 		atomic_inc(&ifp->pend_8021x_cnt);
+		mutex_lock(&ifp->pend_8021x_mutex);
+		list_add_tail(&e->list, &ifp->pend_8021x_skbs);
+		mutex_unlock(&ifp->pend_8021x_mutex);
+	}
 
 	ret = brcmf_fws_process_skb(ifp, skb);
 
@@ -333,7 +383,7 @@  static int brcmf_rx_hdrpull(struct brcmf_pub *drvr, struct sk_buff *skb,
 	if (ret || !(*ifp) || !(*ifp)->ndev) {
 		if (ret != -ENODATA && *ifp)
 			(*ifp)->stats.rx_errors++;
-		brcmu_pkt_buf_free_skb(skb);
+		__brcmu_pkt_buf_free_skb(__func__, *ifp, skb);
 		return -ENODATA;
 	}
 
@@ -378,7 +428,7 @@  void brcmf_rx_event(struct device *dev, struct sk_buff *skb)
 	brcmu_pkt_buf_free_skb(skb);
 }
 
-void brcmf_txfinalize(struct brcmf_if *ifp, struct sk_buff *txp, bool success)
+void __brcmf_txfinalize(const char *c0, struct brcmf_if *ifp, struct sk_buff *txp, bool success)
 {
 	struct ethhdr *eh;
 	u16 type;
@@ -387,7 +437,30 @@  void brcmf_txfinalize(struct brcmf_if *ifp, struct sk_buff *txp, bool success)
 	type = ntohs(eh->h_proto);
 
 	if (type == ETH_P_PAE) {
+		struct pend_skb *e, *tmp;
+
 		atomic_dec(&ifp->pend_8021x_cnt);
+		mutex_lock(&ifp->pend_8021x_mutex);
+		list_for_each_entry_safe(e, tmp, &ifp->pend_8021x_skbs, list) {
+			if (e->skb == txp) {
+				if (e->timedout) {
+					char start[32], commit[32];
+
+					print_time(e->start_time, start);
+					print_time(e->commit_time, commit);
+
+					pr_info("[%s -> %s] Finally finalizing skb:%p skb->dev:%p skb->dev->name:%s (start_time:%s; commit_time:%s)\n",
+						c0, __func__,
+						e->skb, e->skb->dev, e->skb->dev ? e->skb->dev->name : "---",
+						start, commit);
+				}
+
+				list_del(&e->list);
+				kfree(e);
+				break;
+			}
+		}
+		mutex_unlock(&ifp->pend_8021x_mutex);
 		if (waitqueue_active(&ifp->pend_8021x_wait))
 			wake_up(&ifp->pend_8021x_wait);
 	}
@@ -476,6 +549,8 @@  static int brcmf_netdev_open(struct net_device *ndev)
 	}
 
 	atomic_set(&ifp->pend_8021x_cnt, 0);
+	INIT_LIST_HEAD(&ifp->pend_8021x_skbs);
+	mutex_init(&ifp->pend_8021x_mutex);
 
 	/* Get current TOE mode from dongle */
 	if (brcmf_fil_iovar_int_get(ifp, "toe_ol", &toe_ol) >= 0
@@ -1170,6 +1245,19 @@  int brcmf_netdev_wait_pend8021x(struct brcmf_if *ifp)
 				 MAX_WAIT_FOR_8021X_TX);
 
 	WARN_ON(!err);
+	if (!err)
+		pr_info("[%s] ifp:%p brcmf_ifname(ifp):%s brcmf_get_pend_8021x_cnt(ifp):%d\n", __func__, ifp, brcmf_ifname(ifp), brcmf_get_pend_8021x_cnt(ifp));
+	if (!list_empty(&ifp->pend_8021x_skbs)) {
+		struct pend_skb *e;
+
+		mutex_lock(&ifp->pend_8021x_mutex);
+		pr_info("[%s] List of pending 802.1x skbs:\n", __func__);
+		list_for_each_entry(e, &ifp->pend_8021x_skbs, list) {
+			e->timedout = true;
+			pr_info("[%s] skb:%p skb->dev:%p skb->dev->name:%s\n", __func__, e->skb, e->skb->dev, e->skb->dev ? e->skb->dev->name : "---");
+		}
+		mutex_unlock(&ifp->pend_8021x_mutex);
+	}
 
 	return !err;
 }
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.h b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.h
index 8fa34ca..0f66e8f 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.h
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/core.h
@@ -50,6 +50,9 @@ 
 
 #define NDOL_MAX_ENTRIES	8
 
+void __brcmu_pkt_buf_free_skb(const char *c0, struct brcmf_if *ifp, struct sk_buff *skb);
+#define brcmu_pkt_buf_free_skb(skb)	__brcmu_pkt_buf_free_skb(__func__, ifp, skb)
+
 /**
  * struct brcmf_ampdu_rx_reorder - AMPDU receive reorder info
  *
@@ -169,6 +172,14 @@  enum brcmf_netif_stop_reason {
 	BRCMF_NETIF_STOP_REASON_DISCONNECTED = BIT(2)
 };
 
+struct pend_skb {
+	struct sk_buff *skb;
+	u64 start_time;
+	u64 commit_time;
+	bool timedout;
+	struct list_head list;
+};
+
 /**
  * struct brcmf_if - interface control information.
  *
@@ -203,6 +214,9 @@  struct brcmf_if {
 	u8 netif_stop;
 	spinlock_t netif_stop_lock;
 	atomic_t pend_8021x_cnt;
+	struct list_head pend_8021x_skbs;
+	struct mutex pend_8021x_mutex;
+	bool pend_8021x_ready;
 	wait_queue_head_t pend_8021x_wait;
 	struct in6_addr ipv6_addr_tbl[NDOL_MAX_ENTRIES];
 	u8 ipv6addr_idx;
@@ -219,7 +233,8 @@  struct brcmf_if *brcmf_add_if(struct brcmf_pub *drvr, s32 bsscfgidx, s32 ifidx,
 void brcmf_remove_interface(struct brcmf_if *ifp, bool rtnl_locked);
 void brcmf_txflowblock_if(struct brcmf_if *ifp,
 			  enum brcmf_netif_stop_reason reason, bool state);
-void brcmf_txfinalize(struct brcmf_if *ifp, struct sk_buff *txp, bool success);
+void __brcmf_txfinalize(const char *c0, struct brcmf_if *ifp, struct sk_buff *txp, bool success);
+#define brcmf_txfinalize(ifp, txp, success)	__brcmf_txfinalize(__func__, ifp, txp, success)
 void brcmf_netif_rx(struct brcmf_if *ifp, struct sk_buff *skb);
 void brcmf_net_setcarrier(struct brcmf_if *ifp, bool on);
 void brcmf_c_set_joinpref_default(struct brcmf_if *ifp);
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/flowring.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/flowring.c
index 7e269f9..87c8de0 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/flowring.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/flowring.c
@@ -249,6 +249,8 @@  void brcmf_flowring_delete(struct brcmf_flowring *flow, u16 flowid)
 
 	skb = skb_dequeue(&ring->skblist);
 	while (skb) {
+		struct brcmf_if *ifp = NULL;
+
 		brcmu_pkt_buf_free_skb(skb);
 		skb = skb_dequeue(&ring->skblist);
 	}
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/fwsignal.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/fwsignal.c
index 9f9024a..7a17afd 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/fwsignal.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/fwsignal.c
@@ -38,6 +38,8 @@ 
 #include "proto.h"
 #include "common.h"
 
+#include <linux/sched.h>
+
 /**
  * DOC: Firmware Signalling
  *
@@ -590,6 +592,8 @@  static void brcmf_fws_psq_flush(struct brcmf_fws_info *fws, struct pktq *q,
 	for (prec = 0; prec < q->num_prec; prec++) {
 		skb = brcmu_pktq_pdeq_match(q, prec, matchfn, &ifidx);
 		while (skb) {
+			struct brcmf_if *ifp = NULL;
+
 			brcmu_pkt_buf_free_skb(skb);
 			skb = brcmu_pktq_pdeq_match(q, prec, matchfn, &ifidx);
 		}
@@ -697,6 +701,8 @@  static void brcmf_fws_hanger_cleanup(struct brcmf_fws_info *fws,
 		    s == BRCMF_FWS_HANGER_ITEM_STATE_INUSE_SUPPRESSED) {
 			skb = h->items[i].pkt;
 			if (fn == NULL || fn(skb, &ifidx)) {
+				struct brcmf_if *ifp = NULL;
+
 				/* suppress packets freed from psq */
 				if (s == BRCMF_FWS_HANGER_ITEM_STATE_INUSE)
 					brcmu_pkt_buf_free_skb(skb);
@@ -845,6 +851,8 @@  static void brcmf_fws_bus_txq_cleanup(struct brcmf_fws_info *fws,
 	for (prec = 0; prec < txq->num_prec; prec++) {
 		skb = brcmu_pktq_pdeq_match(txq, prec, fn, &ifidx);
 		while (skb) {
+			struct brcmf_if *ifp = NULL;
+
 			hslot = brcmf_skb_htod_tag_get_field(skb, HSLOT);
 			hi = &fws->hanger.items[hslot];
 			WARN_ON(skb != hi->pkt);
@@ -971,8 +979,11 @@  static bool brcmf_fws_tim_update(struct brcmf_fws_info *fws,
 		brcmf_fws_unlock(fws);
 		err = brcmf_proto_txdata(fws->drvr, ifidx, data_offset, skb);
 		brcmf_fws_lock(fws);
-		if (err)
+		if (err) {
+			struct brcmf_if *ifp = NULL;
+
 			brcmu_pkt_buf_free_skb(skb);
+		}
 		return true;
 	}
 	return false;
@@ -2056,6 +2067,22 @@  static int brcmf_fws_commit_skb(struct brcmf_fws_info *fws, int fifo,
 		(void)brcmf_proto_hdrpull(fws->drvr, false, skb, NULL);
 		goto rollback;
 	}
+	{
+		struct brcmf_if *ifp = brcmf_get_ifp(fws->drvr, brcmf_skb_if_flags_get_field(skb, INDEX));
+
+		if (ifp) {
+			struct pend_skb *e;
+
+			mutex_lock(&ifp->pend_8021x_mutex);
+			list_for_each_entry(e, &ifp->pend_8021x_skbs, list) {
+				if (e->skb == skb) {
+					e->commit_time = local_clock();
+					break;
+				}
+			}
+			mutex_unlock(&ifp->pend_8021x_mutex);
+		}
+	}
 
 	fws->stats.pkt2bus++;
 	fws->stats.send_pkts[fifo]++;
@@ -2454,6 +2481,7 @@  bool brcmf_fws_fc_active(struct brcmf_fws_info *fws)
 
 void brcmf_fws_bustxfail(struct brcmf_fws_info *fws, struct sk_buff *skb)
 {
+	struct brcmf_if *ifp = NULL;
 	u32 hslot;
 
 	if (brcmf_skbcb(skb)->state == BRCMF_FWS_SKBSTATE_TIM) {
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/msgbuf.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/msgbuf.c
index 2b9a2bc..6ff91c2 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/msgbuf.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/msgbuf.c
@@ -34,6 +34,8 @@ 
 #include "bus.h"
 #include "tracepoint.h"
 
+#include <linux/sched.h>
+
 
 #define MSGBUF_IOCTL_RESP_TIMEOUT		msecs_to_jiffies(2000)
 
@@ -392,6 +394,8 @@  brcmf_msgbuf_release_array(struct device *dev,
 	count = 0;
 	do {
 		if (array[count].allocated.counter) {
+			struct brcmf_if *ifp = NULL;
+
 			pktid = &array[count];
 			dma_unmap_single(dev, pktid->physaddr,
 					 pktid->skb->len - pktid->data_offset,
@@ -483,6 +487,7 @@  static int brcmf_msgbuf_query_dcmd(struct brcmf_pub *drvr, int ifidx,
 {
 	struct brcmf_msgbuf *msgbuf = (struct brcmf_msgbuf *)drvr->proto->pd;
 	struct sk_buff *skb = NULL;
+	struct brcmf_if *ifp = NULL;
 	int timeout;
 	int err;
 
@@ -747,6 +752,22 @@  static void brcmf_msgbuf_txflow(struct brcmf_msgbuf *msgbuf, u16 flowid)
 			brcmf_commonring_write_complete(commonring);
 			count = 0;
 		}
+		{
+			struct brcmf_if *ifp = brcmf_get_ifp(msgbuf->drvr, tx_msghdr->msg.ifidx);
+
+			if (ifp) {
+				struct pend_skb *e;
+
+				mutex_lock(&ifp->pend_8021x_mutex);
+				list_for_each_entry(e, &ifp->pend_8021x_skbs, list) {
+					if (e->skb == skb) {
+						e->commit_time = local_clock();
+						break;
+					}
+				}
+				mutex_unlock(&ifp->pend_8021x_mutex);
+			}
+		}
 	}
 	if (count)
 		brcmf_commonring_write_complete(commonring);
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/usb.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/usb.c
index 2f978a3..edbe353 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/usb.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/usb.c
@@ -498,6 +498,7 @@  static void brcmf_usb_rx_complete(struct urb *urb)
 {
 	struct brcmf_usbreq  *req = (struct brcmf_usbreq *)urb->context;
 	struct brcmf_usbdev_info *devinfo = req->devinfo;
+	struct brcmf_if *ifp = NULL;
 	struct sk_buff *skb;
 
 	brcmf_dbg(USB, "Enter, urb->status=%d\n", urb->status);
@@ -548,6 +549,8 @@  static void brcmf_usb_rx_refill(struct brcmf_usbdev_info *devinfo,
 
 	ret = usb_submit_urb(req->urb, GFP_ATOMIC);
 	if (ret) {
+		struct brcmf_if *ifp = NULL;
+
 		brcmf_usb_del_fromq(devinfo, req);
 		brcmu_pkt_buf_free_skb(req->skb);
 		req->skb = NULL;
diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmutil/utils.c b/drivers/net/wireless/broadcom/brcm80211/brcmutil/utils.c
index 0543607..bf525b7 100644
--- a/drivers/net/wireless/broadcom/brcm80211/brcmutil/utils.c
+++ b/drivers/net/wireless/broadcom/brcm80211/brcmutil/utils.c
@@ -49,7 +49,7 @@  void brcmu_pkt_buf_free_skb(struct sk_buff *skb)
 	WARN_ON(skb->next);
 	dev_kfree_skb_any(skb);
 }
-EXPORT_SYMBOL(brcmu_pkt_buf_free_skb);
+//EXPORT_SYMBOL(brcmu_pkt_buf_free_skb);
 
 /*
  * osl multiple-precedence packet queue
diff --git a/drivers/net/wireless/broadcom/brcm80211/include/brcmu_utils.h b/drivers/net/wireless/broadcom/brcm80211/include/brcmu_utils.h
index 4196952..7bd705d 100644
--- a/drivers/net/wireless/broadcom/brcm80211/include/brcmu_utils.h
+++ b/drivers/net/wireless/broadcom/brcm80211/include/brcmu_utils.h
@@ -126,7 +126,7 @@  struct sk_buff *brcmu_pktq_pdeq_match(struct pktq *pq, int prec,
 
 /* packet primitives */
 struct sk_buff *brcmu_pkt_buf_get_skb(uint len);
-void brcmu_pkt_buf_free_skb(struct sk_buff *skb);
+//void brcmu_pkt_buf_free_skb(struct sk_buff *skb);
 
 /* Empty the queue at particular precedence level */
 /* callback function fn(pkt, arg) returns true if pkt belongs to if */