Bug 499 - oscillating ping times
: oscillating ping times
Status: VERIFIED FIXED
: IPW2200
__UNSPECIFIED__
: 0.18
: All All
: P1 critical
Assigned To:
:
:
:
:
:
  Show dependency treegraph
 
Reported: 2004-12-14 22:14 by
Modified: 2005-10-05 13:33 (History)


Attachments
dmesg -c (15.36 KB, text/plain)
2004-12-14 22:26, Lars Heer
Details


Note

You need to log in before you can comment on or make changes to this bug.


Description From 2004-12-14 22:14:47
I've seen oscillating answering times while pinging a remotehost with
0.17 (still with 0.18).

knecht:/usr/src# ping fw
PING fw (10.2.2.200) 56(84) bytes of data.
64 bytes from fw (10.2.2.200): icmp_seq=1 ttl=64 time=5.87 ms
64 bytes from fw (10.2.2.200): icmp_seq=2 ttl=64 time=351 ms
64 bytes from fw (10.2.2.200): icmp_seq=3 ttl=64 time=15.3 ms
64 bytes from fw (10.2.2.200): icmp_seq=4 ttl=64 time=147 ms
64 bytes from fw (10.2.2.200): icmp_seq=5 ttl=64 time=6.41 ms
64 bytes from fw (10.2.2.200): icmp_seq=6 ttl=64 time=113 ms
64 bytes from fw (10.2.2.200): icmp_seq=7 ttl=64 time=17.5 ms
64 bytes from fw (10.2.2.200): icmp_seq=8 ttl=64 time=20.8 ms
64 bytes from fw (10.2.2.200): icmp_seq=9 ttl=64 time=80.5 ms
64 bytes from fw (10.2.2.200): icmp_seq=10 ttl=64 time=6.51 ms
64 bytes from fw (10.2.2.200): icmp_seq=11 ttl=64 time=5.62 ms
64 bytes from fw (10.2.2.200): icmp_seq=12 ttl=64 time=19.9 ms
64 bytes from fw (10.2.2.200): icmp_seq=13 ttl=64 time=3.29 ms
64 bytes from fw (10.2.2.200): icmp_seq=14 ttl=64 time=5.72 ms
64 bytes from fw (10.2.2.200): icmp_seq=15 ttl=64 time=39.3 ms
64 bytes from fw (10.2.2.200): icmp_seq=16 ttl=64 time=28.5 ms
64 bytes from fw (10.2.2.200): icmp_seq=17 ttl=64 time=5.85 ms
64 bytes from fw (10.2.2.200): icmp_seq=18 ttl=64 time=359 ms
64 bytes from fw (10.2.2.200): icmp_seq=19 ttl=64 time=5.90 ms
64 bytes from fw (10.2.2.200): icmp_seq=20 ttl=64 time=17.6 ms
64 bytes from fw (10.2.2.200): icmp_seq=21 ttl=64 time=136 ms
64 bytes from fw (10.2.2.200): icmp_seq=22 ttl=64 time=7.10 ms
64 bytes from fw (10.2.2.200): icmp_seq=23 ttl=64 time=6.04 ms
64 bytes from fw (10.2.2.200): icmp_seq=24 ttl=64 time=241 ms
64 bytes from fw (10.2.2.200): icmp_seq=25 ttl=64 time=29.1 ms
64 bytes from fw (10.2.2.200): icmp_seq=26 ttl=64 time=50.1 ms
64 bytes from fw (10.2.2.200): icmp_seq=27 ttl=64 time=9.96 ms
64 bytes from fw (10.2.2.200): icmp_seq=28 ttl=64 time=8.43 ms
64 bytes from fw (10.2.2.200): icmp_seq=29 ttl=64 time=24.6 ms
64 bytes from fw (10.2.2.200): icmp_seq=30 ttl=64 time=15.2 ms
64 bytes from fw (10.2.2.200): icmp_seq=31 ttl=64 time=6.22 ms
64 bytes from fw (10.2.2.200): icmp_seq=32 ttl=64 time=11.2 ms
64 bytes from fw (10.2.2.200): icmp_seq=33 ttl=64 time=6.28 ms
64 bytes from fw (10.2.2.200): icmp_seq=34 ttl=64 time=81.3 ms
64 bytes from fw (10.2.2.200): icmp_seq=35 ttl=64 time=6.35 ms
64 bytes from fw (10.2.2.200): icmp_seq=36 ttl=64 time=21.0 ms
64 bytes from fw (10.2.2.200): icmp_seq=37 ttl=64 time=6.38 ms
64 bytes from fw (10.2.2.200): icmp_seq=38 ttl=64 time=13.3 ms

