ndt-users - Re: S2C Protocol Error with 1GB Connections
Subject: ndt-users list created
List archive
- From:
- To:
- Subject: Re: S2C Protocol Error with 1GB Connections
- Date: Thu, 4 Feb 2010 13:48:53 -0500 (EST)
I have more data for you. I had to run several bandwidth tests on the 1GB
machine to get a successful test.
I noticed when getting a successful run with the 1GB connection, the output
from the web100srv process still reports a Protocol Error.
Also, the data collected varies from the applet, depending on whether or not
the run is successful. If the run fails, no diagnostic data will be
collected by the applet. If it is successful, I will get diagnostic data.
Because I am already posting 400+ lines in these messages, I am not going to
provide the differences in the diagnostic output in the applet unless it's
requested of me. If it fails, it's simply not there, if its successful, I
get all of the data in the applet.
However...perhaps you can see a difference that I am not seeing between
successful/failed runs, so...
Here is the output from web100srv at debug level 6, when I have a successful
run:
--------------------------------------------------------------
New connection received, waiting for accept() to complete
New connection received from [155.138.8.12].
Parent process spawned child = 971
Parent thinks pipe() returned fd0=5, fd1=6
Incrementing waiting variable now = 1
Telling client 971 testing will begin now
>>> send_msg: type=1, len=1
>>>
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer runningChild thinks pipe() returned fd0=5,
fd1=6 for pid=0
Got 'go' signal from parent, ready to start testing
Child process 971 started
>>> send_msg: type=2, len=6
<<< recv_msg: type=2, len=1
>>> send_msg: type=2, len=7
Starting test suite:
> Middlebox test
> Simple firewall test
> C2S throughput test
> S2C throughput test
<-- Middlebox test -->
KillHung(): returned non-0 response, nothing to kill or kill failed
-- port: 3003
>>> send_msg: type=3, len=4
Middlebox test, Port 3003 waiting for incoming connection (fd=3)
Set MSS to 536, Receiving Window size set to 262142KB
Sending Window size set to 262142KB
Looking for Web100 data on socketid 5
Server: 155.138.1.49;3003 Client: 155.138.8.12;8160 1456;6;6;
Sending 1456 Byte packets over the network
Setting Cwnd Limit to 2912 octets
Signal 17 received by process 971
now = 1265308366 Process started at 1265308363, run time = 3
Timer expired while waiting for a new connection
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer running
now = 1265308369 Process started at 1265308363, run time = 6
Timer expired while waiting for a new connection
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer running
>>> send_msg: type=5, len=35
<<< recv_msg: type=5, len=17
CWND limited throughput = 95136 kbps (95136.45955280858)
>>> send_msg: type=6, len=0
<-------------------->
<-- Simple firewall test -->
-- port: 52286
-- time: 1
>>> send_msg: type=3, len=7
<<< recv_msg: type=5, len=4
-- oport: 8164
>>> send_msg: type=4, len=0
>>> send_msg: type=5, len=20
<<< recv_msg: type=5, len=20
>>> send_msg: type=5, len=1
>>> send_msg: type=6, len=0
<-------------------------->
<-- C2S throughput test -->
-- port: 3002
listening for Inet connection on testOptions->c2ssockfd, fd=3
Sending 'GO' signal, to tell client to head for the next test
>>> send_msg: type=3, len=4
C2S test Child thinks pipe() returned fd0=7, fd1=8
C2S test calling init_pkttrace() with pd=0xbfd97edc
Opening network interface 'eth0' for packet-pair timing
pcap_open_live() returned pointer 0x8084098
installing pkt filter for 'host 155.138.8.12 and port 8167'
Initial pkt src data = 8068484
C2S test Parent thinks pipe() returned fd0=7, fd1=8
now = 1265308372 Process started at 1265308363, run time = 9
Timer expired while waiting for a new connection
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer running
>>> send_msg: type=4, len=0
New packet trace started -- initializing counters
now = 1265308375 Process started at 1265308363, run time = 12
Timer expired while waiting for a new connection
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer running
now = 1265308378 Process started at 1265308363, run time = 15
Timer expired while waiting for a new connection
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer running
now = 1265308381 Process started at 1265308363, run time = 18
Timer expired while waiting for a new connection
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer running
933582 kbps outbound
>>> send_msg: type=5, len=6
Signal USR1(10) sent to child [974]
Signal 10 received by process 974
DEBUG, caught SIGUSR1, setting sig1 flag to force exit
Received SIGUSRx signal terminating data collection loop for pid=974
Sending pkt-pair data back to parent on pipe 7, 8
fwd.saddr = c088a9b:8167, rev.saddr = 31018a9b:3002
12:32:53.782460 155.138.8.12:8167 --> 155.138.1.49:3002 Collected pkt-pair
data max = 403424
wrote 128 bytes: link counters are ' 0 0 1 4 46 129 64214 403424 317049
16396 15 7 802.06 0 0 0 1 0'
#$#$#$#$ pcap routine says window increases = 0, decreases = 0, no change = 0
12:32:53.782460 155.138.1.49:3002 --> 155.138.8.12:8167 Collected pkt-pair
data max = 130113
wrote 128 bytes: link counters are ' 0 0 1 1 27 38 43115 117130 130113 18188
98 0 948.14 50415 37184 221112 0 98'
#$#$#$#$ pcap routine says window increases = 50415, decreases = 37184, no
change = 221112
128 bytes read ' 0 0 1 4 46 129 64214 403424 317049 16396 15 7 802.06 0 0 0
1 0' from monitor pipe
128 bytes read ' 0 0 1 1 27 38 43115 117130 130113 18188 98 0 948.14 50415
37184 221112 0 98' from monitor pipe
>>> send_msg: type=6, len=0
>>>
Finished reading pkt-pair data from network, process 974 should terminate now
Signal 11 received by process 974
DEBUG, caught SIGSEGV signal and terminated process (974)
Signal 17 received by process 971
<------------------------->
<-- S2C throughput test -->
-- port: 3003
>>> send_msg: type=3, len=4
>>>
waiting for data on testOptions->s2csockfd
S2C test Child thinks pipe() returned fd0=7, fd1=8
S2C test calling init_pkttrace() with pd=0xbfd97ed0
Opening network interface 'eth0' for packet-pair timing
pcap_open_live() returned pointer 0x8084d70
installing pkt filter for 'host 155.138.8.12 and port 8174'
Initial pkt src data = 8068484
Signal 17 received by process 971
>>> send_msg: type=4, len=0
>>>
New packet trace started -- initializing counters
now = 1265308384 Process started at 1265308363, run time = 21
Timer expired while waiting for a new connection
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer running
now = 1265308387 Process started at 1265308363, run time = 24
Timer expired while waiting for a new connection
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer running
now = 1265308390 Process started at 1265308363, run time = 27
Timer expired while waiting for a new connection
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer running
now = 1265308393 Process started at 1265308363, run time = 30
Timer expired while waiting for a new connection
Queue pointer = 971, testing = 1, waiting = 1
Waiting for new connection, timer running
>>> send_msg: type=5, len=24
>>>
sent 1023606784 bytes to client in 10.00 seconds
Buffer control counters Total = 124952, new data = 0, Draining Queue = 0
Signal USR2(12) sent to child [977]
Signal 12 received by process 977
DEBUG, caught SIGUSR2, setting sig2 flag to force exit
Received SIGUSRx signal terminating data collection loop for pid=977
Sending pkt-pair data back to parent on pipe 7, 8
fwd.saddr = 31018a9b:3003, rev.saddr = c088a9b:8174
12:33:04.061537 155.138.1.49:3003 --> 155.138.8.12:8174 Collected pkt-pair
data max = 29321
wrote 128 bytes: link counters are ' 0 0 2 0 5 45 21308 6277 6124 29321 1
728 5577.83 0 0 0 1 0'
#$#$#$#$ pcap routine says window increases = 0, decreases = 0, no change = 0
12:33:04.061537 155.138.8.12:8174 --> 155.138.1.49:3003 Collected pkt-pair
data max = 142172
wrote 128 bytes: link counters are ' 0 0 1 0 21 1519 20646 7534 142172 94321
1333 993 1804.07 2122 2182 264236 0 1333'
#$#$#$#$ pcap routine says window increases = 2122, decreases = 2182, no
change = 264236
Read ' 0 0 2 0 5 45 21308 6277 6124 29321 1 728 5577.83 0 0 0 1 0' from
monitor pipe
Read ' 0 0 1 0 21 1519 20646 7534 142172 94321 1333 993 1804.07 2122 2182
264236 0 1333' from monitor pipe
818793 kbps inbound
libweb100: warning: accessing depricated variable AckPktsIn
Variable 0 (AckPktsIn): web100_snap_read(): invalid arguments
libweb100: warning: accessing depricated variable AckPktsOut
Variable 1 (AckPktsOut): web100_snap_read(): invalid arguments
Variable 2 (BytesRetrans): web100_snap_read(): invalid arguments
Variable 3 (CongAvoid): web100_snap_read(): invalid arguments
Variable 4 (CongestionOverCount): web100_snap_read(): invalid arguments
Variable 5 (CongestionSignals): web100_snap_read(): invalid arguments
Variable 6 (CountRTT): web100_snap_read(): invalid arguments
Variable 7 (CurCwnd): web100_snap_read(): invalid arguments
>>> send_msg: type=5, len=13
>>>
CurMSS: 1460
Variable 9 (CurRTO): web100_snap_read(): invalid arguments
Variable 10 (CurRwinRcvd): web100_snap_read(): invalid arguments
Variable 11 (CurRwinSent): web100_snap_read(): invalid arguments
Variable 12 (CurSsthresh): web100_snap_read(): invalid arguments
Variable 13 (CwndRestores) not found in KIS
Variable 14 (DSACKDups): web100_snap_read(): invalid arguments
Variable 15 (DataBytesIn): web100_snap_read(): invalid arguments
Variable 16 (DataBytesOut): web100_snap_read(): invalid arguments
Variable 17 (DataPktsIn): web100_snap_read(): invalid arguments
Variable 18 (DataPktsOut): web100_snap_read(): invalid arguments
Variable 19 (DupAcksIn): web100_snap_read(): invalid arguments
Variable 20 (ECNEnabled): web100_snap_read(): invalid arguments
Variable 21 (FastRetran): web100_snap_read(): invalid arguments
Variable 22 (MaxCaCwnd) not found in KIS
Variable 23 (MaxCwnd): web100_snap_read(): invalid arguments
Variable 24 (MaxMSS): web100_snap_read(): invalid arguments
Variable 25 (MaxRTO): web100_snap_read(): invalid arguments
Variable 26 (MaxRTT): web100_snap_read(): invalid arguments
Variable 27 (MaxRwinRcvd): web100_snap_read(): invalid arguments
Variable 28 (MaxRwinSent): web100_snap_read(): invalid arguments
Variable 29 (MaxSsthresh): web100_snap_read(): invalid arguments
Variable 30 (MaxSaCwnd) not found in KIS
Variable 31 (MinMSS): web100_snap_read(): invalid arguments
Variable 32 (MinRTO): web100_snap_read(): invalid arguments
Variable 33 (MinRTT): web100_snap_read(): invalid arguments
Variable 34 (MinRwinRcvd): web100_snap_read(): invalid arguments
Variable 35 (MinRwinSent): web100_snap_read(): invalid arguments
Variable 36 (NagleEnabled): web100_snap_read(): invalid arguments
Variable 37 (OtherReductions): web100_snap_read(): invalid arguments
Variable 38 (PktsIn): web100_snap_read(): invalid arguments
Variable 39 (PktsOut): web100_snap_read(): invalid arguments
Variable 40 (PktsRetrans): web100_snap_read(): invalid arguments
>>> send_msg: type=5, len=17
>>>
X_Rcvbuf: 262142
Variable 42 (RcvWinScale): web100_snap_read(): invalid arguments
Variable 43 (SACKEnabled): web100_snap_read(): invalid arguments
Variable 44 (SACKsRcvd): web100_snap_read(): invalid arguments
Variable 45 (SendStall): web100_snap_read(): invalid arguments
Variable 46 (SlowStart): web100_snap_read(): invalid arguments
Variable 47 (SampleRTT): web100_snap_read(): invalid arguments
Variable 48 (SmoothedRTT): web100_snap_read(): invalid arguments
>>> send_msg: type=5, len=17
>>>
X_Sndbuf: 262142
Variable 50 (SndWinScale): web100_snap_read(): invalid arguments
Variable 51 (SndLimTimeRwin): web100_snap_read(): invalid arguments
Variable 52 (SndLimTimeCwnd): web100_snap_read(): invalid arguments
Variable 53 (SndLimTimeSender): web100_snap_read(): invalid arguments
Variable 54 (SndLimTransRwin): web100_snap_read(): invalid arguments
Variable 55 (SndLimTransCwnd): web100_snap_read(): invalid arguments
Variable 56 (SndLimTransSender): web100_snap_read(): invalid arguments
Variable 57 (SndLimBytesRwin): web100_snap_read(): invalid arguments
Variable 58 (SndLimBytesCwnd): web100_snap_read(): invalid arguments
Variable 59 (SndLimBytesSender): web100_snap_read(): invalid arguments
Variable 60 (SubsequentTimeouts): web100_snap_read(): invalid arguments
Variable 61 (SumRTT): web100_snap_read(): invalid arguments
Variable 62 (Timeouts): web100_snap_read(): invalid arguments
Variable 63 (TimestampsEnabled): web100_snap_read(): invalid arguments
Variable 64 (WinScaleRcvd): web100_snap_read(): invalid arguments
Variable 65 (WinScaleSent): web100_snap_read(): invalid arguments
Variable 66 (DupAcksOut): web100_snap_read(): invalid arguments
Variable 67 (StartTimeUsec): web100_snap_read(): invalid arguments
Variable 68 (Duration): web100_snap_read(): invalid arguments
>>> send_msg: type=5, len=18
>>>
AckPktsIn: 268534
>>> send_msg: type=5, len=14
>>>
AckPktsOut: 0
>>> send_msg: type=5, len=19
>>>
BytesRetrans: 2920
>>> send_msg: type=5, len=13
>>>
CongAvoid: 0
>>> send_msg: type=5, len=23
>>>
CongestionOverCount: 0
>>> send_msg: type=5, len=21
>>>
CongestionSignals: 1
>>> send_msg: type=5, len=17
>>>
CountRTT: 267199
>>> send_msg: type=5, len=15
>>>
CurCwnd: 99280
Variable 8 (CurMSS): web100_snap_read(): invalid arguments
>>> send_msg: type=5, len=12
>>>
CurRTO: 201
>>> send_msg: type=5, len=19
>>>
CurRwinRcvd: 65700
>>> send_msg: type=5, len=18
>>>
CurRwinSent: 5888
>>> send_msg: type=5, len=19
>>>
CurSsthresh: 43800
Variable 13 (CwndRestores) not found in KIS
>>> send_msg: type=5, len=13
>>>
DSACKDups: 0
>>> send_msg: type=5, len=15
>>>
DataBytesIn: 0
>>> send_msg: type=5, len=25
>>>
DataBytesOut: 1024851580
>>> send_msg: type=5, len=14
>>>
DataPktsIn: 0
>>> send_msg: type=5, len=20
>>>
DataPktsOut: 701079
>>> send_msg: type=5, len=16
>>>
DupAcksIn: 1239
>>> send_msg: type=5, len=14
>>>
ECNEnabled: 0
>>> send_msg: type=5, len=14
>>>
FastRetran: 1
Variable 22 (MaxCaCwnd) not found in KIS
>>> send_msg: type=5, len=15
>>>
MaxCwnd: 99280
>>> send_msg: type=5, len=13
>>>
MaxMSS: 1460
>>> send_msg: type=5, len=12
>>>
MaxRTO: 203
>>> send_msg: type=5, len=10
>>>
MaxRTT: 3
>>> send_msg: type=5, len=19
>>>
MaxRwinRcvd: 65700
>>> send_msg: type=5, len=18
>>>
MaxRwinSent: 5888
>>> send_msg: type=5, len=19
>>>
MaxSsthresh: 43800
Variable 30 (MaxSaCwnd) not found in KIS
>>> send_msg: type=5, len=13
>>>
MinMSS: 1460
>>> send_msg: type=5, len=12
>>>
MinRTO: 201
>>> send_msg: type=5, len=10
>>>
MinRTT: 0
>>> send_msg: type=5, len=17
>>>
MinRwinRcvd: 204
>>> send_msg: type=5, len=18
>>>
MinRwinSent: 5840
>>> send_msg: type=5, len=16
>>>
NagleEnabled: 1
>>> send_msg: type=5, len=19
>>>
OtherReductions: 1
>>> send_msg: type=5, len=15
>>>
PktsIn: 268534
>>> send_msg: type=5, len=16
>>>
PktsOut: 701079
>>> send_msg: type=5, len=15
>>>
PktsRetrans: 2
Variable 41 (X_Rcvbuf): web100_snap_read(): invalid arguments
>>> send_msg: type=5, len=15
>>>
RcvWinScale: 6
>>> send_msg: type=5, len=15
>>>
SACKEnabled: 3
>>> send_msg: type=5, len=14
>>>
SACKsRcvd: 44
>>> send_msg: type=5, len=13
>>>
SendStall: 0
>>> send_msg: type=5, len=13
>>>
SlowStart: 0
>>> send_msg: type=5, len=13
>>>
SampleRTT: 0
>>> send_msg: type=5, len=15
>>>
SmoothedRTT: 1
Variable 49 (X_Sndbuf): web100_snap_read(): invalid arguments
>>> send_msg: type=5, len=15
>>>
SndWinScale: 2
>>> send_msg: type=5, len=24
>>>
SndLimTimeRwin: 1381730
>>> send_msg: type=5, len=22
>>>
SndLimTimeCwnd: 27784
>>> send_msg: type=5, len=26
>>>
SndLimTimeSender: 8664628
>>> send_msg: type=5, len=23
>>>
SndLimTransRwin: 39117
>>> send_msg: type=5, len=21
>>>
SndLimTransCwnd: 561
>>> send_msg: type=5, len=25
>>>
SndLimTransSender: 39674
>>> send_msg: type=5, len=27
>>>
SndLimBytesRwin: 794226740
>>> send_msg: type=5, len=25
>>>
SndLimBytesCwnd: 9183520
>>> send_msg: type=5, len=29
>>>
SndLimBytesSender: 221441320
>>> send_msg: type=5, len=22
SubsequentTimeouts: 0
>>> send_msg: type=5, len=15
SumRTT: 150838
>>> send_msg: type=5, len=12
Timeouts: 0
>>> send_msg: type=5, len=21
TimestampsEnabled: 0
>>> send_msg: type=5, len=16
WinScaleRcvd: 2
>>> send_msg: type=5, len=16
WinScaleSent: 6
>>> send_msg: type=5, len=14
DupAcksOut: 0
>>> send_msg: type=5, len=22
StartTimeUsec: 988970
>>> send_msg: type=5, len=19
Duration: 10074297
Finished reading pkt-pair data from network, process 977 should terminate now
Signal 11 received by process 977
DEBUG, caught SIGSEGV signal and terminated process (977)
Signal 17 received by process 971
Protocol error!
>>> send_msg: type=7, len=61
S2C throughput test FAILED!
Finished testing C2S = 933.58 Mbps, S2C = 0.00 Mbps
Client --> Server data detects link = Gigabit Ethernet
Client <-- Server Ack's detect link = OC-48
Server --> Client data detects link = 10 Gigabit Enet
Server <-- Client Ack's detect link = OC-48
CWND limited test = 95136.46 while unlimited = 0.00
Better throughput when CWND is limited, may be duplex mismatch
>>> send_msg: type=8, len=42
>>> send_msg: type=8, len=76
>>> send_msg: type=8, len=87
>>> send_msg: type=8, len=77
>>> send_msg: type=8, len=82
>>> send_msg: type=8, len=50
>>> send_msg: type=9, len=0
Successfully returned from run_test() routine
Signal 17 received by process 563
now = 1265308394 Process started at 1265308363, run time = 31
Select exited with rc = -1
Queue pointer = 971, testing = 1, waiting = 1
Received SIGCHLD signal for active web100srv process [563]
wait3() returned 0 for PID=971
wexitstatus = '0'
Attempting to clean up child 971, head pid = 971
Child process 971 causing head pointer modification
Removing Child from head, decrementing waiting now = 0
Timer not running, waiting for new connection
- S2C Protocol Error with 1GB Connections, hlsander, 02/04/2010
- <Possible follow-up(s)>
- Re: S2C Protocol Error with 1GB Connections, hlsander, 02/04/2010
- Re: S2C Protocol Error with 1GB Connections, Richard Carlson, 02/04/2010
Archive powered by MHonArc 2.6.16.