Cheap way to detect client round trip times for http

Question

I am trying to figure out a way to detect round trip times for each IP that connects to port 80 on my server. What is a good way to do this?

There are far to many connections, and pinging each ip is not practical. I was thinking, somehow measuring the time difference between when server send the syn/ack packet and when server receives the ack for it.

Is there a way to log this cheaply? Maybe using some magic tcpdump filter?

The goal of this exercise is to aggregate the data and figure if there are any routing inefficiencies. Say one ISP in one region maybe routing incorrectly, etc.

FWIW the webserver is nginx.

Solution 1

$tcpinfo_rtt, $tcpinfo_rttvar, $tcpinfo_snd_cwnd, $tcpinfo_rcv_space

information about the client TCP connection; available on systems that support
the TCP_INFO socket option

http://nginx.org/en/docs/http/ngx_http_core_module.html#variables

Solution 2

If you have access to a linux or unix machine¹, you should use tcptrace. All you need to do is capture the client traffic with wireshark or tcpdump to a pcap file.

After you have that .pcap file², analyze with tcptrace -xtraffic <pcap_filename>³. This will generate two text files, and the average RTT stats for all connections in that pcap are shown at the bottom of the one called traffic_stats.dat.

[mpenning@Bucksnort tcpperf]$ tcptrace -xtraffic willers.pcap
mod_traffic: characterizing traffic
1 arg remaining, starting with 'willers.pcap'
Ostermann's tcptrace -- version 6.6.1 -- Wed Nov 19, 2003

16522 packets seen, 16522 TCP packets traced
elapsed wallclock time: 0:00:00.200709, 82318 pkts/sec analyzed
trace file elapsed time: 0:03:21.754962
Dumping port statistics into file traffic_byport.dat
Dumping overall statistics into file traffic_stats.dat
Plotting performed at 15.000 second intervals
[mpenning@Bucksnort tcpperf]$
[mpenning@Bucksnort tcpperf]$ cat traffic_stats.dat


Overall Statistics over 201 seconds (0:03:21.754962):
4135308 ttl bytes sent, 20573.672 bytes/second
4135308 ttl non-rexmit bytes sent, 20573.672 bytes/second
0 ttl rexmit bytes sent, 0.000 bytes/second
16522 packets sent, 82.199 packets/second
200 connections opened, 0.995 conns/second
11 dupacks sent, 0.055 dupacks/second
0 rexmits sent, 0.000 rexmits/second
average RTT: 67.511 msecs        <------------------
[mpenning@Bucksnort tcpperf]$

The .pcap file used in this example was a capture I generated when I looped through an expect script that pulled data from one of my servers. This was how I generated the loop...

#!/usr/bin/python
from subprocess import Popen, PIPE
import time

for ii in xrange(0,200):
    # willers.exp is an expect script
    Popen(['./willers.exp'], stdin=PIPE, stdout=PIPE, stderr=PIPE)
    time.sleep(1)

---

END NOTES:

1. A Knoppix Live-CD will do
2. Filtered to only capture test traffic
3. tcptrace is capable of very detailed per-socket stats if you use other options...

================================
[mpenning@Bucksnort tcpperf]$ tcptrace -lr willers.pcap
1 arg remaining, starting with 'willers.pcap'
Ostermann's tcptrace -- version 6.6.1 -- Wed Nov 19, 2003

