Re: iwlagn is getting very shaky

From: Emmanuel Grumbach
Date: Fri Nov 25 2011 - 07:31:19 EST

Next message: Lars-Peter Clausen: "Re: [PATCH 1/1] iio: iio_event_getfd -- fix ev_int build failure"
Previous message: Hillf Danton: "[PATCH] mm: migration: pair unlock_page and lock_page when migratinghuge pages"
In reply to: Norbert Preining: "Re: iwlagn is getting very shaky"
Next in thread: Norbert Preining: "Re: iwlagn is getting very shaky"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

On Fri, Nov 25, 2011 at 14:21, Norbert Preining <preining@xxxxxxxx> wrote:
> Hi Emmanuel,
>
> On Do, 24 Nov 2011, Emmanuel Grumbach wrote:
>> Please apply the patch attached on top of the one I previously sent.
>> Let me know I you have trouble with patch.
>
> The patch you sent was not against kernel git, but I moved the
> debug statement from iwl-mac80211.c to iwl-agn.c (where I guess is
> the right place) and applied the rest of the patch.

Thanks for doing the porting job :-)

>
>> Please also enable the MAC80211_HT_DEBUG compilation flag
>> I also the (HT + TXQUEUES) debug flag of the driver: modprobe iwlwifi
>> debug=0x84000000
>
> Also activated.
>

cool

> Here my very very small theory, but that is just guessing: Could it
> be related to the time being adjusted by ntp or something? I have the
> feeling it works for a bit, then hangs. In this little bit it might
> be that ntp updates the time of the laptop. That would explain why
> on a full normal reboot it most of the times work, but when the laptop
> sleeps for long time, or is turned of for long time, then it is
> getting problems. But this is surely just a stupid theory.
>

Well.. All this is really Layer 2 related, and even lower. It is a
kind of bad handshake between the driver / HW / mac80211. So I
wouldn't think that NTP may hurt here. Although one should never
underestimate the damage a piece of software can do....

> Here we go with the debug output
>
>
> [ 4592.437269] iwlwifi 0000:06:00.0: L1 Enabled; Disabling L0S
> [ 4592.441080] iwlwifi 0000:06:00.0: Radio type=0x1-0x2-0x0
> [ 4592.482332] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 0
> [ 4592.482346] iwlwifi 0000:06:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 0 on FIFO 3
> [ 4592.482349] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 1
> [ 4592.482362] iwlwifi 0000:06:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 1 on FIFO 2
> [ 4592.482365] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 2
> [ 4592.482377] iwlwifi 0000:06:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 2 on FIFO 1
> [ 4592.482380] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 3
> [ 4592.482392] iwlwifi 0000:06:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 3 on FIFO 0
> [ 4592.482395] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 4
> [ 4592.482407] iwlwifi 0000:06:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 4 on FIFO 7
> [ 4592.482410] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 5
> [ 4592.482412] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 6
> [ 4592.482415] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 7
> [ 4592.482417] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 8
> [ 4592.482419] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 9
> [ 4592.482422] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 10
> [ 4600.139699] wlan0: authenticate with 00:0a:79:eb:56:10 (try 1)
> [ 4600.142190] wlan0: authenticated
> [ 4600.148081] wlan0: associate with 00:0a:79:eb:56:10 (try 1)
> [ 4600.153962] wlan0: RX AssocResp from 00:0a:79:eb:56:10 (capab=0x411 status=0 aid=2)
> [ 4600.153972] wlan0: associated
> [ 4601.280512] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action A-MPDU action on addr 00:0a:79:eb:56:10 tid 0
> [ 4601.280525] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action start Rx
> [ 4616.622380] iwlwifi 0000:06:00.0: I rs_tl_turn_on_agg_for_tid Starting Tx agg: STA: 00:0a:79:eb:56:10 tid: 0
> [ 4616.652083] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action A-MPDU action on addr 00:0a:79:eb:56:10 tid 0
> [ 4616.652087] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action start Tx
> [ 4616.652090] iwlwifi 0000:06:00.0: U iwlagn_tx_agg_start TX AGG request on ra = 00:0a:79:eb:56:10 tid = 0
> [ 4616.652238] iwlwifi 0000:06:00.0: U iwlagn_txq_ctx_activate_free Activate txq 11
> [ 4616.652241] iwlwifi 0000:06:00.0: U iwl_trans_pcie_tx_agg_alloc HW queue is empty
> [ 4616.652244] iwlwifi 0000:06:00.0: U iwl_start_tx_ba_trans_ready Telling mac start BA ready tid: 0
> [ 4617.652070] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action A-MPDU action on addr 00:0a:79:eb:56:10 tid 0
> [ 4617.652075] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action stop Tx
> [ 4617.652077] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action Stop Tx agg for tid 0
> [ 4617.652081] iwlwifi 0000:06:00.0: U iwl_trans_pcie_tx_agg_disable HW queue is empty
> [ 4617.652139] iwlwifi 0000:06:00.0: U iwl_trans_pcie_txq_agg_disable Disable AGG txq_id 11
> [ 4617.652192] iwlwifi 0000:06:00.0: U iwl_txq_ctx_deactivate Deactivate txq 11
> [ 4617.652210] iwlwifi 0000:06:00.0: U iwl_trans_tx_queue_set_status Deactivate AC/CMD Queue 11 on FIFO 0
> [ 4617.652213] iwlwifi 0000:06:00.0: U iwl_stop_tx_ba_trans_ready Telling mac stop BA ready tid: 0
> [ 4621.013744] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action A-MPDU action on addr 00:0a:79:eb:56:10 tid 0
> [ 4621.013760] iwlwifi 0000:06:00.0: U iwl_trans_pcie_tx_agg_setup Setup AGG for tid 0
> [ 4621.013916] iwlwifi 0000:06:00.0: U iwl_trans_tx_queue_set_status Deactivate BA Queue 11 on FIFO 1
> [ 4621.013925] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action priv->agg_tids_count = 1
> [ 4621.013937] iwlwifi 0000:06:00.0: Tx aggregation enabled on ra = 00:0a:79:eb:56:10 tid = 0