--- fw ping statistics ---
38 packets transmitted, 38 received, 0% packet loss, time 37027ms
rtt min/avg/max/mdev = 3.291/50.973/359.285/87.049 ms
knecht:/usr/src# 


knecht:/usr/src# iwconfig eth1
eth1      IEEE 802.11g  ESSID:"default"  
          Mode:Managed  Frequency:2.437 GHz  Access Point:
00:0F:3D:9F:E0:AA   
          Bit Rate=54 Mb/s   Tx-Power=20 dBm   
          RTS thr:off   Fragment thr:off
          Encryption key:5555-5555-55   Security mode:open
          Power Management:off
          Link Quality=80/100  Signal level=-44 dBm  Noise level=-81 dBm
          Rx invalid nwid:0  Rx invalid crypt:0  Rx invalid frag:0
          Tx excessive retries:19  Invalid misc:0   Missed beacon:33

knecht:/usr/src# 

Several people even ipw2100 users have the same issue.
------- Comment #1 From 2004-12-14 22:26:26 -------
Created an attachment (id=175) [details]
dmesg -c

Hi,

Alejandro Bonilla told me to use iwevent to get further informations about
that.
I get no output on debian-testing with iwevent. Then he told to use
debug=0x1400 and get a dmesg -c output... which I attached to the bug-report.
------- Comment #2 From 2004-12-14 22:31:06 -------
As someone reported that this problem seems to be related to drivers after
0.16... I retested and can verify it:

knecht:/usr/src/ipw2200-0.16# ping fw
PING fw (10.2.2.200) 56(84) bytes of data.
64 bytes from fw (10.2.2.200): icmp_seq=2 ttl=64 time=7.61 ms
64 bytes from fw (10.2.2.200): icmp_seq=3 ttl=64 time=26.1 ms
64 bytes from fw (10.2.2.200): icmp_seq=4 ttl=64 time=6.68 ms
64 bytes from fw (10.2.2.200): icmp_seq=5 ttl=64 time=6.69 ms
64 bytes from fw (10.2.2.200): icmp_seq=6 ttl=64 time=6.79 ms
64 bytes from fw (10.2.2.200): icmp_seq=7 ttl=64 time=6.78 ms
64 bytes from fw (10.2.2.200): icmp_seq=8 ttl=64 time=6.80 ms
64 bytes from fw (10.2.2.200): icmp_seq=9 ttl=64 time=7.07 ms
64 bytes from fw (10.2.2.200): icmp_seq=10 ttl=64 time=6.42 ms
64 bytes from fw (10.2.2.200): icmp_seq=11 ttl=64 time=6.86 ms
64 bytes from fw (10.2.2.200): icmp_seq=12 ttl=64 time=5.88 ms
64 bytes from fw (10.2.2.200): icmp_seq=13 ttl=64 time=5.94 ms
64 bytes from fw (10.2.2.200): icmp_seq=14 ttl=64 time=5.95 ms
64 bytes from fw (10.2.2.200): icmp_seq=15 ttl=64 time=6.15 ms
64 bytes from fw (10.2.2.200): icmp_seq=16 ttl=64 time=6.01 ms

--- fw ping statistics ---
16 packets transmitted, 15 received, 6% packet loss, time 15010ms
rtt min/avg/max/mdev = 5.889/7.857/26.184/4.921 ms
knecht:/usr/src/ipw2200-0.16# 

Additionally there is no output with dmesg -c with this driver. So problem seems
to depend on driver or firmware coming with 0.17.

Lars
------- Comment #3 From 2004-12-14 23:21:55 -------
I am seeing the same phenomenon with ipw2100-1.0.2.
------- Comment #4 From 2004-12-15 00:02:19 -------
I checked the throughput-difference with that bug:

lars@knecht:~$ dd if=/dev/zero of=/tmp/testfile-1gb count=1000 bs=1M
1000+0 Datensätze ein
1000+0 Datensätze aus
1048576000 bytes transferred in 34,154225 seconds (30701209 bytes/sec)
lars@knecht:~$ 

With 0.16 using the above created file:
eth1      IEEE 802.11g  ESSID:"default"  
          Mode:Managed  Frequency:2.437 GHz  Access Point: 00:0F:3D:9F:E0:AA   
          Bit Rate=54 Mb/s   Tx-Power=20 dBm   
          RTS thr:off   Fragment thr:off
          Encryption key:5555-5555-55   Security mode:open
          Power Management:off
          Link Quality=100/100  Signal level=-51 dBm  
          Rx invalid nwid:0  Rx invalid crypt:0  Rx invalid frag:0
          Tx excessive retries:1  Invalid misc:0   Missed beacon:4

