[PATCH] iwlegacy: print how long queue was actually stuck

[PATCH] iwlegacy: print how long queue was actually stuck

[Paul Bolle]

Every now and then, after resuming from suspend, the iwlegacy driver
prints
    iwl4965 0000:03:00.0: Queue 2 stuck for 2000 ms.
    iwl4965 0000:03:00.0: On demand firmware reload

I have no idea what causes these errors. But the code currently uses
wd_timeout in the first error. wd_timeout will generally be set at
IL_DEF_WD_TIMEOUT (ie, 2000). Perhaps printing for how long the queue
was actually stuck can clarify the cause of these errors.

Signed-off-by: Paul Bolle <pebolle@tiscali.nl>
---
0) Compile tested on v3.5-rc4. Tested on Fedora 's current v3.4.2 based
kernel (ie, on F16). That required an edit to this commit because of
trivial context changes.

1) Please note that testing here involved waiting until I again
triggered this error (which now of course printed how long the queue was
actually stuck).

 drivers/net/wireless/iwlegacy/common.c |    7 ++++---
 1 files changed, 4 insertions(+), 3 deletions(-)

diff --git a/drivers/net/wireless/iwlegacy/common.c b/drivers/net/wireless/iwlegacy/common.c
index cbf2dc1..763c752 100644
--- a/drivers/net/wireless/iwlegacy/common.c
+++ b/drivers/net/wireless/iwlegacy/common.c
@@ -4717,10 +4717,11 @@ il_check_stuck_queue(struct il_priv *il, int cnt)
 	struct il_tx_queue *txq = &il->txq[cnt];
 	struct il_queue *q = &txq->q;
 	unsigned long timeout;
+	unsigned long now = jiffies;
 	int ret;
 
 	if (q->read_ptr == q->write_ptr) {
-		txq->time_stamp = jiffies;
+		txq->time_stamp = now;
 		return 0;
 	}
 
@@ -4728,9 +4729,9 @@ il_check_stuck_queue(struct il_priv *il, int cnt)
 	    txq->time_stamp +
 	    msecs_to_jiffies(il->cfg->wd_timeout);
 
-	if (time_after(jiffies, timeout)) {
+	if (time_after(now, timeout)) {
 		IL_ERR("Queue %d stuck for %u ms.\n", q->id,
-		       il->cfg->wd_timeout);
+		       jiffies_to_msecs(now - txq->time_stamp));
 		ret = il_force_reset(il, false);
 		return (ret == -EAGAIN) ? 0 : 1;
 	}
-- 
1.7.7.6

Re: [PATCH] iwlegacy: print how long queue was actually stuck

[Paul Bolle]

On Wed, 2012-06-27 at 10:36 +0200, Paul Bolle wrote:
> Every now and then, after resuming from suspend, the iwlegacy driver
> prints
>     iwl4965 0000:03:00.0: Queue 2 stuck for 2000 ms.
>     iwl4965 0000:03:00.0: On demand firmware reload
> 
> I have no idea what causes these errors. But the code currently uses
> wd_timeout in the first error. wd_timeout will generally be set at
> IL_DEF_WD_TIMEOUT (ie, 2000). Perhaps printing for how long the queue
> was actually stuck can clarify the cause of these errors.

0) It's not just after resume! I just found the following lines through
dmesg (note that it's a period that all messages in dmesg were wlan
related, for some reason):

