Frequent spurious tx_timeouts for libertas

Frequent spurious tx_timeouts for libertas

[Daniel Drake]

Hi,

The libertas driver works as follows:

Once successfully connected to wifi, it enables the TX queue.
When the network layer calls hard_start_xmit, the driver stores the
packet in memory, stops the TX queue with netif_stop_queue(), and
returns NETDEV_TX_OK.
Some time later, the libertas kernel thread wakes up, sees the new
packet stored for delivery, sends it to the card, then runs
netif_wake_queue() to get things moving again.

Sometimes the TX queue is stopped and started from other places (e.g.
while scanning for networks, which NetworkManager triggers every
couple of minutes)

Thus the TX queue is stopped and started very often.

The libertas tx_timeout handler is being called quite a lot, and quite
soon after boot we get this in the kernel logs (the first time it
happens):

[   97.050101] ------------[ cut here ]------------
[   97.054866] WARNING: at net/sched/sch_generic.c:258 dev_watchdog+0x102/0x17c
[   97.062277] Hardware name: XO
[   97.065335] NETDEV WATCHDOG: eth0 (libertas_sdio): transmit queue 0 timed out
<snip large trace>

This message seems bogus - all the recent transmissions happened correctly.

What is this watchdog trying to detect exactly? Using what criteria?

I had a look at the code and it doesn't quite make sense to me - also
explaining why we get this bogus message. Here's what happens:

1. Kernel asks libertas to transmit a packet; libertas stops the TX
queue and puts the packet in memory
2. Very shortly after, libertas thread picks up the packet, transmits
it via the card, and restarts the tx queue. The packet is transmitted
correctly, and the queue is awake again.
3. Shortly after (with no further TX activity occuring in this time),
NetworkManager starts scanning for networks. This causes the TX queue
to be stopped and started a few times over the space of a few seconds,
and during this time the queue is stopped for quite a while.
4. The netdev watchdog wakes up in one of these times when the TX
queue is stopped, and uses its criteria (last TX was a few seconds
ago, queue is currently stopped) to determine that a transmit timeout
has occurred (???)

Is libertas doing something wrong, or is this a bug/oddity in the network layer?

Also, while looking at this code, I spotted a bug in dev_watchdog():
				/*
				 * old device drivers set dev->trans_start
				 */
				trans_start = txq->trans_start ? : dev->trans_start;

i.e. it is trying to figure out whether to read trans_start from txq
or dev. In both cases, trans_start is updated based on the value of
jiffies, which will occasionally be 0 (as it wraps around). Therefore
this line of code will occasionally make the wrong decision.

Daniel

Re: Frequent spurious tx_timeouts for libertas

[Ben Hutchings]

On Sun, 2011-05-01 at 22:21 +0100, Daniel Drake wrote:
[...]
> Sometimes the TX queue is stopped and started from other places (e.g.
> while scanning for networks, which NetworkManager triggers every
> couple of minutes)
> 
> Thus the TX queue is stopped and started very often.
> 
> The libertas tx_timeout handler is being called quite a lot, and quite
> soon after boot we get this in the kernel logs (the first time it
> happens):
> 
> [   97.050101] ------------[ cut here ]------------
> [   97.054866] WARNING: at net/sched/sch_generic.c:258 dev_watchdog+0x102/0x17c
> [   97.062277] Hardware name: XO
> [   97.065335] NETDEV WATCHDOG: eth0 (libertas_sdio): transmit queue 0 timed out
> <snip large trace>
> 
> This message seems bogus - all the recent transmissions happened correctly.
> 
> What is this watchdog trying to detect exactly? Using what criteria?

I'll repeat my answer from the last time this was asked on netdev:

The watchdog fires when the software queue has been stopped *and* the
link has been reported as up for over dev->watchdog_timeo ticks.

The software queue should be stopped iff the hardware queue is full or
nearly full.  If the software queue remains stopped and the link is
still reported up, then one of these things is happening:

1. The link went down but the driver didn't notice
2. TX completions are not being indicated or handled correctly
3. The hardware TX path has locked up
4. The link is stalled by excessive pause frames or collisions
5. Timeout is too low and/or low watermark is too high
(there may be other explanations)

I think the watchdog is primarily meant to deal with case 3, though all
of cases 1-3 may be worked around by resetting the hardware.

And now, for the specific case of libertas:

It appears that libertas reports carrier off (link down) while scanning,
so that should mean the watchdog does not fire.  However:

1. The watchdog will only check the current link state, which might be
up again when it runs.
2. The watchdog assumes that TX queues only fill up in response to
packets sent by the TX scheduler.

