Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 1 | #!/usr/bin/python |
| 2 | # @lint-avoid-python-3-compatibility-imports |
| 3 | # |
| 4 | # ext4dist Summarize ext4 operation latency. |
| 5 | # For Linux, uses BCC, eBPF. |
| 6 | # |
| 7 | # USAGE: ext4dist [-h] [-T] [-m] [-p PID] [interval] [count] |
| 8 | # |
| 9 | # Copyright 2016 Netflix, Inc. |
| 10 | # Licensed under the Apache License, Version 2.0 (the "License") |
| 11 | # |
| 12 | # 12-Feb-2016 Brendan Gregg Created this. |
| 13 | |
| 14 | from __future__ import print_function |
| 15 | from bcc import BPF |
| 16 | from time import sleep, strftime |
| 17 | import argparse |
| 18 | |
| 19 | # symbols |
| 20 | kallsyms = "/proc/kallsyms" |
| 21 | |
| 22 | # arguments |
| 23 | examples = """examples: |
| 24 | ./ext4dist # show operation latency as a histogram |
| 25 | ./ext4dist -p 181 # trace PID 181 only |
| 26 | ./ext4dist 1 10 # print 1 second summaries, 10 times |
| 27 | ./ext4dist -m 5 # 5s summaries, milliseconds |
| 28 | """ |
| 29 | parser = argparse.ArgumentParser( |
| 30 | description="Summarize ext4 operation latency", |
| 31 | formatter_class=argparse.RawDescriptionHelpFormatter, |
| 32 | epilog=examples) |
| 33 | parser.add_argument("-T", "--notimestamp", action="store_true", |
| 34 | help="don't include timestamp on interval output") |
| 35 | parser.add_argument("-m", "--milliseconds", action="store_true", |
| 36 | help="output in milliseconds") |
| 37 | parser.add_argument("-p", "--pid", |
| 38 | help="trace this PID only") |
| 39 | parser.add_argument("interval", nargs="?", |
| 40 | help="output interval, in seconds") |
| 41 | parser.add_argument("count", nargs="?", default=99999999, |
| 42 | help="number of outputs") |
Nathan Scott | cf0792f | 2018-02-02 16:56:50 +1100 | [diff] [blame] | 43 | parser.add_argument("--ebpf", action="store_true", |
| 44 | help=argparse.SUPPRESS) |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 45 | args = parser.parse_args() |
| 46 | pid = args.pid |
| 47 | countdown = int(args.count) |
| 48 | if args.milliseconds: |
| 49 | factor = 1000000 |
| 50 | label = "msecs" |
| 51 | else: |
| 52 | factor = 1000 |
| 53 | label = "usecs" |
| 54 | if args.interval and int(args.interval) == 0: |
| 55 | print("ERROR: interval 0. Exiting.") |
| 56 | exit() |
| 57 | debug = 0 |
| 58 | |
| 59 | # define BPF program |
| 60 | bpf_text = """ |
| 61 | #include <uapi/linux/ptrace.h> |
| 62 | #include <linux/fs.h> |
| 63 | #include <linux/sched.h> |
| 64 | |
| 65 | #define OP_NAME_LEN 8 |
| 66 | typedef struct dist_key { |
| 67 | char op[OP_NAME_LEN]; |
| 68 | u64 slot; |
| 69 | } dist_key_t; |
| 70 | BPF_HASH(start, u32); |
| 71 | BPF_HISTOGRAM(dist, dist_key_t); |
| 72 | |
| 73 | // time operation |
| 74 | int trace_entry(struct pt_regs *ctx) |
| 75 | { |
| 76 | u32 pid = bpf_get_current_pid_tgid(); |
| 77 | if (FILTER_PID) |
| 78 | return 0; |
| 79 | u64 ts = bpf_ktime_get_ns(); |
| 80 | start.update(&pid, &ts); |
| 81 | return 0; |
| 82 | } |
| 83 | |
| 84 | // The current ext4 (Linux 4.5) uses generic_file_read_iter(), instead of it's |
| 85 | // own function, for reads. So we need to trace that and then filter on ext4, |
| 86 | // which I do by checking file->f_op. |
| 87 | int trace_read_entry(struct pt_regs *ctx, struct kiocb *iocb) |
| 88 | { |
| 89 | u32 pid = bpf_get_current_pid_tgid(); |
| 90 | if (FILTER_PID) |
| 91 | return 0; |
| 92 | |
| 93 | // ext4 filter on file->f_op == ext4_file_operations |
| 94 | struct file *fp = iocb->ki_filp; |
| 95 | if ((u64)fp->f_op != EXT4_FILE_OPERATIONS) |
| 96 | return 0; |
| 97 | |
| 98 | u64 ts = bpf_ktime_get_ns(); |
| 99 | start.update(&pid, &ts); |
| 100 | return 0; |
| 101 | } |
| 102 | |
| 103 | static int trace_return(struct pt_regs *ctx, const char *op) |
| 104 | { |
| 105 | u64 *tsp; |
| 106 | u32 pid = bpf_get_current_pid_tgid(); |
| 107 | |
| 108 | // fetch timestamp and calculate delta |
| 109 | tsp = start.lookup(&pid); |
| 110 | if (tsp == 0) { |
| 111 | return 0; // missed start or filtered |
| 112 | } |
| 113 | u64 delta = (bpf_ktime_get_ns() - *tsp) / FACTOR; |
| 114 | |
| 115 | // store as histogram |
| 116 | dist_key_t key = {.slot = bpf_log2l(delta)}; |
| 117 | __builtin_memcpy(&key.op, op, sizeof(key.op)); |
| 118 | dist.increment(key); |
| 119 | |
| 120 | start.delete(&pid); |
| 121 | return 0; |
| 122 | } |
| 123 | |
| 124 | int trace_read_return(struct pt_regs *ctx) |
| 125 | { |
| 126 | char *op = "read"; |
| 127 | return trace_return(ctx, op); |
| 128 | } |
| 129 | |
| 130 | int trace_write_return(struct pt_regs *ctx) |
| 131 | { |
| 132 | char *op = "write"; |
| 133 | return trace_return(ctx, op); |
| 134 | } |
| 135 | |
| 136 | int trace_open_return(struct pt_regs *ctx) |
| 137 | { |
| 138 | char *op = "open"; |
| 139 | return trace_return(ctx, op); |
| 140 | } |
| 141 | |
| 142 | int trace_fsync_return(struct pt_regs *ctx) |
| 143 | { |
| 144 | char *op = "fsync"; |
| 145 | return trace_return(ctx, op); |
| 146 | } |
| 147 | """ |
| 148 | |
| 149 | # code replacements |
| 150 | with open(kallsyms) as syms: |
| 151 | ops = '' |
| 152 | for line in syms: |
| 153 | (addr, size, name) = line.rstrip().split(" ", 2) |
ygrek | a5e2ce5 | 2016-06-27 12:54:55 -0700 | [diff] [blame] | 154 | name = name.split("\t")[0] |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 155 | if name == "ext4_file_operations": |
| 156 | ops = "0x" + addr |
| 157 | break |
| 158 | if ops == '': |
| 159 | print("ERROR: no ext4_file_operations in /proc/kallsyms. Exiting.") |
Aleksander Alekseev | 4a950bf | 2017-10-23 21:22:36 +0300 | [diff] [blame] | 160 | print("HINT: the kernel should be built with CONFIG_KALLSYMS_ALL.") |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 161 | exit() |
| 162 | bpf_text = bpf_text.replace('EXT4_FILE_OPERATIONS', ops) |
| 163 | bpf_text = bpf_text.replace('FACTOR', str(factor)) |
| 164 | if args.pid: |
| 165 | bpf_text = bpf_text.replace('FILTER_PID', 'pid != %s' % pid) |
| 166 | else: |
| 167 | bpf_text = bpf_text.replace('FILTER_PID', '0') |
Nathan Scott | cf0792f | 2018-02-02 16:56:50 +1100 | [diff] [blame] | 168 | if debug or args.ebpf: |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 169 | print(bpf_text) |
Nathan Scott | cf0792f | 2018-02-02 16:56:50 +1100 | [diff] [blame] | 170 | if args.ebpf: |
| 171 | exit() |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 172 | |
| 173 | # load BPF program |
| 174 | b = BPF(text=bpf_text) |
| 175 | |
| 176 | # Common file functions. See earlier comment about generic_file_read_iter(). |
Joe Yin | c325d6d | 2018-06-27 10:12:17 +0800 | [diff] [blame] | 177 | # Comment by Joe Yin |
| 178 | # From Linux 4.10, the function .read_iter at the ext4_file_operations has |
| 179 | # changed to ext4_file_read_iter. |
| 180 | # So, I add get_kprobe_functions('ext4_file_read_iter'),it will first to attach ext4_file_read_iter, |
| 181 | # if fails and will attach the generic_file_read_iter which used to pre-4.10. |
| 182 | |
| 183 | if BPF.get_kprobe_functions('ext4_file_read_iter'): |
| 184 | b.attach_kprobe(event="ext4_file_read_iter", fn_name="trace_entry") |
| 185 | else: |
| 186 | b.attach_kprobe(event="generic_file_read_iter", fn_name="trace_read_entry") |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 187 | b.attach_kprobe(event="ext4_file_write_iter", fn_name="trace_entry") |
| 188 | b.attach_kprobe(event="ext4_file_open", fn_name="trace_entry") |
| 189 | b.attach_kprobe(event="ext4_sync_file", fn_name="trace_entry") |
| 190 | b.attach_kretprobe(event="generic_file_read_iter", fn_name="trace_read_return") |
| 191 | b.attach_kretprobe(event="ext4_file_write_iter", fn_name="trace_write_return") |
| 192 | b.attach_kretprobe(event="ext4_file_open", fn_name="trace_open_return") |
| 193 | b.attach_kretprobe(event="ext4_sync_file", fn_name="trace_fsync_return") |
| 194 | |
| 195 | print("Tracing ext4 operation latency... Hit Ctrl-C to end.") |
| 196 | |
| 197 | # output |
| 198 | exiting = 0 |
| 199 | dist = b.get_table("dist") |
| 200 | while (1): |
| 201 | try: |
| 202 | if args.interval: |
| 203 | sleep(int(args.interval)) |
| 204 | else: |
| 205 | sleep(99999999) |
| 206 | except KeyboardInterrupt: |
| 207 | exiting = 1 |
| 208 | |
| 209 | print() |
| 210 | if args.interval and (not args.notimestamp): |
| 211 | print(strftime("%H:%M:%S:")) |
| 212 | |
Rafael F | 78948e4 | 2017-03-26 14:54:25 +0200 | [diff] [blame] | 213 | dist.print_log2_hist(label, "operation", section_print_fn=bytes.decode) |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 214 | dist.clear() |
| 215 | |
| 216 | countdown -= 1 |
| 217 | if exiting or countdown == 0: |
| 218 | exit() |