Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 1 | #!/usr/bin/python |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 2 | # @lint-avoid-python-3-compatibility-imports |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 3 | # |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 4 | # funclatency Time kernel funcitons and print latency as a histogram. |
| 5 | # For Linux, uses BCC, eBPF. |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 6 | # |
| 7 | # USAGE: funclatency [-h] [-p PID] [-i INTERVAL] [-T] [-u] [-m] [-r] pattern |
| 8 | # |
| 9 | # Run "funclatency -h" for full usage. |
| 10 | # |
| 11 | # The pattern is a string with optional '*' wildcards, similar to file globbing. |
| 12 | # If you'd prefer to use regular expressions, use the -r option. Matching |
| 13 | # multiple functions is of limited use, since the output has one histogram for |
| 14 | # everything. Future versions should split the output histogram by the function. |
| 15 | # |
Brendan Gregg | 50bbca4 | 2015-09-25 12:47:53 -0700 | [diff] [blame] | 16 | # Currently nested or recursive functions are not supported properly, and |
| 17 | # timestamps will be overwritten, creating dubious output. Try to match single |
| 18 | # functions, or groups of functions that run at the same stack layer, and |
| 19 | # don't ultimately call each other. |
| 20 | # |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 21 | # Copyright (c) 2015 Brendan Gregg. |
| 22 | # Licensed under the Apache License, Version 2.0 (the "License") |
| 23 | # |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 24 | # 20-Sep-2015 Brendan Gregg Created this. |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 25 | |
| 26 | from __future__ import print_function |
| 27 | from bcc import BPF |
| 28 | from time import sleep, strftime |
| 29 | import argparse |
| 30 | import signal |
| 31 | |
| 32 | # arguments |
| 33 | examples = """examples: |
| 34 | ./funclatency do_sys_open # time the do_sys_open() kenel function |
| 35 | ./funclatency -u vfs_read # time vfs_read(), in microseconds |
| 36 | ./funclatency -m do_nanosleep # time do_nanosleep(), in milliseconds |
| 37 | ./funclatency -mTi 5 vfs_read # output every 5 seconds, with timestamps |
| 38 | ./funclatency -p 181 vfs_read # time process 181 only |
| 39 | ./funclatency 'vfs_fstat*' # time both vfs_fstat() and vfs_fstatat() |
Brendan Gregg | 50bbca4 | 2015-09-25 12:47:53 -0700 | [diff] [blame] | 40 | ./funclatency -F 'vfs_r*' # show one histogram per matched function |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 41 | """ |
| 42 | parser = argparse.ArgumentParser( |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 43 | description="Time kernel funcitons and print latency as a histogram", |
| 44 | formatter_class=argparse.RawDescriptionHelpFormatter, |
| 45 | epilog=examples) |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 46 | parser.add_argument("-p", "--pid", |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 47 | help="trace this PID only") |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 48 | parser.add_argument("-i", "--interval", default=99999999, |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 49 | help="summary interval, seconds") |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 50 | parser.add_argument("-T", "--timestamp", action="store_true", |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 51 | help="include timestamp on output") |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 52 | parser.add_argument("-u", "--microseconds", action="store_true", |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 53 | help="microsecond histogram") |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 54 | parser.add_argument("-m", "--milliseconds", action="store_true", |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 55 | help="millisecond histogram") |
Brendan Gregg | 50bbca4 | 2015-09-25 12:47:53 -0700 | [diff] [blame] | 56 | parser.add_argument("-F", "--function", action="store_true", |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 57 | help="show a separate histogram per function") |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 58 | parser.add_argument("-r", "--regexp", action="store_true", |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 59 | help="use regular expressions. Default is \"*\" wildcards only.") |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 60 | parser.add_argument("pattern", |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 61 | help="search expression for kernel functions") |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 62 | args = parser.parse_args() |
| 63 | pattern = args.pattern |
| 64 | if not args.regexp: |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 65 | pattern = pattern.replace('*', '.*') |
| 66 | pattern = '^' + pattern + '$' |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 67 | debug = 0 |
| 68 | |
| 69 | # define BPF program |
| 70 | bpf_text = """ |
| 71 | #include <uapi/linux/ptrace.h> |
| 72 | #include <linux/blkdev.h> |
| 73 | |
Brendan Gregg | 50bbca4 | 2015-09-25 12:47:53 -0700 | [diff] [blame] | 74 | typedef struct ip_key { |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 75 | u64 ip; |
| 76 | u64 slot; |
Brendan Gregg | 50bbca4 | 2015-09-25 12:47:53 -0700 | [diff] [blame] | 77 | } ip_key_t; |
| 78 | |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 79 | BPF_HASH(start, u32); |
Brendan Gregg | 50bbca4 | 2015-09-25 12:47:53 -0700 | [diff] [blame] | 80 | STORAGE |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 81 | |
| 82 | int trace_func_entry(struct pt_regs *ctx) |
| 83 | { |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 84 | u32 pid = bpf_get_current_pid_tgid(); |
| 85 | u64 ts = bpf_ktime_get_ns(); |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 86 | |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 87 | FILTER |
| 88 | ENTRYSTORE |
| 89 | start.update(&pid, &ts); |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 90 | |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 91 | return 0; |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 92 | } |
| 93 | |
| 94 | int trace_func_return(struct pt_regs *ctx) |
| 95 | { |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 96 | u64 *tsp, delta; |
| 97 | u32 pid = bpf_get_current_pid_tgid(); |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 98 | |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 99 | // calculate delta time |
| 100 | tsp = start.lookup(&pid); |
| 101 | if (tsp == 0) { |
| 102 | return 0; // missed start |
| 103 | } |
| 104 | delta = bpf_ktime_get_ns() - *tsp; |
| 105 | start.delete(&pid); |
| 106 | FACTOR |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 107 | |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 108 | // store as histogram |
| 109 | STORE |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 110 | |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 111 | return 0; |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 112 | } |
| 113 | """ |
Brendan Gregg | 50bbca4 | 2015-09-25 12:47:53 -0700 | [diff] [blame] | 114 | |
| 115 | # code substitutions |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 116 | if args.pid: |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 117 | bpf_text = bpf_text.replace('FILTER', |
| 118 | 'if (pid != %s) { return 0; }' % args.pid) |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 119 | else: |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 120 | bpf_text = bpf_text.replace('FILTER', '') |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 121 | if args.milliseconds: |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 122 | bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000000;') |
| 123 | label = "msecs" |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 124 | elif args.microseconds: |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 125 | bpf_text = bpf_text.replace('FACTOR', 'delta /= 1000;') |
| 126 | label = "usecs" |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 127 | else: |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 128 | bpf_text = bpf_text.replace('FACTOR', '') |
| 129 | label = "nsecs" |
Brendan Gregg | 50bbca4 | 2015-09-25 12:47:53 -0700 | [diff] [blame] | 130 | if args.function: |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 131 | bpf_text = bpf_text.replace('STORAGE', 'BPF_HASH(ipaddr, u32);\n' + |
| 132 | 'BPF_HISTOGRAM(dist, ip_key_t);') |
| 133 | # stash the IP on entry, as on return it's kretprobe_trampoline: |
| 134 | bpf_text = bpf_text.replace('ENTRYSTORE', |
Naveen N. Rao | 4afa96a | 2016-05-03 14:54:21 +0530 | [diff] [blame^] | 135 | 'u64 ip = PT_REGS_IP(ctx); ipaddr.update(&pid, &ip);') |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 136 | bpf_text = bpf_text.replace('STORE', |
| 137 | 'u64 ip, *ipp = ipaddr.lookup(&pid); if (ipp) { ip = *ipp; ' + |
| 138 | 'dist.increment((ip_key_t){ip, bpf_log2l(delta)}); ' + |
| 139 | 'ipaddr.delete(&pid); }') |
Brendan Gregg | 50bbca4 | 2015-09-25 12:47:53 -0700 | [diff] [blame] | 140 | else: |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 141 | bpf_text = bpf_text.replace('STORAGE', 'BPF_HISTOGRAM(dist);') |
| 142 | bpf_text = bpf_text.replace('ENTRYSTORE', '') |
| 143 | bpf_text = bpf_text.replace('STORE', |
| 144 | 'dist.increment(bpf_log2l(delta));') |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 145 | if debug: |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 146 | print(bpf_text) |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 147 | |
| 148 | # signal handler |
| 149 | def signal_ignore(signal, frame): |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 150 | print() |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 151 | |
| 152 | # load BPF program |
| 153 | b = BPF(text=bpf_text) |
| 154 | b.attach_kprobe(event_re=pattern, fn_name="trace_func_entry") |
| 155 | b.attach_kretprobe(event_re=pattern, fn_name="trace_func_return") |
Brendan Gregg | 6b8add0 | 2015-09-25 11:16:33 -0700 | [diff] [blame] | 156 | matched = b.num_open_kprobes() |
| 157 | if matched == 0: |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 158 | print("0 functions matched by \"%s\". Exiting." % args.pattern) |
| 159 | exit() |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 160 | |
| 161 | # header |
Brendan Gregg | 6b8add0 | 2015-09-25 11:16:33 -0700 | [diff] [blame] | 162 | print("Tracing %d functions for \"%s\"... Hit Ctrl-C to end." % |
| 163 | (matched / 2, args.pattern)) |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 164 | |
| 165 | # output |
| 166 | exiting = 0 if args.interval else 1 |
| 167 | dist = b.get_table("dist") |
| 168 | while (1): |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 169 | try: |
| 170 | sleep(int(args.interval)) |
| 171 | except KeyboardInterrupt: |
| 172 | exiting = 1 |
| 173 | # as cleanup can take many seconds, trap Ctrl-C: |
| 174 | signal.signal(signal.SIGINT, signal_ignore) |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 175 | |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 176 | print() |
| 177 | if args.timestamp: |
| 178 | print("%-8s\n" % strftime("%H:%M:%S"), end="") |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 179 | |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 180 | if args.function: |
| 181 | dist.print_log2_hist(label, "Function", BPF.ksym) |
| 182 | else: |
| 183 | dist.print_log2_hist(label) |
| 184 | dist.clear() |
Brendan Gregg | 74016c3 | 2015-09-21 15:49:21 -0700 | [diff] [blame] | 185 | |
Alexei Starovoitov | bdf0773 | 2016-01-14 10:09:20 -0800 | [diff] [blame] | 186 | if exiting: |
| 187 | print("Detaching...") |
| 188 | exit() |