ath0: device timeout

Mon May 1 15:46:56 UTC 2006

>The only significant difference in ath between stable and current is 
>that the task q thread runs at PI_NET on current and whatever 
>priority kthread_create assigns on stable.  However I don't believe 
>this is relevant.  A watchdog timeout means a tx request was pending 
>for 5 seconds w/o the hardware delivering a tx interrupt.  In my 
>experience this occurs only when the tx descriptor is setup wrong 
>and causes the tx dma h/w to wedge.  So when this happens what 
>people need to provide is a dump of the tx descriptors and 
>associated tx buffer state (athdebug reset will do that).

OK, I did this, and here is is the log (from /var/log/messages) of 
the output, for three successive "ath0: device timeout errors":

May  1 08:29:02 ns kernel: ath0: device timeout
May  1 08:29:02 ns kernel: ath_draintxq: beacon queue 0xe000440
May  1 08:29:02 ns kernel: ath_tx_stopdma: tx queue [0] 0, link 0
May  1 08:29:02 ns kernel: ath_tx_stopdma: tx queue [1] 0xf5cf600, 
link 0xcd5ca600
May  1 08:29:02 ns kernel: ath_tx_stopdma: tx queue [2] 0, link 0
May  1 08:29:02 ns kernel: ath_tx_stopdma: tx queue [3] 0, link 0
May  1 08:29:02 ns kernel: ath_tx_stopdma: tx queue [8] 0xf5c6b40, 
link 0xcd5c5740
May  1 08:29:02 ns kernel: Q1[  0] (DS.V:0xcd5ca600 DS.P:0xf5cf600) 
L:00000000 D:0f7d00c4 F:043 *
May  1 08:29:02 ns kernel: 01260040 0100003c 00010000 0000001b 
20250001 0102c44d
May  1 08:29:02 ns kernel: Q8[  0] (DS.V:0xcd5c1b40 DS.P:0xf5c6b40) 
L:0f5c8ee0 D:03d699c4 F:043
May  1 08:29:02 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:29:02 ns kernel: Q8[  1] (DS.V:0xcd5c3ee0 DS.P:0xf5c8ee0) 
L:0f5cd800 D:0031b0c4 F:043
May  1 08:29:02 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:29:02 ns kernel: Q8[  2] (DS.V:0xcd5c8800 DS.P:0xf5cd800) 
L:0f5d0aa0 D:0f71bbc4 F:043
May  1 08:29:02 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:29:02 ns kernel: Q8[  3] (DS.V:0xcd5cbaa0 DS.P:0xf5d0aa0) 
L:0f5cccc0 D:087b59c4 F:0413
May  1 08:29:02 ns kernel: 21260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:29:02 ns kernel: Q8[  4] (DS.V:0xcd5c7cc0 DS.P:0xf5cccc0) 
L:0f5cab00 D:074f41c4 F:043
May  1 08:29:02 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:29:02 ns kernel: Q8[  5] (DS.V:0xcd5c5b00 DS.P:0xf5cab00) 
L:0f5cc180 D:0f7cedc4 F:043
May  1 08:29:02 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:29:02 ns kernel: Q8[  6] (DS.V:0xcd5c7180 DS.P:0xf5cc180) 
L:0f5cb280 D:0f7a39c4 F:043
May  1 08:29:02 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:29:02 ns kernel: Q8[  7] (DS.V:0xcd5c6280 DS.P:0xf5cb280) 
L:0f5ca1a0 D:0d03c4c4 F:043
May  1 08:29:02 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:29:02 ns kernel: Q8[  8] (DS.V:0xcd5c51a0 DS.P:0xf5ca1a0) 
L:0f5d17c0 D:0e00fec4 F:0413
May  1 08:29:02 ns kernel: 21260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:29:02 ns kernel: Q8[  9] (DS.V:0xcd5cc7c0 DS.P:0xf5d17c0) 
L:0f5cf420 D:0f7d02c4 F:043
May  1 08:29:02 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:29:02 ns kernel: Q8[ 10] (DS.V:0xcd5ca420 DS.P:0xf5cf420) 
L:0f5d15e0 D:0d6577c4 F:043
May  1 08:29:02 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:29:02 ns kernel: Q8[ 11] (DS.V:0xcd5cc5e0 DS.P:0xf5d15e0) 
L:0f5ca380 D:0f5fe7c4 F:043
May  1 08:29:02 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:29:02 ns kernel: Q8[ 12] (DS.V:0xcd5c5380 DS.P:0xf5ca380) 
L:0f5ca740 D:0bb86ec4 F:043
May  1 08:29:02 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:29:02 ns kernel: Q8[ 13] (DS.V:0xcd5c5740 DS.P:0xf5ca740) 
L:00000000 D:08eb2ec4 F:0413
May  1 08:29:02 ns kernel: 21260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:29:02 ns kernel: ath_stoprecv: rx queue 0xa6c2360, link 0xc268e330