knecht:/usr/src/ipw2200-0.16# 
lars@knecht:~$ scp /tmp/testfile-1gb root@marge:/tmp
testfile-1gb                                                                   
                            100% 1000MB 742.0KB/s   23:00    
lars@knecht:~$ 

With 0.18 I reach nearly half the throughput:

eth1      IEEE 802.11g  ESSID:"default"  
          Mode:Managed  Frequency:2.437 GHz  Access Point: 00:0F:3D:9F:E0:AA   
          Bit Rate=54 Mb/s   Tx-Power=20 dBm   
          RTS thr:off   Fragment thr:off
          Encryption key:5555-5555-55   Security mode:open
          Power Management:off
          Link Quality=78/100  Signal level=-50 dBm  Noise level=-85 dBm
          Rx invalid nwid:0  Rx invalid crypt:0  Rx invalid frag:0
          Tx excessive retries:603  Invalid misc:0   Missed beacon:38

knecht:/usr/src/ipw2200-0.18# 
lars@knecht:~$ scp /tmp/testfile-1gb root@marge:/tmp
testfile-1gb                                                                   
                            100% 1000MB 423.3KB/s   40:19    
lars@knecht:~$ 
------- Comment #5 From 2004-12-15 08:09:59 -------
What are these Numbers between the lines? This looks like a C3?