Thanks

I am already on week-end here and will look at it more carefully
later. First impression is that things are messy here. I guess we are
getting in a bad failure path that wasn't checked...

> [ 4621.013954] ------------[ cut here ]------------
> [ 4621.013991] WARNING: at drivers/net/wireless/iwlwifi/iwl-trans-pcie.c:1106 iwl_trans_pcie_tx+0x180/0x668 [iwlwifi]()
> [ 4621.013999] Hardware name: VGN-Z11VN_B
> [ 4621.014004] Modules linked in: usb_storage rfcomm bnep vboxpci(O) vboxnetadp(O) vboxnetflt(O) vboxdrv(O) snd_hrtimer binfmt_misc dm_crypt dm_mod isofs btrfs zlib_deflate crc32c libcrc32c vfat fat fuse loop uinput snd_hda_codec_realtek snd_hda_intel snd_hda_codec snd_hwdep snd_pcm_oss snd_mixer_oss arc4 snd_pcm iwlwifi mac80211 snd_seq_dummy snd_seq_oss snd_seq_midi snd_rawmidi snd_seq_midi_event btusb sony_laptop(O) bluetooth snd_seq snd_timer snd_seq_device snd soundcore cfg80211 firewire_ohci firewire_core mxm_wmi joydev rfkill tpm_infineon snd_page_alloc crc16 crc_itu_t
> [ 4621.014134] Pid: 6169, comm: kworker/u:44 Tainted: G W O 3.2.0-rc3+ #2
> [ 4621.014140] Call Trace:
> [ 4621.014145] <IRQ> [<ffffffff8103849d>] warn_slowpath_common+0x83/0x9b
> [ 4621.014171] [<ffffffff810384cf>] warn_slowpath_null+0x1a/0x1c
> [ 4621.014194] [<ffffffffa0204f4d>] iwl_trans_pcie_tx+0x180/0x668 [iwlwifi]
> [ 4621.014208] [<ffffffff810d3861>] ? kmem_cache_alloc+0x44/0xb9
> [ 4621.014229] [<ffffffffa01eca7d>] iwlagn_tx_skb+0x87b/0x91b [iwlwifi]
> [ 4621.014247] [<ffffffffa01e2fea>] iwlagn_mac_tx+0x131/0x1a2 [iwlwifi]
> [ 4621.014268] [<ffffffffa01c1cc6>] ? ieee80211_tx_h_fragment+0x16/0x22c [mac80211]
> [ 4621.014296] [<ffffffffa01b6000>] __ieee80211_tx+0x176/0x1cf [mac80211]
> [ 4621.014314] [<ffffffffa01c1c38>] ? ieee80211_tx_h_calculate_duration+0x4c/0x65 [mac80211]
> [ 4621.014344] [<ffffffffa01b6dc6>] ieee80211_tx+0x97/0xaf [mac80211]
> [ 4621.014374] [<ffffffffa01b7cc2>] ieee80211_tx_pending+0xf0/0x1c3 [mac80211]
> [ 4621.014386] [<ffffffff8103dc16>] tasklet_action+0x77/0xc2
> [ 4621.014395] [<ffffffff8103dd57>] __do_softirq+0xbc/0x1a5
> [ 4621.014408] [<ffffffff8140b24c>] call_softirq+0x1c/0x30
> [ 4621.014413] <EOI> [<ffffffff8100359e>] do_softirq+0x38/0x6e
> [ 4621.014430] [<ffffffff8103da1d>] _local_bh_enable_ip.isra.12+0x7d/0xa0
> [ 4621.014439] [<ffffffff8103da4e>] local_bh_enable_ip+0xe/0x10
> [ 4621.014448] [<ffffffff81409462>] _raw_spin_unlock_bh+0x23/0x25
> [ 4621.014471] [<ffffffffa01a5c6c>] ieee80211_agg_tx_operational+0x99/0xa4 [mac80211]
> [ 4621.014496] [<ffffffffa01a67bd>] ieee80211_process_addba_resp+0xb8/0xf3 [mac80211]
> [ 4621.014508] [<ffffffff81064840>] ? do_raw_spin_trylock+0x18/0x2a
> [ 4621.014534] [<ffffffffa01adada>] ieee80211_iface_work+0x130/0x2b5 [mac80211]
> [ 4621.014560] [<ffffffffa01ad9aa>] ? ieee80211_teardown_sdata+0xcc/0xcc [mac80211]
> [ 4621.014572] [<ffffffff8104de54>] process_one_work+0x17b/0x2bd
> [ 4621.014583] [<ffffffff8104c499>] ? need_to_create_worker+0x12/0x26
> [ 4621.014593] [<ffffffff8104ef4f>] worker_thread+0xdb/0x15f
> [ 4621.014602] [<ffffffff8104ee74>] ? manage_workers.isra.24+0x171/0x171
> [ 4621.014612] [<ffffffff81052639>] kthread+0x84/0x8c
> [ 4621.014622] [<ffffffff8140b154>] kernel_thread_helper+0x4/0x10
> [ 4621.014633] [<ffffffff810525b5>] ? kthread_worker_fn+0x148/0x148
> [ 4621.014642] [<ffffffff8140b150>] ? gs_change+0xb/0xb
> [ 4621.014649] ---[ end trace 81df68812429b16c ]---
> [ 4622.112804] iwlwifi 0000:06:00.0: I rs_tl_turn_on_agg_for_tid Starting Tx agg: STA: 00:0a:79:eb:56:10 tid: 0
> [ 4622.124104] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action A-MPDU action on addr 00:0a:79:eb:56:10 tid 0
> [ 4622.124116] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action start Tx
> [ 4622.124126] iwlwifi 0000:06:00.0: U iwlagn_tx_agg_start TX AGG request on ra = 00:0a:79:eb:56:10 tid = 0
> [ 4622.124304] iwlwifi 0000:06:00.0: U iwlagn_txq_ctx_activate_free Activate txq 11
> [ 4622.124315] iwlwifi 0000:06:00.0: U iwl_trans_pcie_tx_agg_alloc HW queue is NOT empty: 21 packets in HW queue
> [ 4630.040070] iwlwifi 0000:06:00.0: Queue 11 stuck for 10000 ms.
> [ 4630.040081] iwlwifi 0000:06:00.0: Current SW read_ptr 242 write_ptr 8
> [ 4630.040136] iwlwifi 0000:06:00.0: Current HW read_ptr 242 write_ptr 8
> [ 4630.040144] iwlwifi 0000:06:00.0: On demand firmware reload
> [ 4630.040587] ieee80211 phy0: Hardware restart was requested
> [ 4630.040698] iwlwifi 0000:06:00.0: L1 Enabled; Disabling L0S
> [ 4630.043703] iwlwifi 0000:06:00.0: Radio type=0x1-0x2-0x0
> [ 4630.086602] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 0
> [ 4630.086624] iwlwifi 0000:06:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 0 on FIFO 3
> [ 4630.086634] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 1
> [ 4630.086653] iwlwifi 0000:06:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 1 on FIFO 2
> [ 4630.086662] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 2
> [ 4630.086681] iwlwifi 0000:06:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 2 on FIFO 1
> [ 4630.086690] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 3
> [ 4630.086709] iwlwifi 0000:06:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 3 on FIFO 0
> [ 4630.086717] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 4
> [ 4630.086736] iwlwifi 0000:06:00.0: U iwl_trans_tx_queue_set_status Activate AC/CMD Queue 4 on FIFO 7
> [ 4630.086745] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 5
> [ 4630.086752] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 6
> [ 4630.086759] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 7
> [ 4630.086767] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 8
> [ 4630.086774] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 9
> [ 4630.086781] iwlwifi 0000:06:00.0: U iwl_txq_ctx_activate Activate txq 10
> [ 4630.157921] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action A-MPDU action on addr 00:0a:79:eb:56:10 tid 0
> [ 4630.157933] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action stop Tx
> [ 4630.157942] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action Stop Tx agg for tid 0
> [ 4630.157951] iwlwifi 0000:06:00.0: U iwl_trans_pcie_tx_agg_disable AGG stop before setup done
> [ 4630.157992] iwlwifi 0000:06:00.0: U iwl_trans_pcie_txq_agg_disable Disable AGG txq_id 11
> [ 4630.158073] iwlwifi 0000:06:00.0: U iwl_txq_ctx_deactivate Deactivate txq 11
> [ 4630.158113] iwlwifi 0000:06:00.0: U iwl_trans_tx_queue_set_status Deactivate AC/CMD Queue 11 on FIFO 0
> [ 4630.158123] iwlwifi 0000:06:00.0: U iwl_stop_tx_ba_trans_ready Telling mac stop BA ready tid: 0
> [ 4630.158136] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action priv->agg_tids_count = 0
> [ 4630.158148] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action A-MPDU action on addr 00:0a:79:eb:56:10 tid 0
> [ 4630.158157] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action stop Rx
> [ 4630.196845] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action A-MPDU action on addr 00:0a:79:eb:56:10 tid 0
> [ 4630.196857] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action start Rx
> [ 4632.759183] iwlwifi 0000:06:00.0: I rs_tl_turn_on_agg_for_tid Starting Tx agg: STA: 00:0a:79:eb:56:10 tid: 0
> [ 4632.812124] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action A-MPDU action on addr 00:0a:79:eb:56:10 tid 0
> [ 4632.812136] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action start Tx
> [ 4632.812145] iwlwifi 0000:06:00.0: U iwlagn_tx_agg_start TX AGG request on ra = 00:0a:79:eb:56:10 tid = 0
> [ 4632.812326] iwlwifi 0000:06:00.0: U iwlagn_txq_ctx_activate_free Activate txq 11
> [ 4632.812337] iwlwifi 0000:06:00.0: U iwl_trans_pcie_tx_agg_alloc HW queue is NOT empty: 21 packets in HW queue
> [ 4634.916847] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action A-MPDU action on addr 00:0a:79:eb:56:10 tid 6
> [ 4634.916860] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action start Rx
> [ 4644.716439] iwlwifi 0000:06:00.0: I rs_tl_turn_on_agg_for_tid Starting Tx agg: STA: 00:0a:79:eb:56:10 tid: 6
> [ 4644.764120] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action A-MPDU action on addr 00:0a:79:eb:56:10 tid 6
> [ 4644.764132] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action start Tx
> [ 4644.764142] iwlwifi 0000:06:00.0: U iwlagn_tx_agg_start TX AGG request on ra = 00:0a:79:eb:56:10 tid = 6
> [ 4644.764306] iwlwifi 0000:06:00.0: U iwlagn_txq_ctx_activate_free Activate txq 12
> [ 4644.764315] iwlwifi 0000:06:00.0: U iwl_trans_pcie_tx_agg_alloc HW queue is empty
> [ 4644.764325] iwlwifi 0000:06:00.0: U iwl_start_tx_ba_trans_ready Telling mac start BA ready tid: 6
> [ 4644.766328] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action A-MPDU action on addr 00:0a:79:eb:56:10 tid 6
> [ 4644.766339] iwlwifi 0000:06:00.0: U iwl_trans_pcie_tx_agg_setup Setup AGG for tid 6
> [ 4644.766494] iwlwifi 0000:06:00.0: U iwl_trans_tx_queue_set_status Activate BA Queue 12 on FIFO 3
> [ 4644.766503] iwlwifi 0000:06:00.0: U iwlagn_mac_ampdu_action priv->agg_tids_count = 1
> [ 4644.766549] iwlwifi 0000:06:00.0: Tx aggregation enabled on ra = 00:0a:79:eb:56:10 tid = 6
> [ 4703.713625] iwlwifi 0000:06:00.0: I iwlagn_rx_reply_compressed_ba agg frames sent:2, acked:2
>
>
> Best wishes
>
> Norbert
> ------------------------------------------------------------------------
> Norbert Preining preining@{jaist.ac.jp, logic.at, debian.org}
> JAIST, Japan TeX Live & Debian Developer
> DSA: 0x09C5B094 fp: 14DF 2E6C 0307 BE6D AD76 A9C0 D2BF 4AA3 09C5 B094
> ------------------------------------------------------------------------
> BRISBANE
> A perfectly reasonable explanation (Such as the one offered by a
> person with a gurgling cough which has nothing to do with the fact
> that they smoke fifty cigarettes a day.)
> --- Douglas Adams, The Meaning of Liff
>
--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/

Next message: Lars-Peter Clausen: "Re: [PATCH 1/1] iio: iio_event_getfd -- fix ev_int build failure"
Previous message: Hillf Danton: "[PATCH] mm: migration: pair unlock_page and lock_page when migratinghuge pages"
In reply to: Norbert Preining: "Re: iwlagn is getting very shaky"
Next in thread: Norbert Preining: "Re: iwlagn is getting very shaky"
Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]