* mwifiex and SD8787: TX queue timeout in AP mode
@ 2014-02-02 6:41 Andrew Wiley
2014-02-02 7:45 ` Avinash Patil
0 siblings, 1 reply; 11+ messages in thread
From: Andrew Wiley @ 2014-02-02 6:41 UTC (permalink / raw)
To: linux-wireless
Hello linux-wireless,
I'm observing a consistent TX queue timeout with a SD8787 on a Marvell
Kirkwood-based Dreamplug running the mwifiex driver.
In particular, with this hostapd config:
====
interface=uap0
bridge=br0
driver=nl80211
logger_stdout=-1
logger_stdout_level=2
ssid=My Clever SSID
country_code=US
ieee80211d=1
hw_mode=g
channel=4
auth_algs=3
max_num_sta=255
#wpa=2
#wpa_passphrase=EvenClevererPassphrase
#wpa_key_mgmt=WPA-PSK
#wpa_pairwise=TKIP
#rsn_pairwise=CCMP
====
I see a hang within about an hour. If I uncomment the encryption
settings, the hang generally occurs a few seconds after my testing
laptop gets on the network (long enough for ~2 pings to return).
I did have one instance where, with encryption enabled, the network
stayed up for an hour or so, but I haven't managed to replicate it.
The timeout consistently looks like this in the kernel log:
====
[ 922.826726] ------------[ cut here ]------------
[ 922.831395] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:264
dev_watchdog+0x2d0/0x2f0()
[ 922.839897] NETDEV WATCHDOG: uap0 (mwifiex_sdio): transmit queue 1 timed out
[ 922.846986] Modules linked in: iptable_raw ipt_MASQUERADE xt_nat
bridge iptable_nat nf_nat_ipv4 nf_nat stp llc iptable_mangle xt_policy
xt_tcpudp nf_conntrack_ipv6 nf_conntrack_ipv4 nf_defrag_ipv6
nf_defrag_ipv4 xt_conntrack nf_conntrack iptable_filter
ip6table_filter ip6_tables ip_tables x_tables hid_generic mwifiex_sdio
snd_usb_audio snd_usbmidi_lib snd_hwdep snd_rawmidi mwifiex
snd_seq_device cfg80211 snd_pcm snd_page_alloc usbhid snd_timer snd
hid soundcore rfkill mv_cesa usbip_host(C) usbip_core(C) ipv6 autofs4
[ 922.893323] CPU: 0 PID: 0 Comm: swapper Tainted: G C
3.13.0-2-ARCH #1
[ 922.900698] [<c000ee04>] (unwind_backtrace+0x0/0xe8) from
[<c000c354>] (show_stack+0x10/0x14)
[ 922.909285] [<c000c354>] (show_stack+0x10/0x14) from [<c001a780>]
(warn_slowpath_common+0x70/0x90)
[ 922.918307] [<c001a780>] (warn_slowpath_common+0x70/0x90) from
[<c001a7d0>] (warn_slowpath_fmt+0x30/0x40)
[ 922.927949] [<c001a7d0>] (warn_slowpath_fmt+0x30/0x40) from
[<c04aa51c>] (dev_watchdog+0x2d0/0x2f0)
[ 922.937059] [<c04aa51c>] (dev_watchdog+0x2d0/0x2f0) from
[<c00258f8>] (call_timer_fn+0x30/0x170)
[ 922.945903] [<c00258f8>] (call_timer_fn+0x30/0x170) from
[<c0025eb4>] (run_timer_softirq+0x1f8/0x368)
[ 922.955187] [<c0025eb4>] (run_timer_softirq+0x1f8/0x368) from
[<c001ec00>] (__do_softirq+0xdc/0x304)
[ 922.964384] [<c001ec00>] (__do_softirq+0xdc/0x304) from
[<c001f1a4>] (irq_exit+0xb0/0xf8)
[ 922.972615] [<c001f1a4>] (irq_exit+0xb0/0xf8) from [<c0009c80>]
(handle_IRQ+0x34/0x84)
[ 922.980585] [<c0009c80>] (handle_IRQ+0x34/0x84) from [<c052ef54>]
(__irq_svc+0x34/0x98)
[ 922.988647] [<c052ef54>] (__irq_svc+0x34/0x98) from [<c043a638>]
(cpuidle_enter_state+0x5c/0xe8)
[ 922.997494] [<c043a638>] (cpuidle_enter_state+0x5c/0xe8) from
[<c043a76c>] (cpuidle_idle_call+0xa8/0x248)
[ 923.007120] [<c043a76c>] (cpuidle_idle_call+0xa8/0x248) from
[<c0009df8>] (arch_cpu_idle+0x8/0x44)
[ 923.016128] [<c0009df8>] (arch_cpu_idle+0x8/0x44) from [<c0052aa0>]
(cpu_startup_entry+0xe8/0x218)
[ 923.025152] [<c0052aa0>] (cpu_startup_entry+0xe8/0x218) from
[<c06fca1c>] (start_kernel+0x308/0x368)
[ 923.034338] ---[ end trace 1f99f5bb6d86ce00 ]---
[ 923.038991] mwifiex_sdio mmc0:0001:1: 61622 : Tx timeout(#1),
bss_type-num = 1-0
[ 932.826851] mwifiex_sdio mmc0:0001:1: 62601 : Tx timeout(#2),
bss_type-num = 1-0
[ 942.826950] mwifiex_sdio mmc0:0001:1: 63601 : Tx timeout(#3),
bss_type-num = 1-0
[ 952.827043] mwifiex_sdio mmc0:0001:1: 64601 : Tx timeout(#4),
bss_type-num = 1-0
[ 962.827135] mwifiex_sdio mmc0:0001:1: 65601 : Tx timeout(#5),
bss_type-num = 1-0
[ 972.827204] mwifiex_sdio mmc0:0001:1: 66601 : Tx timeout(#6),
bss_type-num = 1-0
[ 982.827274] mwifiex_sdio mmc0:0001:1: 67601 : Tx timeout(#7),
bss_type-num = 1-0
[ 982.834710] mwifiex_sdio mmc0:0001:1: tx_timeout_cnt exceeds
threshold. Triggering card reset!
[ 982.847311] mwifiex_sdio: Resetting card...
[ 982.858835] mwifiex_sdio mmc0:0001:1: rx_pending=0, tx_pending=134,
cmd_pending=0
[ 982.890370] br0: port 3(uap0) entered disabled state
[ 982.927420] mwifiex_sdio mmc0:0001:1: PREP_CMD: card is removed
[ 982.933379] ieee80211 phy0: Failed to delete mgmt IEs!
[ 982.944768] mwifiex_sdio mmc0:0001:1: PREP_CMD: card is removed
[ 982.954303] ieee80211 phy0: Failed to stop the BSS
[ 982.965174] br0: port 3(uap0) entered disabled state
[ 982.997332] device uap0 left promiscuous mode
[ 983.002107] br0: port 3(uap0) entered disabled state
[ 983.047777] mmc0: card 0001 removed
[ 983.162307] mmc0: new high speed SDIO card at address 0001
[ 994.467374] mwifiex_sdio mmc0:0001:1: FW failed to be active in time
<span class="sew7w4eq1wq2zww"><br></span>====
Firstly, I'm guessing there's more debug information to be had - is
there a flag I should be turning on to get some more useful output?
Would the hostapd debug output help?
Secondly, I've never seen the card come back up after the driver
resets it. Does this normally work?
Thirdly, if I try to kill hostapd after pings from my test machine
stop working but before the watchdog triggers, I get a kernel log that
looks like this:
====
[ 415.625875] mwifiex_sdio mmc0:0001:1: cmd_wait_q terminated: -512
[ 417.554508] mwifiex_sdio mmc0:0001:1: cmd_wait_q terminated: -512
[ 417.637845] mwifiex_sdio mmc0:0001:1: cmd_wait_q terminated: -512
[ 420.831554] mwifiex_sdio mmc0:0001:1: mwifiex_cmd_timeout_func:
Timeout cmd id (1391322753.261340) = 0xb5, act = 0x85c4
[ 420.842426] mwifiex_sdio mmc0:0001:1: num_data_h2c_failure = 0
[ 420.848289] mwifiex_sdio mmc0:0001:1: num_cmd_h2c_failure = 0
[ 420.854075] mwifiex_sdio mmc0:0001:1: num_cmd_timeout = 1
[ 420.859503] mwifiex_sdio mmc0:0001:1: num_tx_timeout = 0
[ 420.864851] mwifiex_sdio mmc0:0001:1: last_cmd_index = 4
[ 420.870184] mwifiex_sdio mmc0:0001:1: last_cmd_id: 28 00 5e 00 5e
00 5e 00 b5 00
[ 420.877626] mwifiex_sdio mmc0:0001:1: last_cmd_act: 93 00 01 00 01
00 01 00 c4 85
[ 420.885151] mwifiex_sdio mmc0:0001:1: last_cmd_resp_index = 3
[ 420.890920] mwifiex_sdio mmc0:0001:1: last_cmd_resp_id: 28 80 5e 80
5e 80 5e 80 b1 80
[ 420.898798] mwifiex_sdio mmc0:0001:1: last_event_index = 3
[ 420.904316] mwifiex_sdio mmc0:0001:1: last_event: 00 00 2e 00 44 00
2d 00 00 00
[ 420.911668] mwifiex_sdio mmc0:0001:1: data_sent=1 cmd_sent=1
[ 420.917351] mwifiex_sdio mmc0:0001:1: ps_mode=1 ps_state=0
[ 420.922875] mwifiex_sdio mmc0:0001:1: cmd timeout
[ 420.930569] mwifiex_sdio: Resetting card...
[ 420.950267] mwifiex_sdio mmc0:0001:1: rx_pending=0, tx_pending=3,
cmd_pending=0
[ 420.997056] br0: port 3(uap0) entered disabled state
[ 421.021696] mwifiex_sdio mmc0:0001:1: PREP_CMD: card is removed
[ 421.027655] ieee80211 phy0: Failed to delete mgmt IEs!
[ 421.037288] mwifiex_sdio mmc0:0001:1: PREP_CMD: card is removed
[ 421.047313] ieee80211 phy0: Failed to stop the BSS
[ 421.056754] br0: port 3(uap0) entered disabled state
[ 421.091582] device uap0 left promiscuous mode
[ 421.096165] br0: port 3(uap0) entered disabled state
[ 421.143900] mmc0: card 0001 removed
[ 421.236334] mmc0: new high speed SDIO card at address 0001
[ 432.541163] mwifiex_sdio mmc0:0001:1: FW failed to be active in time
====
So it looks like the entire card is hanging, rather than just a queue
getting stuck?
Some environment info:
kernel is 3.13.0 with mwifiex and mwifiex_sdio built as modules
hostapd is v2.0
Dreamplug is a variant of the Guruplug, and my distro (Arch Linux ARM)
patches it into the Guruplug boardfile
(Dreamplug has a DTS in mainline, but not a boardfile. This is a
non-DTB kernel - the DTB kernel seems to have trouble with SDIO
interrupt handling)
Thanks,
Andrew
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: mwifiex and SD8787: TX queue timeout in AP mode
2014-02-02 6:41 mwifiex and SD8787: TX queue timeout in AP mode Andrew Wiley
@ 2014-02-02 7:45 ` Avinash Patil
2014-02-02 21:13 ` Andrew Wiley
0 siblings, 1 reply; 11+ messages in thread
From: Avinash Patil @ 2014-02-02 7:45 UTC (permalink / raw)
To: Andrew Wiley; +Cc: linux-wireless
Hi Andrew,
It looks like AP_STA_DEAUTH command is timed out.
Can you please enable dynamic debug and collect logs with attached change?
1. CONFIG_DYNAMIC_DEBUG=y in kernel .config and rebuild the kernel
2. Load the driver.
3. echo "module mwifiex +p" > /sys/kernel/debug/dynamic_debug/control
4. echo "module mwifiex_sdio +p" > /sys/kernel/debug/dynamic_debug/control
5. save the logs from dmesg after the test.
Thanks,
Avinash.
On Sun, Feb 2, 2014 at 12:11 PM, Andrew Wiley <wiley.andrew.j@gmail.com> wrote:
> Hello linux-wireless,
>
> I'm observing a consistent TX queue timeout with a SD8787 on a Marvell
> Kirkwood-based Dreamplug running the mwifiex driver.
>
> In particular, with this hostapd config:
> ====
> interface=uap0
> bridge=br0
> driver=nl80211
> logger_stdout=-1
> logger_stdout_level=2
> ssid=My Clever SSID
> country_code=US
> ieee80211d=1
>
> hw_mode=g
> channel=4
> auth_algs=3
> max_num_sta=255
>
> #wpa=2
> #wpa_passphrase=EvenClevererPassphrase
> #wpa_key_mgmt=WPA-PSK
> #wpa_pairwise=TKIP
> #rsn_pairwise=CCMP
> ====
>
> I see a hang within about an hour. If I uncomment the encryption
> settings, the hang generally occurs a few seconds after my testing
> laptop gets on the network (long enough for ~2 pings to return).
> I did have one instance where, with encryption enabled, the network
> stayed up for an hour or so, but I haven't managed to replicate it.
>
> The timeout consistently looks like this in the kernel log:
> ====
> [ 922.826726] ------------[ cut here ]------------
> [ 922.831395] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:264
> dev_watchdog+0x2d0/0x2f0()
> [ 922.839897] NETDEV WATCHDOG: uap0 (mwifiex_sdio): transmit queue 1 timed out
> [ 922.846986] Modules linked in: iptable_raw ipt_MASQUERADE xt_nat
> bridge iptable_nat nf_nat_ipv4 nf_nat stp llc iptable_mangle xt_policy
> xt_tcpudp nf_conntrack_ipv6 nf_conntrack_ipv4 nf_defrag_ipv6
> nf_defrag_ipv4 xt_conntrack nf_conntrack iptable_filter
> ip6table_filter ip6_tables ip_tables x_tables hid_generic mwifiex_sdio
> snd_usb_audio snd_usbmidi_lib snd_hwdep snd_rawmidi mwifiex
> snd_seq_device cfg80211 snd_pcm snd_page_alloc usbhid snd_timer snd
> hid soundcore rfkill mv_cesa usbip_host(C) usbip_core(C) ipv6 autofs4
> [ 922.893323] CPU: 0 PID: 0 Comm: swapper Tainted: G C
> 3.13.0-2-ARCH #1
> [ 922.900698] [<c000ee04>] (unwind_backtrace+0x0/0xe8) from
> [<c000c354>] (show_stack+0x10/0x14)
> [ 922.909285] [<c000c354>] (show_stack+0x10/0x14) from [<c001a780>]
> (warn_slowpath_common+0x70/0x90)
> [ 922.918307] [<c001a780>] (warn_slowpath_common+0x70/0x90) from
> [<c001a7d0>] (warn_slowpath_fmt+0x30/0x40)
> [ 922.927949] [<c001a7d0>] (warn_slowpath_fmt+0x30/0x40) from
> [<c04aa51c>] (dev_watchdog+0x2d0/0x2f0)
> [ 922.937059] [<c04aa51c>] (dev_watchdog+0x2d0/0x2f0) from
> [<c00258f8>] (call_timer_fn+0x30/0x170)
> [ 922.945903] [<c00258f8>] (call_timer_fn+0x30/0x170) from
> [<c0025eb4>] (run_timer_softirq+0x1f8/0x368)
> [ 922.955187] [<c0025eb4>] (run_timer_softirq+0x1f8/0x368) from
> [<c001ec00>] (__do_softirq+0xdc/0x304)
> [ 922.964384] [<c001ec00>] (__do_softirq+0xdc/0x304) from
> [<c001f1a4>] (irq_exit+0xb0/0xf8)
> [ 922.972615] [<c001f1a4>] (irq_exit+0xb0/0xf8) from [<c0009c80>]
> (handle_IRQ+0x34/0x84)
> [ 922.980585] [<c0009c80>] (handle_IRQ+0x34/0x84) from [<c052ef54>]
> (__irq_svc+0x34/0x98)
> [ 922.988647] [<c052ef54>] (__irq_svc+0x34/0x98) from [<c043a638>]
> (cpuidle_enter_state+0x5c/0xe8)
> [ 922.997494] [<c043a638>] (cpuidle_enter_state+0x5c/0xe8) from
> [<c043a76c>] (cpuidle_idle_call+0xa8/0x248)
> [ 923.007120] [<c043a76c>] (cpuidle_idle_call+0xa8/0x248) from
> [<c0009df8>] (arch_cpu_idle+0x8/0x44)
> [ 923.016128] [<c0009df8>] (arch_cpu_idle+0x8/0x44) from [<c0052aa0>]
> (cpu_startup_entry+0xe8/0x218)
> [ 923.025152] [<c0052aa0>] (cpu_startup_entry+0xe8/0x218) from
> [<c06fca1c>] (start_kernel+0x308/0x368)
> [ 923.034338] ---[ end trace 1f99f5bb6d86ce00 ]---
> [ 923.038991] mwifiex_sdio mmc0:0001:1: 61622 : Tx timeout(#1),
> bss_type-num = 1-0
> [ 932.826851] mwifiex_sdio mmc0:0001:1: 62601 : Tx timeout(#2),
> bss_type-num = 1-0
> [ 942.826950] mwifiex_sdio mmc0:0001:1: 63601 : Tx timeout(#3),
> bss_type-num = 1-0
> [ 952.827043] mwifiex_sdio mmc0:0001:1: 64601 : Tx timeout(#4),
> bss_type-num = 1-0
> [ 962.827135] mwifiex_sdio mmc0:0001:1: 65601 : Tx timeout(#5),
> bss_type-num = 1-0
> [ 972.827204] mwifiex_sdio mmc0:0001:1: 66601 : Tx timeout(#6),
> bss_type-num = 1-0
> [ 982.827274] mwifiex_sdio mmc0:0001:1: 67601 : Tx timeout(#7),
> bss_type-num = 1-0
> [ 982.834710] mwifiex_sdio mmc0:0001:1: tx_timeout_cnt exceeds
> threshold. Triggering card reset!
> [ 982.847311] mwifiex_sdio: Resetting card...
> [ 982.858835] mwifiex_sdio mmc0:0001:1: rx_pending=0, tx_pending=134,
> cmd_pending=0
> [ 982.890370] br0: port 3(uap0) entered disabled state
> [ 982.927420] mwifiex_sdio mmc0:0001:1: PREP_CMD: card is removed
> [ 982.933379] ieee80211 phy0: Failed to delete mgmt IEs!
> [ 982.944768] mwifiex_sdio mmc0:0001:1: PREP_CMD: card is removed
> [ 982.954303] ieee80211 phy0: Failed to stop the BSS
> [ 982.965174] br0: port 3(uap0) entered disabled state
> [ 982.997332] device uap0 left promiscuous mode
> [ 983.002107] br0: port 3(uap0) entered disabled state
> [ 983.047777] mmc0: card 0001 removed
> [ 983.162307] mmc0: new high speed SDIO card at address 0001
> [ 994.467374] mwifiex_sdio mmc0:0001:1: FW failed to be active in time
> <span class="sew7w4eq1wq2zww"><br></span>====
>
>
> Firstly, I'm guessing there's more debug information to be had - is
> there a flag I should be turning on to get some more useful output?
> Would the hostapd debug output help?
>
> Secondly, I've never seen the card come back up after the driver
> resets it. Does this normally work?
>
> Thirdly, if I try to kill hostapd after pings from my test machine
> stop working but before the watchdog triggers, I get a kernel log that
> looks like this:
> ====
> [ 415.625875] mwifiex_sdio mmc0:0001:1: cmd_wait_q terminated: -512
> [ 417.554508] mwifiex_sdio mmc0:0001:1: cmd_wait_q terminated: -512
> [ 417.637845] mwifiex_sdio mmc0:0001:1: cmd_wait_q terminated: -512
> [ 420.831554] mwifiex_sdio mmc0:0001:1: mwifiex_cmd_timeout_func:
> Timeout cmd id (1391322753.261340) = 0xb5, act = 0x85c4
> [ 420.842426] mwifiex_sdio mmc0:0001:1: num_data_h2c_failure = 0
> [ 420.848289] mwifiex_sdio mmc0:0001:1: num_cmd_h2c_failure = 0
> [ 420.854075] mwifiex_sdio mmc0:0001:1: num_cmd_timeout = 1
> [ 420.859503] mwifiex_sdio mmc0:0001:1: num_tx_timeout = 0
> [ 420.864851] mwifiex_sdio mmc0:0001:1: last_cmd_index = 4
> [ 420.870184] mwifiex_sdio mmc0:0001:1: last_cmd_id: 28 00 5e 00 5e
> 00 5e 00 b5 00
> [ 420.877626] mwifiex_sdio mmc0:0001:1: last_cmd_act: 93 00 01 00 01
> 00 01 00 c4 85
> [ 420.885151] mwifiex_sdio mmc0:0001:1: last_cmd_resp_index = 3
> [ 420.890920] mwifiex_sdio mmc0:0001:1: last_cmd_resp_id: 28 80 5e 80
> 5e 80 5e 80 b1 80
> [ 420.898798] mwifiex_sdio mmc0:0001:1: last_event_index = 3
> [ 420.904316] mwifiex_sdio mmc0:0001:1: last_event: 00 00 2e 00 44 00
> 2d 00 00 00
> [ 420.911668] mwifiex_sdio mmc0:0001:1: data_sent=1 cmd_sent=1
> [ 420.917351] mwifiex_sdio mmc0:0001:1: ps_mode=1 ps_state=0
> [ 420.922875] mwifiex_sdio mmc0:0001:1: cmd timeout
> [ 420.930569] mwifiex_sdio: Resetting card...
> [ 420.950267] mwifiex_sdio mmc0:0001:1: rx_pending=0, tx_pending=3,
> cmd_pending=0
> [ 420.997056] br0: port 3(uap0) entered disabled state
> [ 421.021696] mwifiex_sdio mmc0:0001:1: PREP_CMD: card is removed
> [ 421.027655] ieee80211 phy0: Failed to delete mgmt IEs!
> [ 421.037288] mwifiex_sdio mmc0:0001:1: PREP_CMD: card is removed
> [ 421.047313] ieee80211 phy0: Failed to stop the BSS
> [ 421.056754] br0: port 3(uap0) entered disabled state
> [ 421.091582] device uap0 left promiscuous mode
> [ 421.096165] br0: port 3(uap0) entered disabled state
> [ 421.143900] mmc0: card 0001 removed
> [ 421.236334] mmc0: new high speed SDIO card at address 0001
> [ 432.541163] mwifiex_sdio mmc0:0001:1: FW failed to be active in time
> ====
>
> So it looks like the entire card is hanging, rather than just a queue
> getting stuck?
>
> Some environment info:
>
> kernel is 3.13.0 with mwifiex and mwifiex_sdio built as modules
> hostapd is v2.0
> Dreamplug is a variant of the Guruplug, and my distro (Arch Linux ARM)
> patches it into the Guruplug boardfile
> (Dreamplug has a DTS in mainline, but not a boardfile. This is a
> non-DTB kernel - the DTB kernel seems to have trouble with SDIO
> interrupt handling)
>
> Thanks,
> Andrew
> --
> To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: mwifiex and SD8787: TX queue timeout in AP mode
2014-02-02 7:45 ` Avinash Patil
@ 2014-02-02 21:13 ` Andrew Wiley
2014-02-03 6:47 ` Avinash Patil
0 siblings, 1 reply; 11+ messages in thread
From: Andrew Wiley @ 2014-02-02 21:13 UTC (permalink / raw)
To: Avinash Patil; +Cc: linux-wireless
Hello Avinash,
Here's one such log: http://www.cs.utexas.edu/users/wiley/mwifiexlog_1.txt
This was run with the WPA2 options uncommented in hostapd.conf. Pings
through the AP were successful for about 10 seconds after my test
machine joined the network. It looks like they started timing out at
about 150s in the kernel log, but `dmesg -w` seems to print messages
lazily, so it might be a bit later than that.
Let me know if there's something else I should try to capture.
Thanks,
Andrew
On Sun, Feb 2, 2014 at 1:45 AM, Avinash Patil <avinashapatil@gmail.com> wrote:
> Hi Andrew,
>
> It looks like AP_STA_DEAUTH command is timed out.
>
> Can you please enable dynamic debug and collect logs with attached change?
>
> 1. CONFIG_DYNAMIC_DEBUG=y in kernel .config and rebuild the kernel
> 2. Load the driver.
> 3. echo "module mwifiex +p" > /sys/kernel/debug/dynamic_debug/control
> 4. echo "module mwifiex_sdio +p" > /sys/kernel/debug/dynamic_debug/control
> 5. save the logs from dmesg after the test.
>
> Thanks,
> Avinash.
>
>
> On Sun, Feb 2, 2014 at 12:11 PM, Andrew Wiley <wiley.andrew.j@gmail.com> wrote:
>> Hello linux-wireless,
>>
>> I'm observing a consistent TX queue timeout with a SD8787 on a Marvell
>> Kirkwood-based Dreamplug running the mwifiex driver.
>>
>> In particular, with this hostapd config:
>> ====
>> interface=uap0
>> bridge=br0
>> driver=nl80211
>> logger_stdout=-1
>> logger_stdout_level=2
>> ssid=My Clever SSID
>> country_code=US
>> ieee80211d=1
>>
>> hw_mode=g
>> channel=4
>> auth_algs=3
>> max_num_sta=255
>>
>> #wpa=2
>> #wpa_passphrase=EvenClevererPassphrase
>> #wpa_key_mgmt=WPA-PSK
>> #wpa_pairwise=TKIP
>> #rsn_pairwise=CCMP
>> ====
>>
>> I see a hang within about an hour. If I uncomment the encryption
>> settings, the hang generally occurs a few seconds after my testing
>> laptop gets on the network (long enough for ~2 pings to return).
>> I did have one instance where, with encryption enabled, the network
>> stayed up for an hour or so, but I haven't managed to replicate it.
>>
>> The timeout consistently looks like this in the kernel log:
>> ====
>> [ 922.826726] ------------[ cut here ]------------
>> [ 922.831395] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:264
>> dev_watchdog+0x2d0/0x2f0()
>> [ 922.839897] NETDEV WATCHDOG: uap0 (mwifiex_sdio): transmit queue 1 timed out
>> [ 922.846986] Modules linked in: iptable_raw ipt_MASQUERADE xt_nat
>> bridge iptable_nat nf_nat_ipv4 nf_nat stp llc iptable_mangle xt_policy
>> xt_tcpudp nf_conntrack_ipv6 nf_conntrack_ipv4 nf_defrag_ipv6
>> nf_defrag_ipv4 xt_conntrack nf_conntrack iptable_filter
>> ip6table_filter ip6_tables ip_tables x_tables hid_generic mwifiex_sdio
>> snd_usb_audio snd_usbmidi_lib snd_hwdep snd_rawmidi mwifiex
>> snd_seq_device cfg80211 snd_pcm snd_page_alloc usbhid snd_timer snd
>> hid soundcore rfkill mv_cesa usbip_host(C) usbip_core(C) ipv6 autofs4
>> [ 922.893323] CPU: 0 PID: 0 Comm: swapper Tainted: G C
>> 3.13.0-2-ARCH #1
>> [ 922.900698] [<c000ee04>] (unwind_backtrace+0x0/0xe8) from
>> [<c000c354>] (show_stack+0x10/0x14)
>> [ 922.909285] [<c000c354>] (show_stack+0x10/0x14) from [<c001a780>]
>> (warn_slowpath_common+0x70/0x90)
>> [ 922.918307] [<c001a780>] (warn_slowpath_common+0x70/0x90) from
>> [<c001a7d0>] (warn_slowpath_fmt+0x30/0x40)
>> [ 922.927949] [<c001a7d0>] (warn_slowpath_fmt+0x30/0x40) from
>> [<c04aa51c>] (dev_watchdog+0x2d0/0x2f0)
>> [ 922.937059] [<c04aa51c>] (dev_watchdog+0x2d0/0x2f0) from
>> [<c00258f8>] (call_timer_fn+0x30/0x170)
>> [ 922.945903] [<c00258f8>] (call_timer_fn+0x30/0x170) from
>> [<c0025eb4>] (run_timer_softirq+0x1f8/0x368)
>> [ 922.955187] [<c0025eb4>] (run_timer_softirq+0x1f8/0x368) from
>> [<c001ec00>] (__do_softirq+0xdc/0x304)
>> [ 922.964384] [<c001ec00>] (__do_softirq+0xdc/0x304) from
>> [<c001f1a4>] (irq_exit+0xb0/0xf8)
>> [ 922.972615] [<c001f1a4>] (irq_exit+0xb0/0xf8) from [<c0009c80>]
>> (handle_IRQ+0x34/0x84)
>> [ 922.980585] [<c0009c80>] (handle_IRQ+0x34/0x84) from [<c052ef54>]
>> (__irq_svc+0x34/0x98)
>> [ 922.988647] [<c052ef54>] (__irq_svc+0x34/0x98) from [<c043a638>]
>> (cpuidle_enter_state+0x5c/0xe8)
>> [ 922.997494] [<c043a638>] (cpuidle_enter_state+0x5c/0xe8) from
>> [<c043a76c>] (cpuidle_idle_call+0xa8/0x248)
>> [ 923.007120] [<c043a76c>] (cpuidle_idle_call+0xa8/0x248) from
>> [<c0009df8>] (arch_cpu_idle+0x8/0x44)
>> [ 923.016128] [<c0009df8>] (arch_cpu_idle+0x8/0x44) from [<c0052aa0>]
>> (cpu_startup_entry+0xe8/0x218)
>> [ 923.025152] [<c0052aa0>] (cpu_startup_entry+0xe8/0x218) from
>> [<c06fca1c>] (start_kernel+0x308/0x368)
>> [ 923.034338] ---[ end trace 1f99f5bb6d86ce00 ]---
>> [ 923.038991] mwifiex_sdio mmc0:0001:1: 61622 : Tx timeout(#1),
>> bss_type-num = 1-0
>> [ 932.826851] mwifiex_sdio mmc0:0001:1: 62601 : Tx timeout(#2),
>> bss_type-num = 1-0
>> [ 942.826950] mwifiex_sdio mmc0:0001:1: 63601 : Tx timeout(#3),
>> bss_type-num = 1-0
>> [ 952.827043] mwifiex_sdio mmc0:0001:1: 64601 : Tx timeout(#4),
>> bss_type-num = 1-0
>> [ 962.827135] mwifiex_sdio mmc0:0001:1: 65601 : Tx timeout(#5),
>> bss_type-num = 1-0
>> [ 972.827204] mwifiex_sdio mmc0:0001:1: 66601 : Tx timeout(#6),
>> bss_type-num = 1-0
>> [ 982.827274] mwifiex_sdio mmc0:0001:1: 67601 : Tx timeout(#7),
>> bss_type-num = 1-0
>> [ 982.834710] mwifiex_sdio mmc0:0001:1: tx_timeout_cnt exceeds
>> threshold. Triggering card reset!
>> [ 982.847311] mwifiex_sdio: Resetting card...
>> [ 982.858835] mwifiex_sdio mmc0:0001:1: rx_pending=0, tx_pending=134,
>> cmd_pending=0
>> [ 982.890370] br0: port 3(uap0) entered disabled state
>> [ 982.927420] mwifiex_sdio mmc0:0001:1: PREP_CMD: card is removed
>> [ 982.933379] ieee80211 phy0: Failed to delete mgmt IEs!
>> [ 982.944768] mwifiex_sdio mmc0:0001:1: PREP_CMD: card is removed
>> [ 982.954303] ieee80211 phy0: Failed to stop the BSS
>> [ 982.965174] br0: port 3(uap0) entered disabled state
>> [ 982.997332] device uap0 left promiscuous mode
>> [ 983.002107] br0: port 3(uap0) entered disabled state
>> [ 983.047777] mmc0: card 0001 removed
>> [ 983.162307] mmc0: new high speed SDIO card at address 0001
>> [ 994.467374] mwifiex_sdio mmc0:0001:1: FW failed to be active in time
>> <span class="sew7w4eq1wq2zww"><br></span>====
>>
>>
>> Firstly, I'm guessing there's more debug information to be had - is
>> there a flag I should be turning on to get some more useful output?
>> Would the hostapd debug output help?
>>
>> Secondly, I've never seen the card come back up after the driver
>> resets it. Does this normally work?
>>
>> Thirdly, if I try to kill hostapd after pings from my test machine
>> stop working but before the watchdog triggers, I get a kernel log that
>> looks like this:
>> ====
>> [ 415.625875] mwifiex_sdio mmc0:0001:1: cmd_wait_q terminated: -512
>> [ 417.554508] mwifiex_sdio mmc0:0001:1: cmd_wait_q terminated: -512
>> [ 417.637845] mwifiex_sdio mmc0:0001:1: cmd_wait_q terminated: -512
>> [ 420.831554] mwifiex_sdio mmc0:0001:1: mwifiex_cmd_timeout_func:
>> Timeout cmd id (1391322753.261340) = 0xb5, act = 0x85c4
>> [ 420.842426] mwifiex_sdio mmc0:0001:1: num_data_h2c_failure = 0
>> [ 420.848289] mwifiex_sdio mmc0:0001:1: num_cmd_h2c_failure = 0
>> [ 420.854075] mwifiex_sdio mmc0:0001:1: num_cmd_timeout = 1
>> [ 420.859503] mwifiex_sdio mmc0:0001:1: num_tx_timeout = 0
>> [ 420.864851] mwifiex_sdio mmc0:0001:1: last_cmd_index = 4
>> [ 420.870184] mwifiex_sdio mmc0:0001:1: last_cmd_id: 28 00 5e 00 5e
>> 00 5e 00 b5 00
>> [ 420.877626] mwifiex_sdio mmc0:0001:1: last_cmd_act: 93 00 01 00 01
>> 00 01 00 c4 85
>> [ 420.885151] mwifiex_sdio mmc0:0001:1: last_cmd_resp_index = 3
>> [ 420.890920] mwifiex_sdio mmc0:0001:1: last_cmd_resp_id: 28 80 5e 80
>> 5e 80 5e 80 b1 80
>> [ 420.898798] mwifiex_sdio mmc0:0001:1: last_event_index = 3
>> [ 420.904316] mwifiex_sdio mmc0:0001:1: last_event: 00 00 2e 00 44 00
>> 2d 00 00 00
>> [ 420.911668] mwifiex_sdio mmc0:0001:1: data_sent=1 cmd_sent=1
>> [ 420.917351] mwifiex_sdio mmc0:0001:1: ps_mode=1 ps_state=0
>> [ 420.922875] mwifiex_sdio mmc0:0001:1: cmd timeout
>> [ 420.930569] mwifiex_sdio: Resetting card...
>> [ 420.950267] mwifiex_sdio mmc0:0001:1: rx_pending=0, tx_pending=3,
>> cmd_pending=0
>> [ 420.997056] br0: port 3(uap0) entered disabled state
>> [ 421.021696] mwifiex_sdio mmc0:0001:1: PREP_CMD: card is removed
>> [ 421.027655] ieee80211 phy0: Failed to delete mgmt IEs!
>> [ 421.037288] mwifiex_sdio mmc0:0001:1: PREP_CMD: card is removed
>> [ 421.047313] ieee80211 phy0: Failed to stop the BSS
>> [ 421.056754] br0: port 3(uap0) entered disabled state
>> [ 421.091582] device uap0 left promiscuous mode
>> [ 421.096165] br0: port 3(uap0) entered disabled state
>> [ 421.143900] mmc0: card 0001 removed
>> [ 421.236334] mmc0: new high speed SDIO card at address 0001
>> [ 432.541163] mwifiex_sdio mmc0:0001:1: FW failed to be active in time
>> ====
>>
>> So it looks like the entire card is hanging, rather than just a queue
>> getting stuck?
>>
>> Some environment info:
>>
>> kernel is 3.13.0 with mwifiex and mwifiex_sdio built as modules
>> hostapd is v2.0
>> Dreamplug is a variant of the Guruplug, and my distro (Arch Linux ARM)
>> patches it into the Guruplug boardfile
>> (Dreamplug has a DTS in mainline, but not a boardfile. This is a
>> non-DTB kernel - the DTB kernel seems to have trouble with SDIO
>> interrupt handling)
>>
>> Thanks,
>> Andrew
>> --
>> To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: mwifiex and SD8787: TX queue timeout in AP mode
2014-02-02 21:13 ` Andrew Wiley
@ 2014-02-03 6:47 ` Avinash Patil
2014-02-03 22:02 ` Andrew Wiley
0 siblings, 1 reply; 11+ messages in thread
From: Avinash Patil @ 2014-02-03 6:47 UTC (permalink / raw)
To: Andrew Wiley; +Cc: linux-wireless
Hi Andrew,
I would suggest few steps:
1. Disable hostapd probe response generation with following setting in
hostadp conf
send_probe_response=0
2. I see lot of prints for realloc headroom. While this is harmless,
if you have any setting to increase this headroom from network stack,
it would be good.
It looks like Tx to FW has timed out. Last TX happened at Line 11384.
This issue is different from earlier one.
Can you please let me know FW version?
Does this issue happens with station interface as well?
Thanks,
Avinash
On Mon, Feb 3, 2014 at 2:43 AM, Andrew Wiley <wiley.andrew.j@gmail.com> wrote:
> Hello Avinash,
>
> Here's one such log: http://www.cs.utexas.edu/users/wiley/mwifiexlog_1.txt
>
> This was run with the WPA2 options uncommented in hostapd.conf. Pings
> through the AP were successful for about 10 seconds after my test
> machine joined the network. It looks like they started timing out at
> about 150s in the kernel log, but `dmesg -w` seems to print messages
> lazily, so it might be a bit later than that.
>
> Let me know if there's something else I should try to capture.
>
> Thanks,
> Andrew
>
> On Sun, Feb 2, 2014 at 1:45 AM, Avinash Patil <avinashapatil@gmail.com> wrote:
>> Hi Andrew,
>>
>> It looks like AP_STA_DEAUTH command is timed out.
>>
>> Can you please enable dynamic debug and collect logs with attached change?
>>
>> 1. CONFIG_DYNAMIC_DEBUG=y in kernel .config and rebuild the kernel
>> 2. Load the driver.
>> 3. echo "module mwifiex +p" > /sys/kernel/debug/dynamic_debug/control
>> 4. echo "module mwifiex_sdio +p" > /sys/kernel/debug/dynamic_debug/control
>> 5. save the logs from dmesg after the test.
>>
>> Thanks,
>> Avinash.
>>
>>
>> On Sun, Feb 2, 2014 at 12:11 PM, Andrew Wiley <wiley.andrew.j@gmail.com> wrote:
>>> Hello linux-wireless,
>>>
>>> I'm observing a consistent TX queue timeout with a SD8787 on a Marvell
>>> Kirkwood-based Dreamplug running the mwifiex driver.
>>>
>>> In particular, with this hostapd config:
>>> ====
>>> interface=uap0
>>> bridge=br0
>>> driver=nl80211
>>> logger_stdout=-1
>>> logger_stdout_level=2
>>> ssid=My Clever SSID
>>> country_code=US
>>> ieee80211d=1
>>>
>>> hw_mode=g
>>> channel=4
>>> auth_algs=3
>>> max_num_sta=255
>>>
>>> #wpa=2
>>> #wpa_passphrase=EvenClevererPassphrase
>>> #wpa_key_mgmt=WPA-PSK
>>> #wpa_pairwise=TKIP
>>> #rsn_pairwise=CCMP
>>> ====
>>>
>>> I see a hang within about an hour. If I uncomment the encryption
>>> settings, the hang generally occurs a few seconds after my testing
>>> laptop gets on the network (long enough for ~2 pings to return).
>>> I did have one instance where, with encryption enabled, the network
>>> stayed up for an hour or so, but I haven't managed to replicate it.
>>>
>>> The timeout consistently looks like this in the kernel log:
>>> ====
>>> [ 922.826726] ------------[ cut here ]------------
>>> [ 922.831395] WARNING: CPU: 0 PID: 0 at net/sched/sch_generic.c:264
>>> dev_watchdog+0x2d0/0x2f0()
>>> [ 922.839897] NETDEV WATCHDOG: uap0 (mwifiex_sdio): transmit queue 1 timed out
>>> [ 922.846986] Modules linked in: iptable_raw ipt_MASQUERADE xt_nat
>>> bridge iptable_nat nf_nat_ipv4 nf_nat stp llc iptable_mangle xt_policy
>>> xt_tcpudp nf_conntrack_ipv6 nf_conntrack_ipv4 nf_defrag_ipv6
>>> nf_defrag_ipv4 xt_conntrack nf_conntrack iptable_filter
>>> ip6table_filter ip6_tables ip_tables x_tables hid_generic mwifiex_sdio
>>> snd_usb_audio snd_usbmidi_lib snd_hwdep snd_rawmidi mwifiex
>>> snd_seq_device cfg80211 snd_pcm snd_page_alloc usbhid snd_timer snd
>>> hid soundcore rfkill mv_cesa usbip_host(C) usbip_core(C) ipv6 autofs4
>>> [ 922.893323] CPU: 0 PID: 0 Comm: swapper Tainted: G C
>>> 3.13.0-2-ARCH #1
>>> [ 922.900698] [<c000ee04>] (unwind_backtrace+0x0/0xe8) from
>>> [<c000c354>] (show_stack+0x10/0x14)
>>> [ 922.909285] [<c000c354>] (show_stack+0x10/0x14) from [<c001a780>]
>>> (warn_slowpath_common+0x70/0x90)
>>> [ 922.918307] [<c001a780>] (warn_slowpath_common+0x70/0x90) from
>>> [<c001a7d0>] (warn_slowpath_fmt+0x30/0x40)
>>> [ 922.927949] [<c001a7d0>] (warn_slowpath_fmt+0x30/0x40) from
>>> [<c04aa51c>] (dev_watchdog+0x2d0/0x2f0)
>>> [ 922.937059] [<c04aa51c>] (dev_watchdog+0x2d0/0x2f0) from
>>> [<c00258f8>] (call_timer_fn+0x30/0x170)
>>> [ 922.945903] [<c00258f8>] (call_timer_fn+0x30/0x170) from
>>> [<c0025eb4>] (run_timer_softirq+0x1f8/0x368)
>>> [ 922.955187] [<c0025eb4>] (run_timer_softirq+0x1f8/0x368) from
>>> [<c001ec00>] (__do_softirq+0xdc/0x304)
>>> [ 922.964384] [<c001ec00>] (__do_softirq+0xdc/0x304) from
>>> [<c001f1a4>] (irq_exit+0xb0/0xf8)
>>> [ 922.972615] [<c001f1a4>] (irq_exit+0xb0/0xf8) from [<c0009c80>]
>>> (handle_IRQ+0x34/0x84)
>>> [ 922.980585] [<c0009c80>] (handle_IRQ+0x34/0x84) from [<c052ef54>]
>>> (__irq_svc+0x34/0x98)
>>> [ 922.988647] [<c052ef54>] (__irq_svc+0x34/0x98) from [<c043a638>]
>>> (cpuidle_enter_state+0x5c/0xe8)
>>> [ 922.997494] [<c043a638>] (cpuidle_enter_state+0x5c/0xe8) from
>>> [<c043a76c>] (cpuidle_idle_call+0xa8/0x248)
>>> [ 923.007120] [<c043a76c>] (cpuidle_idle_call+0xa8/0x248) from
>>> [<c0009df8>] (arch_cpu_idle+0x8/0x44)
>>> [ 923.016128] [<c0009df8>] (arch_cpu_idle+0x8/0x44) from [<c0052aa0>]
>>> (cpu_startup_entry+0xe8/0x218)
>>> [ 923.025152] [<c0052aa0>] (cpu_startup_entry+0xe8/0x218) from
>>> [<c06fca1c>] (start_kernel+0x308/0x368)
>>> [ 923.034338] ---[ end trace 1f99f5bb6d86ce00 ]---
>>> [ 923.038991] mwifiex_sdio mmc0:0001:1: 61622 : Tx timeout(#1),
>>> bss_type-num = 1-0
>>> [ 932.826851] mwifiex_sdio mmc0:0001:1: 62601 : Tx timeout(#2),
>>> bss_type-num = 1-0
>>> [ 942.826950] mwifiex_sdio mmc0:0001:1: 63601 : Tx timeout(#3),
>>> bss_type-num = 1-0
>>> [ 952.827043] mwifiex_sdio mmc0:0001:1: 64601 : Tx timeout(#4),
>>> bss_type-num = 1-0
>>> [ 962.827135] mwifiex_sdio mmc0:0001:1: 65601 : Tx timeout(#5),
>>> bss_type-num = 1-0
>>> [ 972.827204] mwifiex_sdio mmc0:0001:1: 66601 : Tx timeout(#6),
>>> bss_type-num = 1-0
>>> [ 982.827274] mwifiex_sdio mmc0:0001:1: 67601 : Tx timeout(#7),
>>> bss_type-num = 1-0
>>> [ 982.834710] mwifiex_sdio mmc0:0001:1: tx_timeout_cnt exceeds
>>> threshold. Triggering card reset!
>>> [ 982.847311] mwifiex_sdio: Resetting card...
>>> [ 982.858835] mwifiex_sdio mmc0:0001:1: rx_pending=0, tx_pending=134,
>>> cmd_pending=0
>>> [ 982.890370] br0: port 3(uap0) entered disabled state
>>> [ 982.927420] mwifiex_sdio mmc0:0001:1: PREP_CMD: card is removed
>>> [ 982.933379] ieee80211 phy0: Failed to delete mgmt IEs!
>>> [ 982.944768] mwifiex_sdio mmc0:0001:1: PREP_CMD: card is removed
>>> [ 982.954303] ieee80211 phy0: Failed to stop the BSS
>>> [ 982.965174] br0: port 3(uap0) entered disabled state
>>> [ 982.997332] device uap0 left promiscuous mode
>>> [ 983.002107] br0: port 3(uap0) entered disabled state
>>> [ 983.047777] mmc0: card 0001 removed
>>> [ 983.162307] mmc0: new high speed SDIO card at address 0001
>>> [ 994.467374] mwifiex_sdio mmc0:0001:1: FW failed to be active in time
>>> <span class="sew7w4eq1wq2zww"><br></span>====
>>>
>>>
>>> Firstly, I'm guessing there's more debug information to be had - is
>>> there a flag I should be turning on to get some more useful output?
>>> Would the hostapd debug output help?
>>>
>>> Secondly, I've never seen the card come back up after the driver
>>> resets it. Does this normally work?
>>>
>>> Thirdly, if I try to kill hostapd after pings from my test machine
>>> stop working but before the watchdog triggers, I get a kernel log that
>>> looks like this:
>>> ====
>>> [ 415.625875] mwifiex_sdio mmc0:0001:1: cmd_wait_q terminated: -512
>>> [ 417.554508] mwifiex_sdio mmc0:0001:1: cmd_wait_q terminated: -512
>>> [ 417.637845] mwifiex_sdio mmc0:0001:1: cmd_wait_q terminated: -512
>>> [ 420.831554] mwifiex_sdio mmc0:0001:1: mwifiex_cmd_timeout_func:
>>> Timeout cmd id (1391322753.261340) = 0xb5, act = 0x85c4
>>> [ 420.842426] mwifiex_sdio mmc0:0001:1: num_data_h2c_failure = 0
>>> [ 420.848289] mwifiex_sdio mmc0:0001:1: num_cmd_h2c_failure = 0
>>> [ 420.854075] mwifiex_sdio mmc0:0001:1: num_cmd_timeout = 1
>>> [ 420.859503] mwifiex_sdio mmc0:0001:1: num_tx_timeout = 0
>>> [ 420.864851] mwifiex_sdio mmc0:0001:1: last_cmd_index = 4
>>> [ 420.870184] mwifiex_sdio mmc0:0001:1: last_cmd_id: 28 00 5e 00 5e
>>> 00 5e 00 b5 00
>>> [ 420.877626] mwifiex_sdio mmc0:0001:1: last_cmd_act: 93 00 01 00 01
>>> 00 01 00 c4 85
>>> [ 420.885151] mwifiex_sdio mmc0:0001:1: last_cmd_resp_index = 3
>>> [ 420.890920] mwifiex_sdio mmc0:0001:1: last_cmd_resp_id: 28 80 5e 80
>>> 5e 80 5e 80 b1 80
>>> [ 420.898798] mwifiex_sdio mmc0:0001:1: last_event_index = 3
>>> [ 420.904316] mwifiex_sdio mmc0:0001:1: last_event: 00 00 2e 00 44 00
>>> 2d 00 00 00
>>> [ 420.911668] mwifiex_sdio mmc0:0001:1: data_sent=1 cmd_sent=1
>>> [ 420.917351] mwifiex_sdio mmc0:0001:1: ps_mode=1 ps_state=0
>>> [ 420.922875] mwifiex_sdio mmc0:0001:1: cmd timeout
>>> [ 420.930569] mwifiex_sdio: Resetting card...
>>> [ 420.950267] mwifiex_sdio mmc0:0001:1: rx_pending=0, tx_pending=3,
>>> cmd_pending=0
>>> [ 420.997056] br0: port 3(uap0) entered disabled state
>>> [ 421.021696] mwifiex_sdio mmc0:0001:1: PREP_CMD: card is removed
>>> [ 421.027655] ieee80211 phy0: Failed to delete mgmt IEs!
>>> [ 421.037288] mwifiex_sdio mmc0:0001:1: PREP_CMD: card is removed
>>> [ 421.047313] ieee80211 phy0: Failed to stop the BSS
>>> [ 421.056754] br0: port 3(uap0) entered disabled state
>>> [ 421.091582] device uap0 left promiscuous mode
>>> [ 421.096165] br0: port 3(uap0) entered disabled state
>>> [ 421.143900] mmc0: card 0001 removed
>>> [ 421.236334] mmc0: new high speed SDIO card at address 0001
>>> [ 432.541163] mwifiex_sdio mmc0:0001:1: FW failed to be active in time
>>> ====
>>>
>>> So it looks like the entire card is hanging, rather than just a queue
>>> getting stuck?
>>>
>>> Some environment info:
>>>
>>> kernel is 3.13.0 with mwifiex and mwifiex_sdio built as modules
>>> hostapd is v2.0
>>> Dreamplug is a variant of the Guruplug, and my distro (Arch Linux ARM)
>>> patches it into the Guruplug boardfile
>>> (Dreamplug has a DTS in mainline, but not a boardfile. This is a
>>> non-DTB kernel - the DTB kernel seems to have trouble with SDIO
>>> interrupt handling)
>>>
>>> Thanks,
>>> Andrew
>>> --
>>> To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
>>> the body of a message to majordomo@vger.kernel.org
>>> More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: mwifiex and SD8787: TX queue timeout in AP mode
2014-02-03 6:47 ` Avinash Patil
@ 2014-02-03 22:02 ` Andrew Wiley
2014-02-03 22:16 ` Andrew Wiley
0 siblings, 1 reply; 11+ messages in thread
From: Andrew Wiley @ 2014-02-03 22:02 UTC (permalink / raw)
To: Avinash Patil; +Cc: linux-wireless
Hello Avinash,
On Mon, Feb 3, 2014 at 12:47 AM, Avinash Patil <avinashapatil@gmail.com> wrote:
> Hi Andrew,
>
> I would suggest few steps:
> 1. Disable hostapd probe response generation with following setting in
> hostadp conf
> send_probe_response=0
This doesn't seem to have an effect on the issue.
> 2. I see lot of prints for realloc headroom. While this is harmless,
> if you have any setting to increase this headroom from network stack,
> it would be good.
I'm not sure what userspace setting would correspond to this. The only
thing that looks related is /proc/sys/net/core/rmem_default and
/proc/sys/net/core/wmem_default, but those seem to operate on memory
pools rather than individual buffers.
>
> It looks like Tx to FW has timed out. Last TX happened at Line 11384.
> This issue is different from earlier one.
> Can you please let me know FW version?
mwifiex logs this on startup:
mwifiex_sdio mmc0:0001:1: driver_version = mwifiex 1.0 (14.66.9.p96)
> Does this issue happens with station interface as well?
I haven't really made use of station mode much, but I just tried it
and it seems stable. The first time I tried to connect, the driver had
a command timeout while scanning and the card dropped out, but the
second time, it connected and has stayed stable for 30 minutes or so.
The network I'm connected to uses WPA2. I'll continue to monitor the
box to see if the queue hangs.
Thanks,
Andrew
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: mwifiex and SD8787: TX queue timeout in AP mode
2014-02-03 22:02 ` Andrew Wiley
@ 2014-02-03 22:16 ` Andrew Wiley
2014-02-04 1:17 ` Andrew Wiley
0 siblings, 1 reply; 11+ messages in thread
From: Andrew Wiley @ 2014-02-03 22:16 UTC (permalink / raw)
To: Avinash Patil; +Cc: linux-wireless
On Mon, Feb 3, 2014 at 4:02 PM, Andrew Wiley <wiley.andrew.j@gmail.com> wrote:
> On Mon, Feb 3, 2014 at 12:47 AM, Avinash Patil <avinashapatil@gmail.com> wrote:
>> Does this issue happens with station interface as well?
>
> I haven't really made use of station mode much, but I just tried it
> and it seems stable. The first time I tried to connect, the driver had
> a command timeout while scanning and the card dropped out, but the
> second time, it connected and has stayed stable for 30 minutes or so.
> The network I'm connected to uses WPA2. I'll continue to monitor the
> box to see if the queue hangs.
>
A few minutes after I wrote this, the box hung. No kernel errors were
logged in the serial console - it just stopped responding.
I'll have to investigate this further.
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: mwifiex and SD8787: TX queue timeout in AP mode
2014-02-03 22:16 ` Andrew Wiley
@ 2014-02-04 1:17 ` Andrew Wiley
2014-02-04 15:57 ` Avinash Patil
0 siblings, 1 reply; 11+ messages in thread
From: Andrew Wiley @ 2014-02-04 1:17 UTC (permalink / raw)
To: Avinash Patil; +Cc: linux-wireless
On Mon, Feb 3, 2014 at 4:16 PM, Andrew Wiley <wiley.andrew.j@gmail.com> wrote:
> On Mon, Feb 3, 2014 at 4:02 PM, Andrew Wiley <wiley.andrew.j@gmail.com> wrote:
>> On Mon, Feb 3, 2014 at 12:47 AM, Avinash Patil <avinashapatil@gmail.com> wrote:
>>> Does this issue happens with station interface as well?
>>
>> I haven't really made use of station mode much, but I just tried it
>> and it seems stable. The first time I tried to connect, the driver had
>> a command timeout while scanning and the card dropped out, but the
>> second time, it connected and has stayed stable for 30 minutes or so.
>> The network I'm connected to uses WPA2. I'll continue to monitor the
>> box to see if the queue hangs.
>>
>
> A few minutes after I wrote this, the box hung. No kernel errors were
> logged in the serial console - it just stopped responding.
> I'll have to investigate this further.
There's a consistent but random hang in station mode. I've reproduced
it five times at this point - the serial console hangs and the
heartbeat LED gets stuck on. There aren't any errors leading up to the
hang.
Here's the last lines of dmesg that printed before the hang:
----
[ 5021.924439] mwifiex_sdio mmc0:0001:1: info: --- Rx: Data packet ---
[ 5021.924576] mwifiex_sdio mmc0:0001:1: data: 471285 BSS(0-0): Data <= kernel
[ 5021.924616] mwifiex_sdio mmc0:0001:1: data: mp_rd_bitmap=0x00000000
[ 5021.924627] mwifiex_sdio mmc0:0001:1: info: no more rd_port available
[ 5021.924644] mwifiex_sdio mmc0:0001:1: data: tid=0
[ 5021.924658] mwifiex_sdio mmc0:0001:1: data: dequeuing the packet
ddfb1240 db063cc0
[ 5021.924674] mwifiex_sdio mmc0:0001:1: data: WMM: Pkt Delay: 0 ms, 0
ms sent to FW
[ 5021.924685] mwifiex_sdio mmc0:0001:1: data: mp_wr_bitmap=0x0000007f
[ 5021.924697] mwifiex_sdio mmc0:0001:1: data: port=1
mp_wr_bitmap=0x0000007f -> 0x0000007d
[ 5021.924708] mwifiex_sdio mmc0:0001:1: info:
mwifiex_host_to_card_mp_aggr: Last packet in Tx Queue.
[ 5021.924719] mwifiex_sdio mmc0:0001:1: data:
mwifiex_host_to_card_mp_aggr: send current buffer 1
[ 5021.979992] mwifiex_sdio mmc0:0001:1: int: sdio_ireg = 0x1
[ 5021.980014] mwifiex_sdio mmc0:0001:1: info: cmd_sent=0 data_sent=0
[ 5021.980025] mwifiex_sdio mmc0:0001:1: int: UPLD: rd_bitmap=0x1
[ 5021.980034] mwifiex_sdio mmc0:0001:1: data: mp_rd_bitmap=0x00000001
[ 5021.980045] mwifiex_sdio mmc0:0001:1: data: port=0 mp_rd_bitmap=0x00000000
[ 5021.980055] mwifiex_sdio mmc0:0001:1: info: RX: port=0 rx_len=10
[ 5021.980068] mwifiex_sdio mmc0:0001:1: info: rx_len = 256 skb->len = 256
[ 5021.980079] mwifiex_sdio mmc0:0001:1: info:
mwifiex_sdio_card_to_host_mp_aggr: no aggregation for cmd response
[ 5021.980089] mwifiex_sdio mmc0:0001:1: info: RX: port: 0, rx_len: 256
[ 5021.980137] mwifiex_sdio mmc0:0001:1: info: --- Rx: Event ---
[ 5021.980150] mwifiex_sdio mmc0:0001:1: data: mp_rd_bitmap=0x00000000
[ 5021.980159] mwifiex_sdio mmc0:0001:1: info: no more rd_port available
[ 5021.980171] mwifiex_sdio mmc0:0001:1: info: EVENT: SLEEP
[ 5021.980183] mwifiex_sdio mmc0:0001:1: info:
mwifiex_host_to_card_mp_aggr: tx aggregation disabled
[ 5021.980194] mwifiex_sdio mmc0:0001:1: data:
mwifiex_host_to_card_mp_aggr: send current buffer 0
[ 5021.980326] mwifiex_sdio mmc0:0001:1: int: sdio_ireg = 0x1
[ 5021.980341] mwifiex_sdio mmc0:0001:1: info: cmd_sent=0 data_sent=0
[ 5021.980351] mwifiex_sdio mmc0:0001:1: int: UPLD: rd_bitmap=0x1
[ 5021.980361] mwifiex_sdio mmc0:0001:1: data: mp_rd_bitmap=0x00000001
[ 5021.980371] mwifiex_sdio mmc0:0001:1: data: port=0 mp_rd_bitmap=0x00000000
[ 5021.980380] mwifiex_sdio mmc0:0001:1: info: RX: port=0 rx_len=16
[ 5021.980392] mwifiex_sdio mmc0:0001:1: info: rx_len = 256 skb->len = 256
[ 5021.980403] mwifiex_sdio mmc0:0001:1: info:
mwifiex_sdio_card_to_host_mp_aggr: no aggregation for cmd response
[ 5021.980413] mwifiex_sdio mmc0:0001:1: info: RX: port: 0, rx_len: 256
[ 5021.980456] mwifiex_sdio mmc0:0001:1: info: --- Rx: Cmd Response ---
[ 5021.980471] mwifiex_sdio mmc0:0001:1: data: mp_rd_bitmap=0x00000000
[ 5021.980480] mwifiex_sdio mmc0:0001:1: info: no more rd_port available
----
Unfortunately, this is from `dmesg -w` and not directly from the
serial console - I think I'll have to recompile the kernel again to
get these debug messages to show up on the serial console, and I'm not
sure what will happen when the message rate exceeds the speed of the
serial connection.
Is this likely a separate issue? Should I see if I can get GDB set up
over JTAG and dump the message buffers after the lockup?
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: mwifiex and SD8787: TX queue timeout in AP mode
2014-02-04 1:17 ` Andrew Wiley
@ 2014-02-04 15:57 ` Avinash Patil
2014-02-05 6:52 ` Andrew Wiley
0 siblings, 1 reply; 11+ messages in thread
From: Avinash Patil @ 2014-02-04 15:57 UTC (permalink / raw)
To: Andrew Wiley; +Cc: linux-wireless
Hi Andrew,
I think this issue not specific to any interface as such.
Do you have following fix in your tree:
http://www.spinics.net/lists/linux-wireless/msg112753.html
Also can you please try printing adapter->int_status during AP TX data timeout?
Thanks,
Avinash
On Tue, Feb 4, 2014 at 6:47 AM, Andrew Wiley <wiley.andrew.j@gmail.com> wrote:
> On Mon, Feb 3, 2014 at 4:16 PM, Andrew Wiley <wiley.andrew.j@gmail.com> wrote:
>> On Mon, Feb 3, 2014 at 4:02 PM, Andrew Wiley <wiley.andrew.j@gmail.com> wrote:
>>> On Mon, Feb 3, 2014 at 12:47 AM, Avinash Patil <avinashapatil@gmail.com> wrote:
>>>> Does this issue happens with station interface as well?
>>>
>>> I haven't really made use of station mode much, but I just tried it
>>> and it seems stable. The first time I tried to connect, the driver had
>>> a command timeout while scanning and the card dropped out, but the
>>> second time, it connected and has stayed stable for 30 minutes or so.
>>> The network I'm connected to uses WPA2. I'll continue to monitor the
>>> box to see if the queue hangs.
>>>
>>
>> A few minutes after I wrote this, the box hung. No kernel errors were
>> logged in the serial console - it just stopped responding.
>> I'll have to investigate this further.
>
> There's a consistent but random hang in station mode. I've reproduced
> it five times at this point - the serial console hangs and the
> heartbeat LED gets stuck on. There aren't any errors leading up to the
> hang.
>
> Here's the last lines of dmesg that printed before the hang:
>
> ----
> [ 5021.924439] mwifiex_sdio mmc0:0001:1: info: --- Rx: Data packet ---
> [ 5021.924576] mwifiex_sdio mmc0:0001:1: data: 471285 BSS(0-0): Data <= kernel
> [ 5021.924616] mwifiex_sdio mmc0:0001:1: data: mp_rd_bitmap=0x00000000
> [ 5021.924627] mwifiex_sdio mmc0:0001:1: info: no more rd_port available
> [ 5021.924644] mwifiex_sdio mmc0:0001:1: data: tid=0
> [ 5021.924658] mwifiex_sdio mmc0:0001:1: data: dequeuing the packet
> ddfb1240 db063cc0
> [ 5021.924674] mwifiex_sdio mmc0:0001:1: data: WMM: Pkt Delay: 0 ms, 0
> ms sent to FW
> [ 5021.924685] mwifiex_sdio mmc0:0001:1: data: mp_wr_bitmap=0x0000007f
> [ 5021.924697] mwifiex_sdio mmc0:0001:1: data: port=1
> mp_wr_bitmap=0x0000007f -> 0x0000007d
> [ 5021.924708] mwifiex_sdio mmc0:0001:1: info:
> mwifiex_host_to_card_mp_aggr: Last packet in Tx Queue.
> [ 5021.924719] mwifiex_sdio mmc0:0001:1: data:
> mwifiex_host_to_card_mp_aggr: send current buffer 1
> [ 5021.979992] mwifiex_sdio mmc0:0001:1: int: sdio_ireg = 0x1
> [ 5021.980014] mwifiex_sdio mmc0:0001:1: info: cmd_sent=0 data_sent=0
> [ 5021.980025] mwifiex_sdio mmc0:0001:1: int: UPLD: rd_bitmap=0x1
> [ 5021.980034] mwifiex_sdio mmc0:0001:1: data: mp_rd_bitmap=0x00000001
> [ 5021.980045] mwifiex_sdio mmc0:0001:1: data: port=0 mp_rd_bitmap=0x00000000
> [ 5021.980055] mwifiex_sdio mmc0:0001:1: info: RX: port=0 rx_len=10
> [ 5021.980068] mwifiex_sdio mmc0:0001:1: info: rx_len = 256 skb->len = 256
> [ 5021.980079] mwifiex_sdio mmc0:0001:1: info:
> mwifiex_sdio_card_to_host_mp_aggr: no aggregation for cmd response
> [ 5021.980089] mwifiex_sdio mmc0:0001:1: info: RX: port: 0, rx_len: 256
> [ 5021.980137] mwifiex_sdio mmc0:0001:1: info: --- Rx: Event ---
> [ 5021.980150] mwifiex_sdio mmc0:0001:1: data: mp_rd_bitmap=0x00000000
> [ 5021.980159] mwifiex_sdio mmc0:0001:1: info: no more rd_port available
> [ 5021.980171] mwifiex_sdio mmc0:0001:1: info: EVENT: SLEEP
> [ 5021.980183] mwifiex_sdio mmc0:0001:1: info:
> mwifiex_host_to_card_mp_aggr: tx aggregation disabled
> [ 5021.980194] mwifiex_sdio mmc0:0001:1: data:
> mwifiex_host_to_card_mp_aggr: send current buffer 0
> [ 5021.980326] mwifiex_sdio mmc0:0001:1: int: sdio_ireg = 0x1
> [ 5021.980341] mwifiex_sdio mmc0:0001:1: info: cmd_sent=0 data_sent=0
> [ 5021.980351] mwifiex_sdio mmc0:0001:1: int: UPLD: rd_bitmap=0x1
> [ 5021.980361] mwifiex_sdio mmc0:0001:1: data: mp_rd_bitmap=0x00000001
> [ 5021.980371] mwifiex_sdio mmc0:0001:1: data: port=0 mp_rd_bitmap=0x00000000
> [ 5021.980380] mwifiex_sdio mmc0:0001:1: info: RX: port=0 rx_len=16
> [ 5021.980392] mwifiex_sdio mmc0:0001:1: info: rx_len = 256 skb->len = 256
> [ 5021.980403] mwifiex_sdio mmc0:0001:1: info:
> mwifiex_sdio_card_to_host_mp_aggr: no aggregation for cmd response
> [ 5021.980413] mwifiex_sdio mmc0:0001:1: info: RX: port: 0, rx_len: 256
> [ 5021.980456] mwifiex_sdio mmc0:0001:1: info: --- Rx: Cmd Response ---
> [ 5021.980471] mwifiex_sdio mmc0:0001:1: data: mp_rd_bitmap=0x00000000
> [ 5021.980480] mwifiex_sdio mmc0:0001:1: info: no more rd_port available
> ----
>
> Unfortunately, this is from `dmesg -w` and not directly from the
> serial console - I think I'll have to recompile the kernel again to
> get these debug messages to show up on the serial console, and I'm not
> sure what will happen when the message rate exceeds the speed of the
> serial connection.
>
> Is this likely a separate issue? Should I see if I can get GDB set up
> over JTAG and dump the message buffers after the lockup?
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: mwifiex and SD8787: TX queue timeout in AP mode
2014-02-04 15:57 ` Avinash Patil
@ 2014-02-05 6:52 ` Andrew Wiley
2014-02-06 7:04 ` Avinash Patil
0 siblings, 1 reply; 11+ messages in thread
From: Andrew Wiley @ 2014-02-05 6:52 UTC (permalink / raw)
To: Avinash Patil; +Cc: linux-wireless
Hello Avinash,
On Tue, Feb 4, 2014 at 9:57 AM, Avinash Patil <avinashapatil@gmail.com> wrote:
> Hi Andrew,
>
> I think this issue not specific to any interface as such.
>
> Do you have following fix in your tree:
>
> http://www.spinics.net/lists/linux-wireless/msg112753.html
Yes.
I'm running 3.13.1, which includes that fix.
>
> Also can you please try printing adapter->int_status during AP TX data timeout?
I added a printk after the TX timeout warning and got this:
[ 437.677151] ------------[ cut here ]------------
[ 437.681815] WARNING: CPU: 0 PID: 423 at net/sched/sch_generic.c:264
dev_watchdog+0x2d0/0x2f0()
[ 437.690485] NETDEV WATCHDOG: uap0 (mwifiex_sdio): transmit queue 1 timed out
[ 437.697580] Modules linked in: iptable_raw ipt_MASQUERADE xt_nat
iptable_nat nf_nat_ipv4 nf_nat iptable_mangle xt_policy
nf_conntrack_ipv4 xt_tcpudp nf_defrag_ipv4 bridge nf_conntrack_ipv6
nf_defrag_ipv6 stp llc xt_conntrack nf_conntrack iptable_filter
ip6table_filter ip6_tables ip_tables x_tables hid_generic
snd_usb_audio snd_usbmidi_lib mwifiex_sdio mwifiex snd_hwdep
snd_rawmidi snd_seq_device snd_pcm snd_page_alloc snd_timer cfg80211
snd usbhid soundcore hid rfkill mv_cesa usbip_host(C) usbip_core(C)
ipv6 autofs4
[ 437.743904] CPU: 0 PID: 423 Comm: tmux Tainted: G C
3.13.1-2-ARCH #1
[ 437.751189] [<c000f01c>] (unwind_backtrace+0x0/0x128) from
[<c000c394>] (show_stack+0x10/0x14)
[ 437.759892] [<c000c394>] (show_stack+0x10/0x14) from [<c001aa80>]
(warn_slowpath_common+0x70/0x90)
[ 437.768923] [<c001aa80>] (warn_slowpath_common+0x70/0x90) from
[<c001aad0>] (warn_slowpath_fmt+0x30/0x40)
[ 437.778563] [<c001aad0>] (warn_slowpath_fmt+0x30/0x40) from
[<c04c6e50>] (dev_watchdog+0x2d0/0x2f0)
[ 437.787673] [<c04c6e50>] (dev_watchdog+0x2d0/0x2f0) from
[<c0025bf8>] (call_timer_fn+0x30/0x170)
[ 437.796512] [<c0025bf8>] (call_timer_fn+0x30/0x170) from
[<c00261b4>] (run_timer_softirq+0x1f8/0x368)
[ 437.805798] [<c00261b4>] (run_timer_softirq+0x1f8/0x368) from
[<c001ef00>] (__do_softirq+0xdc/0x304)
[ 437.814997] [<c001ef00>] (__do_softirq+0xdc/0x304) from
[<c001f4a4>] (irq_exit+0xb0/0xf8)
[ 437.823228] [<c001f4a4>] (irq_exit+0xb0/0xf8) from [<c0009cc0>]
(handle_IRQ+0x34/0x84)
[ 437.831199] [<c0009cc0>] (handle_IRQ+0x34/0x84) from [<c054cb38>]
(__irq_usr+0x38/0xa0)
[ 437.839248] ---[ end trace 14ce7b4e4b0c47cb ]---
[ 437.843888] mwifiex_sdio mmc0:0001:1: 12617 : Tx timeout(#1),
bss_type-num = 1-0
[ 437.851335] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
[ 447.676774] mwifiex_sdio mmc0:0001:1: 13601 : Tx timeout(#2),
bss_type-num = 1-0
[ 447.684238] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
[ 457.676409] mwifiex_sdio mmc0:0001:1: 14601 : Tx timeout(#3),
bss_type-num = 1-0
[ 457.683848] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
[ 467.676042] mwifiex_sdio mmc0:0001:1: 15601 : Tx timeout(#4),
bss_type-num = 1-0
[ 467.683501] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
[ 477.675679] mwifiex_sdio mmc0:0001:1: 16601 : Tx timeout(#5),
bss_type-num = 1-0
[ 477.683116] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
[ 487.675308] mwifiex_sdio mmc0:0001:1: 17601 : Tx timeout(#6),
bss_type-num = 1-0
[ 487.682760] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
[ 497.674942] mwifiex_sdio mmc0:0001:1: 18601 : Tx timeout(#7),
bss_type-num = 1-0
[ 497.682383] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
[ 497.688188] mwifiex_sdio mmc0:0001:1: tx_timeout_cnt exceeds
threshold. Triggering card reset!
[ 497.698397] mwifiex_sdio: Resetting card...
The full log is at
http://www.cs.utexas.edu/users/wiley/mwifiexlog_2.txt if you want to
take a look - I didn't trim it down this time. It has debug output for
mwifiex and mwifiex_sdio.
Thanks,
Andrew
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: mwifiex and SD8787: TX queue timeout in AP mode
2014-02-05 6:52 ` Andrew Wiley
@ 2014-02-06 7:04 ` Avinash Patil
2014-02-06 20:27 ` Andrew Wiley
0 siblings, 1 reply; 11+ messages in thread
From: Avinash Patil @ 2014-02-06 7:04 UTC (permalink / raw)
To: Andrew Wiley; +Cc: linux-wireless
Hi Andrew,
I ran this test on my x86_64 machine using 3.13 & same p96 FW. I could
not reproduce this issue after 4 hrs of ping.
This issue may be specific to Dreamplug and I dont have this hardware with me.
Can you please log a bug at bugzilla.kernel.org. Maintainers would
take care of it from there onwards.
Thanks,
Avinash.
On Wed, Feb 5, 2014 at 12:22 PM, Andrew Wiley <wiley.andrew.j@gmail.com> wrote:
> Hello Avinash,
>
> On Tue, Feb 4, 2014 at 9:57 AM, Avinash Patil <avinashapatil@gmail.com> wrote:
>> Hi Andrew,
>>
>> I think this issue not specific to any interface as such.
>>
>> Do you have following fix in your tree:
>>
>> http://www.spinics.net/lists/linux-wireless/msg112753.html
>
> Yes.
> I'm running 3.13.1, which includes that fix.
>
>>
>> Also can you please try printing adapter->int_status during AP TX data timeout?
>
> I added a printk after the TX timeout warning and got this:
>
> [ 437.677151] ------------[ cut here ]------------
> [ 437.681815] WARNING: CPU: 0 PID: 423 at net/sched/sch_generic.c:264
> dev_watchdog+0x2d0/0x2f0()
> [ 437.690485] NETDEV WATCHDOG: uap0 (mwifiex_sdio): transmit queue 1 timed out
> [ 437.697580] Modules linked in: iptable_raw ipt_MASQUERADE xt_nat
> iptable_nat nf_nat_ipv4 nf_nat iptable_mangle xt_policy
> nf_conntrack_ipv4 xt_tcpudp nf_defrag_ipv4 bridge nf_conntrack_ipv6
> nf_defrag_ipv6 stp llc xt_conntrack nf_conntrack iptable_filter
> ip6table_filter ip6_tables ip_tables x_tables hid_generic
> snd_usb_audio snd_usbmidi_lib mwifiex_sdio mwifiex snd_hwdep
> snd_rawmidi snd_seq_device snd_pcm snd_page_alloc snd_timer cfg80211
> snd usbhid soundcore hid rfkill mv_cesa usbip_host(C) usbip_core(C)
> ipv6 autofs4
> [ 437.743904] CPU: 0 PID: 423 Comm: tmux Tainted: G C
> 3.13.1-2-ARCH #1
> [ 437.751189] [<c000f01c>] (unwind_backtrace+0x0/0x128) from
> [<c000c394>] (show_stack+0x10/0x14)
> [ 437.759892] [<c000c394>] (show_stack+0x10/0x14) from [<c001aa80>]
> (warn_slowpath_common+0x70/0x90)
> [ 437.768923] [<c001aa80>] (warn_slowpath_common+0x70/0x90) from
> [<c001aad0>] (warn_slowpath_fmt+0x30/0x40)
> [ 437.778563] [<c001aad0>] (warn_slowpath_fmt+0x30/0x40) from
> [<c04c6e50>] (dev_watchdog+0x2d0/0x2f0)
> [ 437.787673] [<c04c6e50>] (dev_watchdog+0x2d0/0x2f0) from
> [<c0025bf8>] (call_timer_fn+0x30/0x170)
> [ 437.796512] [<c0025bf8>] (call_timer_fn+0x30/0x170) from
> [<c00261b4>] (run_timer_softirq+0x1f8/0x368)
> [ 437.805798] [<c00261b4>] (run_timer_softirq+0x1f8/0x368) from
> [<c001ef00>] (__do_softirq+0xdc/0x304)
> [ 437.814997] [<c001ef00>] (__do_softirq+0xdc/0x304) from
> [<c001f4a4>] (irq_exit+0xb0/0xf8)
> [ 437.823228] [<c001f4a4>] (irq_exit+0xb0/0xf8) from [<c0009cc0>]
> (handle_IRQ+0x34/0x84)
> [ 437.831199] [<c0009cc0>] (handle_IRQ+0x34/0x84) from [<c054cb38>]
> (__irq_usr+0x38/0xa0)
> [ 437.839248] ---[ end trace 14ce7b4e4b0c47cb ]---
> [ 437.843888] mwifiex_sdio mmc0:0001:1: 12617 : Tx timeout(#1),
> bss_type-num = 1-0
> [ 437.851335] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
> [ 447.676774] mwifiex_sdio mmc0:0001:1: 13601 : Tx timeout(#2),
> bss_type-num = 1-0
> [ 447.684238] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
> [ 457.676409] mwifiex_sdio mmc0:0001:1: 14601 : Tx timeout(#3),
> bss_type-num = 1-0
> [ 457.683848] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
> [ 467.676042] mwifiex_sdio mmc0:0001:1: 15601 : Tx timeout(#4),
> bss_type-num = 1-0
> [ 467.683501] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
> [ 477.675679] mwifiex_sdio mmc0:0001:1: 16601 : Tx timeout(#5),
> bss_type-num = 1-0
> [ 477.683116] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
> [ 487.675308] mwifiex_sdio mmc0:0001:1: 17601 : Tx timeout(#6),
> bss_type-num = 1-0
> [ 487.682760] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
> [ 497.674942] mwifiex_sdio mmc0:0001:1: 18601 : Tx timeout(#7),
> bss_type-num = 1-0
> [ 497.682383] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
> [ 497.688188] mwifiex_sdio mmc0:0001:1: tx_timeout_cnt exceeds
> threshold. Triggering card reset!
> [ 497.698397] mwifiex_sdio: Resetting card...
>
> The full log is at
> http://www.cs.utexas.edu/users/wiley/mwifiexlog_2.txt if you want to
> take a look - I didn't trim it down this time. It has debug output for
> mwifiex and mwifiex_sdio.
>
> Thanks,
> Andrew
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: mwifiex and SD8787: TX queue timeout in AP mode
2014-02-06 7:04 ` Avinash Patil
@ 2014-02-06 20:27 ` Andrew Wiley
0 siblings, 0 replies; 11+ messages in thread
From: Andrew Wiley @ 2014-02-06 20:27 UTC (permalink / raw)
To: Avinash Patil; +Cc: linux-wireless
Hello Avinash,
Filed: https://bugzilla.kernel.org/show_bug.cgi?id=70191
I also went ahead and got a new trace with dynamic debug for mvsdio
enabled because you couldn't reproduce it on a different SDIO host.
Thanks,
Andrew
On Thu, Feb 6, 2014 at 1:04 AM, Avinash Patil <avinashapatil@gmail.com> wrote:
> Hi Andrew,
>
> I ran this test on my x86_64 machine using 3.13 & same p96 FW. I could
> not reproduce this issue after 4 hrs of ping.
> This issue may be specific to Dreamplug and I dont have this hardware with me.
> Can you please log a bug at bugzilla.kernel.org. Maintainers would
> take care of it from there onwards.
>
> Thanks,
> Avinash.
>
> On Wed, Feb 5, 2014 at 12:22 PM, Andrew Wiley <wiley.andrew.j@gmail.com> wrote:
>> Hello Avinash,
>>
>> On Tue, Feb 4, 2014 at 9:57 AM, Avinash Patil <avinashapatil@gmail.com> wrote:
>>> Hi Andrew,
>>>
>>> I think this issue not specific to any interface as such.
>>>
>>> Do you have following fix in your tree:
>>>
>>> http://www.spinics.net/lists/linux-wireless/msg112753.html
>>
>> Yes.
>> I'm running 3.13.1, which includes that fix.
>>
>>>
>>> Also can you please try printing adapter->int_status during AP TX data timeout?
>>
>> I added a printk after the TX timeout warning and got this:
>>
>> [ 437.677151] ------------[ cut here ]------------
>> [ 437.681815] WARNING: CPU: 0 PID: 423 at net/sched/sch_generic.c:264
>> dev_watchdog+0x2d0/0x2f0()
>> [ 437.690485] NETDEV WATCHDOG: uap0 (mwifiex_sdio): transmit queue 1 timed out
>> [ 437.697580] Modules linked in: iptable_raw ipt_MASQUERADE xt_nat
>> iptable_nat nf_nat_ipv4 nf_nat iptable_mangle xt_policy
>> nf_conntrack_ipv4 xt_tcpudp nf_defrag_ipv4 bridge nf_conntrack_ipv6
>> nf_defrag_ipv6 stp llc xt_conntrack nf_conntrack iptable_filter
>> ip6table_filter ip6_tables ip_tables x_tables hid_generic
>> snd_usb_audio snd_usbmidi_lib mwifiex_sdio mwifiex snd_hwdep
>> snd_rawmidi snd_seq_device snd_pcm snd_page_alloc snd_timer cfg80211
>> snd usbhid soundcore hid rfkill mv_cesa usbip_host(C) usbip_core(C)
>> ipv6 autofs4
>> [ 437.743904] CPU: 0 PID: 423 Comm: tmux Tainted: G C
>> 3.13.1-2-ARCH #1
>> [ 437.751189] [<c000f01c>] (unwind_backtrace+0x0/0x128) from
>> [<c000c394>] (show_stack+0x10/0x14)
>> [ 437.759892] [<c000c394>] (show_stack+0x10/0x14) from [<c001aa80>]
>> (warn_slowpath_common+0x70/0x90)
>> [ 437.768923] [<c001aa80>] (warn_slowpath_common+0x70/0x90) from
>> [<c001aad0>] (warn_slowpath_fmt+0x30/0x40)
>> [ 437.778563] [<c001aad0>] (warn_slowpath_fmt+0x30/0x40) from
>> [<c04c6e50>] (dev_watchdog+0x2d0/0x2f0)
>> [ 437.787673] [<c04c6e50>] (dev_watchdog+0x2d0/0x2f0) from
>> [<c0025bf8>] (call_timer_fn+0x30/0x170)
>> [ 437.796512] [<c0025bf8>] (call_timer_fn+0x30/0x170) from
>> [<c00261b4>] (run_timer_softirq+0x1f8/0x368)
>> [ 437.805798] [<c00261b4>] (run_timer_softirq+0x1f8/0x368) from
>> [<c001ef00>] (__do_softirq+0xdc/0x304)
>> [ 437.814997] [<c001ef00>] (__do_softirq+0xdc/0x304) from
>> [<c001f4a4>] (irq_exit+0xb0/0xf8)
>> [ 437.823228] [<c001f4a4>] (irq_exit+0xb0/0xf8) from [<c0009cc0>]
>> (handle_IRQ+0x34/0x84)
>> [ 437.831199] [<c0009cc0>] (handle_IRQ+0x34/0x84) from [<c054cb38>]
>> (__irq_usr+0x38/0xa0)
>> [ 437.839248] ---[ end trace 14ce7b4e4b0c47cb ]---
>> [ 437.843888] mwifiex_sdio mmc0:0001:1: 12617 : Tx timeout(#1),
>> bss_type-num = 1-0
>> [ 437.851335] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
>> [ 447.676774] mwifiex_sdio mmc0:0001:1: 13601 : Tx timeout(#2),
>> bss_type-num = 1-0
>> [ 447.684238] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
>> [ 457.676409] mwifiex_sdio mmc0:0001:1: 14601 : Tx timeout(#3),
>> bss_type-num = 1-0
>> [ 457.683848] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
>> [ 467.676042] mwifiex_sdio mmc0:0001:1: 15601 : Tx timeout(#4),
>> bss_type-num = 1-0
>> [ 467.683501] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
>> [ 477.675679] mwifiex_sdio mmc0:0001:1: 16601 : Tx timeout(#5),
>> bss_type-num = 1-0
>> [ 477.683116] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
>> [ 487.675308] mwifiex_sdio mmc0:0001:1: 17601 : Tx timeout(#6),
>> bss_type-num = 1-0
>> [ 487.682760] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
>> [ 497.674942] mwifiex_sdio mmc0:0001:1: 18601 : Tx timeout(#7),
>> bss_type-num = 1-0
>> [ 497.682383] mwifiex_sdio mmc0:0001:1: adapter->int_status = 0
>> [ 497.688188] mwifiex_sdio mmc0:0001:1: tx_timeout_cnt exceeds
>> threshold. Triggering card reset!
>> [ 497.698397] mwifiex_sdio: Resetting card...
>>
>> The full log is at
>> http://www.cs.utexas.edu/users/wiley/mwifiexlog_2.txt if you want to
>> take a look - I didn't trim it down this time. It has debug output for
>> mwifiex and mwifiex_sdio.
>>
>> Thanks,
>> Andrew
^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2014-02-06 20:27 UTC | newest]
Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2014-02-02 6:41 mwifiex and SD8787: TX queue timeout in AP mode Andrew Wiley
2014-02-02 7:45 ` Avinash Patil
2014-02-02 21:13 ` Andrew Wiley
2014-02-03 6:47 ` Avinash Patil
2014-02-03 22:02 ` Andrew Wiley
2014-02-03 22:16 ` Andrew Wiley
2014-02-04 1:17 ` Andrew Wiley
2014-02-04 15:57 ` Avinash Patil
2014-02-05 6:52 ` Andrew Wiley
2014-02-06 7:04 ` Avinash Patil
2014-02-06 20:27 ` Andrew Wiley
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.