Re: iwlwifi worse than ever in current git.

Re: iwlwifi worse than ever in current git.

[Guy, Wey-Yi]

Emmanuel,

On Tue, 2012-01-10 at 13:49 -0500, Dave Jones wrote:
> For the last few releases, iwlwifi has been getting consistently worse
> wrt reliability for me.  The failure mode has varied, from the chip just
> locking up with no tx/rx of packets with nothing being logged, to
> microcode warnings, and spewing 'Tx aggregation enabled' messages over and over.
> 
> The merge post 3.2 has made these problems a lot worse.  Before, these
> lock-ups were happening once or twice a day. Now they happen several times an hour
> (and after the first one, they seem more frequent). When they happen,
> unloading and reloading the module is the only way for me to get working wireless again.
> They may happen more frequently when the laptop is not idle.
> 
> I did a bisect of the changes since 3.2, which pointed at 76bc10fcd128ad028cf77c62e179cd20dc2ffecf
> as being the culprit, but to be honest I'm not 100% convinced.
> 
> Because every step of the way during the bisect, I saw different failure modes,
> so when I marked something as 'good', it meant "doesn't lock up in the same way",
> even though it may be symptomatic of the same problem.
> 
> The specific chip I'm using is a 5300 in a Dell Adamo, connecting to
> an Apple airport extreme (current model) in N mode.
> 
ANy thought on this, patch 76bc10fcd128ad028cf77c62e179cd20dc2ffecf move
the tid_data to different layer, it shall not have any functional
changes.

Thanks
Wey
> 

iwlwifi worse than ever in current git.

[Dave Jones]

For the last few releases, iwlwifi has been getting consistently worse
wrt reliability for me.  The failure mode has varied, from the chip just
locking up with no tx/rx of packets with nothing being logged, to
microcode warnings, and spewing 'Tx aggregation enabled' messages over and over.

The merge post 3.2 has made these problems a lot worse.  Before, these
lock-ups were happening once or twice a day. Now they happen several times an hour
(and after the first one, they seem more frequent). When they happen,
unloading and reloading the module is the only way for me to get working wireless again.
They may happen more frequently when the laptop is not idle.

I did a bisect of the changes since 3.2, which pointed at 76bc10fcd128ad028cf77c62e179cd20dc2ffecf
as being the culprit, but to be honest I'm not 100% convinced.

Because every step of the way during the bisect, I saw different failure modes,
so when I marked something as 'good', it meant "doesn't lock up in the same way",
even though it may be symptomatic of the same problem.

The specific chip I'm using is a 5300 in a Dell Adamo, connecting to
an Apple airport extreme (current model) in N mode.

	Dave

Re: iwlwifi worse than ever in current git.

[Dan Williams]

On Tue, 2012-01-10 at 13:49 -0500, Dave Jones wrote:
> For the last few releases, iwlwifi has been getting consistently worse
> wrt reliability for me.  The failure mode has varied, from the chip just
> locking up with no tx/rx of packets with nothing being logged, to
> microcode warnings, and spewing 'Tx aggregation enabled' messages over and over.

You might want to CC linux-wireless@vger too...

> The merge post 3.2 has made these problems a lot worse.  Before, these
> lock-ups were happening once or twice a day. Now they happen several times an hour
> (and after the first one, they seem more frequent). When they happen,
> unloading and reloading the module is the only way for me to get working wireless again.
> They may happen more frequently when the laptop is not idle.
> 
> I did a bisect of the changes since 3.2, which pointed at 76bc10fcd128ad028cf77c62e179cd20dc2ffecf
> as being the culprit, but to be honest I'm not 100% convinced.
> 
> Because every step of the way during the bisect, I saw different failure modes,
> so when I marked something as 'good', it meant "doesn't lock up in the same way",
> even though it may be symptomatic of the same problem.
> 
> The specific chip I'm using is a 5300 in a Dell Adamo, connecting to
> an Apple airport extreme (current model) in N mode.
> 
> 	Dave
> 
> --
> To unsubscribe from this list: send the line "unsubscribe netdev" in
> the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html


--
To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

RE: iwlwifi worse than ever in current git.

[Grumbach, Emmanuel]

Hi,

Is that series I added a debug flag that tells us what happens with the queues: please enable the 31st bit: 0x80000000

Just debug=0x80000000 as a module parameter.

> 
> On Tue, 2012-01-10 at 13:49 -0500, Dave Jones wrote:
> > For the last few releases, iwlwifi has been getting consistently worse
> > wrt reliability for me.  The failure mode has varied, from the chip just
> > locking up with no tx/rx of packets with nothing being logged, to
> > microcode warnings, and spewing 'Tx aggregation enabled' messages over and
> over.
> 
> You might want to CC linux-wireless@vger too...
> 
> > The merge post 3.2 has made these problems a lot worse.  Before, these
> > lock-ups were happening once or twice a day. Now they happen several times
> an hour
> > (and after the first one, they seem more frequent). When they happen,
> > unloading and reloading the module is the only way for me to get working
> wireless again.
> > They may happen more frequently when the laptop is not idle.
> >
> > I did a bisect of the changes since 3.2, which pointed at
> 76bc10fcd128ad028cf77c62e179cd20dc2ffecf
> > as being the culprit, but to be honest I'm not 100% convinced.
> >
> > Because every step of the way during the bisect, I saw different failure
> modes,
> > so when I marked something as 'good', it meant "doesn't lock up in the same
> way",
> > even though it may be symptomatic of the same problem.
> >
> > The specific chip I'm using is a 5300 in a Dell Adamo, connecting to
> > an Apple airport extreme (current model) in N mode.
> >
> > 	Dave
> >
> > --
> > To unsubscribe from this list: send the line "unsubscribe netdev" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 

---------------------------------------------------------------------
Intel Israel (74) Limited

This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.

RE: iwlwifi worse than ever in current git.

[Venkataraman, Meenakshi]

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #1: Type: text/plain; charset="utf-8", Size: 802 bytes --]

Hi Dan,

>> For the last few releases, iwlwifi has been getting consistently worse
>> wrt reliability for me. 

[MV] Do you have an approximate idea of what release the failure started occurring?

 The failure mode has varied, from the chip
>> just locking up with no tx/rx of packets with nothing being logged, to
>> microcode warnings, and spewing 'Tx aggregation enabled' messages over
>and over.
 
[MV] I'm not sure if it is related to the problem you're seeing, but I see that you're using a 5300, so can you try to load the iwlwifi module with the following parameter and see if it helps?

modprobe iwlagn bt_coex_active=0