[...]
[114649.872338] wlan0: associated
[115837.970798] wlan0: deauthenticated from [...] (Reason: 7)
[115837.993405] cfg80211: Calling CRDA to update world regulatory domain
[115838.011979] cfg80211: World regulatory domain updated:
[115838.011986] cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[115838.011995] cfg80211:   (2402000 KHz - 2472000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[115838.012033] cfg80211:   (2457000 KHz - 2482000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[115838.012041] cfg80211:   (2474000 KHz - 2494000 KHz @ 20000 KHz), (300 mBi, 2000 mBm)
[115838.012048] cfg80211:   (5170000 KHz - 5250000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[115838.012055] cfg80211:   (5735000 KHz - 5835000 KHz @ 40000 KHz), (300 mBi, 2000 mBm)
[115838.012108] cfg80211: Calling CRDA for country: NL
[115838.022615] cfg80211: Regulatory domain changed to country: NL
[115838.022622] cfg80211:   (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp)
[115838.022630] cfg80211:   (2402000 KHz - 2482000 KHz @ 40000 KHz), (N/A, 2000 mBm)
[115838.022637] cfg80211:   (5170000 KHz - 5250000 KHz @ 40000 KHz), (N/A, 2000 mBm)
[115838.022644] cfg80211:   (5250000 KHz - 5330000 KHz @ 40000 KHz), (N/A, 2000 mBm)
[115838.022651] cfg80211:   (5490000 KHz - 5710000 KHz @ 40000 KHz), (N/A, 2700 mBm)
[115840.219977] wlan0: authenticate with [...]
[115840.228865] wlan0: send auth to [...] (try 1/3)
[115840.429054] wlan0: send auth to [...] (try 2/3)
[115840.630026] wlan0: send auth to [...] (try 3/3)
[115840.831051] wlan0: authentication with [...] timed out
[115848.022336] wlan0: authenticate with [...]
[115848.022495] wlan0: direct probe to [...] (try 1/3)
[115848.223052] wlan0: direct probe to [...] (try 2/3)
[115848.424052] wlan0: direct probe to [...] (try 3/3)
[115848.625048] wlan0: authentication with [...] timed out
[115855.702461] wlan0: authenticate with [...]
[115855.702623] wlan0: direct probe to [...] (try 1/3)
[115855.903053] wlan0: direct probe to [...] (try 2/3)
[115856.104061] wlan0: direct probe to [...] (try 3/3)
[115856.305050] wlan0: authentication with [...] timed out
[115863.464067] wlan0: authenticate with [...]
[115863.464221] wlan0: direct probe to [...] (try 1/3)
[115863.665054] wlan0: direct probe to [...] (try 2/3)
[115863.866058] wlan0: direct probe to [...] (try 3/3)
[115864.067051] wlan0: authentication with [...] timed out
[115871.267216] wlan0: authenticate with [...]
[115871.267376] wlan0: send auth to [...] (try 1/3)
[115871.269191] wlan0: authenticated
[115871.279459] wlan0: associate with [...] (try 1/3)
[115871.281715] wlan0: RX AssocResp from [...] (capab=0x411 status=0 aid=2)
[115871.281723] wlan0: associated
[115871.457043] iwl4965 0000:03:00.0: Queue 2 stuck for 33487 ms.
[115871.457048] iwl4965 0000:03:00.0: On demand firmware reload
[115871.457149] ieee80211 phy0: Hardware restart was requested
[117985.197630] wlan0: deauthenticating from [...] by local choice (reason=3)
[...]

1) My guess is that I left my laptop unattended for quite some time (so
_perhaps_ generating little to no wlan traffic), and in that period
NetworkManager and friends ran into trouble re-authenticating to my
wireless router. By the time authentication succeeded it just looked
like "Queue 2" was stuck. Wild, uneducated guess, actually.

2) It's always "Queue 2" that's stuck. What does that queue do?


Paul Bolle

Re: [PATCH] iwlegacy: print how long queue was actually stuck

[Emmanuel Grumbach]

>
> On Wed, 2012-06-27 at 10:36 +0200, Paul Bolle wrote:
> > Every now and then, after resuming from suspend, the iwlegacy driver
> > prints
> >     iwl4965 0000:03:00.0: Queue 2 stuck for 2000 ms.
> >     iwl4965 0000:03:00.0: On demand firmware reload
> >
> > I have no idea what causes these errors. But the code currently uses
> > wd_timeout in the first error. wd_timeout will generally be set at
> > IL_DEF_WD_TIMEOUT (ie, 2000). Perhaps printing for how long the queue
> > was actually stuck can clarify the cause of these errors.
>

You may want to try this one:
http://www.spinics.net/lists/stable-commits/msg18110.html

Re: [PATCH] iwlegacy: print how long queue was actually stuck

[Emmanuel Grumbach]

>
> On Wed, 2012-06-27 at 10:36 +0200, Paul Bolle wrote:
> > Every now and then, after resuming from suspend, the iwlegacy driver
> > prints
> >     iwl4965 0000:03:00.0: Queue 2 stuck for 2000 ms.
> >     iwl4965 0000:03:00.0: On demand firmware reload
> >
> > I have no idea what causes these errors. But the code currently uses
> > wd_timeout in the first error. wd_timeout will generally be set at
> > IL_DEF_WD_TIMEOUT (ie, 2000). Perhaps printing for how long the queue
> > was actually stuck can clarify the cause of these errors.
>

You may want to try this one:
http://www.spinics.net/lists/stable-commits/msg18110.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: [PATCH] iwlegacy: print how long queue was actually stuck

[Paul Bolle]

On Sat, 2012-06-30 at 21:18 +0300, Emmanuel Grumbach wrote:
> You may want to try this one:
> http://www.spinics.net/lists/stable-commits/msg18110.html

That issue looks similar, though it regards iwlwifi. Thanks anyway.
Perhaps commit d6ee27eb13beab94056e0de52d81220058ca2297 ("iwlwifi: don't
mess up the SCD when removing a key") can be ported to iwlegacy. We'll
see whether I manage to port it and whether it helps.

Note that iwlwifi also seems to print the (default) timeout in its
message and not how long a queue was actually stuck. So perhaps
something like my patch could be ported to iwlwifi too.


Paul Bolle

Re: [PATCH] iwlegacy: print how long queue was actually stuck

[Stanislaw Gruszka]

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

On Sat, Jun 30, 2012 at 03:20:06PM +0200, Paul Bolle wrote:
> On Wed, 2012-06-27 at 10:36 +0200, Paul Bolle wrote:
> > Every now and then, after resuming from suspend, the iwlegacy driver
> > prints
> >     iwl4965 0000:03:00.0: Queue 2 stuck for 2000 ms.
> >     iwl4965 0000:03:00.0: On demand firmware reload
> > 
> > I have no idea what causes these errors. But the code currently uses
> > wd_timeout in the first error. wd_timeout will generally be set at
> > IL_DEF_WD_TIMEOUT (ie, 2000). Perhaps printing for how long the queue
> > was actually stuck can clarify the cause of these errors.
> 
> 0) It's not just after resume! I just found the following lines through
> dmesg (note that it's a period that all messages in dmesg were wlan
> related, for some reason):
> 
> [115840.219977] wlan0: authenticate with [...]
> [115840.228865] wlan0: send auth to [...] (try 1/3)
> [115840.429054] wlan0: send auth to [...] (try 2/3)
> [115840.630026] wlan0: send auth to [...] (try 3/3)
> [115840.831051] wlan0: authentication with [...] timed out
> [115848.022336] wlan0: authenticate with [...]
> [115848.022495] wlan0: direct probe to [...] (try 1/3)
> [115848.223052] wlan0: direct probe to [...] (try 2/3)
> [115848.424052] wlan0: direct probe to [...] (try 3/3)
> [115848.625048] wlan0: authentication with [...] timed out
> [115855.702461] wlan0: authenticate with [...]
> [115855.702623] wlan0: direct probe to [...] (try 1/3)
> [115855.903053] wlan0: direct probe to [...] (try 2/3)
> [115856.104061] wlan0: direct probe to [...] (try 3/3)
> [115856.305050] wlan0: authentication with [...] timed out
> [115863.464067] wlan0: authenticate with [...]
> [115863.464221] wlan0: direct probe to [...] (try 1/3)
> [115863.665054] wlan0: direct probe to [...] (try 2/3)
> [115863.866058] wlan0: direct probe to [...] (try 3/3)
> [115864.067051] wlan0: authentication with [...] timed out
> [115871.267216] wlan0: authenticate with [...]
> [115871.267376] wlan0: send auth to [...] (try 1/3)
> [115871.269191] wlan0: authenticated
> [115871.279459] wlan0: associate with [...] (try 1/3)
> [115871.281715] wlan0: RX AssocResp from [...] (capab=0x411 status=0 aid=2)
> [115871.281723] wlan0: associated
> [115871.457043] iwl4965 0000:03:00.0: Queue 2 stuck for 33487 ms.
> [115871.457048] iwl4965 0000:03:00.0: On demand firmware reload
For some reason we are not able to authenticate, what itself is a
problem. Maybe this is wrong key offset problem and that will
be fixed by Emmanuel patch.

Regarding "Queue 2 stuck", there is another fix in iwlwifi that
did not make to iwlegacy, which perhaps could help. If not here
then maybe on suspend.  

commit 342bbf3fee2fa9a18147e74b2e3c4229a4564912
Author: Johannes Berg <johannes.berg@intel.com>
Date:   Sun Mar 4 08:50:46 2012 -0800

    iwlwifi: always monitor for stuck queues

I'm attaching iwlegacy version of it.

> 2) It's always "Queue 2" that's stuck. What does that queue do?

