Alexey Ivanov | cc01a9c | 2019-01-16 09:50:46 -0800 | [diff] [blame] | 1 | #!/usr/bin/python |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 2 | # @lint-avoid-python-3-compatibility-imports |
| 3 | # |
| 4 | # zfsslower Trace slow ZFS operations. |
| 5 | # For Linux, uses BCC, eBPF. |
| 6 | # |
| 7 | # USAGE: zfsslower [-h] [-j] [-p PID] [min_ms] |
| 8 | # |
| 9 | # This script traces common ZFS file operations: reads, writes, opens, and |
| 10 | # syncs. It measures the time spent in these operations, and prints details |
| 11 | # for each that exceeded a threshold. |
| 12 | # |
| 13 | # WARNING: This adds low-overhead instrumentation to these ZFS operations, |
| 14 | # including reads and writes from the file system cache. Such reads and writes |
| 15 | # can be very frequent (depending on the workload; eg, 1M/sec), at which |
| 16 | # point the overhead of this tool (even if it prints no "slower" events) can |
| 17 | # begin to become significant. |
| 18 | # |
| 19 | # This works by using kernel dynamic tracing of the ZPL interface, and will |
| 20 | # need updates to match any changes to this interface. |
| 21 | # |
| 22 | # By default, a minimum millisecond threshold of 10 is used. |
| 23 | # |
| 24 | # Copyright 2016 Netflix, Inc. |
| 25 | # Licensed under the Apache License, Version 2.0 (the "License") |
| 26 | # |
| 27 | # 14-Feb-2016 Brendan Gregg Created this. |
Dina Goldshtein | c8b9ae3 | 2016-10-18 03:01:05 +0300 | [diff] [blame] | 28 | # 16-Oct-2016 Dina Goldshtein -p to filter by process ID. |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 29 | |
| 30 | from __future__ import print_function |
| 31 | from bcc import BPF |
| 32 | import argparse |
| 33 | from time import strftime |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 34 | |
| 35 | # arguments |
| 36 | examples = """examples: |
| 37 | ./zfsslower # trace operations slower than 10 ms (default) |
| 38 | ./zfsslower 1 # trace operations slower than 1 ms |
| 39 | ./zfsslower -j 1 # ... 1 ms, parsable output (csv) |
| 40 | ./zfsslower 0 # trace all operations (warning: verbose) |
| 41 | ./zfsslower -p 185 # trace PID 185 only |
| 42 | """ |
| 43 | parser = argparse.ArgumentParser( |
| 44 | description="Trace common ZFS file operations slower than a threshold", |
| 45 | formatter_class=argparse.RawDescriptionHelpFormatter, |
| 46 | epilog=examples) |
| 47 | parser.add_argument("-j", "--csv", action="store_true", |
| 48 | help="just print fields: comma-separated values") |
| 49 | parser.add_argument("-p", "--pid", |
| 50 | help="trace this PID only") |
| 51 | parser.add_argument("min_ms", nargs="?", default='10', |
| 52 | help="minimum I/O duration to trace, in ms (default 10)") |
Nathan Scott | cf0792f | 2018-02-02 16:56:50 +1100 | [diff] [blame] | 53 | parser.add_argument("--ebpf", action="store_true", |
| 54 | help=argparse.SUPPRESS) |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 55 | args = parser.parse_args() |
| 56 | min_ms = int(args.min_ms) |
| 57 | pid = args.pid |
| 58 | csv = args.csv |
| 59 | debug = 0 |
| 60 | |
| 61 | # define BPF program |
| 62 | bpf_text = """ |
| 63 | #include <uapi/linux/ptrace.h> |
| 64 | #include <linux/fs.h> |
| 65 | #include <linux/sched.h> |
| 66 | #include <linux/dcache.h> |
| 67 | |
| 68 | // XXX: switch these to char's when supported |
| 69 | #define TRACE_READ 0 |
| 70 | #define TRACE_WRITE 1 |
| 71 | #define TRACE_OPEN 2 |
| 72 | #define TRACE_FSYNC 3 |
| 73 | |
| 74 | struct val_t { |
| 75 | u64 ts; |
| 76 | u64 offset; |
| 77 | struct file *fp; |
| 78 | }; |
| 79 | |
| 80 | struct data_t { |
| 81 | // XXX: switch some to u32's when supported |
| 82 | u64 ts_us; |
| 83 | u64 type; |
| 84 | u64 size; |
| 85 | u64 offset; |
| 86 | u64 delta_us; |
| 87 | u64 pid; |
| 88 | char task[TASK_COMM_LEN]; |
| 89 | char file[DNAME_INLINE_LEN]; |
| 90 | }; |
| 91 | |
Dina Goldshtein | c8b9ae3 | 2016-10-18 03:01:05 +0300 | [diff] [blame] | 92 | BPF_HASH(entryinfo, u64, struct val_t); |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 93 | BPF_PERF_OUTPUT(events); |
| 94 | |
| 95 | // |
| 96 | // Store timestamp and size on entry |
| 97 | // |
| 98 | |
| 99 | // zpl_read(), zpl_write(): |
| 100 | int trace_rw_entry(struct pt_regs *ctx, struct file *filp, char __user *buf, |
| 101 | size_t len, loff_t *ppos) |
| 102 | { |
Dina Goldshtein | c8b9ae3 | 2016-10-18 03:01:05 +0300 | [diff] [blame] | 103 | u64 id = bpf_get_current_pid_tgid(); |
| 104 | u32 pid = id >> 32; // PID is higher part |
| 105 | |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 106 | if (FILTER_PID) |
| 107 | return 0; |
| 108 | |
Dina Goldshtein | c8b9ae3 | 2016-10-18 03:01:05 +0300 | [diff] [blame] | 109 | // store filep and timestamp by id |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 110 | struct val_t val = {}; |
| 111 | val.ts = bpf_ktime_get_ns(); |
| 112 | val.fp = filp; |
| 113 | val.offset = *ppos; |
| 114 | if (val.fp) |
Dina Goldshtein | c8b9ae3 | 2016-10-18 03:01:05 +0300 | [diff] [blame] | 115 | entryinfo.update(&id, &val); |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 116 | |
| 117 | return 0; |
| 118 | } |
| 119 | |
| 120 | // zpl_open(): |
| 121 | int trace_open_entry(struct pt_regs *ctx, struct inode *inode, |
| 122 | struct file *filp) |
| 123 | { |
Dina Goldshtein | c8b9ae3 | 2016-10-18 03:01:05 +0300 | [diff] [blame] | 124 | u64 id = bpf_get_current_pid_tgid(); |
| 125 | u32 pid = id >> 32; // PID is higher part |
| 126 | |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 127 | if (FILTER_PID) |
| 128 | return 0; |
| 129 | |
Dina Goldshtein | c8b9ae3 | 2016-10-18 03:01:05 +0300 | [diff] [blame] | 130 | // store filep and timestamp by id |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 131 | struct val_t val = {}; |
| 132 | val.ts = bpf_ktime_get_ns(); |
| 133 | val.fp = filp; |
| 134 | val.offset = 0; |
| 135 | if (val.fp) |
Dina Goldshtein | c8b9ae3 | 2016-10-18 03:01:05 +0300 | [diff] [blame] | 136 | entryinfo.update(&id, &val); |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 137 | |
| 138 | return 0; |
| 139 | } |
| 140 | |
| 141 | // zpl_fsync(): |
| 142 | int trace_fsync_entry(struct pt_regs *ctx, struct file *filp) |
| 143 | { |
Dina Goldshtein | c8b9ae3 | 2016-10-18 03:01:05 +0300 | [diff] [blame] | 144 | u64 id = bpf_get_current_pid_tgid(); |
| 145 | u32 pid = id >> 32; // PID is higher part |
| 146 | |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 147 | if (FILTER_PID) |
| 148 | return 0; |
| 149 | |
Dina Goldshtein | c8b9ae3 | 2016-10-18 03:01:05 +0300 | [diff] [blame] | 150 | // store filp and timestamp by id |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 151 | struct val_t val = {}; |
| 152 | val.ts = bpf_ktime_get_ns(); |
| 153 | val.fp = filp; |
| 154 | val.offset = 0; |
| 155 | if (val.fp) |
Dina Goldshtein | c8b9ae3 | 2016-10-18 03:01:05 +0300 | [diff] [blame] | 156 | entryinfo.update(&id, &val); |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 157 | |
| 158 | return 0; |
| 159 | } |
| 160 | |
| 161 | // |
| 162 | // Output |
| 163 | // |
| 164 | |
| 165 | static int trace_return(struct pt_regs *ctx, int type) |
| 166 | { |
| 167 | struct val_t *valp; |
Dina Goldshtein | c8b9ae3 | 2016-10-18 03:01:05 +0300 | [diff] [blame] | 168 | u64 id = bpf_get_current_pid_tgid(); |
| 169 | u32 pid = id >> 32; // PID is higher part |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 170 | |
Dina Goldshtein | c8b9ae3 | 2016-10-18 03:01:05 +0300 | [diff] [blame] | 171 | valp = entryinfo.lookup(&id); |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 172 | if (valp == 0) { |
| 173 | // missed tracing issue or filtered |
| 174 | return 0; |
| 175 | } |
| 176 | |
| 177 | // calculate delta |
| 178 | u64 ts = bpf_ktime_get_ns(); |
| 179 | u64 delta_us = (ts - valp->ts) / 1000; |
Dina Goldshtein | c8b9ae3 | 2016-10-18 03:01:05 +0300 | [diff] [blame] | 180 | entryinfo.delete(&id); |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 181 | if (FILTER_US) |
| 182 | return 0; |
| 183 | |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 184 | // populate output struct |
Naveen N. Rao | 4afa96a | 2016-05-03 14:54:21 +0530 | [diff] [blame] | 185 | u32 size = PT_REGS_RC(ctx); |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 186 | struct data_t data = {.type = type, .size = size, .delta_us = delta_us, |
| 187 | .pid = pid}; |
| 188 | data.ts_us = ts / 1000; |
| 189 | data.offset = valp->offset; |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 190 | bpf_get_current_comm(&data.task, sizeof(data.task)); |
| 191 | |
Paul Chaignon | 3ba742e | 2018-05-17 22:50:41 +0200 | [diff] [blame] | 192 | struct qstr qs = valp->fp->f_path.dentry->d_name; |
Brendan Gregg | be294db | 2016-10-20 21:46:09 -0700 | [diff] [blame] | 193 | if (qs.len == 0) |
| 194 | return 0; |
Sumanth Korikkar | 7f6066d | 2020-05-20 10:49:56 -0500 | [diff] [blame] | 195 | bpf_probe_read_kernel(&data.file, sizeof(data.file), (void *)qs.name); |
Brendan Gregg | be294db | 2016-10-20 21:46:09 -0700 | [diff] [blame] | 196 | |
| 197 | // output |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 198 | events.perf_submit(ctx, &data, sizeof(data)); |
| 199 | |
| 200 | return 0; |
| 201 | } |
| 202 | |
| 203 | int trace_read_return(struct pt_regs *ctx) |
| 204 | { |
| 205 | return trace_return(ctx, TRACE_READ); |
| 206 | } |
| 207 | |
| 208 | int trace_write_return(struct pt_regs *ctx) |
| 209 | { |
| 210 | return trace_return(ctx, TRACE_WRITE); |
| 211 | } |
| 212 | |
| 213 | int trace_open_return(struct pt_regs *ctx) |
| 214 | { |
| 215 | return trace_return(ctx, TRACE_OPEN); |
| 216 | } |
| 217 | |
| 218 | int trace_fsync_return(struct pt_regs *ctx) |
| 219 | { |
| 220 | return trace_return(ctx, TRACE_FSYNC); |
| 221 | } |
| 222 | |
| 223 | """ |
| 224 | if min_ms == 0: |
| 225 | bpf_text = bpf_text.replace('FILTER_US', '0') |
| 226 | else: |
| 227 | bpf_text = bpf_text.replace('FILTER_US', |
| 228 | 'delta_us <= %s' % str(min_ms * 1000)) |
| 229 | if args.pid: |
| 230 | bpf_text = bpf_text.replace('FILTER_PID', 'pid != %s' % pid) |
| 231 | else: |
| 232 | bpf_text = bpf_text.replace('FILTER_PID', '0') |
Nathan Scott | cf0792f | 2018-02-02 16:56:50 +1100 | [diff] [blame] | 233 | if debug or args.ebpf: |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 234 | print(bpf_text) |
Nathan Scott | cf0792f | 2018-02-02 16:56:50 +1100 | [diff] [blame] | 235 | if args.ebpf: |
| 236 | exit() |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 237 | |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 238 | # process event |
| 239 | def print_event(cpu, data, size): |
Xiaozhou Liu | 51d62d3 | 2019-02-15 13:03:05 +0800 | [diff] [blame] | 240 | event = b["events"].event(data) |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 241 | |
| 242 | type = 'R' |
| 243 | if event.type == 1: |
| 244 | type = 'W' |
| 245 | elif event.type == 2: |
| 246 | type = 'O' |
| 247 | elif event.type == 3: |
| 248 | type = 'S' |
| 249 | |
| 250 | if (csv): |
| 251 | print("%d,%s,%d,%s,%d,%d,%d,%s" % ( |
jeromemarchand | b96ebcd | 2018-10-10 01:58:15 +0200 | [diff] [blame] | 252 | event.ts_us, event.task.decode('utf-8', 'replace'), event.pid, |
| 253 | type, event.size, event.offset, event.delta_us, |
| 254 | event.file.decode('utf-8', 'replace'))) |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 255 | return |
| 256 | print("%-8s %-14.14s %-6s %1s %-7s %-8d %7.2f %s" % (strftime("%H:%M:%S"), |
jeromemarchand | b96ebcd | 2018-10-10 01:58:15 +0200 | [diff] [blame] | 257 | event.task.decode('utf-8', 'replace'), event.pid, type, event.size, |
| 258 | event.offset / 1024, float(event.delta_us) / 1000, |
| 259 | event.file.decode('utf-8', 'replace'))) |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 260 | |
| 261 | # initialize BPF |
| 262 | b = BPF(text=bpf_text) |
| 263 | |
| 264 | # common file functions |
yonghong-song | 3b86b56 | 2018-06-13 06:12:43 -0700 | [diff] [blame] | 265 | if BPF.get_kprobe_functions(b'zpl_iter'): |
Marcin Skarbek | 4f444a5 | 2017-08-28 17:39:50 +0200 | [diff] [blame] | 266 | b.attach_kprobe(event="zpl_iter_read", fn_name="trace_rw_entry") |
| 267 | b.attach_kprobe(event="zpl_iter_write", fn_name="trace_rw_entry") |
yonghong-song | 3b86b56 | 2018-06-13 06:12:43 -0700 | [diff] [blame] | 268 | elif BPF.get_kprobe_functions(b'zpl_aio'): |
Marcin Skarbek | 4f444a5 | 2017-08-28 17:39:50 +0200 | [diff] [blame] | 269 | b.attach_kprobe(event="zpl_aio_read", fn_name="trace_rw_entry") |
| 270 | b.attach_kprobe(event="zpl_aio_write", fn_name="trace_rw_entry") |
| 271 | else: |
| 272 | b.attach_kprobe(event="zpl_read", fn_name="trace_rw_entry") |
| 273 | b.attach_kprobe(event="zpl_write", fn_name="trace_rw_entry") |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 274 | b.attach_kprobe(event="zpl_open", fn_name="trace_open_entry") |
| 275 | b.attach_kprobe(event="zpl_fsync", fn_name="trace_fsync_entry") |
yonghong-song | 3b86b56 | 2018-06-13 06:12:43 -0700 | [diff] [blame] | 276 | if BPF.get_kprobe_functions(b'zpl_iter'): |
Marcin Skarbek | 4f444a5 | 2017-08-28 17:39:50 +0200 | [diff] [blame] | 277 | b.attach_kretprobe(event="zpl_iter_read", fn_name="trace_read_return") |
| 278 | b.attach_kretprobe(event="zpl_iter_write", fn_name="trace_write_return") |
yonghong-song | 3b86b56 | 2018-06-13 06:12:43 -0700 | [diff] [blame] | 279 | elif BPF.get_kprobe_functions(b'zpl_aio'): |
Marcin Skarbek | 4f444a5 | 2017-08-28 17:39:50 +0200 | [diff] [blame] | 280 | b.attach_kretprobe(event="zpl_aio_read", fn_name="trace_read_return") |
| 281 | b.attach_kretprobe(event="zpl_aio_write", fn_name="trace_write_return") |
| 282 | else: |
| 283 | b.attach_kretprobe(event="zpl_read", fn_name="trace_read_return") |
| 284 | b.attach_kretprobe(event="zpl_write", fn_name="trace_write_return") |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 285 | b.attach_kretprobe(event="zpl_open", fn_name="trace_open_return") |
| 286 | b.attach_kretprobe(event="zpl_fsync", fn_name="trace_fsync_return") |
| 287 | |
| 288 | # header |
| 289 | if (csv): |
| 290 | print("ENDTIME_us,TASK,PID,TYPE,BYTES,OFFSET_b,LATENCY_us,FILE") |
| 291 | else: |
| 292 | if min_ms == 0: |
| 293 | print("Tracing ZFS operations") |
| 294 | else: |
| 295 | print("Tracing ZFS operations slower than %d ms" % min_ms) |
| 296 | print("%-8s %-14s %-6s %1s %-7s %-8s %7s %s" % ("TIME", "COMM", "PID", "T", |
| 297 | "BYTES", "OFF_KB", "LAT(ms)", "FILENAME")) |
| 298 | |
| 299 | # read events |
Mark Drayton | 5f5687e | 2017-02-20 18:13:03 +0000 | [diff] [blame] | 300 | b["events"].open_perf_buffer(print_event, page_cnt=64) |
Brendan Gregg | bc54bb6 | 2016-02-14 23:13:13 -0800 | [diff] [blame] | 301 | while 1: |
Jerome Marchand | 5167127 | 2018-12-19 01:57:24 +0100 | [diff] [blame] | 302 | try: |
| 303 | b.perf_buffer_poll() |
| 304 | except KeyboardInterrupt: |
| 305 | exit() |