[...]
> Is libertas doing something wrong, or is this a bug/oddity in the network layer?

Since the TX scheduler doesn't know about the extra packets you are
injecting to do channel scanning, I think you need to call
txq_trans_update() when you do that.  And I don't think it's a good idea
to call netif_carrier_off() there at all.  If it has any effect at all
(which I don't think it will, as channel scanning is being done under
RTNL lock and link change notifications also require that lock) it will
be to confuse userland.

> Also, while looking at this code, I spotted a bug in dev_watchdog():
> 				/*
> 				 * old device drivers set dev->trans_start
> 				 */
> 				trans_start = txq->trans_start ? : dev->trans_start;
> 
> i.e. it is trying to figure out whether to read trans_start from txq
> or dev. In both cases, trans_start is updated based on the value of
> jiffies, which will occasionally be 0 (as it wraps around). Therefore
> this line of code will occasionally make the wrong decision.

No, I don't think so.

If only dev->trans_start is being updated then the watchdog reads that.
If both txq->trans_start and dev->trans_start are being updated then it
doesn't matter much which the watchdog reads.
If only txq->trans_start is being updated then dev->trans_start is
always set to 0, so when txq->trans_start is 0 the watchdog still gets
0.

Ben.

-- 
Ben Hutchings, Senior Software Engineer, Solarflare
Not speaking for my employer; that's the marketing department's job.
They asked us to note that Solarflare product names are trademarked.

Re: Frequent spurious tx_timeouts for libertas

[Ben Hutchings]

On Sun, 2011-05-01 at 22:21 +0100, Daniel Drake wrote:
[...]
> Sometimes the TX queue is stopped and started from other places (e.g.
> while scanning for networks, which NetworkManager triggers every
> couple of minutes)
> 
> Thus the TX queue is stopped and started very often.
> 
> The libertas tx_timeout handler is being called quite a lot, and quite
> soon after boot we get this in the kernel logs (the first time it
> happens):
> 
> [   97.050101] ------------[ cut here ]------------
> [   97.054866] WARNING: at net/sched/sch_generic.c:258 dev_watchdog+0x102/0x17c
> [   97.062277] Hardware name: XO
> [   97.065335] NETDEV WATCHDOG: eth0 (libertas_sdio): transmit queue 0 timed out
> <snip large trace>
> 
> This message seems bogus - all the recent transmissions happened correctly.
> 
> What is this watchdog trying to detect exactly? Using what criteria?

I'll repeat my answer from the last time this was asked on netdev:

The watchdog fires when the software queue has been stopped *and* the
link has been reported as up for over dev->watchdog_timeo ticks.

The software queue should be stopped iff the hardware queue is full or
nearly full.  If the software queue remains stopped and the link is
still reported up, then one of these things is happening:

1. The link went down but the driver didn't notice
2. TX completions are not being indicated or handled correctly
3. The hardware TX path has locked up
4. The link is stalled by excessive pause frames or collisions
5. Timeout is too low and/or low watermark is too high
(there may be other explanations)

I think the watchdog is primarily meant to deal with case 3, though all
of cases 1-3 may be worked around by resetting the hardware.

And now, for the specific case of libertas:

It appears that libertas reports carrier off (link down) while scanning,
so that should mean the watchdog does not fire.  However:

1. The watchdog will only check the current link state, which might be
up again when it runs.
2. The watchdog assumes that TX queues only fill up in response to
packets sent by the TX scheduler.

[...]
> Is libertas doing something wrong, or is this a bug/oddity in the network layer?

Since the TX scheduler doesn't know about the extra packets you are
injecting to do channel scanning, I think you need to call
txq_trans_update() when you do that.  And I don't think it's a good idea
to call netif_carrier_off() there at all.  If it has any effect at all
(which I don't think it will, as channel scanning is being done under
RTNL lock and link change notifications also require that lock) it will
be to confuse userland.

> Also, while looking at this code, I spotted a bug in dev_watchdog():
> 				/*
> 				 * old device drivers set dev->trans_start
> 				 */
> 				trans_start = txq->trans_start ? : dev->trans_start;
> 
> i.e. it is trying to figure out whether to read trans_start from txq
> or dev. In both cases, trans_start is updated based on the value of
> jiffies, which will occasionally be 0 (as it wraps around). Therefore
> this line of code will occasionally make the wrong decision.

No, I don't think so.