It's TX queue, probably one used for default traffic i.e. for Best
Effort category (others are Video, Voice and Background).

Stanislaw

[-- Attachment #2: iwlegacy-allways-monitor-for-stuck-queues.patch --]
[-- Type: text/plain, Size: 822 bytes --]

diff --git a/drivers/net/wireless/iwlegacy/common.c b/drivers/net/wireless/iwlegacy/common.c
index cbf2dc1..5d4807c 100644
--- a/drivers/net/wireless/iwlegacy/common.c
+++ b/drivers/net/wireless/iwlegacy/common.c
@@ -4767,14 +4767,12 @@ il_bg_watchdog(unsigned long data)
 		return;
 
 	/* monitor and check for other stuck queues */
-	if (il_is_any_associated(il)) {
-		for (cnt = 0; cnt < il->hw_params.max_txq_num; cnt++) {
-			/* skip as we already checked the command queue */
-			if (cnt == il->cmd_queue)
-				continue;
-			if (il_check_stuck_queue(il, cnt))
-				return;
-		}
+	for (cnt = 0; cnt < il->hw_params.max_txq_num; cnt++) {
+		/* skip as we already checked the command queue */
+		if (cnt == il->cmd_queue)
+			continue;
+		if (il_check_stuck_queue(il, cnt))
+			return;
 	}
 
 	mod_timer(&il->watchdog,

Re: [PATCH] iwlegacy: print how long queue was actually stuck

[Paul Bolle]

On Mon, 2012-07-02 at 11:06 +0200, Stanislaw Gruszka wrote:
> On Sat, Jun 30, 2012 at 03:20:06PM +0200, Paul Bolle wrote:
> For some reason we are not able to authenticate, what itself is a
> problem. Maybe this is wrong key offset problem and that will
> be fixed by Emmanuel patch.

Which I can only try if we fix the small problem you mentioned in your
comment on Emmanuel's patch (reference
<20120702082653.GA2479@redhat.com>, not yet archived on lkml.org), can't
I?

> Regarding "Queue 2 stuck", there is another fix in iwlwifi that
> did not make to iwlegacy, which perhaps could help. If not here
> then maybe on suspend.  
> 
> commit 342bbf3fee2fa9a18147e74b2e3c4229a4564912
> Author: Johannes Berg <johannes.berg@intel.com>
> Date:   Sun Mar 4 08:50:46 2012 -0800
> 
>     iwlwifi: always monitor for stuck queues
> 
> I'm attaching iwlegacy version of it.

Thanks, I'll try it. The explanation of the iwlwifi commit makes a lot
of sense: it seems to match the events found in the logs of this laptop.
That's encouraging. Should I report whether the iwlegacy version works
or not?

> > 2) It's always "Queue 2" that's stuck. What does that queue do?
> 
> It's TX queue, probably one used for default traffic i.e. for Best
> Effort category (others are Video, Voice and Background).

I see.

Any thoughts on my patch (ie, the patch that is actually the subject of
this thread?


Paul Bolle

Re: [PATCH] iwlegacy: print how long queue was actually stuck

[Stanislaw Gruszka]

On Mon, Jul 02, 2012 at 11:32:43AM +0200, Paul Bolle wrote:
> On Mon, 2012-07-02 at 11:06 +0200, Stanislaw Gruszka wrote:
> > On Sat, Jun 30, 2012 at 03:20:06PM +0200, Paul Bolle wrote:
> > For some reason we are not able to authenticate, what itself is a
> > problem. Maybe this is wrong key offset problem and that will
> > be fixed by Emmanuel patch.
> 
> Which I can only try if we fix the small problem you mentioned in your
> comment on Emmanuel's patch (reference
> <20120702082653.GA2479@redhat.com>, not yet archived on lkml.org), can't
> I?
Oh, you were not CCed, and lkml too, v2 patch is here:
http://marc.info/?l=linux-wireless&m=134121823510017&w=2

> > Regarding "Queue 2 stuck", there is another fix in iwlwifi that
> > did not make to iwlegacy, which perhaps could help. If not here
> > then maybe on suspend.  
> > 
> > commit 342bbf3fee2fa9a18147e74b2e3c4229a4564912
> > Author: Johannes Berg <johannes.berg@intel.com>
> > Date:   Sun Mar 4 08:50:46 2012 -0800
> > 
> >     iwlwifi: always monitor for stuck queues
> > 
> > I'm attaching iwlegacy version of it.
> 
> Thanks, I'll try it. The explanation of the iwlwifi commit makes a lot
> of sense: it seems to match the events found in the logs of this laptop.
> That's encouraging. Should I report whether the iwlegacy version works
> or not?
Actually I'll post it anyway. But if this patch and Emmanuel's will not 
fix the problem you should report it. 
   
> > > 2) It's always "Queue 2" that's stuck. What does that queue do?
> > 
> > It's TX queue, probably one used for default traffic i.e. for Best
> > Effort category (others are Video, Voice and Background).
> 
> I see.
> 
> Any thoughts on my patch (ie, the patch that is actually the subject of
> this thread?
It was applied to wireless-testing.

Stanislaw

Re: [PATCH] iwlegacy: print how long queue was actually stuck

[Stanislaw Gruszka]

On Mon, Jul 02, 2012 at 11:32:43AM +0200, Paul Bolle wrote:
> On Mon, 2012-07-02 at 11:06 +0200, Stanislaw Gruszka wrote:
> > On Sat, Jun 30, 2012 at 03:20:06PM +0200, Paul Bolle wrote:
> > For some reason we are not able to authenticate, what itself is a
> > problem. Maybe this is wrong key offset problem and that will
> > be fixed by Emmanuel patch.
> 
> Which I can only try if we fix the small problem you mentioned in your
> comment on Emmanuel's patch (reference
> <20120702082653.GA2479-H+wXaHxf7aLQT0dZR+AlfA@public.gmane.org>, not yet archived on lkml.org), can't
> I?
Oh, you were not CCed, and lkml too, v2 patch is here:
http://marc.info/?l=linux-wireless&m=134121823510017&w=2