16522 packets seen, 16522 TCP packets traced
elapsed wallclock time: 0:00:00.080496, 205252 pkts/sec analyzed
trace file elapsed time: 0:03:21.754962
TCP connection info:
200 TCP connections traced:
TCP connection 1:
        host c:        myhost.local:44781
        host d:        willers.local:22
        complete conn: RESET    (SYNs: 2)  (FINs: 1)
        first packet:  Tue May 31 22:52:24.154801 2011
        last packet:   Tue May 31 22:52:25.668430 2011
        elapsed time:  0:00:01.513628
        total packets: 73
        filename:      willers.pcap
   c->d:                              d->c:
     total packets:            34           total packets:            39
     resets sent:               4           resets sent:               0
     ack pkts sent:            29           ack pkts sent:            39
     pure acks sent:           11           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:      2512           unique bytes sent:     14336
     actual data pkts:         17           actual data pkts:         36
     actual data bytes:      2512           actual data bytes:     14336
     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:         17           pushed data pkts:         33
     SYN/FIN pkts sent:       1/1           SYN/FIN pkts sent:       1/0
     req 1323 ws/ts:          Y/Y           req 1323 ws/ts:          Y/Y
     adv wind scale:            6           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:           792 bytes     max segm size:          1448 bytes
     min segm size:            16 bytes     min segm size:            32 bytes
     avg segm size:           147 bytes     avg segm size:           398 bytes
     max win adv:           40832 bytes     max win adv:           66608 bytes
     min win adv:            5888 bytes     min win adv:           66608 bytes
     zero win adv:              0 times     zero win adv:              0 times
     avg win adv:           14035 bytes     avg win adv:           66608 bytes
     initial window:           32 bytes     initial window:           40 bytes
     initial window:            1 pkts      initial window:            1 pkts
     ttl stream length:      2512 bytes     ttl stream length:        NA
     missed data:               0 bytes     missed data:              NA
     truncated data:            0 bytes     truncated data:            0 bytes
     truncated packets:         0 pkts      truncated packets:         0 pkts
     data xmit time:        1.181 secs      data xmit time:        1.236 secs
     idletime max:          196.9 ms        idletime max:          196.9 ms
     throughput:             1660 Bps       throughput:             9471 Bps

     RTT samples:              18           RTT samples:              24
     RTT min:                43.8 ms        RTT min:                 0.0 ms
     RTT max:               142.5 ms        RTT max:                 7.2 ms
     RTT avg:                68.5 ms        RTT avg:                 0.7 ms
     RTT stdev:              35.8 ms        RTT stdev:               1.6 ms

     RTT from 3WHS:          80.8 ms        RTT from 3WHS:           0.0 ms

     RTT full_sz smpls:         1           RTT full_sz smpls:         3
     RTT full_sz min:       142.5 ms        RTT full_sz min:         0.0 ms
     RTT full_sz max:       142.5 ms        RTT full_sz max:         0.0 ms
     RTT full_sz avg:       142.5 ms        RTT full_sz avg:         0.0 ms
     RTT full_sz stdev:       0.0 ms        RTT full_sz stdev:       0.0 ms

     post-loss acks:            0           post-loss acks:            0
     segs cum acked:            0           segs cum acked:            9
     duplicate acks:            0           duplicate acks:            1
     triple dupacks:            0           triple dupacks:            0
     max # retrans:             0           max # retrans:             0
     min retr time:           0.0 ms        min retr time:           0.0 ms
     max retr time:           0.0 ms        max retr time:           0.0 ms
     avg retr time:           0.0 ms        avg retr time:           0.0 ms
     sdv retr time:           0.0 ms        sdv retr time:           0.0 ms
================================

Comments

[Admin]

Why is pinging not practical? It doesn't maintain a TCP connection.

[Admin]

my goal is to know the round trip time of real traffic already going thru the server which is doing 100s of connections/second. Wouldnt it be inefficient to ignore the data already passing thru, and pinging each discovered IP? moreover ICMP could be blocked by many ISPs. remember im the server and want to know the latency from end users connections.

[sajal]

Would generating full .pcap file on a server doing 100 Mbit/second make the file huge and eat up all the IO available? +1 for tcptrace. I didnt know about it.

[Spence]

@sajal: You can decrease the snaplen on the capture because you don't need the payloads. No matter where you're capturing (mirrored port, on the web server itself) it probably makes good sense to decreased the snaplen because that's just wasted disk space and longed processing time after-the-fact due to I/O reading the pcap files.

[Mike Pennington]

If you perform the tcpdump directly on the webserver, then yes you'll burn a lot of IO. If you're that concerned, have your network team fire up a mirrored port on the ethernet switch that your webserver is connected to, then pipe the traffic to and from your webserver to that mirrored port. You can put another linux machine on that port and capture everything... as Evan mentioned, you can decrease your snaplen to reduce load... but if you're concerned about performance a port mirror is best. FYI you may need to increase your linux port buffers

[resmon6]

if you're running tcpdump on the server, only capture the packets with the syn bit set and snap to 56-68 bytes. tcpdump -s 56 'tcp[tcpflags] & tcp-syn !=0'

[sajal]

tcp[tcpflags] & tcp-syn !=0 seems to be dumping the syn sent by the client and the ack sent by the server. since i measure on the server side, the time difference is ~0

[Mike Pennington]

if he limits captures to syn only, he will loose min, avg and max rtt stats. snaplen should be long enough to grab any tcp options in the packets... just do snaplen around one hundred and it will get anything important.

[sajal]

This looks very promising, however on nginx/0.8.54 the config doesn't validate : [emerg]: unknown "tcpinfo_rttvar" variable. Will try with newer versions.

[VBart]

nginx.org/en/CHANGES it appeared in version 1.1.18

[resmon6]

Good points. You could capture just the tcp-ack flags and catch the syn-ack and ack packets.

[est]

This is so cool. Why it's not on the new wiki.nginx.org site?

[VBart]

wiki.nginx.org isn't new. In fact it is non-official community-based wiki, and currently it is abandoned by its creator.