ipw2200: I ipw_irq_tasklet Command completed.
ipw2200: U ipw_send_cmd Sending SCAN_REQUEST_EXT command (#26), 96 bytes
00000000 39 00 00 00 4A 01 02 03  04 05 07 08 09 0A 0B 00
9...J... ........
00000010 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000020 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000030 00 00 00 00 00 00 00 00  00 00 04 44 44 44 44
40   ........ ...DDDD@
00000040 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000050 00 00 00 00 00 00 00 00  78 00 00 00 14 00 14 00   ........
x.......
ipw2200: I ipw_irq_tasklet Command completed.
ipw2200: U ipw_send_cmd Sending SCAN_REQUEST_EXT command (#26), 96 bytes
00000000 3A 00 00 00 4A 01 02 03  04 05 07 08 09 0A 0B
00   :...J... ........
00000010 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000020 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000030 00 00 00 00 00 00 00 00  00 00 03 33 33 33 33
30   ........ ...33330
00000040 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000050 00 00 00 00 00 00 00 00  78 00 00 00 14 00 14 00   ........
x.......
ipw2200: I ipw_irq_tasklet Command completed.
ipw2200: U ipw_send_cmd Sending SSID command (#8), 7 bytes
00000000 64 65 66 61 75 6C 74
default          
ipw2200: I ipw_irq_tasklet Command completed.
ipw2200: U ipw_send_cmd Sending SCAN_REQUEST_EXT command (#26), 96 bytes
00000000 3B 00 00 00 4A 01 02 03  04 05 07 08 09 0A 0B
00   ;...J... ........
00000010 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000020 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000030 00 00 00 00 00 00 00 00  00 00 04 44 44 44 44
40   ........ ...DDDD@
00000040 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000050 00 00 00 00 00 00 00 00  78 00 00 00 14 00 14 00   ........
x.......
ipw2200: I ipw_irq_tasklet Command completed.
ipw2200: U ipw_send_cmd Sending SCAN_REQUEST_EXT command (#26), 96 bytes
00000000 3C 00 00 00 4A 01 02 03  04 05 07 08 09 0A 0B 00
<...J... ........
00000010 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000020 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000030 00 00 00 00 00 00 00 00  00 00 03 33 33 33 33
30   ........ ...33330
00000040 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000050 00 00 00 00 00 00 00 00  78 00 00 00 14 00 14 00   ........
x.......
ipw2200: I ipw_irq_tasklet Command completed.
ipw2200: U ipw_send_cmd Sending SSID command (#8), 7 bytes
00000000 64 65 66 61 75 6C 74
default          
ipw2200: I ipw_irq_tasklet Command completed.
ipw2200: U ipw_send_cmd Sending SCAN_REQUEST_EXT command (#26), 96 bytes
00000000 3D 00 00 00 4A 01 02 03  04 05 07 08 09 0A 0B 00
=...J... ........
00000010 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000020 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000030 00 00 00 00 00 00 00 00  00 00 04 44 44 44 44
40   ........ ...DDDD@
00000040 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000050 00 00 00 00 00 00 00 00  78 00 00 00 14 00 14 00   ........
x.......
ipw2200: I ipw_irq_tasklet Command completed.
ipw2200: U ipw_send_cmd Sending SCAN_REQUEST_EXT command (#26), 96 bytes
00000000 3E 00 00 00 4A 01 02 03  04 05 07 08 09 0A 0B 00
>...J... ........
00000010 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000020 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000030 00 00 00 00 00 00 00 00  00 00 03 33 33 33 33
30   ........ ...33330
00000040 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000050 00 00 00 00 00 00 00 00  78 00 00 00 14 00 14 00   ........
x.......
ipw2200: I ipw_irq_tasklet Command completed.
ipw2200: U ipw_send_cmd Sending SSID command (#8), 7 bytes
00000000 64 65 66 61 75 6C 74
default          
ipw2200: I ipw_irq_tasklet Command completed.
ipw2200: U ipw_send_cmd Sending SCAN_REQUEST_EXT command (#26), 96 bytes
00000000 3F 00 00 00 4A 01 02 03  04 05 07 08 09 0A 0B
00   ?...J... ........
00000010 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000020 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000030 00 00 00 00 00 00 00 00  00 00 04 44 44 44 44
40   ........ ...DDDD@
00000040 00 00 00 00 00 00 00 00  00 00 00 00 00 00 00
00   ........ ........
00000050 00 00 00 00 00 00 00 00  78 00 00 00 14 00 14 00   ........
x.......
ipw2200: I ipw_irq_tasklet Command completed.
------- Comment #6 From 2004-12-15 08:25:53 -------
What do you mean by C3?
------- Comment #7 From 2004-12-16 21:59:27 -------
I retested this with a fixed dsdt kernel 2.6.9 and it shows the same behaviour.
The connection gets sometimes very slow. I turned back to 0.16 which works for me.

If I can gather further information... let me know. 
------- Comment #8 From 2004-12-16 22:27:30 -------
With kernel 2.6.9 and ipw2200 0.18:

iwevent shows:
knecht:/usr/src/ipw2200-0.18# iwevent
Waiting for Wireless Events from interfaces...
06:14:48.403049    eth1     Set Mode:Managed
06:14:48.403090    eth1     Set Encryption key:****-****-**
06:14:48.403104    eth1     Set ESSID:"default"
06:14:48.990078    eth1     New Access Point/Cell address:00:0F:3D:9F:E0:AA

I've seen that ping sometimes hangs (Bit rate went down):

knecht:~# iwconfig eth1
eth1      IEEE 802.11g  ESSID:"default"  
          Mode:Managed  Frequency:2.437 GHz  Access Point: 00:0F:3D:9F:E0:AA   
          Bit Rate=24 Mb/s   Tx-Power=20 dBm   
          RTS thr:off   Fragment thr:off
          Encryption key:5555-5555-55   Security mode:open
          Power Management:off
          Link Quality=61/100  Signal level=-51 dBm  Noise level=-82 dBm
          Rx invalid nwid:0  Rx invalid crypt:0  Rx invalid frag:0
          Tx excessive retries:105  Invalid misc:0   Missed beacon:38

knecht:~# 

With 0.16 the bit rate remain at 54mbit:
knecht:/usr/src/ipw2200-0.16# iwconfig eth1
eth1      IEEE 802.11g  ESSID:"default"  
          Mode:Managed  Frequency:2.437 GHz  Access Point: 00:0F:3D:9F:E0:AA   
          Bit Rate=54 Mb/s   Tx-Power=20 dBm   
          RTS thr:off   Fragment thr:off
          Encryption key:5555-5555-55   Security mode:open
          Power Management:off
          Link Quality=100/100  Signal level=-54 dBm  
          Rx invalid nwid:0  Rx invalid crypt:0  Rx invalid frag:0
          Tx excessive retries:0  Invalid misc:0   Missed beacon:1

knecht:/usr/src/ipw2200-0.16# 

iwevent shows the same output like with 0.18

Resume:
With 0.18 
- "Missed beacons" increased extremly. (results in higher Tx retries)
- "Signal level" is higher 
- "Link Quality" is lower
- "Noise Level" has been added
------- Comment #9 From 2004-12-18 16:50:28 -------
Removed background scanning which was causing this problem.  Fixed in 0.19.
------- Comment #10 From 2004-12-19 01:13:55 -------
Will this affect the ipw2100 as well?
------- Comment #11 From 2004-12-21 00:12:48 -------
Retested in 0.19...

It works.

Lars