> > Regarding "Queue 2 stuck", there is another fix in iwlwifi that
> > did not make to iwlegacy, which perhaps could help. If not here
> > then maybe on suspend.  
> > 
> > commit 342bbf3fee2fa9a18147e74b2e3c4229a4564912
> > Author: Johannes Berg <johannes.berg-ral2JQCrhuEAvxtiuMwx3w@public.gmane.org>
> > Date:   Sun Mar 4 08:50:46 2012 -0800
> > 
> >     iwlwifi: always monitor for stuck queues
> > 
> > I'm attaching iwlegacy version of it.
> 
> Thanks, I'll try it. The explanation of the iwlwifi commit makes a lot
> of sense: it seems to match the events found in the logs of this laptop.
> That's encouraging. Should I report whether the iwlegacy version works
> or not?
Actually I'll post it anyway. But if this patch and Emmanuel's will not 
fix the problem you should report it. 
   
> > > 2) It's always "Queue 2" that's stuck. What does that queue do?
> > 
> > It's TX queue, probably one used for default traffic i.e. for Best
> > Effort category (others are Video, Voice and Background).
> 
> I see.
> 
> Any thoughts on my patch (ie, the patch that is actually the subject of
> this thread?
It was applied to wireless-testing.

Stanislaw
--
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: [PATCH] iwlegacy: print how long queue was actually stuck

[Paul Bolle]

On Mon, 2012-07-02 at 11:39 +0200, Stanislaw Gruszka wrote:
> On Mon, Jul 02, 2012 at 11:32:43AM +0200, Paul Bolle wrote:
> Oh, you were not CCed, and lkml too, v2 patch is here:
> http://marc.info/?l=linux-wireless&m=134121823510017&w=2

Thanks.

> > Should I report whether the iwlegacy version works
> > or not?
> Actually I'll post it anyway. But if this patch and Emmanuel's will not 
> fix the problem you should report it. 

I'll try to report any oddities I notice.

> > Any thoughts on my patch (ie, the patch that is actually the subject of
> > this thread?
> It was applied to wireless-testing.

That's nice.


Paul Bolle