If only dev->trans_start is being updated then the watchdog reads that.
If both txq->trans_start and dev->trans_start are being updated then it
doesn't matter much which the watchdog reads.
If only txq->trans_start is being updated then dev->trans_start is
always set to 0, so when txq->trans_start is 0 the watchdog still gets
0.

Ben.

-- 
Ben Hutchings, Senior Software Engineer, Solarflare
Not speaking for my employer; that's the marketing department's job.
They asked us to note that Solarflare product names are trademarked.

--
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: Frequent spurious tx_timeouts for libertas

[Daniel Drake]

On 2 May 2011 03:24, Ben Hutchings <bhutchings@solarflare.com> wrote:
>> Also, while looking at this code, I spotted a bug in dev_watchdog():
>>                               /*
>>                                * old device drivers set dev->trans_start
>>                                */
>>                               trans_start = txq->trans_start ? : dev->trans_start;
>>
>> i.e. it is trying to figure out whether to read trans_start from txq
>> or dev. In both cases, trans_start is updated based on the value of
>> jiffies, which will occasionally be 0 (as it wraps around). Therefore
>> this line of code will occasionally make the wrong decision.
>
> No, I don't think so.
>
> If only dev->trans_start is being updated then the watchdog reads that.
> If both txq->trans_start and dev->trans_start are being updated then it
> doesn't matter much which the watchdog reads.
> If only txq->trans_start is being updated then dev->trans_start is
> always set to 0, so when txq->trans_start is 0 the watchdog still gets
> 0.

dev->trans_start is unconditionally initialized by dev_activate() in
sch_generic.c:

	if (need_watchdog) {
		dev->trans_start = jiffies;
		dev_watchdog_up(dev);
	}

so it is (usually) not 0.

Thanks for your input on the tx timeout issue, now that I understand
it better I think the right plan of action is to remove it from
libertas entirely, I'll CC you on the patch.

Daniel

Re: Frequent spurious tx_timeouts for libertas

[Daniel Drake]

On 2 May 2011 03:24, Ben Hutchings <bhutchings-s/n/eUQHGBpZroRs9YW3xA@public.gmane.org> wrote:
>> Also, while looking at this code, I spotted a bug in dev_watchdog():
>>                               /*
>>                                * old device drivers set dev->trans_start
>>                                */
>>                               trans_start = txq->trans_start ? : dev->trans_start;
>>
>> i.e. it is trying to figure out whether to read trans_start from txq
>> or dev. In both cases, trans_start is updated based on the value of
>> jiffies, which will occasionally be 0 (as it wraps around). Therefore
>> this line of code will occasionally make the wrong decision.
>
> No, I don't think so.
>
> If only dev->trans_start is being updated then the watchdog reads that.
> If both txq->trans_start and dev->trans_start are being updated then it
> doesn't matter much which the watchdog reads.
> If only txq->trans_start is being updated then dev->trans_start is
> always set to 0, so when txq->trans_start is 0 the watchdog still gets
> 0.

dev->trans_start is unconditionally initialized by dev_activate() in
sch_generic.c:

	if (need_watchdog) {
		dev->trans_start = jiffies;
		dev_watchdog_up(dev);
	}

so it is (usually) not 0.

Thanks for your input on the tx timeout issue, now that I understand
it better I think the right plan of action is to remove it from
libertas entirely, I'll CC you on the patch.

Daniel
--
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: Frequent spurious tx_timeouts for libertas

[Daniel Drake]

On 2 May 2011 20:59, Daniel Drake <dsd@laptop.org> wrote:
> dev->trans_start is unconditionally initialized by dev_activate() in
> sch_generic.c:

Also, many drivers (including libertas) set it in their tx_timeout handlers:
   dev->trans_start = jiffies; /* prevent tx timeout */
I don't understand why (the TX timeout has already occurred, it can't
be prevented at that stage).

Daniel

Re: Frequent spurious tx_timeouts for libertas

[Daniel Drake]

On 2 May 2011 20:59, Daniel Drake <dsd-2X9k7bc8m7Mdnm+yROfE0A@public.gmane.org> wrote:
> dev->trans_start is unconditionally initialized by dev_activate() in
> sch_generic.c:

Also, many drivers (including libertas) set it in their tx_timeout handlers:
   dev->trans_start = jiffies; /* prevent tx timeout */
I don't understand why (the TX timeout has already occurred, it can't
be prevented at that stage).

Daniel
--
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: Frequent spurious tx_timeouts for libertas

[Ben Hutchings]