Thanks,
Meenakshi
N‹§²æìr¸›yúèšØb²X¬¶Ç§vØ^–)Þº{.nÇ+‰·¥Š{±Â*Þ•ë,Š{ayº\x1dʇڙë,j\a­¢f£¢·hš‹»öì\x17/oSc¾™Ú³9˜uÀ¦æå‰È&jw¨®\x03(­éšŽŠÝ¢j"ú\x1a¶^[m§ÿïêäz¹Þ–Šàþf£¢·hšˆ§~ˆmš

Re: iwlwifi worse than ever in current git.

[Dave Jones]

On Tue, Jan 10, 2012 at 08:40:32PM +0000, Grumbach, Emmanuel wrote:
 > Hi,
 > 
 > Is that series I added a debug flag that tells us what happens with the queues: please enable the 31st bit: 0x80000000
 > 
 > Just debug=0x80000000 as a module parameter.
 
>From boot to first hang..

[   24.874236] Intel(R) Wireless WiFi Link AGN driver for Linux, in-tree:d
[   24.875980] Copyright(c) 2003-2011 Intel Corporation
[   24.877877] iwlwifi 0000:04:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[   24.879733] iwlwifi 0000:04:00.0: setting latency timer to 64
[   24.879847] iwlwifi 0000:04:00.0: pci_resource_len = 0x00002000
[   24.881528] iwlwifi 0000:04:00.0: pci_resource_base = ffffc9001155c000
[   24.883276] iwlwifi 0000:04:00.0: HW Revision ID = 0x0
[   24.885297] iwlwifi 0000:04:00.0: irq 46 for MSI/MSI-X
[   24.885766] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEBUG enabled
[   24.887414] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEBUGFS enabled
[   24.889060] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEVICE_TRACING enabled
[   24.890740] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEVICE_TESTMODE enabled
[   24.892371] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_P2P disabled
[   24.893963] iwlwifi 0000:04:00.0: Detected Intel(R) Ultimate N WiFi Link 5300 AGN, REV=0x24
[   24.896234] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
[   24.919869] iwlwifi 0000:04:00.0: device EEPROM VER=0x120, CALIB=0x4
[   24.921403] iwlwifi 0000:04:00.0: Device SKU: 0xF0
[   24.922924] iwlwifi 0000:04:00.0: Tunable channels: 13 802.11bg, 24 802.11a channels
[   24.943679] iwlwifi 0000:04:00.0: loaded firmware version 8.83.5.1 build 33692
[   24.946313] Registered led device: phy0-led
[   24.978763] ieee80211 phy0: Selected rate control algorithm 'iwl-agn-rs'
[   25.032235] cfg80211: Calling CRDA for country: US
[   25.083063] cfg80211: Regulatory domain changed to country: US
[   25.084776] cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[   25.086556] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
[   25.088280] cfg80211:   (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
[   25.089954] cfg80211:   (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[   25.091618] cfg80211:   (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[   25.093234] cfg80211:   (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[   25.095115] cfg80211:   (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)

[   36.649871] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
[   36.662470] iwlwifi 0000:04:00.0: Radio type=0x0-0x2-0x0
[   36.825012] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 4  WrPtr: 0
[   36.825012] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 0 on FIFO 3
[   36.830829] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 1 on FIFO 2
[   36.830829] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 2 on FIFO 1
[   36.830829] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 3 on FIFO 0
[   36.830829] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 4 on FIFO 7
[   37.023008] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
[   37.033727] iwlwifi 0000:04:00.0: Radio type=0x0-0x2-0x0
[   37.215009] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 4  WrPtr: 0
[   37.215009] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 0 on FIFO 3
[   37.215009] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 1 on FIFO 2
[   37.215009] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 2 on FIFO 1
[   37.222439] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 3 on FIFO 0
[   37.222439] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 4 on FIFO 7
[   37.321187] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   44.614100] wlan0: authenticate with b8:c7:5d:0c:39:88 (try 1)
[   44.815110] wlan0: authenticate with b8:c7:5d:0c:39:88 (try 2)
[   44.817695] wlan0: authenticated
[   44.839289] wlan0: associate with b8:c7:5d:0c:39:88 (try 1)
[   44.842270] wlan0: RX AssocResp from b8:c7:5d:0c:39:88 (capab=0x511 status=0 aid=3)
[   44.842270] wlan0: associated
[   44.842270] wlan0: moving STA b8:c7:5d:0c:39:88 to state 1
[   44.842270] wlan0: moving STA b8:c7:5d:0c:39:88 to state 2
[   44.862870] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   44.866222] cfg80211: Calling CRDA for country: US
[   44.869918] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 0 ac 0 stop count 1. Tx on passive channel
[   44.904744] cfg80211: Regulatory domain changed to country: US
[   44.905049] cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[   44.905435] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
[   44.905788] cfg80211:   (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
[   44.906167] cfg80211:   (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[   44.906524] cfg80211:   (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[   44.906879] cfg80211:   (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[   44.907312] cfg80211:   (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
[   44.937401] iwlwifi 0000:04:00.0: I iwl_trans_pcie_wake_any_queue Queue Status: Q[0] stopped
[   44.937789] iwlwifi 0000:04:00.0: I iwl_wake_queue Wake hwq 0 ac 0. channel got active
[   44.938089] iwlwifi 0000:04:00.0: I iwl_trans_pcie_wake_any_queue Queue Status: Q[1] awake
[   44.938089] iwlwifi 0000:04:00.0: I iwl_trans_pcie_wake_any_queue Queue Status: Q[2] awake
[   44.938089] iwlwifi 0000:04:00.0: I iwl_trans_pcie_wake_any_queue Queue Status: Q[3] awake
[   45.891438] wlan0: moving STA b8:c7:5d:0c:39:88 to state 3
[   56.018088] wlan0: no IPv6 routers present
[   97.157673] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn = next_recl = 137
[   97.159663] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 137
[   97.159932] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate BA Queue 11 on FIFO 1
[   97.160516] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra = b8:c7:5d:0c:39:88 tid = 0
[  111.136741] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn = next_recl = 194
[  111.137162] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 0
[  111.137531] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Deactivate AC/CMD Queue 11 on FIFO 0

[  147.455293] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn = next_recl = 264
[  147.456993] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 8
[  147.457027] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate BA Queue 11 on FIFO 1
[  147.457830] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra = b8:c7:5d:0c:39:88 tid = 0
[  164.513842] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn = next_recl = 816
[  164.514282] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 0
[  164.514664] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Deactivate AC/CMD Queue 11 on FIFO 0
[  173.145695] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn = next_recl = 869
[  173.147133] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 101
[  173.147545] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate BA Queue 11 on FIFO 1
[  173.148050] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra = b8:c7:5d:0c:39:88 tid = 0
[  192.805102] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
[  192.807392] wlan0: authenticated
[  192.814840] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn 1633, next_recl = 139
[  192.818669] wlan0: moving STA b8:c7:5d:0c:39:88 to state 2
[  192.818939] wlan0: moving STA b8:c7:5d:0c:39:88 to state 1
[  192.819206] wlan0: moving STA b8:c7:5d:0c:39:88 to state 0
[  192.824157] wlan0: associate with b8:c7:5d:0c:39:87 (try 1)
[  192.828014] wlan0: RX ReassocResp from b8:c7:5d:0c:39:87 (capab=0x431 status=0 aid=3)
[  192.828372] wlan0: associated
[  192.828515] wlan0: moving STA b8:c7:5d:0c:39:87 to state 1
[  192.828713] wlan0: moving STA b8:c7:5d:0c:39:87 to state 2
[  193.853664] wlan0: moving STA b8:c7:5d:0c:39:87 to state 3
[  278.421399] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn = next_recl = 165
[  278.423946] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 12  WrPtr: 165
[  278.424007] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate BA Queue 12 on FIFO 1
[  278.424835] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra = b8:c7:5d:0c:39:87 tid = 0
[  285.176431] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 12 ac 2 stop count 1. Queue is full
[  290.304163] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn 397, next_recl = 174


At this point I unloaded, and reloaded the module.
I had to do this several times until it finally came back up.

Shortly afterwards..

[  599.752969] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
[  599.755359] wlan0: authenticated
[  599.762131] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 0 ac 0 stop count 1. Tx on passive channel
[  599.774132] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue Status: Q[0] stopped
[  599.774551] iwlwifi 0000:04:00.0: U iwl_wake_queue Wake hwq 0 ac 0. Disassoc: flush queue
[  599.774921] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue Status: Q[1] awake
[  599.775779] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue Status: Q[2] awake
[  599.776515] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue Status: Q[3] awake
[  599.777198] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 0 ac 0 stop count 1. Tx on passive channel
[  599.782692] wlan0: moving STA b8:c7:5d:0c:39:88 to state 2
[  599.782964] wlan0: moving STA b8:c7:5d:0c:39:88 to state 1
[  599.783538] wlan0: moving STA b8:c7:5d:0c:39:88 to state 0
[  599.790449] wlan0: associate with b8:c7:5d:0c:39:87 (try 1)
[  599.990029] wlan0: associate with b8:c7:5d:0c:39:87 (try 2)
[  600.190028] wlan0: associate with b8:c7:5d:0c:39:87 (try 3)
[  600.390029] wlan0: association with b8:c7:5d:0c:39:87 timed out
[  608.005916] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
[  608.206036] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
[  608.406036] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
[  608.607032] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
[  616.193769] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
[  616.394070] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
[  616.594039] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
[  616.794053] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
[  619.373114] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
[  619.573124] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
[  619.773146] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
[  619.973146] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
[  627.666387] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
[  627.866077] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
[  628.066146] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
[  628.266121] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
[  635.854105] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
[  636.054043] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
[  636.254134] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
[  636.454125] wlan0: authentication with b8:c7:5d:0c:39:87 timed out

and dead again.

	Dave

--
To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: iwlwifi worse than ever in current git.

[Dave Jones]

On Tue, Jan 10, 2012 at 10:05:25PM +0000, Venkataraman, Meenakshi wrote:
 > Hi Dan,
 > 
 > >> For the last few releases, iwlwifi has been getting consistently worse
 > >> wrt reliability for me. 
 > 
 > [MV] Do you have an approximate idea of what release the failure started occurring?
 > 
 >  The failure mode has varied, from the chip
 > >> just locking up with no tx/rx of packets with nothing being logged, to
 > >> microcode warnings, and spewing 'Tx aggregation enabled' messages over
 > >and over.
 >  
 > [MV] I'm not sure if it is related to the problem you're seeing, but I see that you're using a 5300, so can you try to load the iwlwifi module with the following parameter and see if it helps?
 > 
 > modprobe iwlagn bt_coex_active=0

Seems to make no difference at all.

	Dave

RE: iwlwifi worse than ever in current git.

[Grumbach, Emmanuel]

> From boot to first hang..
> 
> [   24.874236] Intel(R) Wireless WiFi Link AGN driver for Linux, in-tree:d
> [   24.875980] Copyright(c) 2003-2011 Intel Corporation
> [   24.877877] iwlwifi 0000:04:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ
> 17
> [   24.879733] iwlwifi 0000:04:00.0: setting latency timer to 64
> [   24.879847] iwlwifi 0000:04:00.0: pci_resource_len = 0x00002000
> [   24.881528] iwlwifi 0000:04:00.0: pci_resource_base = ffffc9001155c000
> [   24.883276] iwlwifi 0000:04:00.0: HW Revision ID = 0x0
> [   24.885297] iwlwifi 0000:04:00.0: irq 46 for MSI/MSI-X
> [   24.885766] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEBUG enabled
> [   24.887414] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEBUGFS enabled
> [   24.889060] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEVICE_TRACING enabled
> [   24.890740] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEVICE_TESTMODE enabled
> [   24.892371] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_P2P disabled
> [   24.893963] iwlwifi 0000:04:00.0: Detected Intel(R) Ultimate N WiFi Link
> 5300 AGN, REV=0x24
> [   24.896234] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
> [   24.919869] iwlwifi 0000:04:00.0: device EEPROM VER=0x120, CALIB=0x4
> [   24.921403] iwlwifi 0000:04:00.0: Device SKU: 0xF0
> [   24.922924] iwlwifi 0000:04:00.0: Tunable channels: 13 802.11bg, 24 802.11a
> channels
> [   24.943679] iwlwifi 0000:04:00.0: loaded firmware version 8.83.5.1 build
> 33692
> [   24.946313] Registered led device: phy0-led
> [   24.978763] ieee80211 phy0: Selected rate control algorithm 'iwl-agn-rs'
> [   25.032235] cfg80211: Calling CRDA for country: US
> [   25.083063] cfg80211: Regulatory domain changed to country: US
> [   25.084776] cfg80211:   (start_freq - end_freq @ bandwidth),
> (max_antenna_gain, max_eirp)
> [   25.086556] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi,
> 2700 mBm)
> [   25.088280] cfg80211:   (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi,
> 1700 mBm)
> [   25.089954] cfg80211:   (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [   25.091618] cfg80211:   (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [   25.093234] cfg80211:   (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [   25.095115] cfg80211:   (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi,
> 3000 mBm)
> 
> [   36.649871] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
> [   36.662470] iwlwifi 0000:04:00.0: Radio type=0x0-0x2-0x0
> [   36.825012] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 4  WrPtr: 0
> [   36.825012] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 0 on FIFO 3
> [   36.830829] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 1 on FIFO 2
> [   36.830829] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 2 on FIFO 1
> [   36.830829] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 3 on FIFO 0
> [   36.830829] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 4 on FIFO 7
> [   37.023008] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
> [   37.033727] iwlwifi 0000:04:00.0: Radio type=0x0-0x2-0x0
> [   37.215009] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 4  WrPtr: 0
> [   37.215009] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 0 on FIFO 3
> [   37.215009] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 1 on FIFO 2
> [   37.215009] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 2 on FIFO 1
> [   37.222439] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 3 on FIFO 0
> [   37.222439] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 4 on FIFO 7
> [   37.321187] ADDRCONF(NETDEV_UP): wlan0: link is not ready
> [   44.614100] wlan0: authenticate with b8:c7:5d:0c:39:88 (try 1)
> [   44.815110] wlan0: authenticate with b8:c7:5d:0c:39:88 (try 2)
> [   44.817695] wlan0: authenticated
> [   44.839289] wlan0: associate with b8:c7:5d:0c:39:88 (try 1)
> [   44.842270] wlan0: RX AssocResp from b8:c7:5d:0c:39:88 (capab=0x511
> status=0 aid=3)
> [   44.842270] wlan0: associated
> [   44.842270] wlan0: moving STA b8:c7:5d:0c:39:88 to state 1
> [   44.842270] wlan0: moving STA b8:c7:5d:0c:39:88 to state 2
> [   44.862870] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
> [   44.866222] cfg80211: Calling CRDA for country: US
> [   44.869918] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 0 ac 0 stop
> count 1. Tx on passive channel
> [   44.904744] cfg80211: Regulatory domain changed to country: US
> [   44.905049] cfg80211:   (start_freq - end_freq @ bandwidth),
> (max_antenna_gain, max_eirp)
> [   44.905435] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi,
> 2700 mBm)
> [   44.905788] cfg80211:   (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi,
> 1700 mBm)
> [   44.906167] cfg80211:   (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [   44.906524] cfg80211:   (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [   44.906879] cfg80211:   (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [   44.907312] cfg80211:   (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi,
> 3000 mBm)
> [   44.937401] iwlwifi 0000:04:00.0: I iwl_trans_pcie_wake_any_queue Queue
> Status: Q[0] stopped
> [   44.937789] iwlwifi 0000:04:00.0: I iwl_wake_queue Wake hwq 0 ac 0. channel
> got active
> [   44.938089] iwlwifi 0000:04:00.0: I iwl_trans_pcie_wake_any_queue Queue
> Status: Q[1] awake
> [   44.938089] iwlwifi 0000:04:00.0: I iwl_trans_pcie_wake_any_queue Queue
> Status: Q[2] awake
> [   44.938089] iwlwifi 0000:04:00.0: I iwl_trans_pcie_wake_any_queue Queue
> Status: Q[3] awake
> [   45.891438] wlan0: moving STA b8:c7:5d:0c:39:88 to state 3
> [   56.018088] wlan0: no IPv6 routers present
> [   97.157673] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 137
> [   97.159663] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 137
> [   97.159932] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 11 on FIFO 1
> [   97.160516] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:88 tid = 0
> [  111.136741] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn =
> next_recl = 194
> [  111.137162] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 0
> [  111.137531] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status
> Deactivate AC/CMD Queue 11 on FIFO 0
> 
> [  147.455293] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 264
> [  147.456993] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 8
> [  147.457027] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 11 on FIFO 1
> [  147.457830] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:88 tid = 0
> [  164.513842] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn =
> next_recl = 816
> [  164.514282] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 0
> [  164.514664] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status
> Deactivate AC/CMD Queue 11 on FIFO 0
> [  173.145695] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 869
> [  173.147133] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 101
> [  173.147545] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 11 on FIFO 1
> [  173.148050] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:88 tid = 0
> [  192.805102] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [  192.807392] wlan0: authenticated
> [  192.814840] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn
> 1633, next_recl = 139
> [  192.818669] wlan0: moving STA b8:c7:5d:0c:39:88 to state 2
> [  192.818939] wlan0: moving STA b8:c7:5d:0c:39:88 to state 1
> [  192.819206] wlan0: moving STA b8:c7:5d:0c:39:88 to state 0
> [  192.824157] wlan0: associate with b8:c7:5d:0c:39:87 (try 1)
> [  192.828014] wlan0: RX ReassocResp from b8:c7:5d:0c:39:87 (capab=0x431
> status=0 aid=3)
> [  192.828372] wlan0: associated
> [  192.828515] wlan0: moving STA b8:c7:5d:0c:39:87 to state 1
> [  192.828713] wlan0: moving STA b8:c7:5d:0c:39:87 to state 2
> [  193.853664] wlan0: moving STA b8:c7:5d:0c:39:87 to state 3
> [  278.421399] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 165
> [  278.423946] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 12  WrPtr: 165
> [  278.424007] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 12 on FIFO 1
> [  278.424835] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:87 tid = 0
> [  285.176431] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 12 ac 2 stop
> count 1. Queue is full
> [  290.304163] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn
> 397, next_recl = 174
> 
> 
> At this point I unloaded, and reloaded the module.
> I had to do this several times until it finally came back up.
> 
> Shortly afterwards..
> 
> [  599.752969] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [  599.755359] wlan0: authenticated
> [  599.762131] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 0 ac 0 stop
> count 1. Tx on passive channel
> [  599.774132] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue
> Status: Q[0] stopped
> [  599.774551] iwlwifi 0000:04:00.0: U iwl_wake_queue Wake hwq 0 ac 0.
> Disassoc: flush queue
> [  599.774921] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue
> Status: Q[1] awake
> [  599.775779] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue
> Status: Q[2] awake
> [  599.776515] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue
> Status: Q[3] awake
> [  599.777198] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 0 ac 0 stop
> count 1. Tx on passive channel
> [  599.782692] wlan0: moving STA b8:c7:5d:0c:39:88 to state 2
> [  599.782964] wlan0: moving STA b8:c7:5d:0c:39:88 to state 1
> [  599.783538] wlan0: moving STA b8:c7:5d:0c:39:88 to state 0
> [  599.790449] wlan0: associate with b8:c7:5d:0c:39:87 (try 1)
> [  599.990029] wlan0: associate with b8:c7:5d:0c:39:87 (try 2)
> [  600.190028] wlan0: associate with b8:c7:5d:0c:39:87 (try 3)
> [  600.390029] wlan0: association with b8:c7:5d:0c:39:87 timed out
> [  608.005916] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [  608.206036] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
> [  608.406036] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
> [  608.607032] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
> [  616.193769] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [  616.394070] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
> [  616.594039] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
> [  616.794053] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
> [  619.373114] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [  619.573124] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
> [  619.773146] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
> [  619.973146] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
> [  627.666387] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [  627.866077] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
> [  628.066146] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
> [  628.266121] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
> [  635.854105] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [  636.054043] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 2)
> [  636.254134] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 3)
> [  636.454125] wlan0: authentication with b8:c7:5d:0c:39:87 timed out
> 
Ok, I see several issues. Will get back to you
In the meantime: disable11n=1 will help (not sure it is the correct syntax, check out the modinfo please. I am in a hurry now :-))

---------------------------------------------------------------------
Intel Israel (74) Limited

This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.

RE: iwlwifi worse than ever in current git.

[Grumbach, Emmanuel]

> [  173.145695] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 869
> [  173.147133] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 101
> [  173.147545] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 11 on FIFO 1
> [  173.148050] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:88 tid = 0

I am missing logs here... You seem to reauthenticate but I can't see disconnection... weird


> [  192.805102] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [  192.807392] wlan0: authenticated
> [  192.814840] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn
> 1633, next_recl = 139

Stop AGG before we are associated ?!
Is that leftovers from the previous association that was torn down ?

> [  192.818669] wlan0: moving STA b8:c7:5d:0c:39:88 to state 2
> [  192.818939] wlan0: moving STA b8:c7:5d:0c:39:88 to state 1
> [  192.819206] wlan0: moving STA b8:c7:5d:0c:39:88 to state 0
> [  192.824157] wlan0: associate with b8:c7:5d:0c:39:87 (try 1)

Associating to another AP ? A band maybe ?

> [  192.828014] wlan0: RX ReassocResp from b8:c7:5d:0c:39:87 (capab=0x431
> status=0 aid=3)
> [  192.828372] wlan0: associated
> [  192.828515] wlan0: moving STA b8:c7:5d:0c:39:87 to state 1
> [  192.828713] wlan0: moving STA b8:c7:5d:0c:39:87 to state 2
> [  193.853664] wlan0: moving STA b8:c7:5d:0c:39:87 to state 3
> [  278.421399] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 165
> [  278.423946] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 12  WrPtr: 165
> [  278.424007] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 12 on FIFO 1
> [  278.424835] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:87 tid = 0
> [  285.176431] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 12 ac 2 stop
> count 1. Queue is full
> [  290.304163] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn
> 397, next_recl = 174
> 
> 
> At this point I unloaded, and reloaded the module.
> I had to do this several times until it finally came back up.
> 
> Shortly afterwards..
> 
> [  599.752969] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [  599.755359] wlan0: authenticated
> [  599.762131] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 0 ac 0 stop
> count 1. Tx on passive channel

Interesting. The FW is complaining that you are Txing on a channel that is defined as passive channel...


> [  599.774132] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue
> Status: Q[0] stopped
> [  599.774551] iwlwifi 0000:04:00.0: U iwl_wake_queue Wake hwq 0 ac 0.
> Disassoc: flush queue
> [  599.774921] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue
> Status: Q[1] awake
> [  599.775779] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue
> Status: Q[2] awake
> [  599.776515] iwlwifi 0000:04:00.0: U iwl_trans_pcie_wake_any_queue Queue
> Status: Q[3] awake
> [  599.777198] iwlwifi 0000:04:00.0: I iwl_stop_queue Stop hwq 0 ac 0 stop
> count 1. Tx on passive channel

Again.


There are a few AMPDUs issues here but I guess the worst issue you are seeing is due to the passive channel thing.
Does it feel better with 11n disabled ?



---------------------------------------------------------------------
Intel Israel (74) Limited

This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.

--
To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: iwlwifi worse than ever in current git.

[Dave Jones]

On Wed, Jan 11, 2012 at 12:38:43PM +0000, Grumbach, Emmanuel wrote:
 > > [  173.145695] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
 > > next_recl = 869
 > > [  173.147133] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 101
 > > [  173.147545] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
 > > BA Queue 11 on FIFO 1
 > > [  173.148050] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
 > > b8:c7:5d:0c:39:88 tid = 0
 > 
 > I am missing logs here... You seem to reauthenticate but I can't see disconnection... weird
 
I'll recreate some clean logs in a few minutes..
 
 > > [  192.805102] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
 > > [  192.807392] wlan0: authenticated
 > > [  192.814840] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn
 > > 1633, next_recl = 139
 > 
 > Stop AGG before we are associated ?!
 > Is that leftovers from the previous association that was torn down ?
 
no idea.

 > > [  192.818669] wlan0: moving STA b8:c7:5d:0c:39:88 to state 2
 > > [  192.818939] wlan0: moving STA b8:c7:5d:0c:39:88 to state 1
 > > [  192.819206] wlan0: moving STA b8:c7:5d:0c:39:88 to state 0
 > > [  192.824157] wlan0: associate with b8:c7:5d:0c:39:87 (try 1)
 > 
 > Associating to another AP ? A band maybe ?
 
I only have one AP.

 > There are a few AMPDUs issues here but I guess the worst issue you are seeing is due to the passive channel thing.
 > Does it feel better with 11n disabled ?
 
5 hours of use this morning with 11n_disabled=1, and not a single problem.

I'll re-enable 11n, and get you some cleaner logs shortly.

	Dave

Re: iwlwifi worse than ever in current git.

[Dave Jones]

On Wed, Jan 11, 2012 at 12:38:43PM +0000, Grumbach, Emmanuel wrote:

 > I am missing logs here... You seem to reauthenticate but I can't see disconnection... weird

Ok, here's a fresh log.

wireless was working, (with 11n_disable=1)

unload, and reload without the 11n_disable=1 ..

[16421.730025] wlan0: deauthenticating from b8:c7:5d:0c:39:87 by local choice (reason=3)
[16421.735002] ieee80211 phy0: failed to remove key (1, ff:ff:ff:ff:ff:ff) from hardware (-16)
[16421.736095] ieee80211 phy0: failed to remove key (2, ff:ff:ff:ff:ff:ff) from hardware (-16)
[16421.737548] ieee80211 phy0: failed to remove key (0, b8:c7:5d:0c:39:87) from hardware (-16)
[16421.738400] wlan0: moving STA b8:c7:5d:0c:39:87 to state 2
[16421.738646] wlan0: moving STA b8:c7:5d:0c:39:87 to state 1
[16421.738878] wlan0: moving STA b8:c7:5d:0c:39:87 to state 0
[16421.741175] cfg80211: Calling CRDA to update world regulatory domain
[16421.777981] iwlwifi 0000:04:00.0: PCI INT A disabled
[16421.803665] cfg80211: World regulatory domain updated:
[16421.803924] cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[16421.808846] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16421.811357] cfg80211:   (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[16421.811739] cfg80211:   (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[16421.812193] cfg80211:   (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16421.812566] cfg80211:   (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16421.820504] cfg80211: Calling CRDA for country: US
[16421.918341] cfg80211: Calling CRDA to update world regulatory domain
[16421.949295] cfg80211: World regulatory domain updated:
[16421.949559] cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[16421.949966] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16421.950851] cfg80211:   (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[16421.951528] cfg80211:   (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[16421.951911] cfg80211:   (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16421.952651] cfg80211:   (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16422.035828] Intel(R) Wireless WiFi Link AGN driver for Linux, in-tree:d
[16422.036165] Copyright(c) 2003-2011 Intel Corporation
[16422.036582] iwlwifi 0000:04:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
[16422.036957] iwlwifi 0000:04:00.0: setting latency timer to 64
[16422.037338] iwlwifi 0000:04:00.0: pci_resource_len = 0x00002000
[16422.037620] iwlwifi 0000:04:00.0: pci_resource_base = ffffc90011560000
[16422.037930] iwlwifi 0000:04:00.0: HW Revision ID = 0x0
[16422.038381] iwlwifi 0000:04:00.0: irq 46 for MSI/MSI-X
[16422.038915] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEBUG enabled
[16422.041287] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEBUGFS enabled
[16422.041569] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEVICE_TRACING enabled
[16422.041881] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEVICE_TESTMODE enabled
[16422.042213] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_P2P disabled
[16422.042517] iwlwifi 0000:04:00.0: Detected Intel(R) Ultimate N WiFi Link 5300 AGN, REV=0x24
[16422.043276] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
[16422.075500] iwlwifi 0000:04:00.0: device EEPROM VER=0x120, CALIB=0x4
[16422.075809] iwlwifi 0000:04:00.0: Device SKU: 0xF0
[16422.076390] iwlwifi 0000:04:00.0: Tunable channels: 13 802.11bg, 24 802.11a channels
[16422.121284] iwlwifi 0000:04:00.0: loaded firmware version 8.83.5.1 build 33692
[16422.122291] Registered led device: phy0-led
[16422.124681] ieee80211 phy0: Selected rate control algorithm 'iwl-agn-rs'
[16422.155786] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
[16422.159119] iwlwifi 0000:04:00.0: Radio type=0x0-0x2-0x0
[16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 4  WrPtr: 0
[16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 0 on FIFO 3
[16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 1 on FIFO 2
[16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 2 on FIFO 1
[16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 3 on FIFO 0
[16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 4 on FIFO 7
[16422.263369] cfg80211: Calling CRDA for country: US
[16422.287176] cfg80211: Regulatory domain changed to country: US
[16422.287457] cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[16422.287849] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
[16422.288337] cfg80211:   (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
[16422.288703] cfg80211:   (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16422.289090] cfg80211:   (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16422.289455] cfg80211:   (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16422.289824] cfg80211:   (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
[16422.318523] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
[16422.321880] iwlwifi 0000:04:00.0: Radio type=0x0-0x2-0x0
[16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 4  WrPtr: 0
[16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 0 on FIFO 3
[16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 1 on FIFO 2
[16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 2 on FIFO 1
[16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 3 on FIFO 0
[16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 4 on FIFO 7
[16422.376787] ADDRCONF(NETDEV_UP): wlan0: link is not ready
[16427.671916] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
[16427.674716] wlan0: authenticated
[16427.678205] wlan0: associate with b8:c7:5d:0c:39:87 (try 1)
[16427.681953] wlan0: RX AssocResp from b8:c7:5d:0c:39:87 (capab=0x431 status=0 aid=3)
[16427.682325] wlan0: associated
[16427.682473] wlan0: moving STA b8:c7:5d:0c:39:87 to state 1
[16427.682731] wlan0: moving STA b8:c7:5d:0c:39:87 to state 2
[16427.700757] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[16427.701667] cfg80211: Calling CRDA for country: US
[16427.721184] cfg80211: Regulatory domain changed to country: US
[16427.721455] cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[16427.721829] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2700 mBm)
[16427.722199] cfg80211:   (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 1700 mBm)
[16427.722566] cfg80211:   (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16427.722924] cfg80211:   (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16427.723289] cfg80211:   (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[16427.723651] cfg80211:   (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 3000 mBm)
[16428.706438] wlan0: moving STA b8:c7:5d:0c:39:87 to state 3
[16438.802048] wlan0: no IPv6 routers present

wifi is back up.

Shortly afterwards ..


[16520.224964] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn = next_recl = 124
[16520.228038] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 124
[16520.228358] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate BA Queue 11 on FIFO 1
[16520.229059] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra = b8:c7:5d:0c:39:87 tid = 0
[16531.888296] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn = next_recl = 631
[16531.888793] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 0
[16531.889247] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Deactivate AC/CMD Queue 11 on FIFO 0
[16552.504609] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn = next_recl = 697
[16552.508182] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 185
[16552.508609] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate BA Queue 11 on FIFO 1
[16552.509077] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra = b8:c7:5d:0c:39:87 tid = 0
[16564.084058] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn = next_recl = 1241
[16564.084506] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 0
[16564.084903] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Deactivate AC/CMD Queue 11 on FIFO 0
[16568.975872] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn = next_recl = 1298
[16568.978796] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 18
[16568.979007] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate BA Queue 11 on FIFO 1
[16568.979734] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra = b8:c7:5d:0c:39:87 tid = 0
[16580.004052] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn 1491, next_recl = 150


A possibly interesting datapoint, is that it seems I can make this happen faster
if there's disk IO going on (I ran a make clean on a kernel tree in this case).
Might be entirely coincidental, but thought I'd mention it..

	Dave

RE: iwlwifi worse than ever in current git.

[Grumbach, Emmanuel]

> 
> Ok, here's a fresh log.
> 
> wireless was working, (with 11n_disable=1)
> 
> unload, and reload without the 11n_disable=1 ..
> 
> [16421.730025] wlan0: deauthenticating from b8:c7:5d:0c:39:87 by local choice
> (reason=3)
> [16421.735002] ieee80211 phy0: failed to remove key (1, ff:ff:ff:ff:ff:ff)
> from hardware (-16)
> [16421.736095] ieee80211 phy0: failed to remove key (2, ff:ff:ff:ff:ff:ff)
> from hardware (-16)
> [16421.737548] ieee80211 phy0: failed to remove key (0, b8:c7:5d:0c:39:87)
> from hardware (-16)
> [16421.738400] wlan0: moving STA b8:c7:5d:0c:39:87 to state 2
> [16421.738646] wlan0: moving STA b8:c7:5d:0c:39:87 to state 1
> [16421.738878] wlan0: moving STA b8:c7:5d:0c:39:87 to state 0
> [16421.741175] cfg80211: Calling CRDA to update world regulatory domain
> [16421.777981] iwlwifi 0000:04:00.0: PCI INT A disabled
> [16421.803665] cfg80211: World regulatory domain updated:
> [16421.803924] cfg80211:   (start_freq - end_freq @ bandwidth),
> (max_antenna_gain, max_eirp)
> [16421.808846] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16421.811357] cfg80211:   (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi,
> 2000 mBm)
> [16421.811739] cfg80211:   (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi,
> 2000 mBm)
> [16421.812193] cfg80211:   (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16421.812566] cfg80211:   (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16421.820504] cfg80211: Calling CRDA for country: US
> [16421.918341] cfg80211: Calling CRDA to update world regulatory domain
> [16421.949295] cfg80211: World regulatory domain updated:
> [16421.949559] cfg80211:   (start_freq - end_freq @ bandwidth),
> (max_antenna_gain, max_eirp)
> [16421.949966] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16421.950851] cfg80211:   (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi,
> 2000 mBm)
> [16421.951528] cfg80211:   (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi,
> 2000 mBm)
> [16421.951911] cfg80211:   (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16421.952651] cfg80211:   (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16422.035828] Intel(R) Wireless WiFi Link AGN driver for Linux, in-tree:d
> [16422.036165] Copyright(c) 2003-2011 Intel Corporation
> [16422.036582] iwlwifi 0000:04:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ
> 17
> [16422.036957] iwlwifi 0000:04:00.0: setting latency timer to 64
> [16422.037338] iwlwifi 0000:04:00.0: pci_resource_len = 0x00002000
> [16422.037620] iwlwifi 0000:04:00.0: pci_resource_base = ffffc90011560000
> [16422.037930] iwlwifi 0000:04:00.0: HW Revision ID = 0x0
> [16422.038381] iwlwifi 0000:04:00.0: irq 46 for MSI/MSI-X
> [16422.038915] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEBUG enabled
> [16422.041287] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEBUGFS enabled
> [16422.041569] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEVICE_TRACING enabled
> [16422.041881] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_DEVICE_TESTMODE enabled
> [16422.042213] iwlwifi 0000:04:00.0: CONFIG_IWLWIFI_P2P disabled
> [16422.042517] iwlwifi 0000:04:00.0: Detected Intel(R) Ultimate N WiFi Link
> 5300 AGN, REV=0x24
> [16422.043276] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
> [16422.075500] iwlwifi 0000:04:00.0: device EEPROM VER=0x120, CALIB=0x4
> [16422.075809] iwlwifi 0000:04:00.0: Device SKU: 0xF0
> [16422.076390] iwlwifi 0000:04:00.0: Tunable channels: 13 802.11bg, 24 802.11a
> channels
> [16422.121284] iwlwifi 0000:04:00.0: loaded firmware version 8.83.5.1 build
> 33692
> [16422.122291] Registered led device: phy0-led
> [16422.124681] ieee80211 phy0: Selected rate control algorithm 'iwl-agn-rs'
> [16422.155786] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
> [16422.159119] iwlwifi 0000:04:00.0: Radio type=0x0-0x2-0x0
> [16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 4  WrPtr: 0
> [16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 0 on FIFO 3
> [16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 1 on FIFO 2
> [16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 2 on FIFO 1
> [16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 3 on FIFO 0
> [16422.201065] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 4 on FIFO 7
> [16422.263369] cfg80211: Calling CRDA for country: US
> [16422.287176] cfg80211: Regulatory domain changed to country: US
> [16422.287457] cfg80211:   (start_freq - end_freq @ bandwidth),
> (max_antenna_gain, max_eirp)
> [16422.287849] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi,
> 2700 mBm)
> [16422.288337] cfg80211:   (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi,
> 1700 mBm)
> [16422.288703] cfg80211:   (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16422.289090] cfg80211:   (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16422.289455] cfg80211:   (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16422.289824] cfg80211:   (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi,
> 3000 mBm)
> [16422.318523] iwlwifi 0000:04:00.0: L1 Enabled; Disabling L0S
> [16422.321880] iwlwifi 0000:04:00.0: Radio type=0x0-0x2-0x0
> [16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 4  WrPtr: 0
> [16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 0 on FIFO 3
> [16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 1 on FIFO 2
> [16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 2 on FIFO 1
> [16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 3 on FIFO 0
> [16422.360115] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> AC/CMD Queue 4 on FIFO 7
> [16422.376787] ADDRCONF(NETDEV_UP): wlan0: link is not ready
> [16427.671916] wlan0: authenticate with b8:c7:5d:0c:39:87 (try 1)
> [16427.674716] wlan0: authenticated
> [16427.678205] wlan0: associate with b8:c7:5d:0c:39:87 (try 1)
> [16427.681953] wlan0: RX AssocResp from b8:c7:5d:0c:39:87 (capab=0x431
> status=0 aid=3)
> [16427.682325] wlan0: associated
> [16427.682473] wlan0: moving STA b8:c7:5d:0c:39:87 to state 1
> [16427.682731] wlan0: moving STA b8:c7:5d:0c:39:87 to state 2
> [16427.700757] ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
> [16427.701667] cfg80211: Calling CRDA for country: US
> [16427.721184] cfg80211: Regulatory domain changed to country: US
> [16427.721455] cfg80211:   (start_freq - end_freq @ bandwidth),
> (max_antenna_gain, max_eirp)
> [16427.721829] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi,
> 2700 mBm)
> [16427.722199] cfg80211:   (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi,
> 1700 mBm)
> [16427.722566] cfg80211:   (5250000 KHz - 5330000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16427.722924] cfg80211:   (5490000 KHz - 5600000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16427.723289] cfg80211:   (5650000 KHz - 5710000 KHz @ 40000 KHz), (300 mBi,
> 2000 mBm)
> [16427.723651] cfg80211:   (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi,
> 3000 mBm)
> [16428.706438] wlan0: moving STA b8:c7:5d:0c:39:87 to state 3
> [16438.802048] wlan0: no IPv6 routers present
> 
> wifi is back up.
> 
> Shortly afterwards ..
> 
> 
> [16520.224964] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 124
> [16520.228038] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 124
> [16520.228358] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 11 on FIFO 1
> [16520.229059] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:87 tid = 0
> [16531.888296] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn =
> next_recl = 631
> [16531.888793] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 0
> [16531.889247] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status
> Deactivate AC/CMD Queue 11 on FIFO 0
> [16552.504609] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 697
> [16552.508182] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 185
> [16552.508609] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 11 on FIFO 1
> [16552.509077] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:87 tid = 0
> [16564.084058] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn =
> next_recl = 1241
> [16564.084506] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 0
> [16564.084903] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status
> Deactivate AC/CMD Queue 11 on FIFO 0
> [16568.975872] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
> next_recl = 1298
> [16568.978796] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 18
> [16568.979007] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
> BA Queue 11 on FIFO 1
> [16568.979734] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
> b8:c7:5d:0c:39:87 tid = 0
> [16580.004052] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn
> 1491, next_recl = 150
> 

I understand there is nothing afterwards... This is really weird. The sequence numbers here are really crazy...
I need to think that over.

> 
> A possibly interesting datapoint, is that it seems I can make this happen
> faster
> if there's disk IO going on (I ran a make clean on a kernel tree in this
> case).
> Might be entirely coincidental, but thought I'd mention it..
> 

Ok, thanks for the info.

---------------------------------------------------------------------
Intel Israel (74) Limited

This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.

Re: iwlwifi worse than ever in current git.

[Emmanuel Grumbach]

>>
>> [16520.224964] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
>> next_recl = 124
>> [16520.228038] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 124
>> [16520.228358] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
>> BA Queue 11 on FIFO 1
>> [16520.229059] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
>> b8:c7:5d:0c:39:87 tid = 0
>> [16531.888296] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn =
>> next_recl = 631
>> [16531.888793] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 0
>> [16531.889247] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status
>> Deactivate AC/CMD Queue 11 on FIFO 0
>> [16552.504609] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
>> next_recl = 697
>> [16552.508182] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 185
>> [16552.508609] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
>> BA Queue 11 on FIFO 1
>> [16552.509077] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
>> b8:c7:5d:0c:39:87 tid = 0
>> [16564.084058] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can proceed: ssn =
>> next_recl = 1241
>> [16564.084506] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 0
>> [16564.084903] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status
>> Deactivate AC/CMD Queue 11 on FIFO 0
>> [16568.975872] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_start Can proceed: ssn =
>> next_recl = 1298
>> [16568.978796] iwlwifi 0000:04:00.0: U iwl_trans_set_wr_ptrs Q 11  WrPtr: 18
>> [16568.979007] iwlwifi 0000:04:00.0: U iwl_trans_tx_queue_set_status Activate
>> BA Queue 11 on FIFO 1
>> [16568.979734] iwlwifi 0000:04:00.0: Tx aggregation enabled on ra =
>> b8:c7:5d:0c:39:87 tid = 0
>> [16580.004052] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn
>> 1491, next_recl = 150
>>
>
> I understand there is nothing afterwards... This is really weird. The sequence numbers here are really crazy...
> I need to think that over.
>
>>

Ok, I finally had a change to take a closer look at this. Please run
with debug=0xC0000000.

This will be noisy, but I guess we have no choice...
I will be travelling next week, so...
--
To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: iwlwifi worse than ever in current git.

[Dave Jones]

On Thu, Jan 19, 2012 at 08:47:28AM +0200, Emmanuel Grumbach wrote:
 > >> [16580.004052] iwlwifi 0000:04:00.0: U iwlagn_tx_agg_stop Can't proceed: ssn
 > >> 1491, next_recl = 150
 > >>
 > >
 > > I understand there is nothing afterwards... This is really weird. The sequence numbers here are really crazy...
 > > I need to think that over.
 > >
 > >>
 > 
 > Ok, I finally had a change to take a closer look at this. Please run
 > with debug=0xC0000000.
 > 
 > This will be noisy, but I guess we have no choice...

It is indeed noisy, and.. I can't reproduce the problem when that's set.
Some timing related problem ?

	Dave

Re: iwlwifi worse than ever in current git.

[Dave Jones]

On Thu, Jan 19, 2012 at 08:47:28AM +0200, Emmanuel Grumbach wrote:
 > Ok, I finally had a change to take a closer look at this. Please run
 > with debug=0xC0000000.
 > 
 > This will be noisy, but I guess we have no choice...
 > I will be travelling next week, so...

Ah. Got it. I had to do a large download (a kernel tarball was enough) to trigger it.
Log is at http://davej.fedorapeople.org/iwl-debug.txt

The download began at around 13:17 in the log.
It hung shortly afterwards.

	Dave

--
To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

RE: iwlwifi worse than ever in current git.

[Grumbach, Emmanuel]

> 
> On Thu, Jan 19, 2012 at 08:47:28AM +0200, Emmanuel Grumbach wrote:
>  > Ok, I finally had a change to take a closer look at this. Please run
>  > with debug=0xC0000000.
>  >
>  > This will be noisy, but I guess we have no choice...
>  > I will be travelling next week, so...
> 
> Ah. Got it. I had to do a large download (a kernel tarball was enough) to
> trigger it.
> Log is at http://davej.fedorapeople.org/iwl-debug.txt
> 
> The download began at around 13:17 in the log.
> It hung shortly afterwards.
> 
> 	Dave

Thanks for that one. Really helpful. I need to send you a patch to get a little more data. I don't know when I will be able to do it though.
---------------------------------------------------------------------
Intel Israel (74) Limited

This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.

--
To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

RE: iwlwifi worse than ever in current git.

[Grumbach, Emmanuel]

[-- Attachment #1: Type: text/plain, Size: 1145 bytes --]

> 
> >
> > On Thu, Jan 19, 2012 at 08:47:28AM +0200, Emmanuel Grumbach wrote:
> >  > Ok, I finally had a change to take a closer look at this. Please run
> >  > with debug=0xC0000000.
> >  >
> >  > This will be noisy, but I guess we have no choice...
> >  > I will be travelling next week, so...
> >
> > Ah. Got it. I had to do a large download (a kernel tarball was enough) to
> > trigger it.
> > Log is at http://davej.fedorapeople.org/iwl-debug.txt
> >
> > The download began at around 13:17 in the log.
> > It hung shortly afterwards.
> >
> > 	Dave
> 
> Thanks for that one. Really helpful. I need to send you a patch to get a
> little more data. I don't know when I will be able to do it though.

Can you please retry with the patch attached ?
Thanks
---------------------------------------------------------------------
Intel Israel (74) Limited

This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.

[-- Attachment #2: ampdu_debug.patch --]
[-- Type: application/octet-stream, Size: 2887 bytes --]

diff --git a/drivers/net/wireless/iwlwifi/iwl-agn-tx.c b/drivers/net/wireless/iwlwifi/iwl-agn-tx.c
index d9d758e..6d9df0d 100644
--- a/drivers/net/wireless/iwlwifi/iwl-agn-tx.c
+++ b/drivers/net/wireless/iwlwifi/iwl-agn-tx.c
@@ -839,11 +839,13 @@ static void iwl_rx_reply_tx_agg(struct iwl_priv *priv,
 			      AGG_TX_STATE_ABORT_MSK))
 			continue;
 
+/*
 		IWL_DEBUG_TX_REPLY(priv, "status %s (0x%08x), "
 				   "try-count (0x%08x)\n",
 				   iwl_get_agg_tx_fail_reason(fstatus),
 				   fstatus & AGG_TX_STATUS_MSK,
 				   fstatus & AGG_TX_TRY_MSK);
+*/
 	}
 }
 
@@ -1016,8 +1018,8 @@ int iwlagn_rx_reply_tx(struct iwl_priv *priv, struct iwl_rx_mem_buffer *rxb,
 		iwl_rx_reply_tx_agg(priv, tx_resp);
 
 	if (tx_resp->frame_count == 1) {
-		u16 next_reclaimed = le16_to_cpu(tx_resp->seq_ctl);
-		next_reclaimed = SEQ_TO_SN(next_reclaimed + 0x10);
+		u16 next_reclaimed_ = le16_to_cpu(tx_resp->seq_ctl);
+		u16 next_reclaimed = SEQ_TO_SN(next_reclaimed_ + 0x10);
 
 		if (is_agg) {
 			/* If this is an aggregation queue, we can rely on the
@@ -1037,8 +1039,8 @@ int iwlagn_rx_reply_tx(struct iwl_priv *priv, struct iwl_rx_mem_buffer *rxb,
 		__skb_queue_head_init(&skbs);
 		priv->tid_data[sta_id][tid].next_reclaimed = next_reclaimed;
 
-		IWL_DEBUG_TX_REPLY(priv, "Next reclaimed packet:%d",
-					  next_reclaimed);
+		IWL_DEBUG_TX_REPLY(priv, "Next reclaimed packet:%d, _%d is_Agg %d SSN %d",
+					  next_reclaimed, next_reclaimed_, is_agg, ssn);
 
 		/*we can free until ssn % q.n_bd not inclusive */
 		WARN_ON(iwl_trans_reclaim(trans(priv), sta_id, tid, txq_id,
@@ -1149,17 +1151,6 @@ int iwlagn_rx_reply_compressed_ba(struct iwl_priv *priv,
 		return 0;
 	}
 
-	__skb_queue_head_init(&reclaimed_skbs);
-
-	/* Release all TFDs before the SSN, i.e. all TFDs in front of
-	 * block-ack window (we assume that they've been successfully
-	 * transmitted ... if not, it's too late anyway). */
-	if (iwl_trans_reclaim(trans(priv), sta_id, tid, scd_flow,
-			      ba_resp_scd_ssn, 0, &reclaimed_skbs)) {
-		spin_unlock_irqrestore(&priv->shrd->sta_lock, flags);
-		return 0;
-	}
-
 	IWL_DEBUG_TX_REPLY(priv, "REPLY_COMPRESSED_BA [%d] Received from %pM, "
 			   "sta_id = %d\n",
 			   agg->wait_for_ba,
@@ -1171,6 +1162,17 @@ int iwlagn_rx_reply_compressed_ba(struct iwl_priv *priv,
 			   (unsigned long long)le64_to_cpu(ba_resp->bitmap),
 			   scd_flow, ba_resp_scd_ssn);
 
+	__skb_queue_head_init(&reclaimed_skbs);
+
+	/* Release all TFDs before the SSN, i.e. all TFDs in front of
+	 * block-ack window (we assume that they've been successfully
+	 * transmitted ... if not, it's too late anyway). */
+	if (iwl_trans_reclaim(trans(priv), sta_id, tid, scd_flow,
+			      ba_resp_scd_ssn, 0, &reclaimed_skbs)) {
+		spin_unlock_irqrestore(&priv->shrd->sta_lock, flags);
+		return 0;
+	}
+
 	/* Mark that the expected block-ack response arrived */
 	agg->wait_for_ba = false;
 

Re: iwlwifi worse than ever in current git.

[Dave Jones]

On Thu, Jan 19, 2012 at 08:38:35PM +0000, Grumbach, Emmanuel wrote:
 > > 
 > > >
 > > > On Thu, Jan 19, 2012 at 08:47:28AM +0200, Emmanuel Grumbach wrote:
 > > >  > Ok, I finally had a change to take a closer look at this. Please run
 > > >  > with debug=0xC0000000.
 > > >  >
 > > >  > This will be noisy, but I guess we have no choice...
 > > >  > I will be travelling next week, so...
 > > >
 > > > Ah. Got it. I had to do a large download (a kernel tarball was enough) to
 > > > trigger it.
 > > > Log is at http://davej.fedorapeople.org/iwl-debug.txt
 > > >
 > > > The download began at around 13:17 in the log.
 > > > It hung shortly afterwards.
 > > >
 > > > 	Dave
 > > 
 > > Thanks for that one. Really helpful. I need to send you a patch to get a
 > > little more data. I don't know when I will be able to do it though.
 > 
 > Can you please retry with the patch attached ?

Hung again.

http://davej.fedorapeople.org/iwl-debug2.txt

	Dave

--
To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html

RE: iwlwifi worse than ever in current git.

[Grumbach, Emmanuel]

> 
> On Thu, Jan 19, 2012 at 08:38:35PM +0000, Grumbach, Emmanuel wrote:
>  > >
>  > > >
>  > > > On Thu, Jan 19, 2012 at 08:47:28AM +0200, Emmanuel Grumbach wrote:
>  > > >  > Ok, I finally had a change to take a closer look at this. Please run
>  > > >  > with debug=0xC0000000.
>  > > >  >
>  > > >  > This will be noisy, but I guess we have no choice...
>  > > >  > I will be travelling next week, so...
>  > > >
>  > > > Ah. Got it. I had to do a large download (a kernel tarball was enough)
> to
>  > > > trigger it.
>  > > > Log is at http://davej.fedorapeople.org/iwl-debug.txt
>  > > >
>  > > > The download began at around 13:17 in the log.
>  > > > It hung shortly afterwards.
>  > > >
>  > > > 	Dave
>  > >
>  > > Thanks for that one. Really helpful. I need to send you a patch to get a
>  > > little more data. I don't know when I will be able to do it though.
>  >
>  > Can you please retry with the patch attached ?
> 
> Hung again.
> 
> http://davej.fedorapeople.org/iwl-debug2.txt
> 
> 	Dave

Thanks. From what I see, a management frame is sent from an AC queue and when we get the Tx response for this frame, we get sta_id = AP, tid = 0 (and the bug is probably here). So we modify the counters for sta_id = AP, and tid = 0, and this messes up everything.
I guess I need to see why I don't see this issue, and see how to give a hint to the Tx response path that counters shouldn't be modified.

---------------------------------------------------------------------
Intel Israel (74) Limited

This e-mail and any attachments may contain confidential material for
the sole use of the intended recipient(s). Any review or distribution
by others is strictly prohibited. If you are not the intended
recipient, please contact the sender and delete all copies.

--
To unsubscribe from this list: send the line "unsubscribe linux-wireless" in
the body of a message to majordomo-u79uwXL29TY76Z2rM5mHXA@public.gmane.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html