Alexey Ivanov | cc01a9c | 2019-01-16 09:50:46 -0800 | [diff] [blame] | 1 | #!/usr/bin/python |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 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 | { |
Hengqi Chen | 89c96a8 | 2021-05-13 21:46:16 +0800 | [diff] [blame] | 76 | u64 pid_tgid = bpf_get_current_pid_tgid(); |
| 77 | u32 pid = pid_tgid >> 32; |
| 78 | u32 tid = (u32)pid_tgid; |
| 79 | |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 80 | if (FILTER_PID) |
| 81 | return 0; |
| 82 | u64 ts = bpf_ktime_get_ns(); |
Hengqi Chen | 89c96a8 | 2021-05-13 21:46:16 +0800 | [diff] [blame] | 83 | start.update(&tid, &ts); |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 84 | return 0; |
| 85 | } |
| 86 | |
Andrea Righi | d3c32b1 | 2019-02-16 20:52:35 +0100 | [diff] [blame] | 87 | EXT4_TRACE_READ_CODE |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 88 | |
| 89 | static int trace_return(struct pt_regs *ctx, const char *op) |
| 90 | { |
| 91 | u64 *tsp; |
Hengqi Chen | 89c96a8 | 2021-05-13 21:46:16 +0800 | [diff] [blame] | 92 | u64 pid_tgid = bpf_get_current_pid_tgid(); |
| 93 | u32 pid = pid_tgid >> 32; |
| 94 | u32 tid = (u32)pid_tgid; |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 95 | |
| 96 | // fetch timestamp and calculate delta |
Hengqi Chen | 89c96a8 | 2021-05-13 21:46:16 +0800 | [diff] [blame] | 97 | tsp = start.lookup(&tid); |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 98 | if (tsp == 0) { |
| 99 | return 0; // missed start or filtered |
| 100 | } |
olsajiri | fe26ca9 | 2018-09-02 22:57:13 +0200 | [diff] [blame] | 101 | u64 delta = bpf_ktime_get_ns() - *tsp; |
Hengqi Chen | 89c96a8 | 2021-05-13 21:46:16 +0800 | [diff] [blame] | 102 | start.delete(&tid); |
olsajiri | fe26ca9 | 2018-09-02 22:57:13 +0200 | [diff] [blame] | 103 | |
| 104 | // Skip entries with backwards time: temp workaround for #728 |
| 105 | if ((s64) delta < 0) |
| 106 | return 0; |
| 107 | |
| 108 | delta /= FACTOR; |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 109 | |
| 110 | // store as histogram |
| 111 | dist_key_t key = {.slot = bpf_log2l(delta)}; |
| 112 | __builtin_memcpy(&key.op, op, sizeof(key.op)); |
zcy | 80242fb | 2021-07-02 00:12:32 +0800 | [diff] [blame] | 113 | dist.atomic_increment(key); |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 114 | |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 115 | return 0; |
| 116 | } |
| 117 | |
| 118 | int trace_read_return(struct pt_regs *ctx) |
| 119 | { |
| 120 | char *op = "read"; |
| 121 | return trace_return(ctx, op); |
| 122 | } |
| 123 | |
| 124 | int trace_write_return(struct pt_regs *ctx) |
| 125 | { |
| 126 | char *op = "write"; |
| 127 | return trace_return(ctx, op); |
| 128 | } |
| 129 | |
| 130 | int trace_open_return(struct pt_regs *ctx) |
| 131 | { |
| 132 | char *op = "open"; |
| 133 | return trace_return(ctx, op); |
| 134 | } |
| 135 | |
| 136 | int trace_fsync_return(struct pt_regs *ctx) |
| 137 | { |
| 138 | char *op = "fsync"; |
| 139 | return trace_return(ctx, op); |
| 140 | } |
| 141 | """ |
| 142 | |
Andrea Righi | d3c32b1 | 2019-02-16 20:52:35 +0100 | [diff] [blame] | 143 | # Starting from Linux 4.10 ext4_file_operations.read_iter has been changed from |
| 144 | # using generic_file_read_iter() to its own ext4_file_read_iter(). |
| 145 | # |
| 146 | # To detect the proper function to trace check if ext4_file_read_iter() is |
| 147 | # defined in /proc/kallsyms, if it's defined attach to that function, otherwise |
| 148 | # use generic_file_read_iter() and inside the trace hook filter on ext4 read |
| 149 | # events (checking if file->f_op == ext4_file_operations). |
| 150 | if BPF.get_kprobe_functions(b'ext4_file_read_iter'): |
| 151 | ext4_read_fn = 'ext4_file_read_iter' |
| 152 | ext4_trace_read_fn = 'trace_entry' |
| 153 | ext4_trace_read_code = '' |
| 154 | else: |
| 155 | ext4_read_fn = 'generic_file_read_iter' |
| 156 | ext4_trace_read_fn = 'trace_read_entry' |
| 157 | ext4_file_ops_addr = '' |
| 158 | with open(kallsyms) as syms: |
| 159 | for line in syms: |
| 160 | (addr, size, name) = line.rstrip().split(" ", 2) |
| 161 | name = name.split("\t")[0] |
| 162 | if name == "ext4_file_operations": |
| 163 | ext4_file_ops_addr = "0x" + addr |
| 164 | break |
| 165 | if ext4_file_ops_addr == '': |
| 166 | print("ERROR: no ext4_file_operations in /proc/kallsyms. Exiting.") |
| 167 | print("HINT: the kernel should be built with CONFIG_KALLSYMS_ALL.") |
| 168 | exit() |
| 169 | ext4_trace_read_code = """ |
| 170 | int trace_read_entry(struct pt_regs *ctx, struct kiocb *iocb) |
| 171 | { |
Hengqi Chen | 89c96a8 | 2021-05-13 21:46:16 +0800 | [diff] [blame] | 172 | u64 pid_tgid = bpf_get_current_pid_tgid(); |
| 173 | u32 pid = pid_tgid >> 32; |
| 174 | u32 tid = (u32)pid_tgid; |
| 175 | |
Andrea Righi | d3c32b1 | 2019-02-16 20:52:35 +0100 | [diff] [blame] | 176 | if (FILTER_PID) |
| 177 | return 0; |
| 178 | |
| 179 | // ext4 filter on file->f_op == ext4_file_operations |
| 180 | struct file *fp = iocb->ki_filp; |
| 181 | if ((u64)fp->f_op != %s) |
| 182 | return 0; |
| 183 | |
| 184 | u64 ts = bpf_ktime_get_ns(); |
Hengqi Chen | 89c96a8 | 2021-05-13 21:46:16 +0800 | [diff] [blame] | 185 | start.update(&tid, &ts); |
Andrea Righi | d3c32b1 | 2019-02-16 20:52:35 +0100 | [diff] [blame] | 186 | return 0; |
| 187 | }""" % ext4_file_ops_addr |
| 188 | |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 189 | # code replacements |
Andrea Righi | d3c32b1 | 2019-02-16 20:52:35 +0100 | [diff] [blame] | 190 | bpf_text = bpf_text.replace('EXT4_TRACE_READ_CODE', ext4_trace_read_code) |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 191 | bpf_text = bpf_text.replace('FACTOR', str(factor)) |
| 192 | if args.pid: |
| 193 | bpf_text = bpf_text.replace('FILTER_PID', 'pid != %s' % pid) |
| 194 | else: |
| 195 | bpf_text = bpf_text.replace('FILTER_PID', '0') |
Nathan Scott | cf0792f | 2018-02-02 16:56:50 +1100 | [diff] [blame] | 196 | if debug or args.ebpf: |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 197 | print(bpf_text) |
Nathan Scott | cf0792f | 2018-02-02 16:56:50 +1100 | [diff] [blame] | 198 | if args.ebpf: |
| 199 | exit() |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 200 | |
| 201 | # load BPF program |
| 202 | b = BPF(text=bpf_text) |
| 203 | |
Andrea Righi | d3c32b1 | 2019-02-16 20:52:35 +0100 | [diff] [blame] | 204 | b.attach_kprobe(event=ext4_read_fn, fn_name=ext4_trace_read_fn) |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 205 | b.attach_kprobe(event="ext4_file_write_iter", fn_name="trace_entry") |
| 206 | b.attach_kprobe(event="ext4_file_open", fn_name="trace_entry") |
| 207 | b.attach_kprobe(event="ext4_sync_file", fn_name="trace_entry") |
Andrea Righi | d3c32b1 | 2019-02-16 20:52:35 +0100 | [diff] [blame] | 208 | b.attach_kretprobe(event=ext4_read_fn, fn_name='trace_read_return') |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 209 | b.attach_kretprobe(event="ext4_file_write_iter", fn_name="trace_write_return") |
| 210 | b.attach_kretprobe(event="ext4_file_open", fn_name="trace_open_return") |
| 211 | b.attach_kretprobe(event="ext4_sync_file", fn_name="trace_fsync_return") |
| 212 | |
| 213 | print("Tracing ext4 operation latency... Hit Ctrl-C to end.") |
| 214 | |
| 215 | # output |
| 216 | exiting = 0 |
| 217 | dist = b.get_table("dist") |
| 218 | while (1): |
| 219 | try: |
| 220 | if args.interval: |
| 221 | sleep(int(args.interval)) |
| 222 | else: |
| 223 | sleep(99999999) |
| 224 | except KeyboardInterrupt: |
| 225 | exiting = 1 |
| 226 | |
| 227 | print() |
| 228 | if args.interval and (not args.notimestamp): |
| 229 | print(strftime("%H:%M:%S:")) |
| 230 | |
Rafael F | 78948e4 | 2017-03-26 14:54:25 +0200 | [diff] [blame] | 231 | dist.print_log2_hist(label, "operation", section_print_fn=bytes.decode) |
Brendan Gregg | 1dcedc4 | 2016-02-12 02:29:08 -0800 | [diff] [blame] | 232 | dist.clear() |
| 233 | |
| 234 | countdown -= 1 |
| 235 | if exiting or countdown == 0: |
| 236 | exit() |