May  1 08:30:42 ns kernel: ath0: device timeout
May  1 08:30:42 ns kernel: ath_draintxq: beacon queue 0xe000440
May  1 08:30:42 ns kernel: ath_tx_stopdma: tx queue [0] 0, link 0
May  1 08:30:42 ns kernel: ath_tx_stopdma: tx queue [1] 0xf5c6f00, 
link 0xcd5c1f00
May  1 08:30:42 ns kernel: ath_tx_stopdma: tx queue [2] 0, link 0
May  1 08:30:42 ns kernel: ath_tx_stopdma: tx queue [3] 0, link 0
May  1 08:30:42 ns kernel: ath_tx_stopdma: tx queue [8] 0xf5c7a40, 
link 0xcd5cc9a0
May  1 08:30:42 ns kernel: Q1[  0] (DS.V:0xcd5c1f00 DS.P:0xf5c6f00) 
L:00000000 D:0dc5d010 F:041 *
May  1 08:30:42 ns kernel: 4126004c 00008048 22240000 000dfbbc 
47920001 00038bc7
May  1 08:30:42 ns kernel: Q8[  0] (DS.V:0xcd5c2a40 DS.P:0xf5c7a40) 
L:0f5d19a0 D:04feadc4 F:043
May  1 08:30:42 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:30:42 ns kernel: Q8[  1] (DS.V:0xcd5cc9a0 DS.P:0xf5d19a0) 
L:00000000 D:0f7a39c4 F:043
May  1 08:30:42 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:30:42 ns kernel: ath_stoprecv: rx queue 0xa6c22a0, link 0xc268e270

May  1 08:35:16 ns kernel: ath0: device timeout
May  1 08:35:16 ns kernel: ath_draintxq: beacon queue 0xe000440
May  1 08:35:16 ns kernel: ath_tx_stopdma: tx queue [0] 0, link 0
May  1 08:35:16 ns kernel: ath_tx_stopdma: tx queue [1] 0xf5c7e00, 
link 0xcd5c2e00
May  1 08:35:16 ns kernel: ath_tx_stopdma: tx queue [2] 0, link 0
May  1 08:35:16 ns kernel: ath_tx_stopdma: tx queue [3] 0, link 0
May  1 08:35:16 ns kernel: ath_tx_stopdma: tx queue [8] 0xf5ccae0, 
link 0xcd5cbc80
May  1 08:35:16 ns kernel: Q1[  0] (DS.V:0xcd5c2e00 DS.P:0xf5c7e00) 
L:00000000 D:0131d010 F:041 *
May  1 08:35:16 ns kernel: 4126007c 00008078 22240000 000dfbbc 
e63b0001 0003629d
May  1 08:35:16 ns kernel: Q8[  0] (DS.V:0xcd5c7ae0 DS.P:0xf5ccae0) 
L:0f5c90c0 D:03d699c4 F:043
May  1 08:35:16 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:35:16 ns kernel: Q8[  1] (DS.V:0xcd5c40c0 DS.P:0xf5c90c0) 
L:0f5cd080 D:0f1a92c4 F:043
May  1 08:35:16 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:35:16 ns kernel: Q8[  2] (DS.V:0xcd5c8080 DS.P:0xf5cd080) 
L:0f5c9de0 D:087b59c4 F:0413
May  1 08:35:16 ns kernel: 21260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:35:16 ns kernel: Q8[  3] (DS.V:0xcd5c4de0 DS.P:0xf5c9de0) 
L:0f5d08c0 D:0bb86ec4 F:043
May  1 08:35:16 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:35:16 ns kernel: Q8[  4] (DS.V:0xcd5cb8c0 DS.P:0xf5d08c0) 
L:0f5ceca0 D:0f6023c4 F:043
May  1 08:35:16 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:35:16 ns kernel: Q8[  5] (DS.V:0xcd5c9ca0 DS.P:0xf5ceca0) 
L:0f5d0c80 D:0d657ac4 F:043
May  1 08:35:16 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:35:16 ns kernel: Q8[  6] (DS.V:0xcd5cbc80 DS.P:0xf5d0c80) 
L:00000000 D:04fea6c4 F:043
May  1 08:35:16 ns kernel: 01260040 0100003c 00010000 0000001b 
00000000 00000000
May  1 08:35:16 ns kernel: ath_stoprecv: rx queue 0xa6c21e0, link 0xc268e1b0

I hope this helps.  Also, FYI:
#athstats
685 watchdog timeouts
36711 tx management frames
3650 tx stopped 'cuz no xmit buffer
7752 tx failed 'cuz too many retries
103702 long on-chip tx retries
32468 tx frames with no ack marked
710058 tx frames with short preamble
2725 tx frames with an alternate rate
563305 rx failed 'cuz of bad CRC
2100254 rx failed 'cuz of PHY err
     2100158 CCK timing
     96 CCK restart
2286193 beacons transmitted
7808 periodic calibrations
234235 rate control checks
268 rate control raised xmit rate
401 rate control dropped xmit rate
rssi of last ack: 27
avg recv rssi: 27
22295 switched default/rx antenna
Antenna profile:
[1] tx   641639 rx  1535266
[2] tx   105961 rx      174

And:
#head -1 /etc/motd
FreeBSD 6.1-PRERELEASE (GENERIC) #0: Sun Apr  2 19:24:21 PDT 2006

         Ross.