On Mon, 2011-05-02 at 20:59 +0100, Daniel Drake wrote:
> On 2 May 2011 03:24, Ben Hutchings <bhutchings@solarflare.com> wrote:
> >> Also, while looking at this code, I spotted a bug in dev_watchdog():
> >>                               /*
> >>                                * old device drivers set dev->trans_start
> >>                                */
> >>                               trans_start = txq->trans_start ? : dev->trans_start;
> >>
> >> i.e. it is trying to figure out whether to read trans_start from txq
> >> or dev. In both cases, trans_start is updated based on the value of
> >> jiffies, which will occasionally be 0 (as it wraps around). Therefore
> >> this line of code will occasionally make the wrong decision.
> >
> > No, I don't think so.
> >
> > If only dev->trans_start is being updated then the watchdog reads that.
> > If both txq->trans_start and dev->trans_start are being updated then it
> > doesn't matter much which the watchdog reads.
> > If only txq->trans_start is being updated then dev->trans_start is
> > always set to 0, so when txq->trans_start is 0 the watchdog still gets
> > 0.
> 
> dev->trans_start is unconditionally initialized by dev_activate() in
> sch_generic.c:
> 
> 	if (need_watchdog) {
> 		dev->trans_start = jiffies;
> 		dev_watchdog_up(dev);
> 	}
> 
> so it is (usually) not 0.
[...]

You're right.  Seems like we have an incomplete compatibility hack that
can hurt drivers that are doing the right thing.

For those few single-queue drivers that need to update the transmit
time, perhaps we could add a dev_trans_update() as a wrapper for
txq_trans_update().  Then delete net_device::trans_start and change
dev_trans_start() to avoid using it.

Ben.

-- 
Ben Hutchings, Senior Software Engineer, Solarflare
Not speaking for my employer; that's the marketing department's job.
They asked us to note that Solarflare product names are trademarked.

Re: Frequent spurious tx_timeouts for libertas

[Ben Hutchings]

On Mon, 2011-05-02 at 20:59 +0100, Daniel Drake wrote:
> On 2 May 2011 03:24, Ben Hutchings <bhutchings-s/n/eUQHGBpZroRs9YW3xA@public.gmane.org> wrote:
> >> Also, while looking at this code, I spotted a bug in dev_watchdog():
> >>                               /*
> >>                                * old device drivers set dev->trans_start
> >>                                */
> >>                               trans_start = txq->trans_start ? : dev->trans_start;
> >>
> >> i.e. it is trying to figure out whether to read trans_start from txq
> >> or dev. In both cases, trans_start is updated based on the value of
> >> jiffies, which will occasionally be 0 (as it wraps around). Therefore
> >> this line of code will occasionally make the wrong decision.
> >
> > No, I don't think so.
> >
> > If only dev->trans_start is being updated then the watchdog reads that.
> > If both txq->trans_start and dev->trans_start are being updated then it
> > doesn't matter much which the watchdog reads.
> > If only txq->trans_start is being updated then dev->trans_start is
> > always set to 0, so when txq->trans_start is 0 the watchdog still gets
> > 0.
> 
> dev->trans_start is unconditionally initialized by dev_activate() in
> sch_generic.c:
> 
> 	if (need_watchdog) {
> 		dev->trans_start = jiffies;
> 		dev_watchdog_up(dev);
> 	}
> 
> so it is (usually) not 0.
[...]

You're right.  Seems like we have an incomplete compatibility hack that
can hurt drivers that are doing the right thing.

For those few single-queue drivers that need to update the transmit
time, perhaps we could add a dev_trans_update() as a wrapper for
txq_trans_update().  Then delete net_device::trans_start and change
dev_trans_start() to avoid using it.

Ben.

-- 
Ben Hutchings, Senior Software Engineer, Solarflare
Not speaking for my employer; that's the marketing department's job.
They asked us to note that Solarflare product names are trademarked.

--
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: Frequent spurious tx_timeouts for libertas

[Ben Hutchings]

On Mon, 2011-05-02 at 03:24 +0100, Ben Hutchings wrote:
[...]
> And now, for the specific case of libertas:
> 
> It appears that libertas reports carrier off (link down) while scanning,
> so that should mean the watchdog does not fire.  However:
> 
> 1. The watchdog will only check the current link state, which might be
> up again when it runs.
[...]

However, netif_carrier_on() will reset the watchdog timer, so the link
really does have to be reported up continuously for 5 seconds before the
watchdog will fire.

There is a small race condition though...

