Hi Amitkumar,
On Thu, Oct 23, 2014 at 2:40 PM, Amitkumar Karwar <[email protected]> wrote:
> Hi Marek,
>
>>> I tried to capture logs but when enable DYNAMIC_DEBUG I cannot
>>> reproduce issue (running test > 30 minutes without allocation
>>> failure).
>
> Thanks for the testing. Yes. Sometimes timing issues won't get reproduced
> with debug messages enabled.
>
>>Any update on this? Should I provide some other logs?
>
> What's the size of Rx data packets? Is the Rx data AMSDU aggregated?(You can
> check if "if (rx_pkt_type == PKT_TYPE_AMSDU)" check is passed in mwifiex
> code) If so, disable AMSDU option in AP and try to reproduce the issue.
Size of Rx data packets are : pkt type == 2, size - 1574bytes + BAR
pkt type, size - 34bytes. AMSDU isn't enabled on AP (verified by
adding debug message in mwifiex_process_sta_rx_packet()).
>
> As you suspected earlier, we might have missed to free skbs allocated for Rx
> data which leads to SKB allocation failure. There is very less probability
> for this. But we can try below experiment.
>
> 1) I observed that debug variable "adapter->rx_pending" doesn;t get
> decremented when packet is submitted to kernel. Add below code change(valid
> only for AMSDU disabled case. Because multiple packets are submitted to
> kernel when AMSDU is enabled)
>
> ----------
> --- a/drivers/net/wireless/mwifiex/util.c
> +++ b/drivers/net/wireless/mwifiex/util.c
> @@ -218,6 +218,7 @@ int mwifiex_recv_packet(struct mwifiex_private *priv,
> struct sk_buff *skb)
>
> priv->stats.rx_bytes += skb->len;
> priv->stats.rx_packets++;
> + atomic_dec(&priv->adapter->rx_pending);
> if (in_interrupt())
> netif_rx(skb);
> ----------
OK, patch applied.
>
> 2) Add BUG_ON when first time SKB allocation is failed and print
> "rx_pending". If it's a huge number, we have missed freeing allocated SKB.
[ 167.624452] usb 1-1: mwifiex_usb_submit_rx_urb: dev_alloc_skb
failed, rx_pending:26893
[ 167.632885] ------------[ cut here ]------------
[ 167.637743] Kernel BUG at bf8a22ae [verbose debug info unavailable]
so number seems to be huge and we seems miss free allocated skb.
I did some hacks to code which shows how many packets are received
between 2 BAR packets + I print every 500ms rx_pending packets (when
packet is received) and
also when packet is send to kernel. I also update counter how many
packets after reordering are sent to kernel. Log:
[ 71.973800] usb 1-1: rx_pending:11
[ 72.077308] usb 1-1: rx_pending kernel:10
[ 72.477546] usb 1-1: rx_pending:868
[ 72.587877] usb 1-1: rx_pending kernel:1096
[ 72.818041] usb 1-1: Received between 2 BAR:6275
[ 72.823127] usb 1-1: Networking send size:6271
[ 72.987375] usb 1-1: rx_pending:1940
[ 73.097504] usb 1-1: rx_pending kernel:2159
[ 73.431973] usb 1-1: Received between 2 BAR:1602
[ 73.437106] usb 1-1: Networking send size:1608
[ 73.497381] usb 1-1: rx_pending:2983
[ 73.608315] usb 1-1: rx_pending kernel:3091
[ 74.007379] usb 1-1: rx_pending:3767
[ 74.117879] usb 1-1: rx_pending kernel:3998
[ 74.517375] usb 1-1: rx_pending:4854
[ 74.543168] usb 1-1: Received between 2 BAR:3152
[ 74.548371] usb 1-1: Networking send size:3152
[ 74.627509] usb 1-1: rx_pending kernel:5062
[ 74.743362] usb 1-1: Received between 2 BAR:495
[ 74.748483] usb 1-1: Networking send size:494
[ 75.027523] usb 1-1: rx_pending:5872
[ 75.137961] usb 1-1: rx_pending kernel:6106
[ 75.537485] usb 1-1: rx_pending:6959
[ 75.647934] usb 1-1: rx_pending kernel:7188
[ 75.656273] usb 1-1: Received between 2 BAR:2383
[ 75.661528] usb 1-1: Networking send size:2382
[ 76.047441] usb 1-1: rx_pending:8004
[ 76.157712] usb 1-1: rx_pending kernel:8240
[ 76.557547] usb 1-1: rx_pending:9095
[ 76.667991] usb 1-1: rx_pending kernel:9326
[ 76.769662] usb 1-1: Received between 2 BAR:2918
[ 76.775047] usb 1-1: Networking send size:2914
[ 77.067491] usb 1-1: rx_pending:10155
[ 77.177524] usb 1-1: rx_pending kernel:10383
[ 77.577547] usb 1-1: rx_pending:11237
[ 77.687859] usb 1-1: rx_pending kernel:11461
[ 78.087401] usb 1-1: rx_pending:12304
[ 78.197992] usb 1-1: rx_pending kernel:12539
[ 78.597442] usb 1-1: rx_pending:13391
[ 78.707786] usb 1-1: rx_pending kernel:13628
[ 79.107487] usb 1-1: rx_pending:14469
[ 79.217812] usb 1-1: rx_pending kernel:14704
[ 79.617528] usb 1-1: rx_pending:15555
[ 79.727734] usb 1-1: rx_pending kernel:15781
[ 80.127486] usb 1-1: rx_pending:16624
[ 80.237756] usb 1-1: rx_pending kernel:16855
[ 80.637423] usb 1-1: rx_pending:17699
[ 80.747868] usb 1-1: rx_pending kernel:17926
[ 81.147446] usb 1-1: rx_pending:18769
[ 81.257800] usb 1-1: rx_pending kernel:18995
[ 81.657399] usb 1-1: rx_pending:19851
[ 81.767785] usb 1-1: rx_pending kernel:20083
[ 82.167341] usb 1-1: rx_pending:20938
[ 82.278005] usb 1-1: rx_pending kernel:21174
[ 82.677527] usb 1-1: rx_pending:22025
[ 82.787508] usb 1-1: rx_pending kernel:22246
[ 83.187390] usb 1-1: rx_pending:23103
[ 83.297690] usb 1-1: rx_pending kernel:23326
[ 83.697376] usb 1-1: rx_pending:24182
[ 83.807711] usb 1-1: rx_pending kernel:24404
[ 84.207487] usb 1-1: rx_pending:25236
[ 84.317747] usb 1-1: rx_pending kernel:25466
[ 84.717378] usb 1-1: rx_pending:26308
[ 84.827806] usb 1-1: rx_pending kernel:26522
[ 85.070931] usb 1-1: mwifiex_usb_submit_rx_urb: dev_alloc_skb
failed - rx_pending:27017
[ 85.079788] usb 1-1: mwifiex_usb_submit_rx_urb: dev_alloc_skb
failed - rx_pending:27019
[ 85.088424] usb 1-1: mwifiex_usb_submit_rx_urb: dev_alloc_skb
failed - rx_pending:27020
[ 85.097029] usb 1-1: mwifiex_usb_submit_rx_urb: dev_alloc_skb
failed - rx_pending:27020
[ 85.105845] usb 1-1: mwifiex_usb_submit_rx_urb: dev_alloc_skb
failed - rx_pending:27022
[ 85.114468] usb 1-1: mwifiex_usb_submit_rx_urb: dev_alloc_skb
failed - rx_pending:27023
[ 85.337391] usb 1-1: rx_pending kernel:22327
[ 85.400153] usb 1-1: Received between 2 BAR:27875
[ 85.405135] usb 1-1: Networking send size:27881
[ 85.766194] usb 1-1: Received between 2 BAR:7781
[ 85.771152] usb 1-1: Networking send size:7781
[ 85.847374] usb 1-1: rx_pending kernel:11681
[ 86.112809] usb 1-1: Received between 2 BAR:7263
[ 86.117755] usb 1-1: Networking send size:7262
[ 86.357378] usb 1-1: rx_pending kernel:827
According log it seems rx_pending is slowly increasing until
allocation fails. Code hacks are attached.
>
> 3) Also, get rx_pending info when Rx traffic works fine with 40M bandwidth
> option.
when -b40 is set then IMO 11n reordering isn't applied. I added some
debug code to mwifiex_11n_rx_reorder_pkt()
.. snip ..
tbl = mwifiex_11n_get_rx_reorder_tbl(priv, tid, ta);
if (!tbl) {
.. snip ..
is always true (!tbl) so rx_pending after session is 0.
>
> Btw, could you move to the firmware image (14.68.29.p38)
> shared recently?
Tested with 14.68.29.p38 FW version. Issue still reproducible.
>
> By any means(redirecting the log to serial console etc.), could you please
> capture and share kernel trace logs when system becomes unresponsive. It may
> give some clue and help us debug further.
As I wrote earlier with DYNAMIC_DEBUG I cannot reproduce issue. Maybe
when we drop some debug code (received packet over USB) issue can be
reproducible again, but it's just guess.
>
> Best Regards,
> Amit
BR,
marek
--
as simple and primitive as possible
-------------------------------------------------
Marek Belisko - OPEN-NANDRA
Freelance Developer
Ruska Nova Ves 219 | Presov, 08005 Slovak Republic
Tel: +421 915 052 184
skype: marekwhite
twitter: #opennandra
web: http://open-nandra.com
diff --git a/drivers/net/wireless/mwifiex/11n_rxreorder.c
b/drivers/net/wireless/mwifiex/11n_rxreorder.c
index 5e796f8..f6a8d0d 100644
--- a/drivers/net/wireless/mwifiex/11n_rxreorder.c
+++ b/drivers/net/wireless/mwifiex/11n_rxreorder.c
@@ -26,6 +26,7 @@
#include "11n.h"
#include "11n_rxreorder.h"
+static int pkt_send = 0;
/*
* This function dispatches all packets in the Rx reorder table until the
* start window.
@@ -36,7 +37,7 @@
*/
static void
mwifiex_11n_dispatch_pkt(struct mwifiex_private *priv,
- struct mwifiex_rx_reorder_tbl *tbl, int start_win)
+ struct mwifiex_rx_reorder_tbl *tbl, int start_win, int
*send_size)
{
int pkt_to_send, i;
void *rx_tmp_ptr;
@@ -45,6 +46,7 @@ mwifiex_11n_dispatch_pkt(struct mwifiex_private *priv,
pkt_to_send = (start_win > tbl->start_win) ?
min((start_win - tbl->start_win), tbl->win_size) :
tbl->win_size;
+// pr_info("%s - pkt_to_send:%d\n", __func__, pkt_to_send);
for (i = 0; i < pkt_to_send; ++i) {
spin_lock_irqsave(&priv->rx_pkt_lock, flags);
@@ -57,8 +59,11 @@ mwifiex_11n_dispatch_pkt(struct mwifiex_private *priv,
if (rx_tmp_ptr) {
if (priv->bss_role == MWIFIEX_BSS_ROLE_UAP)
mwifiex_handle_uap_rx_forward(priv, rx_tmp_ptr);
- else
+ else {
mwifiex_process_rx_packet(priv, rx_tmp_ptr);
+ if (send_size)
+ *send_size += 1;
+ }
}
}
@@ -86,7 +91,7 @@ mwifiex_11n_dispatch_pkt(struct mwifiex_private *priv,
*/
static void
mwifiex_11n_scan_and_dispatch(struct mwifiex_private *priv,
- struct mwifiex_rx_reorder_tbl *tbl)
+ struct mwifiex_rx_reorder_tbl *tbl, int
*send_size)
{
int i, j, xchg;
void *rx_tmp_ptr;
@@ -104,8 +109,10 @@ mwifiex_11n_scan_and_dispatch(struct mwifiex_private *priv,
if (priv->bss_role == MWIFIEX_BSS_ROLE_UAP)
mwifiex_handle_uap_rx_forward(priv, rx_tmp_ptr);
- else
+ else {
mwifiex_process_rx_packet(priv, rx_tmp_ptr);
+ *send_size += 1;
+ }
}
spin_lock_irqsave(&priv->rx_pkt_lock, flags);
@@ -140,7 +147,7 @@ mwifiex_del_rx_reorder_entry(struct mwifiex_private *priv,
return;
mwifiex_11n_dispatch_pkt(priv, tbl, (tbl->start_win + tbl->win_size) &
- (MAX_TID_VALUE - 1));
+ (MAX_TID_VALUE - 1), NULL);
del_timer(&tbl->timer_context.timer);
@@ -238,7 +245,7 @@ mwifiex_flush_data(unsigned long context)
dev_dbg(ctx->priv->adapter->dev, "info: flush data %d\n", start_win);
mwifiex_11n_dispatch_pkt(ctx->priv, ctx->ptr,
(ctx->ptr->start_win + start_win + 1) &
- (MAX_TID_VALUE - 1));
+ (MAX_TID_VALUE - 1), NULL);
}
/*
@@ -267,7 +274,7 @@ mwifiex_11n_create_rx_reorder_tbl(struct mwifiex_private
*priv, u8 *ta,
*/
tbl = mwifiex_11n_get_rx_reorder_tbl(priv, tid, ta);
if (tbl) {
- mwifiex_11n_dispatch_pkt(priv, tbl, seq_num);
+ mwifiex_11n_dispatch_pkt(priv, tbl, seq_num, NULL);
return;
}
/* if !tbl then create one */
@@ -434,11 +441,15 @@ int mwifiex_11n_rx_reorder_pkt(struct mwifiex_private
*priv,
tbl = mwifiex_11n_get_rx_reorder_tbl(priv, tid, ta);
if (!tbl) {
+ pr_info("!tbl\n");
if (pkt_type != PKT_TYPE_BAR) {
if (priv->bss_role == MWIFIEX_BSS_ROLE_UAP)
mwifiex_handle_uap_rx_forward(priv, payload);
else
mwifiex_process_rx_packet(priv, payload);
+ } else {
+ // missing free (maybe also rx_pending)
+ dev_kfree_skb_any(payload);
}
return 0;
}
@@ -485,7 +496,7 @@ int mwifiex_11n_rx_reorder_pkt(struct mwifiex_private *priv,
start_win = (end_win - win_size) + 1;
else
start_win = (MAX_TID_VALUE - (win_size - seq_num)) + 1;
- mwifiex_11n_dispatch_pkt(priv, tbl, start_win);
+ mwifiex_11n_dispatch_pkt(priv, tbl, start_win, &pkt_send);
}
if (pkt_type != PKT_TYPE_BAR) {
@@ -498,13 +509,16 @@ int mwifiex_11n_rx_reorder_pkt(struct mwifiex_private
*priv,
return -1;
tbl->rx_reorder_ptr[pkt_index] = payload;
+ } else if (pkt_type == PKT_TYPE_BAR) {
+ dev_info(priv->adapter->dev, "Networking send size:%d\n",
pkt_send);
+ pkt_send = 0;
}
/*
* Dispatch all packets sequentially from start_win until a
* hole is found and adjust the start_win appropriately
*/
- mwifiex_11n_scan_and_dispatch(priv, tbl);
+ mwifiex_11n_scan_and_dispatch(priv, tbl, &pkt_send);
return 0;
}
diff --git a/drivers/net/wireless/mwifiex/sta_rx.c
b/drivers/net/wireless/mwifiex/sta_rx.c
index b5c1095..bc1c0d7 100644
--- a/drivers/net/wireless/mwifiex/sta_rx.c
+++ b/drivers/net/wireless/mwifiex/sta_rx.c
@@ -122,6 +122,7 @@ int mwifiex_process_sta_rx_packet(struct mwifiex_private
*priv,
struct rx_packet_hdr *rx_pkt_hdr;
u8 ta[ETH_ALEN];
u16 rx_pkt_type, rx_pkt_offset, rx_pkt_length, seq_num;
+ static int pkts_received = 0;
local_rx_pd = (struct rxpd *) (skb->data);
rx_pkt_type = le16_to_cpu(local_rx_pd->rx_pkt_type);
@@ -146,6 +147,7 @@ int mwifiex_process_sta_rx_packet(struct mwifiex_private
*priv,
}
if (rx_pkt_type == PKT_TYPE_AMSDU) {
+ pr_info("AMSDU\n");
struct sk_buff_head list;
struct sk_buff *rx_skb;
@@ -168,6 +170,7 @@ int mwifiex_process_sta_rx_packet(struct mwifiex_private
*priv,
ret = mwifiex_process_mgmt_packet(priv, skb);
if (ret)
dev_err(adapter->dev, "Rx of mgmt packet failed");
+ atomic_dec(&priv->adapter->rx_pending);
dev_kfree_skb_any(skb);
return ret;
}
@@ -191,10 +194,19 @@ int mwifiex_process_sta_rx_packet(struct mwifiex_private
*priv,
ETH_ALEN);
}
+ if (rx_pkt_type != PKT_TYPE_BAR && skb->len > 1500) {
+ pkts_received++;
+ }
+
+ if (rx_pkt_type == PKT_TYPE_BAR) {
+ dev_info(priv->adapter->dev, "Received between 2 BAR:%d\n",
pkts_received);
+ pkts_received = 0;
+ }
/* Reorder and send to OS */
ret = mwifiex_11n_rx_reorder_pkt(priv, seq_num, local_rx_pd->priority,
ta, (u8) rx_pkt_type, skb);
+
if (ret || (rx_pkt_type == PKT_TYPE_BAR)) {
if (adapter->if_ops.data_complete)
adapter->if_ops.data_complete(adapter, skb);
diff --git a/drivers/net/wireless/mwifiex/usb.c
b/drivers/net/wireless/mwifiex/usb.c
index 7d9d10b..959daed 100644
--- a/drivers/net/wireless/mwifiex/usb.c
+++ b/drivers/net/wireless/mwifiex/usb.c
@@ -38,6 +38,7 @@ static struct usb_device_id mwifiex_usb_table[] = {
MODULE_DEVICE_TABLE(usb, mwifiex_usb_table);
+unsigned long timeout = 0;
/* Indicate if load FW in MFG (testing) mode */
static int mfg_mode = 0;
@@ -178,8 +179,14 @@ static void mwifiex_usb_rx_complete(struct urb *urb)
atomic_inc(&adapter->rx_pending);
status = mwifiex_usb_recv(adapter, skb, context->ep);
+ if (time_after(jiffies, timeout)) {
+ dev_info(adapter->dev, "rx_pending:%d\n",
atomic_read(&adapter->rx_pending));
+ timeout = jiffies + msecs_to_jiffies(500);
+ }
+
dev_dbg(adapter->dev, "info: recv_length=%d, status=%d\n",
recv_length, status);
+
if (status == -EINPROGRESS) {
queue_work(adapter->workqueue, &adapter->main_work);
@@ -259,7 +266,7 @@ static int mwifiex_usb_submit_rx_urb(struct urb_context
*ctx, int size)
ctx->skb = dev_alloc_skb(size);
if (!ctx->skb) {
dev_err(adapter->dev,
- "%s: dev_alloc_skb failed\n", __func__);
+ "%s: dev_alloc_skb failed - rx_pending:%d\n",
__func__, atomic_read(&adapter->rx_pending));
return -ENOMEM;
}
}
@@ -344,6 +351,7 @@ static int mwifiex_usb_probe(struct usb_interface *intf,
bcd_usb = le16_to_cpu(udev->descriptor.bcdUSB);
pr_debug("info: VID/PID = %X/%X, Boot2 version = %X\n",
id_vendor, id_product, bcd_device);
+ timeout = jiffies + msecs_to_jiffies(1000);
/* PID_1 is used for firmware downloading only */
if (id_product == USB8797_PID_1)
diff --git a/drivers/net/wireless/mwifiex/util.c
b/drivers/net/wireless/mwifiex/util.c
index 2155397..b18ee13 100644
--- a/drivers/net/wireless/mwifiex/util.c
+++ b/drivers/net/wireless/mwifiex/util.c
@@ -25,6 +25,7 @@
#include "wmm.h"
#include "11n.h"
+unsigned long timeout = 0;
/*
* Firmware initialization complete callback handler.
*
@@ -195,6 +196,9 @@ int mwifiex_recv_packet(struct mwifiex_private *priv,
struct sk_buff *skb)
skb->protocol = eth_type_trans(skb, priv->netdev);
skb->ip_summed = CHECKSUM_NONE;
+ if (timeout == 0)
+ timeout = jiffies;
+
/* This is required only in case of 11n and USB as we alloc
* a buffer of 4K only if its 11N (to be able to receive 4K
* AMSDU packets). In case of SD we allocate buffers based
@@ -218,6 +222,12 @@ int mwifiex_recv_packet(struct mwifiex_private *priv,
struct sk_buff *skb)
priv->stats.rx_bytes += skb->len;
priv->stats.rx_packets++;
+ atomic_dec(&priv->adapter->rx_pending);
+ if (time_after(jiffies, timeout)) {
+ dev_info(priv->adapter->dev, "rx_pending kernel:%d\n",
atomic_read(&priv->adapter->rx_pending));
+ timeout = jiffies + msecs_to_jiffies(500);
+ }
+
if (in_interrupt())
netif_rx(skb);
else
