Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 1 | #!/usr/bin/python |
| 2 | # @lint-avoid-python-3-compatibility-imports |
| 3 | # |
| 4 | # tcpconnlat Trace TCP active connection latency (connect). |
| 5 | # For Linux, uses BCC, eBPF. Embedded C. |
| 6 | # |
| 7 | # USAGE: tcpconnlat [-h] [-t] [-p PID] |
| 8 | # |
| 9 | # This uses dynamic tracing of kernel functions, and will need to be updated |
| 10 | # to match kernel changes. |
| 11 | # |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 12 | # Copyright 2016 Netflix, Inc. |
| 13 | # Licensed under the Apache License, Version 2.0 (the "License") |
| 14 | # |
| 15 | # 19-Feb-2016 Brendan Gregg Created this. |
| 16 | |
| 17 | from __future__ import print_function |
| 18 | from bcc import BPF |
Mark Drayton | 11de298 | 2016-06-26 21:14:44 +0100 | [diff] [blame] | 19 | from socket import inet_ntop, AF_INET, AF_INET6 |
| 20 | from struct import pack |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 21 | import argparse |
| 22 | import ctypes as ct |
| 23 | |
dpayne | fc50799 | 2018-01-18 14:09:28 -0800 | [diff] [blame] | 24 | # arg validation |
| 25 | def positive_float(val): |
| 26 | try: |
| 27 | ival = float(val) |
| 28 | except ValueError: |
| 29 | raise argparse.ArgumentTypeError("must be a float") |
| 30 | |
| 31 | if ival < 0: |
| 32 | raise argparse.ArgumentTypeError("must be positive") |
| 33 | return ival |
| 34 | |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 35 | # arguments |
| 36 | examples = """examples: |
| 37 | ./tcpconnlat # trace all TCP connect()s |
dpayne | fc50799 | 2018-01-18 14:09:28 -0800 | [diff] [blame] | 38 | ./tcpconnlat 1 # trace connection latency slower than 1 ms |
| 39 | ./tcpconnlat 0.1 # trace connection latency slower than 100 us |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 40 | ./tcpconnlat -t # include timestamps |
| 41 | ./tcpconnlat -p 181 # only trace PID 181 |
| 42 | """ |
| 43 | parser = argparse.ArgumentParser( |
| 44 | description="Trace TCP connects and show connection latency", |
| 45 | formatter_class=argparse.RawDescriptionHelpFormatter, |
| 46 | epilog=examples) |
| 47 | parser.add_argument("-t", "--timestamp", action="store_true", |
| 48 | help="include timestamp on output") |
| 49 | parser.add_argument("-p", "--pid", |
| 50 | help="trace this PID only") |
dpayne | fc50799 | 2018-01-18 14:09:28 -0800 | [diff] [blame] | 51 | parser.add_argument("duration_ms", nargs="?", default=0, |
| 52 | type=positive_float, |
| 53 | help="minimum duration to trace (ms)") |
dpayne | 3aed4fb | 2018-01-17 13:56:49 -0800 | [diff] [blame] | 54 | parser.add_argument("-v", "--verbose", action="store_true", |
| 55 | help="print the BPF program for debugging purposes") |
Nathan Scott | cf0792f | 2018-02-02 16:56:50 +1100 | [diff] [blame] | 56 | parser.add_argument("--ebpf", action="store_true", |
| 57 | help=argparse.SUPPRESS) |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 58 | args = parser.parse_args() |
dpayne | 3aed4fb | 2018-01-17 13:56:49 -0800 | [diff] [blame] | 59 | |
dpayne | fc50799 | 2018-01-18 14:09:28 -0800 | [diff] [blame] | 60 | if args.duration_ms: |
| 61 | # support fractions but round to nearest microsecond |
| 62 | duration_us = int(args.duration_ms * 1000) |
dpayne | 3aed4fb | 2018-01-17 13:56:49 -0800 | [diff] [blame] | 63 | else: |
| 64 | duration_us = 0 # default is show all |
| 65 | |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 66 | debug = 0 |
| 67 | |
| 68 | # define BPF program |
| 69 | bpf_text = """ |
| 70 | #include <uapi/linux/ptrace.h> |
| 71 | #include <net/sock.h> |
Mark Drayton | 11de298 | 2016-06-26 21:14:44 +0100 | [diff] [blame] | 72 | #include <net/tcp_states.h> |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 73 | #include <bcc/proto.h> |
| 74 | |
| 75 | struct info_t { |
| 76 | u64 ts; |
Joe Yin | 44c28bf | 2018-06-27 23:34:59 +0800 | [diff] [blame] | 77 | u32 pid; |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 78 | char task[TASK_COMM_LEN]; |
| 79 | }; |
| 80 | BPF_HASH(start, struct sock *, struct info_t); |
| 81 | |
| 82 | // separate data structs for ipv4 and ipv6 |
| 83 | struct ipv4_data_t { |
| 84 | // XXX: switch some to u32's when supported |
| 85 | u64 ts_us; |
Joe Yin | 44c28bf | 2018-06-27 23:34:59 +0800 | [diff] [blame] | 86 | u32 pid; |
| 87 | u32 saddr; |
| 88 | u32 daddr; |
Mark Drayton | 11de298 | 2016-06-26 21:14:44 +0100 | [diff] [blame] | 89 | u64 ip; |
Joe Yin | 44c28bf | 2018-06-27 23:34:59 +0800 | [diff] [blame] | 90 | u16 dport; |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 91 | u64 delta_us; |
| 92 | char task[TASK_COMM_LEN]; |
| 93 | }; |
| 94 | BPF_PERF_OUTPUT(ipv4_events); |
| 95 | |
| 96 | struct ipv6_data_t { |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 97 | u64 ts_us; |
Joe Yin | 44c28bf | 2018-06-27 23:34:59 +0800 | [diff] [blame] | 98 | u32 pid; |
Mark Drayton | 11de298 | 2016-06-26 21:14:44 +0100 | [diff] [blame] | 99 | unsigned __int128 saddr; |
| 100 | unsigned __int128 daddr; |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 101 | u64 ip; |
Joe Yin | 44c28bf | 2018-06-27 23:34:59 +0800 | [diff] [blame] | 102 | u16 dport; |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 103 | u64 delta_us; |
| 104 | char task[TASK_COMM_LEN]; |
| 105 | }; |
| 106 | BPF_PERF_OUTPUT(ipv6_events); |
| 107 | |
| 108 | int trace_connect(struct pt_regs *ctx, struct sock *sk) |
| 109 | { |
| 110 | u32 pid = bpf_get_current_pid_tgid(); |
| 111 | FILTER |
| 112 | struct info_t info = {.pid = pid}; |
| 113 | info.ts = bpf_ktime_get_ns(); |
| 114 | bpf_get_current_comm(&info.task, sizeof(info.task)); |
| 115 | start.update(&sk, &info); |
| 116 | return 0; |
| 117 | }; |
| 118 | |
| 119 | // See tcp_v4_do_rcv() and tcp_v6_do_rcv(). So TCP_ESTBALISHED and TCP_LISTEN |
| 120 | // are fast path and processed elsewhere, and leftovers are processed by |
Brendan Gregg | 2482c1c | 2016-02-19 16:14:01 -0800 | [diff] [blame] | 121 | // tcp_rcv_state_process(). We can trace this for handshake completion. |
| 122 | // This should all be switched to static tracepoints when available. |
Paul Chaignon | 7e1cf0a | 2017-08-06 11:14:12 +0200 | [diff] [blame] | 123 | int trace_tcp_rcv_state_process(struct pt_regs *ctx, struct sock *skp) |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 124 | { |
Brendan Gregg | 4db6d44 | 2016-02-19 16:56:47 -0800 | [diff] [blame] | 125 | // will be in TCP_SYN_SENT for handshake |
Paul Chaignon | 7e1cf0a | 2017-08-06 11:14:12 +0200 | [diff] [blame] | 126 | if (skp->__sk_common.skc_state != TCP_SYN_SENT) |
Brendan Gregg | 4db6d44 | 2016-02-19 16:56:47 -0800 | [diff] [blame] | 127 | return 0; |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 128 | |
| 129 | // check start and calculate delta |
Paul Chaignon | 7e1cf0a | 2017-08-06 11:14:12 +0200 | [diff] [blame] | 130 | struct info_t *infop = start.lookup(&skp); |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 131 | if (infop == 0) { |
| 132 | return 0; // missed entry or filtered |
| 133 | } |
dpayne | 3aed4fb | 2018-01-17 13:56:49 -0800 | [diff] [blame] | 134 | |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 135 | u64 ts = infop->ts; |
| 136 | u64 now = bpf_ktime_get_ns(); |
| 137 | |
dpayne | 3aed4fb | 2018-01-17 13:56:49 -0800 | [diff] [blame] | 138 | u64 delta_us = (now - ts) / 1000ul; |
| 139 | |
| 140 | #ifdef MIN_LATENCY |
| 141 | if ( delta_us < DURATION_US ) { |
| 142 | return 0; // connect latency is below latency filter minimum |
| 143 | } |
| 144 | #endif |
| 145 | |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 146 | // pull in details |
| 147 | u16 family = 0, dport = 0; |
Paul Chaignon | 7e1cf0a | 2017-08-06 11:14:12 +0200 | [diff] [blame] | 148 | family = skp->__sk_common.skc_family; |
| 149 | dport = skp->__sk_common.skc_dport; |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 150 | |
| 151 | // emit to appropriate data path |
| 152 | if (family == AF_INET) { |
| 153 | struct ipv4_data_t data4 = {.pid = infop->pid, .ip = 4}; |
| 154 | data4.ts_us = now / 1000; |
Paul Chaignon | 7e1cf0a | 2017-08-06 11:14:12 +0200 | [diff] [blame] | 155 | data4.saddr = skp->__sk_common.skc_rcv_saddr; |
| 156 | data4.daddr = skp->__sk_common.skc_daddr; |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 157 | data4.dport = ntohs(dport); |
dpayne | ce0cf92 | 2018-01-17 14:02:29 -0800 | [diff] [blame] | 158 | data4.delta_us = delta_us; |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 159 | __builtin_memcpy(&data4.task, infop->task, sizeof(data4.task)); |
| 160 | ipv4_events.perf_submit(ctx, &data4, sizeof(data4)); |
| 161 | |
| 162 | } else /* AF_INET6 */ { |
| 163 | struct ipv6_data_t data6 = {.pid = infop->pid, .ip = 6}; |
| 164 | data6.ts_us = now / 1000; |
Mark Drayton | 11de298 | 2016-06-26 21:14:44 +0100 | [diff] [blame] | 165 | bpf_probe_read(&data6.saddr, sizeof(data6.saddr), |
Paul Chaignon | 7e1cf0a | 2017-08-06 11:14:12 +0200 | [diff] [blame] | 166 | skp->__sk_common.skc_v6_rcv_saddr.in6_u.u6_addr32); |
Mark Drayton | 11de298 | 2016-06-26 21:14:44 +0100 | [diff] [blame] | 167 | bpf_probe_read(&data6.daddr, sizeof(data6.daddr), |
Paul Chaignon | 7e1cf0a | 2017-08-06 11:14:12 +0200 | [diff] [blame] | 168 | skp->__sk_common.skc_v6_daddr.in6_u.u6_addr32); |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 169 | data6.dport = ntohs(dport); |
dpayne | ce0cf92 | 2018-01-17 14:02:29 -0800 | [diff] [blame] | 170 | data6.delta_us = delta_us; |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 171 | __builtin_memcpy(&data6.task, infop->task, sizeof(data6.task)); |
| 172 | ipv6_events.perf_submit(ctx, &data6, sizeof(data6)); |
| 173 | } |
| 174 | |
Paul Chaignon | 7e1cf0a | 2017-08-06 11:14:12 +0200 | [diff] [blame] | 175 | start.delete(&skp); |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 176 | |
| 177 | return 0; |
| 178 | } |
| 179 | """ |
| 180 | |
dpayne | 3aed4fb | 2018-01-17 13:56:49 -0800 | [diff] [blame] | 181 | if duration_us > 0: |
| 182 | bpf_text = "#define MIN_LATENCY\n" + bpf_text |
| 183 | bpf_text = bpf_text.replace('DURATION_US', str(duration_us)) |
| 184 | |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 185 | # code substitutions |
| 186 | if args.pid: |
| 187 | bpf_text = bpf_text.replace('FILTER', |
| 188 | 'if (pid != %s) { return 0; }' % args.pid) |
| 189 | else: |
| 190 | bpf_text = bpf_text.replace('FILTER', '') |
Nathan Scott | cf0792f | 2018-02-02 16:56:50 +1100 | [diff] [blame] | 191 | if debug or args.verbose or args.ebpf: |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 192 | print(bpf_text) |
Nathan Scott | cf0792f | 2018-02-02 16:56:50 +1100 | [diff] [blame] | 193 | if args.ebpf: |
| 194 | exit() |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 195 | |
| 196 | # initialize BPF |
| 197 | b = BPF(text=bpf_text) |
| 198 | b.attach_kprobe(event="tcp_v4_connect", fn_name="trace_connect") |
| 199 | b.attach_kprobe(event="tcp_v6_connect", fn_name="trace_connect") |
| 200 | b.attach_kprobe(event="tcp_rcv_state_process", |
| 201 | fn_name="trace_tcp_rcv_state_process") |
| 202 | |
| 203 | # event data |
| 204 | TASK_COMM_LEN = 16 # linux/sched.h |
Mark Drayton | 11de298 | 2016-06-26 21:14:44 +0100 | [diff] [blame] | 205 | |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 206 | class Data_ipv4(ct.Structure): |
| 207 | _fields_ = [ |
| 208 | ("ts_us", ct.c_ulonglong), |
Joe Yin | 44c28bf | 2018-06-27 23:34:59 +0800 | [diff] [blame] | 209 | ("pid", ct.c_uint), |
| 210 | ("saddr", ct.c_uint), |
| 211 | ("daddr", ct.c_uint), |
Mark Drayton | 11de298 | 2016-06-26 21:14:44 +0100 | [diff] [blame] | 212 | ("ip", ct.c_ulonglong), |
Joe Yin | 44c28bf | 2018-06-27 23:34:59 +0800 | [diff] [blame] | 213 | ("dport", ct.c_ushort), |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 214 | ("delta_us", ct.c_ulonglong), |
| 215 | ("task", ct.c_char * TASK_COMM_LEN) |
| 216 | ] |
Mark Drayton | 11de298 | 2016-06-26 21:14:44 +0100 | [diff] [blame] | 217 | |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 218 | class Data_ipv6(ct.Structure): |
| 219 | _fields_ = [ |
| 220 | ("ts_us", ct.c_ulonglong), |
Joe Yin | 44c28bf | 2018-06-27 23:34:59 +0800 | [diff] [blame] | 221 | ("pid", ct.c_uint), |
Mark Drayton | 11de298 | 2016-06-26 21:14:44 +0100 | [diff] [blame] | 222 | ("saddr", (ct.c_ulonglong * 2)), |
| 223 | ("daddr", (ct.c_ulonglong * 2)), |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 224 | ("ip", ct.c_ulonglong), |
Joe Yin | 44c28bf | 2018-06-27 23:34:59 +0800 | [diff] [blame] | 225 | ("dport", ct.c_ushort), |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 226 | ("delta_us", ct.c_ulonglong), |
| 227 | ("task", ct.c_char * TASK_COMM_LEN) |
| 228 | ] |
| 229 | |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 230 | # process event |
| 231 | start_ts = 0 |
Mark Drayton | 11de298 | 2016-06-26 21:14:44 +0100 | [diff] [blame] | 232 | |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 233 | def print_ipv4_event(cpu, data, size): |
| 234 | event = ct.cast(data, ct.POINTER(Data_ipv4)).contents |
| 235 | global start_ts |
| 236 | if args.timestamp: |
| 237 | if start_ts == 0: |
| 238 | start_ts = event.ts_us |
Mark Drayton | 11de298 | 2016-06-26 21:14:44 +0100 | [diff] [blame] | 239 | print("%-9.3f" % ((float(event.ts_us) - start_ts) / 1000000), end="") |
Rafael F | 78948e4 | 2017-03-26 14:54:25 +0200 | [diff] [blame] | 240 | print("%-6d %-12.12s %-2d %-16s %-16s %-5d %.2f" % (event.pid, |
| 241 | event.task.decode(), event.ip, |
| 242 | inet_ntop(AF_INET, pack("I", event.saddr)), |
Mark Drayton | 11de298 | 2016-06-26 21:14:44 +0100 | [diff] [blame] | 243 | inet_ntop(AF_INET, pack("I", event.daddr)), event.dport, |
| 244 | float(event.delta_us) / 1000)) |
| 245 | |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 246 | def print_ipv6_event(cpu, data, size): |
| 247 | event = ct.cast(data, ct.POINTER(Data_ipv6)).contents |
| 248 | global start_ts |
| 249 | if args.timestamp: |
| 250 | if start_ts == 0: |
| 251 | start_ts = event.ts_us |
Mark Drayton | 11de298 | 2016-06-26 21:14:44 +0100 | [diff] [blame] | 252 | print("%-9.3f" % ((float(event.ts_us) - start_ts) / 1000000), end="") |
Rafael F | 78948e4 | 2017-03-26 14:54:25 +0200 | [diff] [blame] | 253 | print("%-6d %-12.12s %-2d %-16s %-16s %-5d %.2f" % (event.pid, |
| 254 | event.task.decode(), event.ip, inet_ntop(AF_INET6, event.saddr), |
Mark Drayton | 11de298 | 2016-06-26 21:14:44 +0100 | [diff] [blame] | 255 | inet_ntop(AF_INET6, event.daddr), event.dport, |
Brendan Gregg | afc9725 | 2016-02-19 16:07:36 -0800 | [diff] [blame] | 256 | float(event.delta_us) / 1000)) |
| 257 | |
| 258 | # header |
| 259 | if args.timestamp: |
| 260 | print("%-9s" % ("TIME(s)"), end="") |
| 261 | print("%-6s %-12s %-2s %-16s %-16s %-5s %s" % ("PID", "COMM", "IP", "SADDR", |
| 262 | "DADDR", "DPORT", "LAT(ms)")) |
| 263 | |
| 264 | # read events |
| 265 | b["ipv4_events"].open_perf_buffer(print_ipv4_event) |
| 266 | b["ipv6_events"].open_perf_buffer(print_ipv6_event) |
| 267 | while 1: |
Teng Qin | dbf0029 | 2018-02-28 21:47:50 -0800 | [diff] [blame] | 268 | b.perf_buffer_poll() |