void netif_carrier_on(struct net_device *dev)
{
	if (test_and_clear_bit(__LINK_STATE_NOCARRIER, &dev->state)) {
/*
 * If the device is running and the link has been down for exactly
 * dev->watchdog_timeo ticks, the watchdog can fire now.
 */
		if (dev->reg_state == NETREG_UNINITIALIZED)
			return;
		linkwatch_fire_event(dev);
		if (netif_running(dev))
/*
 * The watchdog timer is reset here:
 */
			__netdev_watchdog_up(dev);
	}
}

However, given the timing of channel scanning that you described, I
don't think this would explain the watchdog firing for libertas.

Ben.

-- 
Ben Hutchings, Senior Software Engineer, Solarflare
Not speaking for my employer; that's the marketing department's job.
They asked us to note that Solarflare product names are trademarked.

Re: Frequent spurious tx_timeouts for libertas

[Ben Hutchings]

On Mon, 2011-05-02 at 03:24 +0100, Ben Hutchings wrote:
[...]
> And now, for the specific case of libertas:
> 
> It appears that libertas reports carrier off (link down) while scanning,
> so that should mean the watchdog does not fire.  However:
> 
> 1. The watchdog will only check the current link state, which might be
> up again when it runs.
[...]

However, netif_carrier_on() will reset the watchdog timer, so the link
really does have to be reported up continuously for 5 seconds before the
watchdog will fire.

There is a small race condition though...

void netif_carrier_on(struct net_device *dev)
{
	if (test_and_clear_bit(__LINK_STATE_NOCARRIER, &dev->state)) {
/*
 * If the device is running and the link has been down for exactly
 * dev->watchdog_timeo ticks, the watchdog can fire now.
 */
		if (dev->reg_state == NETREG_UNINITIALIZED)
			return;
		linkwatch_fire_event(dev);
		if (netif_running(dev))
/*
 * The watchdog timer is reset here:
 */
			__netdev_watchdog_up(dev);
	}
}

However, given the timing of channel scanning that you described, I
don't think this would explain the watchdog firing for libertas.

Ben.

-- 
Ben Hutchings, Senior Software Engineer, Solarflare
Not speaking for my employer; that's the marketing department's job.
They asked us to note that Solarflare product names are trademarked.

--
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: Frequent spurious tx_timeouts for libertas

[David Miller]

From: Ben Hutchings <bhutchings@solarflare.com>
Date: Mon, 02 May 2011 21:47:39 +0100

> On Mon, 2011-05-02 at 20:59 +0100, Daniel Drake wrote:
>> On 2 May 2011 03:24, Ben Hutchings <bhutchings@solarflare.com> wrote:
>> >> Also, while looking at this code, I spotted a bug in dev_watchdog():
>> >>                               /*
>> >>                                * old device drivers set dev->trans_start
>> >>                                */
>> >>                               trans_start = txq->trans_start ? : dev->trans_start;
>> >>
>> >> i.e. it is trying to figure out whether to read trans_start from txq
>> >> or dev. In both cases, trans_start is updated based on the value of
>> >> jiffies, which will occasionally be 0 (as it wraps around). Therefore
>> >> this line of code will occasionally make the wrong decision.
>> >
>> > No, I don't think so.
>> >
>> > If only dev->trans_start is being updated then the watchdog reads that.
>> > If both txq->trans_start and dev->trans_start are being updated then it
>> > doesn't matter much which the watchdog reads.
>> > If only txq->trans_start is being updated then dev->trans_start is
>> > always set to 0, so when txq->trans_start is 0 the watchdog still gets
>> > 0.
>> 
>> dev->trans_start is unconditionally initialized by dev_activate() in
>> sch_generic.c:
>> 
>> 	if (need_watchdog) {
>> 		dev->trans_start = jiffies;
>> 		dev_watchdog_up(dev);
>> 	}
>> 
>> so it is (usually) not 0.
> [...]
> 
> You're right.  Seems like we have an incomplete compatibility hack that
> can hurt drivers that are doing the right thing.
> 
> For those few single-queue drivers that need to update the transmit
> time, perhaps we could add a dev_trans_update() as a wrapper for
> txq_trans_update().  Then delete net_device::trans_start and change
> dev_trans_start() to avoid using it.

Even though this unconditional assignment exists, it should not cause
problems.

First, in dev_watchdog(), any non-zero txq->trans_start will be preferred
over dev->trans_start.

Second, in dev_trans_start(), netdev->trans_start is used as a baseline,
and any more recent stamp in txq->trans_start will be preferred.

In fact, this makes the assignment of netdev->trans_start to zero in
transition_one_qdisc() look erroneous.