Date: Mon, 1 Jan 2007 20:07:59 -0800 From: "Stephan Wehner" <stephanwehner@gmail.com> To: .@babolo.ru Cc: freebsd-net@freebsd.org, Matthew Hudson <fbsd@synoptic.org> Subject: Re: Diagnose co-location networking problem Message-ID: <e66d1efb0701012007w27823c0ch294ae1039b8bea48@mail.gmail.com> In-Reply-To: <1167660016.168305.67043.nullmailer@cicuta.babolo.ru> References: <20061228203100.GA1165@gort.synoptic.org> <1167660016.168305.67043.nullmailer@cicuta.babolo.ru>
next in thread | previous in thread | raw e-mail | index | archive | help
Hello again, to give a short summary; I contacted this list to ask for help with diagnosing a problem with a co-located server (accessible at http://stbgo.org) running FreeBSD 6.1. When I swamp it with requests (simply, lynx -dump http://stbgo.org > /dev/null in a loop) some responses take 90 seconds -- far too long. This is reproducible, but seemingly not from other source addresses - only my own (home) machine, 64.114.83.92 The recommendations have been to look at the traceroute output, and at tcpdump from both ends; the tcpdump output was so far only available from the client side, since the server's kernel didn't support tcpdump. (Also, to "swamp" a different port and see the result - planned next step) The traceroute brought up a host with name a.core.65-110-0-1.van.data-fortress.com which sits between my server and the Internet. (As far as I can tell, this looks legitimate. The co-location provider says their machines perform no filtering) Traceroute from the client is not available; this service provider blocked it for some reason, and I can live without it. (tcptraceroute was suggested, but that gave no meaningful output; I may try again from a different machine on the local network) Now to where I got in the mean time. I recompiled the server's kernel so that tcpdump is available. Client tcpdump command ----------------------------------------------------------------------------- $ sudo /usr/sbin/tcpdump -n -s 1600 -w clientside.dmp host stbgo.org tcpdump: listening on eth0 398 packets received by filter 0 packets dropped by kernel Server tcpdump command --------------------------------------------------------------- $ sudo /usr/sbin/tcpdump -n -s 1600 -w /tmp/serverside.dmp tcpdump: listening on bge0, link-type EN10MB (Ethernet), capture size 1600 bytes Hm, dispatch protocol error: type 3 plen 4 302 packets captured 303 packets received by filter 0 packets dropped by kernel During the times that these two commands ran, this was executed on the client. Client swamping command ---------------------------------------------------------------- $ ruby o 0 : Mon Jan 01 14:09:38 PST 2007 -- done at Mon Jan 01 14:09:39 PST 2007. Took 0.532589 1 : Mon Jan 01 14:09:39 PST 2007 -- done at Mon Jan 01 14:09:39 PST 2007. Took 0.368819 2 : Mon Jan 01 14:09:39 PST 2007 -- done at Mon Jan 01 14:09:39 PST 2007. Took 0.352839 3 : Mon Jan 01 14:09:39 PST 2007 -- done at Mon Jan 01 14:09:40 PST 2007. Took 0.45799 4 : Mon Jan 01 14:09:40 PST 2007 -- done at Mon Jan 01 14:09:40 PST 2007. Took 0.369304 5 : Mon Jan 01 14:09:40 PST 2007 -- done at Mon Jan 01 14:09:41 PST 2007. Took 0.446588 6 : Mon Jan 01 14:09:41 PST 2007 -- done at Mon Jan 01 14:09:41 PST 2007. Took 0.345532 7 : Mon Jan 01 14:09:41 PST 2007 -- done at Mon Jan 01 14:09:41 PST 2007. Took 0.354955 8 : Mon Jan 01 14:09:41 PST 2007 -- done at Mon Jan 01 14:09:42 PST 2007. Took 0.465013 9 : Mon Jan 01 14:09:42 PST 2007 -- done at Mon Jan 01 14:09:42 PST 2007. Took 0.431748 10 : Mon Jan 01 14:09:42 PST 2007 -- done at Mon Jan 01 14:09:43 PST 2007. Took 0.368716 11 : Mon Jan 01 14:09:43 PST 2007 -- done at Mon Jan 01 14:09:43 PST 2007. Took 0.451658 12 : Mon Jan 01 14:09:43 PST 2007 -- done at Mon Jan 01 14:11:17 PST 2007. Took 93.492797 13 : Mon Jan 01 14:11:17 PST 2007 -- done at Mon Jan 01 14:11:17 PST 2007. Took 0.425495 14 : Mon Jan 01 14:11:17 PST 2007 -- done at Mon Jan 01 14:11:17 PST 2007. Took 0.430457 The "swamping script - o -" accesses the webserver 15 times in a loop without pausing, and records the elapsed time. Note #12 took 93.49 seconds Looking at the tcpdump dump files with tcptrace I find these connection entries --- (Client side) --- Ostermann's tcptrace -- version 6.6.7 -- Thu Nov 4, 2004 398 packets seen, 398 TCP packets traced elapsed wallclock time: 0:00:00.109089, 3648 pkts/sec analyzed trace file elapsed time: 0:02:12.449926 TCP connection info: 16 TCP connections traced: TCP connection 1: host a: sucrose.sugarmotor.net:35012 host b: vps-18-138.virtualprivateservers.ca:pcanywherestat complete conn: no (SYNs: 0) (FINs: 0) first packet: Mon Jan 1 14:09:14.224706 2007 last packet: Mon Jan 1 14:11:26.674632 2007 elapsed time: 0:02:12.449926 total packets: 137 filename: /tmp/clientside.dmp a->b: b->a: total packets: 90 total packets: 47 ack pkts sent: 90 ack pkts sent: 47 pure acks sent: 47 pure acks sent: 0 sack pkts sent: 0 sack pkts sent: 0 dsack pkts sent: 0 dsack pkts sent: 0 max sack blks/ack: 0 max sack blks/ack: 0 unique bytes sent: 2240 unique bytes sent: 2480 actual data pkts: 43 actual data pkts: 47 actual data bytes: 2240 actual data bytes: 2480 rexmt data pkts: 0 rexmt data pkts: 0 rexmt data bytes: 0 rexmt data bytes: 0 zwnd probe pkts: 0 zwnd probe pkts: 0 zwnd probe bytes: 0 zwnd probe bytes: 0 outoforder pkts: 0 outoforder pkts: 0 pushed data pkts: 43 pushed data pkts: 47 SYN/FIN pkts sent: 0/0 SYN/FIN pkts sent: 0/0 req 1323 ws/ts: N/Y req 1323 ws/ts: N/Y urgent data pkts: 0 pkts urgent data pkts: 0 pkts urgent data bytes: 0 bytes urgent data bytes: 0 bytes mss requested: 0 bytes mss requested: 0 bytes max segm size: 224 bytes max segm size: 128 bytes min segm size: 48 bytes min segm size: 32 bytes avg segm size: 52 bytes avg segm size: 52 bytes max win adv: 19856 bytes max win adv: 33304 bytes min win adv: 19856 bytes min win adv: 33304 bytes zero win adv: 0 times zero win adv: 0 times avg win adv: 19856 bytes avg win adv: 33304 bytes initial window: 48 bytes initial window: 0 bytes initial window: 1 pkts initial window: 0 pkts ttl stream length: NA ttl stream length: NA missed data: NA missed data: NA truncated data: 0 bytes truncated data: 0 bytes truncated packets: 0 pkts truncated packets: 0 pkts data xmit time: 132.431 secs data xmit time: 132.434 secs idletime max: 99997.8 ms idletime max: 100015.9 ms throughput: 17 Bps throughput: 19 Bps ================================ TCP connection 2: host c: sucrose.sugarmotor.net:35041 host d: vps-18-138.virtualprivateservers.ca:80 complete conn: yes first packet: Mon Jan 1 14:09:38.899996 2007 last packet: Mon Jan 1 14:09:39.215879 2007 elapsed time: 0:00:00.315883 total packets: 17 filename: /tmp/clientside.dmp c->d: d->c: total packets: 9 total packets: 8 ack pkts sent: 8 ack pkts sent: 8 pure acks sent: 5 pure acks sent: 2 sack pkts sent: 0 sack pkts sent: 0 dsack pkts sent: 0 dsack pkts sent: 0 max sack blks/ack: 0 max sack blks/ack: 0 unique bytes sent: 2500 unique bytes sent: 3750 actual data pkts: 2 actual data pkts: 5 actual data bytes: 2500 actual data bytes: 3750 rexmt data pkts: 0 rexmt data pkts: 0 rexmt data bytes: 0 rexmt data bytes: 0 zwnd probe pkts: 0 zwnd probe pkts: 0 zwnd probe bytes: 0 zwnd probe bytes: 0 outoforder pkts: 0 outoforder pkts: 0 pushed data pkts: 1 pushed data pkts: 3 SYN/FIN pkts sent: 1/1 SYN/FIN pkts sent: 1/1 req 1323 ws/ts: Y/Y req 1323 ws/ts: Y/Y adv wind scale: 0 adv wind scale: 1 req sack: Y req sack: Y sacks sent: 0 sacks sent: 0 urgent data pkts: 0 pkts urgent data pkts: 0 pkts urgent data bytes: 0 bytes urgent data bytes: 0 bytes mss requested: 1460 bytes mss requested: 1460 bytes max segm size: 1448 bytes max segm size: 1448 bytes min segm size: 1052 bytes min segm size: 65 bytes avg segm size: 1249 bytes avg segm size: 749 bytes max win adv: 14480 bytes max win adv: 66608 bytes min win adv: 5840 bytes min win adv: 65556 bytes zero win adv: 0 times zero win adv: 0 times avg win adv: 9148 bytes avg win adv: 66457 bytes initial window: 2500 bytes initial window: 189 bytes initial window: 2 pkts initial window: 1 pkts ttl stream length: 2500 bytes ttl stream length: 3750 bytes missed data: 0 bytes missed data: 0 bytes truncated data: 0 bytes truncated data: 0 bytes truncated packets: 0 pkts truncated packets: 0 pkts data xmit time: 0.000 secs data xmit time: 0.026 secs idletime max: 257.0 ms idletime max: 203.1 ms throughput: 7914 Bps throughput: 11871 Bps ===== : : ...12 similar connections... : : TCP connection 14: host aa: sucrose.sugarmotor.net:35053 host ab: vps-18-138.virtualprivateservers.ca:80 complete conn: yes first packet: Mon Jan 1 14:09:43.755058 2007 last packet: Mon Jan 1 14:11:17.122339 2007 elapsed time: 0:01:33.367281 total packets: 23 filename: /tmp/clientside.dmp aa->ab: ab->aa: total packets: 14 total packets: 9 ack pkts sent: 8 ack pkts sent: 9 pure acks sent: 5 pure acks sent: 3 sack pkts sent: 0 sack pkts sent: 0 dsack pkts sent: 0 dsack pkts sent: 0 max sack blks/ack: 0 max sack blks/ack: 0 unique bytes sent: 2500 unique bytes sent: 3750 actual data pkts: 2 actual data pkts: 5 actual data bytes: 2500 actual data bytes: 3750 rexmt data pkts: 5 rexmt data pkts: 0 rexmt data bytes: 5 rexmt data bytes: 0 zwnd probe pkts: 0 zwnd probe pkts: 0 zwnd probe bytes: 0 zwnd probe bytes: 0 outoforder pkts: 0 outoforder pkts: 0 pushed data pkts: 1 pushed data pkts: 3 SYN/FIN pkts sent: 6/1 SYN/FIN pkts sent: 1/1 req 1323 ws/ts: Y/Y req 1323 ws/ts: Y/Y adv wind scale: 0 adv wind scale: 1 req sack: Y req sack: Y sacks sent: 0 sacks sent: 0 urgent data pkts: 0 pkts urgent data pkts: 0 pkts urgent data bytes: 0 bytes urgent data bytes: 0 bytes mss requested: 1460 bytes mss requested: 1460 bytes max segm size: 1448 bytes max segm size: 1448 bytes min segm size: 1052 bytes min segm size: 65 bytes avg segm size: 1249 bytes avg segm size: 749 bytes max win adv: 14480 bytes max win adv: 66608 bytes min win adv: 5840 bytes min win adv: 66606 bytes zero win adv: 0 times zero win adv: 0 times avg win adv: 9148 bytes avg win adv: 66607 bytes initial window: 1448 bytes initial window: 189 bytes initial window: 1 pkts initial window: 1 pkts ttl stream length: 2500 bytes ttl stream length: 3750 bytes missed data: 0 bytes missed data: 0 bytes truncated data: 0 bytes truncated data: 0 bytes truncated packets: 0 pkts truncated packets: 0 pkts data xmit time: 0.137 secs data xmit time: 0.027 secs idletime max: 48000.0 ms idletime max: 139.8 ms throughput: 27 Bps throughput: 40 Bps What is TCP Connection 1 about ("PCanywhere"); why for 2 minutes? Could it be the ssh shell which is open at the same time? TCP Connection 14 seems to be the one corresponding to the ca. 90 seconds response time recorded by the ruby command. It is the only one with a line SYN/FIN pkts sent: 6/1 All others have 1/1 in the first column (or 0/0 for the PCAnywhere connection) To match things up, below is the excerpt from the serverside dump for the same connections. Should I look closely into the dump files themselves to see further? What to look for? Or can anything be concluded with this alone? Thanks a lot, and happy new year -- Stephan --- (Server side) --- TCP connection 1: host a: vps-18-138.virtualprivateservers.ca:pcanywherestat host b: zz83092.cipherkey.net:55116 complete conn: no (SYNs: 0) (FINs: 0) first packet: Mon Jan 1 14:13:20.414784 2007 last packet: Mon Jan 1 14:15:00.446913 2007 elapsed time: 0:01:40.032128 total packets: 5 filename: /tmp/serverside.dmp a->b: b->a: total packets: 2 total packets: 3 ack pkts sent: 2 ack pkts sent: 3 pure acks sent: 0 pure acks sent: 2 sack pkts sent: 0 sack pkts sent: 0 dsack pkts sent: 0 dsack pkts sent: 0 max sack blks/ack: 0 max sack blks/ack: 0 unique bytes sent: 160 unique bytes sent: 224 actual data pkts: 2 actual data pkts: 1 actual data bytes: 160 actual data bytes: 224 rexmt data pkts: 0 rexmt data pkts: 0 rexmt data bytes: 0 rexmt data bytes: 0 zwnd probe pkts: 0 zwnd probe pkts: 0 zwnd probe bytes: 0 zwnd probe bytes: 0 outoforder pkts: 0 outoforder pkts: 0 pushed data pkts: 2 pushed data pkts: 1 SYN/FIN pkts sent: 0/0 SYN/FIN pkts sent: 0/0 req 1323 ws/ts: N/Y req 1323 ws/ts: N/Y urgent data pkts: 0 pkts urgent data pkts: 0 pkts urgent data bytes: 0 bytes urgent data bytes: 0 bytes mss requested: 0 bytes mss requested: 0 bytes max segm size: 128 bytes max segm size: 224 bytes min segm size: 32 bytes min segm size: 224 bytes avg segm size: 79 bytes avg segm size: 223 bytes max win adv: 33304 bytes max win adv: 19856 bytes min win adv: 33304 bytes min win adv: 19856 bytes zero win adv: 0 times zero win adv: 0 times avg win adv: 33304 bytes avg win adv: 19856 bytes initial window: 128 bytes initial window: 0 bytes initial window: 1 pkts initial window: 0 pkts ttl stream length: NA ttl stream length: NA missed data: NA missed data: NA truncated data: 0 bytes truncated data: 0 bytes truncated packets: 0 pkts truncated packets: 0 pkts data xmit time: 100.016 secs data xmit time: 0.000 secs idletime max: 100015.6 ms idletime max: 99999.4 ms throughput: 2 Bps throughput: 2 Bps ================================ TCP connection 2: host c: zz83092.cipherkey.net:55402 host d: vps-18-138.virtualprivateservers.ca:80 complete conn: yes first packet: Mon Jan 1 14:13:26.336098 2007 last packet: Mon Jan 1 14:13:26.637267 2007 elapsed time: 0:00:00.301169 total packets: 17 filename: /tmp/serverside.dmp c->d: d->c: total packets: 9 total packets: 8 ack pkts sent: 8 ack pkts sent: 8 pure acks sent: 5 pure acks sent: 2 sack pkts sent: 0 sack pkts sent: 0 dsack pkts sent: 0 dsack pkts sent: 0 max sack blks/ack: 0 max sack blks/ack: 0 unique bytes sent: 2500 unique bytes sent: 3750 actual data pkts: 2 actual data pkts: 5 actual data bytes: 2500 actual data bytes: 3750 rexmt data pkts: 0 rexmt data pkts: 0 rexmt data bytes: 0 rexmt data bytes: 0 zwnd probe pkts: 0 zwnd probe pkts: 0 zwnd probe bytes: 0 zwnd probe bytes: 0 outoforder pkts: 0 outoforder pkts: 0 pushed data pkts: 1 pushed data pkts: 3 SYN/FIN pkts sent: 1/1 SYN/FIN pkts sent: 1/1 req 1323 ws/ts: Y/Y req 1323 ws/ts: Y/Y adv wind scale: 0 adv wind scale: 1 req sack: Y req sack: Y sacks sent: 0 sacks sent: 0 urgent data pkts: 0 pkts urgent data pkts: 0 pkts urgent data bytes: 0 bytes urgent data bytes: 0 bytes mss requested: 1460 bytes mss requested: 1460 bytes max segm size: 1448 bytes max segm size: 1448 bytes min segm size: 1052 bytes min segm size: 65 bytes avg segm size: 1249 bytes avg segm size: 749 bytes max win adv: 14480 bytes max win adv: 66608 bytes min win adv: 5840 bytes min win adv: 65556 bytes zero win adv: 0 times zero win adv: 0 times avg win adv: 9148 bytes avg win adv: 66457 bytes initial window: 2500 bytes initial window: 2237 bytes initial window: 2 pkts initial window: 3 pkts ttl stream length: 2500 bytes ttl stream length: 3750 bytes missed data: 0 bytes missed data: 0 bytes truncated data: 0 bytes truncated data: 0 bytes truncated packets: 0 pkts truncated packets: 0 pkts data xmit time: 0.015 secs data xmit time: 0.017 secs idletime max: 218.1 ms idletime max: 201.4 ms throughput: 8301 Bps throughput: 12451 Bps ========== : : : TCP connection 14: host aa: zz83092.cipherkey.net:55402 host ab: vps-18-138.virtualprivateservers.ca:80 complete conn: yes first packet: Mon Jan 1 14:13:31.191783 2007 last packet: Mon Jan 1 14:15:04.543351 2007 elapsed time: 0:01:33.351567 total packets: 23 filename: /tmp/serverside.dmp aa->ab: ab->aa: total packets: 14 total packets: 9 ack pkts sent: 8 ack pkts sent: 9 pure acks sent: 5 pure acks sent: 3 sack pkts sent: 0 sack pkts sent: 0 dsack pkts sent: 0 dsack pkts sent: 0 max sack blks/ack: 0 max sack blks/ack: 0 unique bytes sent: 2500 unique bytes sent: 3750 actual data pkts: 2 actual data pkts: 5 actual data bytes: 2500 actual data bytes: 3750 rexmt data pkts: 5 rexmt data pkts: 0 rexmt data bytes: 5 rexmt data bytes: 0 zwnd probe pkts: 0 zwnd probe pkts: 0 zwnd probe bytes: 0 zwnd probe bytes: 0 outoforder pkts: 0 outoforder pkts: 0 pushed data pkts: 1 pushed data pkts: 3 SYN/FIN pkts sent: 6/1 SYN/FIN pkts sent: 1/1 req 1323 ws/ts: Y/Y req 1323 ws/ts: Y/Y adv wind scale: 0 adv wind scale: 1 req sack: Y req sack: Y sacks sent: 0 sacks sent: 0 urgent data pkts: 0 pkts urgent data pkts: 0 pkts urgent data bytes: 0 bytes urgent data bytes: 0 bytes mss requested: 1460 bytes mss requested: 1460 bytes max segm size: 1448 bytes max segm size: 1448 bytes min segm size: 1052 bytes min segm size: 65 bytes avg segm size: 1249 bytes avg segm size: 749 bytes max win adv: 14480 bytes max win adv: 66608 bytes min win adv: 5840 bytes min win adv: 66606 bytes zero win adv: 0 times zero win adv: 0 times avg win adv: 9148 bytes avg win adv: 66607 bytes initial window: 1448 bytes initial window: 2237 bytes initial window: 1 pkts initial window: 3 pkts ttl stream length: 2500 bytes ttl stream length: 3750 bytes missed data: 0 bytes missed data: 0 bytes truncated data: 0 bytes truncated data: 0 bytes truncated packets: 0 pkts truncated packets: 0 pkts data xmit time: 0.131 secs data xmit time: 0.020 secs idletime max: 47998.4 ms idletime max: 141.9 ms throughput: 27 Bps throughput: 40 Bps
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?e66d1efb0701012007w27823c0ch294ae1039b8bea48>