[rt2x00-users] rt2x00usb_watchdog_tx_status: Warning - TX queue 0 status timed out

[Helmut Schaa]

Hi,

Am Dienstag 30 November 2010 schrieb Johannes Stezenbach:
> On Tue, Nov 30, 2010 at 10:31:21PM +0100, Helmut Schaa wrote:
> > Am Dienstag 30 November 2010 schrieb Johannes Stezenbach:
> > > 
> > > I meant to decrease it to a few milliseconds -- the time it usually
> > > takes to send a frame.  If the hardware/firmware works like it looks
> > > (complete the URB now, but send the packet later)
> > 
> > Yes, that is how it works on PCI as well but we've got an interrupt there
> > when the frame is really sent out. USB is lacking such a functionality.
> > 
> > > then it's not a
> > > "timeout", it is "wait until frame is sent and then read TX_STA_FIFO".
> > 
> > Why not try again to read TX_STA_FIFO again when the watchdog triggers?
> 
> That's what happens already, the full message is:
> 
> phy0 -> rt2x00usb_watchdog_tx_status: Warning - TX queue 2 status timed out, invoke forced tx handler

Ah, ok, thanks for clarification and sorry for the noise.

> > > However, I don't know if it is time critical to call ieee80211_tx_status()
> > > ASAP, maybe there is no downside to wait 1 second?
> > 
> > I'm not sure about all the timeouts but for example injected EAPOL frames
> > (from hostapd) require a tx status before hostapd times out but I guess the
> > timeout in hostapd for that should be > 1 second. Not sure though.
> > 
> > Other then that and a few other cases the tx status is only used by the 
> > rate control algorithm and to send frames to monitor mode interfaces.
> > 
> > > "Watchdog" and "warning" sound like this is an unexpected event
> > > or a malfunction, but if this is a normal event then the
> > > message can be removed,  Agreed?
> > > 
> > > BTW, I was using channel 1 and there are maybe half a dozen APs
> > > in neighbouring office rooms on that channel, so maybe the packet
> > > was delayed because the channel was busy.
> > 
> > I doubt that. I don't think a frame should be delayed for such a long time
> > and even if the channel is busy. In that case the frame should get reported
> > as failed within time, no?
> 
> I didn't mean to say the frame was delayed for one second, but it was
> delayed longer than it takes for the tx_done workqueue handler to read
> the TX_STA_FIFO.  In the log from my first mail you can see two
> packets where TX_STA_FIFO entry was there in time so rt2800_txdone()
> could pick it up, but for the third frame TX_STA_FIFO entry was not there.
> The time between rt2x00usb_kick_tx_entry() and rt2800_txdone() was ~11ms.

Ok, understood, I haven't read the code actually ;)

However, the ~11ms are system dependent, so the behavior might be quite
different on slow vs. fast systems.

> Then, half a second later the watchdog thread ran and completed the
> rt2800_txdone().  If there had been more TX activity the rt2x00usb_interrupt_txdone()
> for the next packet would have triggered the completeion, too.
> (The watchdog runs asynchronous, once per second and calls a timeout for
> every packet more then 100ms in the queue.)
> 
> Besides that the warning annoys me, what I'm seeing is that
> wpa_supplicant on the client sometimes needs more than one attempt
> to associate. 

Thats's bad. Did you compare the airtraffic with the hostapd logs to see if
all association requests, EAPOL frames etc. make it through?

> And I notice that DHCP also takes a long time to
> complete.  I'm not sure if this is caused by this issue, though.

Same here, you could compare the airtaffic (captured with a seperate wifi card)
with a tcpdump on your AP mode (wlanX) interface.

Helmut