transmit timed out when downloading files
Dongas
dongas86 at gmail.com
Wed Jun 17 11:05:21 EDT 2009
2009/6/16 Dongas <dongas86 at gmail.com>:
> Dear ALL,
>
> I'm facing a urgent issue that 'transmit timed out' issue frequently
> happened when i downloaded files with WiFi function.
> The WiFi modules i used is based on Marvell 8686 chipset and the
> dirver is libertas in kernel 2.6.25.
>
> The error message is as follows:
> (I also tried downloading other files, but with the same issue)
> # wget http://172.31.42.217/move.rar &
> # Connecting to 172.31.42.217 (172.31.42.217:80)
> move.rar 14% |**** | 21061k
> 00:16:07 ETA[ 270.720049] NETDEV WATCHDOG: eth0: transmit timed out
> [ 270.725166] libertas: tx watch dog timeout
> move.rar 14% |**** | 21061k -
> stalled -[ 275.720063] libertas: Command 1f timed out
> [ 275.724291] libertas: requeueing command 1f due to timeout (#1)
> move.rar 14% |**** | 21061k -
> stalled -[ 280.720062] NETDEV WATCHDOG: eth0: transmit timed out
> [ 280.725176] libertas: tx watch dog timeout
> move.rar 14% |**** | 21061k -
> stalled -[ 285.720062] libertas: Command 1f timed out
> [ 285.724284] libertas: requeueing command 1f due to timeout (#2)
> move.rar 14% |**** | 21061k -
> stalled -[ 290.720049] NETDEV WATCHDOG: eth0: transmit timed out
> [ 290.725162] libertas: tx watch dog timeout
> move.rar 14% |**** | 21061k -
> stalled -[ 295.720063] libertas: Command 1f timed out
> [ 295.724288] libertas: requeueing command 1f due to timeout (#3)
> …………
> Then the downloading process stuck at here.
>
> With the libertas debug info is fully enabled, the message is as follows:
> -------------------------------------------------------------------------------------------------------------------------------------------
> ……
> [ 1172.260000] libertas enter (INT): lbs_hard_start_xmit():69
> [ 1172.260000] libertas TX Data: 00 1d 09 01 18 75 00 1a 6b a0 c7 58
> 08 00 45 00
> [ 1172.270000] libertas TX Data: 00 34 a2 2f 40 00 40 06 ea a2 ac 1f
> 2a da ac 1f
> [ 1172.280000] libertas TX Data: 2a d9 e1 68 00 50 43 df 34 c7 58 9e
> ca 00 80 10
> [ 1172.290000] libertas TX Data: 68 ae 43 8d 00 00 01 01 08 0a 00 01
> 53 3c 00 1a
> [ 1172.290000] libertas TX Data: 4c 3a
> [ 1172.300000] libertas txpd: 48 0e 06 c5 a8 c6 03 c0 00 06 d7 c3 00 00 00 00
> [ 1172.300000] libertas txpd: 00 00 06 c5 00 06 d7 c3
> [ 1172.310000] libertas Tx Data: 00 1d 09 01 18 75 00 1a 6b a0 c7 58
> 08 00 45 00
> [ 1172.320000] libertas Tx Data: 00 34 a2 2f 40 00 40 06 ea a2 ac 1f
> 2a da ac 1f
> [ 1172.320000] libertas Tx Data: 2a d9 e1 68 00 50 43 df 34 c7 58 9e
> ca 00 80 10
> [ 1172.330000] libertas Tx Data: 68 ae 43 8d 00 00 01 01 08 0a 00 01
> 53 3c 00 1a
> [ 1172.340000] libertas Tx Data: 4c 3a
> [ 1172.340000] libertas tx (INT): lbs_hard_start_xmit lined up packet
> [ 1172.350000] libertas leave (INT): lbs_hard_start_xmit():169, ret 0
>
> [ 1172.360000] libertas enter: if_sdio_host_to_card_worker():361
> [ 1172.360000] libertas thread: main-thread 111: intcounter=0
> currenttxskb=00000000 dnld_sent=1
> [ 1172.370000] libertas thread: main-thread sleeping... Conn=0 IntC=0
> PS_mode=0 PS_State=0
>
> 10M.mp3 24% |******* | 2510k -
> stalled -[ 1178.000000] NETDEV WATCHDOG: eth0: transmit timed out
> [ 1178.000000] libertas enter (INT): lbs_tx_timeout():472
> [ 1178.010000] libertas: tx watch dog timeout
> [ 1178.010000] libertas enter (INT): lbs_host_to_card_done():500
> [ 1178.020000] libertas leave (INT): lbs_host_to_card_done():511
> [ 1178.020000] libertas enter (INT): lbs_prepare_and_send_command():1318
> [ 1178.030000] libertas enter (INT): lbs_get_cmd_ctrl_node():1679
> [ 1178.030000] libertas leave (INT): lbs_get_cmd_ctrl_node():1697
> [ 1178.040000] libertas enter (INT): lbs_set_cmd_ctrl_node():1720
> [ 1178.050000] libertas leave (INT): lbs_set_cmd_ctrl_node():1728
> [ 1178.050000] libertas host (INT): PREP_CMD: command 0x001f
> [ 1178.060000] libertas enter (INT): lbs_cmd_802_11_rssi():830
> [ 1178.060000] libertas leave (INT): lbs_cmd_802_11_rssi():843
> [ 1178.070000] libertas enter (INT): lbs_queue_cmd():1093
> [ 1178.070000] libertas host (INT): QUEUE_CMD: inserted command 0x001f
> into cmdpendingq
> [ 1178.080000] libertas leave (INT): lbs_queue_cmd():1128
> [ 1178.090000] libertas leave (INT): lbs_prepare_and_send_command():1577, ret 0
> [ 1178.090000] libertas leave (INT): lbs_tx_timeout():493
> [ 1178.100000] libertas thread: main-thread 222 (waking up):
> intcounter=0 currenttxskb=00000000 dnld_sent=0
> [ 1178.110000] libertas thread: main-thread 333: intcounter=0
> currenttxskb=00000000 dnld_sent=0
> [ 1178.120000] libertas thread: main-thread 444: intcounter=0
> currenttxskb=00000000 dnld_sent=0
> [ 1178.130000] libertas enter: lbs_execute_next_command():1749
> [ 1178.130000] libertas host: EXEC_NEXT_CMD: OK to send command 0x001f
> in psstate 0
> [ 1178.140000] libertas host: EXEC_NEXT_CMD: sending command 0x001f
> [ 1178.140000] libertas enter: lbs_submit_command():1141
> [ 1178.150000] libertas host: DNLD_CMD: command 0x001f, seq 21, size
> 16, jiffies 87815
> [ 1178.160000] libertas DNLD_CMD: 1f 00 10 00 15 00 00 00 08 00 00 00
> 00 00 00 00
> [ 1178.170000] libertas enter: if_sdio_host_to_card(type 1, bytes 16):726
> [ 1178.170000] libertas leave: if_sdio_host_to_card():796, ret 0
> [ 1178.180000] libertas cmd: DNLD_CMD: sent command 0x001f, jiffies 87818
> [ 1178.180000] libertas leave: lbs_submit_command():1176
> [ 1178.190000] libertas leave: lbs_execute_next_command():1884
> [ 1178.200000] libertas thread: main-thread 111: intcounter=0
> currenttxskb=00000000 dnld_sent=2
> [ 1178.200000] libertas thread: main-thread sleeping... Conn=0 IntC=0
> PS_mode=0 PS_State=0
> 10M.mp3 24% |******* | 2510k -
> stalled -[ 1183.180000] libertas enter (INT): command_timer_fn():971
> [ 1183.180000] libertas: Command 1f timed out
> [ 1183.180000] libertas leave (INT): command_timer_fn():985
> [ 1183.190000] libertas thread: main-thread 222 (waking up):
> intcounter=0 currenttxskb=00000000 dnld_sent=2
> [ 1183.200000] libertas thread: main-thread 333: intcounter=0
> currenttxskb=00000000 dnld_sent=2
> [ 1183.210000] libertas thread: main-thread 444: intcounter=0
> currenttxskb=00000000 dnld_sent=2
> [ 1183.210000] libertas: requeueing command 1f due to timeout (#1)
> [ 1183.220000] libertas thread: main-thread 111: intcounter=0
> currenttxskb=00000000 dnld_sent=2
> [ 1183.230000] libertas thread: main-thread sleeping... Conn=0 IntC=0
> PS_mode=0 PS_State=0
> 10M.mp3 24% |******* | 2510k -
> stalled -[ 1188.000000] NETDEV WATCHDOG: eth0: transmit timed out
> [ 1188.000000] libertas enter (INT): lbs_tx_timeout():472
> [ 1188.010000] libertas: tx watch dog timeout
> [ 1188.010000] libertas enter (INT): lbs_host_to_card_done():500
> [ 1188.020000] libertas leave (INT): lbs_host_to_card_done():511
> [ 1188.020000] libertas enter (INT): lbs_prepare_and_send_command():1318
> [ 1188.030000] libertas enter (INT): lbs_get_cmd_ctrl_node():1679
> [ 1188.030000] libertas leave (INT): lbs_get_cmd_ctrl_node():1697
> [ 1188.040000] libertas enter (INT): lbs_set_cmd_ctrl_node():1720
> [ 1188.050000] libertas leave (INT): lbs_set_cmd_ctrl_node():1728
> [ 1188.050000] libertas host (INT): PREP_CMD: command 0x001f
> [ 1188.060000] libertas enter (INT): lbs_cmd_802_11_rssi():830
> [ 1188.060000] libertas leave (INT): lbs_cmd_802_11_rssi():843
> [ 1188.070000] libertas enter (INT): lbs_queue_cmd():1093
> [ 1188.070000] libertas host (INT): QUEUE_CMD: inserted command 0x001f
> into cmdpendingq
> [ 1188.080000] libertas leave (INT): lbs_queue_cmd():1128
> [ 1188.090000] libertas leave (INT): lbs_prepare_and_send_command():1577, ret 0
> [ 1188.090000] libertas leave (INT): lbs_tx_timeout():493
> [ 1188.100000] libertas thread: main-thread 222 (waking up):
> intcounter=0 currenttxskb=00000000 dnld_sent=0
> [ 1188.110000] libertas thread: main-thread 333: intcounter=0
> currenttxskb=00000000 dnld_sent=0
> [ 1188.120000] libertas thread: main-thread 444: intcounter=0
> currenttxskb=00000000 dnld_sent=0
> [ 1188.130000] libertas enter: lbs_execute_next_command():1749
> [ 1188.130000] libertas host: EXEC_NEXT_CMD: OK to send command 0x001f
> in psstate 0
> [ 1188.140000] libertas host: EXEC_NEXT_CMD: sending command 0x001f
> [ 1188.140000] libertas enter: lbs_submit_command():1141
> [ 1188.150000] libertas host: DNLD_CMD: command 0x001f, seq 21, size
> 16, jiffies 88815
> [ 1188.160000] libertas DNLD_CMD: 1f 00 10 00 15 00 00 00 08 00 00 00
> 00 00 00 00
> [ 1188.170000] libertas enter: if_sdio_host_to_card(type 1, bytes 16):726
> [ 1188.170000] libertas leave: if_sdio_host_to_card():796, ret 0
> [ 1188.180000] libertas cmd: DNLD_CMD: sent command 0x001f, jiffies 88818
> [ 1188.180000] libertas leave: lbs_submit_command():1176
> [ 1188.190000] libertas leave: lbs_execute_next_command():1884
> [ 1188.200000] libertas thread: main-thread 111: intcounter=0
> currenttxskb=00000000 dnld_sent=2
> [ 1188.200000] libertas thread: main-thread sleeping... Conn=0 IntC=0
> PS_mode=0 PS_State=0
> 10M.mp3 24% |******* | 2510k -
> stalled -[ 1193.180000] libertas enter (INT): command_timer_fn():971
> [ 1193.180000] libertas: Command 1f timed out
> [ 1193.180000] libertas leave (INT): command_timer_fn():985
> [ 1193.190000] libertas thread: main-thread 222 (waking up):
> intcounter=0 currenttxskb=00000000 dnld_sent=2
> [ 1193.200000] libertas thread: main-thread 333: intcounter=0
> currenttxskb=00000000 dnld_sent=2
> [ 1193.210000] libertas thread: main-thread 444: intcounter=0
> currenttxskb=00000000 dnld_sent=2
> [ 1193.210000] libertas: requeueing command 1f due to timeout (#2)
> [ 1193.220000] libertas thread: main-thread 111: intcounter=0
> currenttxskb=00000000 dnld_sent=2
> [ 1193.230000] libertas thread: main-thread sleeping... Conn=0 IntC=0
> PS_mode=0 PS_State=0
> 10M.mp3 24% |******* | 2510k -
> stalled -[ 1198.000000] NETDEV WATCHDOG: eth0: transmit timed out
> ………………
> ------------------------------------------------------------------------------------------------------
>
> It would be highly appreciated if someone can provide any hints to fix
> the issue.
>
I know the 'transmission timeout' coud be considered as a normal
phenomenon for network driver caused by its nature.
Each driver should be capable of handling this issue properly to
complete the transmission .
However the issue i encountered is that once the transmit timeout
happened, the libertas driver never has the opportunity to resume the
transfer, alway timeout.
I'm not very familiar with Libertas driver, maybe someone of you can
provide some hints for me to debug this issue quickly since the tight
time i have.
After digging in the code , i found when the transmit timeout
happened, the libertas will try to send a CMD_802_11_RSSI command to
help resume the transfer.
But from the log above, during the invoking of if_sdio_host_to_card
function, when the "packet_worker" is waken for the next real data
transfer, the if_sdio_host_to_card_worker function should be excuted
soon.
But in my error log, this function was never excuted once the timeout
issue happened.
There's must be something wrong.
I'm not sure if this has something to do with my "trasnmit timeout"
issue, but up to this point , i only found it.
I will continue to investigate this issue.
I hope someone can give me some hints which would be high appreciated.
Thanks
Best Regards
Dongas
More information about the libertas-dev
mailing list