Merge pull request #1538 from dpayne/master

Adding minimum latency filter to tcpconnlat

man/man8/tcpconnlat.8

-.TH tcpconnect 8  "2016-02-19" "USER COMMANDS"
+.TH tcpconnlat 8  "2016-02-19" "USER COMMANDS"
 .SH NAME
-tcpconnect \- Trace TCP active connection latency. Uses Linux eBPF/bcc.
+tcpconnlat \- Trace TCP active connection latency. Uses Linux eBPF/bcc.
 .SH SYNOPSIS
-.B tcpconnect [\-h] [\-t] [\-p PID]
+.B tcpconnlat [\-h] [\-t] [\-p PID] [-v] [min_ms]
 .SH DESCRIPTION
 This tool traces active TCP connections
 (eg, via a connect() syscall), and shows the latency (time) for the connection
@@ -30,19 +30,33 @@ Include a timestamp column.
 .TP
 \-p PID
 Trace this process ID only (filtered in-kernel).
+.TP
+\-v
+Print the resulting BPF program, for debugging purposes.
+.TP
+min_ms
+Minimum duration to trace, in milliseconds.
 .SH EXAMPLES
 .TP
 Trace all active TCP connections, and show connection latency (SYN->response round trip):
 #
-.B tcpconnect
+.B tcpconnlat
 .TP
 Include timestamps:
 #
-.B tcpconnect \-t
+.B tcpconnlat \-t
 .TP
 Trace PID 181 only:
 #
-.B tcpconnect \-p 181
+.B tcpconnlat \-p 181
+.TP
+Trace connects with latency longer than 10 ms:
+#
+.B tcpconnlat 10
+.TP
+Print the BPF program:
+#
+.B tcpconnlat \-v
 .SH FIELDS
 .TP
 TIME(s)

tools/tcpconnlat.py

@@ -21,9 +21,22 @@ from struct import pack
 import argparse
 import ctypes as ct
 
+# arg validation
+def positive_float(val):
+    try:
+        ival = float(val)
+    except ValueError:
+        raise argparse.ArgumentTypeError("must be a float")
+
+    if ival < 0:
+        raise argparse.ArgumentTypeError("must be positive")
+    return ival
+
 # arguments
 examples = """examples:
     ./tcpconnlat           # trace all TCP connect()s
+    ./tcpconnlat 1         # trace connection latency slower than 1 ms
+    ./tcpconnlat 0.1       # trace connection latency slower than 100 us
     ./tcpconnlat -t        # include timestamps
     ./tcpconnlat -p 181    # only trace PID 181
 """
@@ -35,7 +48,19 @@ parser.add_argument("-t", "--timestamp", action="store_true",
     help="include timestamp on output")
 parser.add_argument("-p", "--pid",
     help="trace this PID only")
+parser.add_argument("duration_ms", nargs="?", default=0,
+    type=positive_float,
+    help="minimum duration to trace (ms)")
+parser.add_argument("-v", "--verbose", action="store_true",
+    help="print the BPF program for debugging purposes")
 args = parser.parse_args()
+
+if args.duration_ms:
+    # support fractions but round to nearest microsecond
+    duration_us = int(args.duration_ms * 1000)
+else:
+    duration_us = 0   # default is show all
+
 debug = 0
 
 # define BPF program
@@ -104,9 +129,18 @@ int trace_tcp_rcv_state_process(struct pt_regs *ctx, struct sock *skp)
     if (infop == 0) {
         return 0;   // missed entry or filtered
     }
+
     u64 ts = infop->ts;
     u64 now = bpf_ktime_get_ns();
 
+    u64 delta_us = (now - ts) / 1000ul;
+
+#ifdef MIN_LATENCY
+    if ( delta_us < DURATION_US ) {
+        return 0; // connect latency is below latency filter minimum
+    }
+#endif
+
     // pull in details
     u16 family = 0, dport = 0;
     family = skp->__sk_common.skc_family;
@@ -119,7 +153,7 @@ int trace_tcp_rcv_state_process(struct pt_regs *ctx, struct sock *skp)
         data4.saddr = skp->__sk_common.skc_rcv_saddr;
         data4.daddr = skp->__sk_common.skc_daddr;
         data4.dport = ntohs(dport);
-        data4.delta_us = (now - ts) / 1000;
+        data4.delta_us = delta_us;
         __builtin_memcpy(&data4.task, infop->task, sizeof(data4.task));
         ipv4_events.perf_submit(ctx, &data4, sizeof(data4));
 
@@ -131,7 +165,7 @@ int trace_tcp_rcv_state_process(struct pt_regs *ctx, struct sock *skp)
         bpf_probe_read(&data6.daddr, sizeof(data6.daddr),
             skp->__sk_common.skc_v6_daddr.in6_u.u6_addr32);
         data6.dport = ntohs(dport);
-        data6.delta_us = (now - ts) / 1000;
+        data6.delta_us = delta_us;
         __builtin_memcpy(&data6.task, infop->task, sizeof(data6.task));
         ipv6_events.perf_submit(ctx, &data6, sizeof(data6));
     }
@@ -142,13 +176,17 @@ int trace_tcp_rcv_state_process(struct pt_regs *ctx, struct sock *skp)
 }
 """
 
+if duration_us > 0:
+    bpf_text = "#define MIN_LATENCY\n" + bpf_text
+    bpf_text = bpf_text.replace('DURATION_US', str(duration_us))
+
 # code substitutions
 if args.pid:
     bpf_text = bpf_text.replace('FILTER',
         'if (pid != %s) { return 0; }' % args.pid)
 else:
     bpf_text = bpf_text.replace('FILTER', '')
-if debug:
+if debug or args.verbose:
     print(bpf_text)
 
 # initialize BPF

tools/tcpconnlat_example.txt

@@ -34,10 +34,13 @@ if the response is a RST (port closed).
 USAGE message:
 
 # ./tcpconnlat -h
-usage: tcpconnlat [-h] [-t] [-p PID]
+usage: tcpconnlat [-h] [-t] [-p PID] [min_ms]
 
 Trace TCP connects and show connection latency
 
+positional arguments:
+  min_ms             minimum duration to trace, in ms (default 0)
+
 optional arguments:
   -h, --help         show this help message and exit
   -t, --timestamp    include timestamp on output
@@ -47,3 +50,6 @@ examples:
     ./tcpconnlat           # trace all TCP connect()s
     ./tcpconnlat -t        # include timestamps
     ./tcpconnlat -p 181    # only trace PID 181
+    ./tcpconnlat 1         # only show connects longer than 1 ms
+    ./tcpconnlat 0.1       # only show connects longer than 100 us
+    ./tcpconnlat -v        # Show the BPF program