• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1#!/usr/bin/python
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.
28# 16-Oct-2016   Dina Goldshtein -p to filter by process ID.
29
30from __future__ import print_function
31from bcc import BPF
32import argparse
33from time import strftime
34
35# arguments
36examples = """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"""
43parser = argparse.ArgumentParser(
44    description="Trace common ZFS file operations slower than a threshold",
45    formatter_class=argparse.RawDescriptionHelpFormatter,
46    epilog=examples)
47parser.add_argument("-j", "--csv", action="store_true",
48    help="just print fields: comma-separated values")
49parser.add_argument("-p", "--pid",
50    help="trace this PID only")
51parser.add_argument("min_ms", nargs="?", default='10',
52    help="minimum I/O duration to trace, in ms (default 10)")
53parser.add_argument("--ebpf", action="store_true",
54    help=argparse.SUPPRESS)
55args = parser.parse_args()
56min_ms = int(args.min_ms)
57pid = args.pid
58csv = args.csv
59debug = 0
60
61# define BPF program
62bpf_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
74struct val_t {
75    u64 ts;
76    u64 offset;
77    struct file *fp;
78};
79
80struct 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
92BPF_HASH(entryinfo, u64, struct val_t);
93BPF_PERF_OUTPUT(events);
94
95//
96// Store timestamp and size on entry
97//
98
99// zpl_read(), zpl_write():
100int trace_rw_entry(struct pt_regs *ctx, struct file *filp, char __user *buf,
101    size_t len, loff_t *ppos)
102{
103    u64 id = bpf_get_current_pid_tgid();
104    u32 pid = id >> 32; // PID is higher part
105
106    if (FILTER_PID)
107        return 0;
108
109    // store filep and timestamp by id
110    struct val_t val = {};
111    val.ts = bpf_ktime_get_ns();
112    val.fp = filp;
113    val.offset = *ppos;
114    if (val.fp)
115        entryinfo.update(&id, &val);
116
117    return 0;
118}
119
120// zpl_open():
121int trace_open_entry(struct pt_regs *ctx, struct inode *inode,
122    struct file *filp)
123{
124    u64 id = bpf_get_current_pid_tgid();
125    u32 pid = id >> 32; // PID is higher part
126
127    if (FILTER_PID)
128        return 0;
129
130    // store filep and timestamp by id
131    struct val_t val = {};
132    val.ts = bpf_ktime_get_ns();
133    val.fp = filp;
134    val.offset = 0;
135    if (val.fp)
136        entryinfo.update(&id, &val);
137
138    return 0;
139}
140
141// zpl_fsync():
142int trace_fsync_entry(struct pt_regs *ctx, struct file *filp)
143{
144    u64 id = bpf_get_current_pid_tgid();
145    u32 pid = id >> 32; // PID is higher part
146
147    if (FILTER_PID)
148        return 0;
149
150    // store filp and timestamp by id
151    struct val_t val = {};
152    val.ts = bpf_ktime_get_ns();
153    val.fp = filp;
154    val.offset = 0;
155    if (val.fp)
156        entryinfo.update(&id, &val);
157
158    return 0;
159}
160
161//
162// Output
163//
164
165static int trace_return(struct pt_regs *ctx, int type)
166{
167    struct val_t *valp;
168    u64 id = bpf_get_current_pid_tgid();
169    u32 pid = id >> 32; // PID is higher part
170
171    valp = entryinfo.lookup(&id);
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;
180    entryinfo.delete(&id);
181    if (FILTER_US)
182        return 0;
183
184    // populate output struct
185    u32 size = PT_REGS_RC(ctx);
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;
190    bpf_get_current_comm(&data.task, sizeof(data.task));
191
192    struct qstr qs = valp->fp->f_path.dentry->d_name;
193    if (qs.len == 0)
194        return 0;
195    bpf_probe_read_kernel(&data.file, sizeof(data.file), (void *)qs.name);
196
197    // output
198    events.perf_submit(ctx, &data, sizeof(data));
199
200    return 0;
201}
202
203int trace_read_return(struct pt_regs *ctx)
204{
205    return trace_return(ctx, TRACE_READ);
206}
207
208int trace_write_return(struct pt_regs *ctx)
209{
210    return trace_return(ctx, TRACE_WRITE);
211}
212
213int trace_open_return(struct pt_regs *ctx)
214{
215    return trace_return(ctx, TRACE_OPEN);
216}
217
218int trace_fsync_return(struct pt_regs *ctx)
219{
220    return trace_return(ctx, TRACE_FSYNC);
221}
222
223"""
224if min_ms == 0:
225    bpf_text = bpf_text.replace('FILTER_US', '0')
226else:
227    bpf_text = bpf_text.replace('FILTER_US',
228        'delta_us <= %s' % str(min_ms * 1000))
229if args.pid:
230    bpf_text = bpf_text.replace('FILTER_PID', 'pid != %s' % pid)
231else:
232    bpf_text = bpf_text.replace('FILTER_PID', '0')
233if debug or args.ebpf:
234    print(bpf_text)
235    if args.ebpf:
236        exit()
237
238# process event
239def print_event(cpu, data, size):
240    event = b["events"].event(data)
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" % (
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')))
255        return
256    print("%-8s %-14.14s %-6s %1s %-7s %-8d %7.2f %s" % (strftime("%H:%M:%S"),
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')))
260
261# initialize BPF
262b = BPF(text=bpf_text)
263
264# common file functions
265if BPF.get_kprobe_functions(b'zpl_iter'):
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")
268elif BPF.get_kprobe_functions(b'zpl_aio'):
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")
271else:
272    b.attach_kprobe(event="zpl_read", fn_name="trace_rw_entry")
273    b.attach_kprobe(event="zpl_write", fn_name="trace_rw_entry")
274b.attach_kprobe(event="zpl_open", fn_name="trace_open_entry")
275b.attach_kprobe(event="zpl_fsync", fn_name="trace_fsync_entry")
276if BPF.get_kprobe_functions(b'zpl_iter'):
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")
279elif BPF.get_kprobe_functions(b'zpl_aio'):
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")
282else:
283    b.attach_kretprobe(event="zpl_read", fn_name="trace_read_return")
284    b.attach_kretprobe(event="zpl_write", fn_name="trace_write_return")
285b.attach_kretprobe(event="zpl_open", fn_name="trace_open_return")
286b.attach_kretprobe(event="zpl_fsync", fn_name="trace_fsync_return")
287
288# header
289if (csv):
290    print("ENDTIME_us,TASK,PID,TYPE,BYTES,OFFSET_b,LATENCY_us,FILE")
291else:
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
300b["events"].open_perf_buffer(print_event, page_cnt=64)
301while 1:
302    try:
303        b.perf_buffer_poll()
304    except KeyboardInterrupt:
305        exit()
306