1#!/usr/bin/env python
2# @lint-avoid-python-3-compatibility-imports
3#
4# nfsslower     Trace slow NFS operations
5#               for Linux using BCC & eBPF
6#
7# Usage: nfsslower [-h] [-p PID] [min_ms]
8#
9# This script traces some common NFS operations: read, write, opens and
10# getattr. 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 NFS 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# Most of this code is copied from similar tools (ext4slower, zfsslower etc)
20#
21# By default, a minimum millisecond threshold of 10 is used.
22#
23# This tool uses kprobes to instrument the kernel for entry and exit
24# information, in the future a preferred way would be to use tracepoints.
25# Currently there are'nt any tracepoints available for nfs_read_file,
26# nfs_write_file and nfs_open_file, nfs_getattr does have entry and exit
27# tracepoints but we chose to use kprobes for consistency
28#
29# 31-Aug-2017   Samuel Nair created this. Should work with NFSv{3,4}
30
31from __future__ import print_function
32from bcc import BPF
33import argparse
34from time import strftime
35import ctypes as ct
36
37examples = """
38    ./nfsslower         # trace operations slower than 10ms
39    ./nfsslower 1       # trace operations slower than 1ms
40    ./nfsslower -j 1    # ... 1 ms, parsable output (csv)
41    ./nfsslower 0       # trace all nfs operations
42    ./nfsslower -p 121  # trace pid 121 only
43"""
44parser = argparse.ArgumentParser(
45    description="""Trace READ, WRITE, OPEN \
46and GETATTR NFS calls slower than a threshold,\
47supports NFSv{3,4}""",
48    formatter_class=argparse.RawDescriptionHelpFormatter,
49    epilog=examples)
50
51parser.add_argument("-j", "--csv", action="store_true",
52                    help="just print fields: comma-separated values")
53parser.add_argument("-p", "--pid", help="Trace this pid only")
54parser.add_argument("min_ms", nargs="?", default='10',
55                    help="Minimum IO duration to trace in ms (default=10ms)")
56parser.add_argument("--ebpf", action="store_true",
57                    help=argparse.SUPPRESS)
58args = parser.parse_args()
59min_ms = int(args.min_ms)
60pid = args.pid
61csv = args.csv
62debug = 0
63
64bpf_text = """
65
66#include <uapi/linux/ptrace.h>
67#include <linux/fs.h>
68#include <linux/sched.h>
69#include <linux/dcache.h>
70
71#define TRACE_READ 0
72#define TRACE_WRITE 1
73#define TRACE_OPEN 2
74#define TRACE_GETATTR 3
75
76struct val_t {
77    u64 ts;
78    u64 offset;
79    struct file *fp;
80    struct dentry *d;
81};
82
83struct data_t {
84    // XXX: switch some to u32's when supported
85    u64 ts_us;
86    u64 type;
87    u64 size;
88    u64 offset;
89    u64 delta_us;
90    u64 pid;
91    char task[TASK_COMM_LEN];
92    char file[DNAME_INLINE_LEN];
93};
94
95BPF_HASH(entryinfo, u64, struct val_t);
96BPF_PERF_OUTPUT(events);
97
98int trace_rw_entry(struct pt_regs *ctx, struct kiocb *iocb,
99                                struct iov_iter *data)
100{
101    u64 id = bpf_get_current_pid_tgid();
102    u32 pid = id >> 32; // PID is higher part
103
104    if(FILTER_PID)
105        return 0;
106
107    // store filep and timestamp by id
108    struct val_t val = {};
109    val.ts = bpf_ktime_get_ns();
110    val.fp = iocb->ki_filp;
111    val.d = NULL;
112    val.offset = iocb->ki_pos;
113
114    if (val.fp)
115        entryinfo.update(&id, &val);
116
117    return 0;
118}
119
120int trace_file_open_entry (struct pt_regs *ctx, struct inode *inode,
121                                struct file *filp)
122{
123    u64 id = bpf_get_current_pid_tgid();
124    u32 pid = id >> 32; // PID is higher part
125
126    if(FILTER_PID)
127        return 0;
128
129    // store filep and timestamp by id
130    struct val_t val = {};
131    val.ts = bpf_ktime_get_ns();
132    val.fp = filp;
133    val.d = NULL;
134    val.offset = 0;
135    if (val.fp)
136        entryinfo.update(&id, &val);
137
138    return 0;
139}
140
141int trace_getattr_entry(struct pt_regs *ctx, struct vfsmount *mnt,
142                        struct dentry *dentry, struct kstat *stat)
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    struct val_t val = {};
151    val.ts = bpf_ktime_get_ns();
152    val.fp = NULL;
153    val.d = dentry;
154    val.offset = 0;
155    if (val.d)
156        entryinfo.update(&id, &val);
157
158    return 0;
159}
160
161static int trace_exit(struct pt_regs *ctx, int type)
162{
163    struct val_t *valp;
164    u64 id = bpf_get_current_pid_tgid();
165    u32 pid = id >> 32; // PID is higher part
166
167    valp = entryinfo.lookup(&id);
168    if (valp == 0) {
169        // missed tracing issue or filtered
170        return 0;
171    }
172
173    // calculate delta
174    u64 ts = bpf_ktime_get_ns();
175    u64 delta_us = (ts - valp->ts) / 1000;
176    entryinfo.delete(&id);
177
178    if (FILTER_US)
179        return 0;
180
181    // populate output struct
182    u32 size = PT_REGS_RC(ctx);
183    struct data_t data = {.type = type, .size = size, .delta_us = delta_us,
184        .pid = pid};
185    data.ts_us = ts / 1000;
186    data.offset = valp->offset;
187    bpf_get_current_comm(&data.task, sizeof(data.task));
188
189    // workaround (rewriter should handle file to d_name in one step):
190    struct dentry *de = NULL;
191    struct qstr qs = {};
192    if(type == TRACE_GETATTR)
193    {
194        bpf_probe_read(&de,sizeof(de), &valp->d);
195    }
196    else
197    {
198        bpf_probe_read(&de, sizeof(de), &valp->fp->f_path.dentry);
199    }
200
201    bpf_probe_read(&qs, sizeof(qs), (void *)&de->d_name);
202    if (qs.len == 0)
203        return 0;
204
205    bpf_probe_read(&data.file, sizeof(data.file), (void *)qs.name);
206    // output
207    events.perf_submit(ctx, &data, sizeof(data));
208    return 0;
209}
210
211int trace_file_open_return(struct pt_regs *ctx)
212{
213    return trace_exit(ctx, TRACE_OPEN);
214}
215
216int trace_read_return(struct pt_regs *ctx)
217{
218    return trace_exit(ctx, TRACE_READ);
219}
220
221int trace_write_return(struct pt_regs *ctx)
222{
223    return trace_exit(ctx, TRACE_WRITE);
224}
225
226int trace_getattr_return(struct pt_regs *ctx)
227{
228    return trace_exit(ctx, TRACE_GETATTR);
229}
230
231"""
232if min_ms == 0:
233    bpf_text = bpf_text.replace('FILTER_US', '0')
234else:
235    bpf_text = bpf_text.replace('FILTER_US',
236                                'delta_us <= %s' % str(min_ms * 1000))
237if args.pid:
238    bpf_text = bpf_text.replace('FILTER_PID', 'pid != %s' % pid)
239else:
240    bpf_text = bpf_text.replace('FILTER_PID', '0')
241if debug or args.ebpf:
242    print(bpf_text)
243    if args.ebpf:
244        exit()
245
246# kernel->user event data: struct data_t
247DNAME_INLINE_LEN = 32   # linux/dcache.h
248TASK_COMM_LEN = 16      # linux/sched.h
249
250
251class Data(ct.Structure):
252    _fields_ = [
253        ("ts_us", ct.c_ulonglong),
254        ("type", ct.c_ulonglong),
255        ("size", ct.c_ulonglong),
256        ("offset", ct.c_ulonglong),
257        ("delta_us", ct.c_ulonglong),
258        ("pid", ct.c_ulonglong),
259        ("task", ct.c_char * TASK_COMM_LEN),
260        ("file", ct.c_char * DNAME_INLINE_LEN)
261    ]
262
263
264# process event
265def print_event(cpu, data, size):
266    event = ct.cast(data, ct.POINTER(Data)).contents
267
268    type = 'R'
269    if event.type == 1:
270        type = 'W'
271    elif event.type == 2:
272        type = 'O'
273    elif event.type == 3:
274        type = 'G'
275
276    if(csv):
277        print("%d,%s,%d,%s,%d,%d,%d,%s" % (
278            event.ts_us, event.task, event.pid, type, event.size,
279            event.offset, event.delta_us, event.file))
280        return
281    print("%-8s %-14.14s %-6s %1s %-7s %-8d %7.2f %s" %
282          (strftime("%H:%M:%S"),
283           event.task.decode('utf-8', 'replace'),
284           event.pid,
285           type,
286           event.size,
287           event.offset / 1024,
288           float(event.delta_us) / 1000,
289           event.file.decode('utf-8', 'replace')))
290
291
292# Currently specifically works for NFSv4, the other kprobes are generic
293# so it should work with earlier NFS versions
294
295b = BPF(text=bpf_text)
296b.attach_kprobe(event="nfs_file_read", fn_name="trace_rw_entry")
297b.attach_kprobe(event="nfs_file_write", fn_name="trace_rw_entry")
298b.attach_kprobe(event="nfs4_file_open", fn_name="trace_file_open_entry")
299b.attach_kprobe(event="nfs_file_open", fn_name="trace_file_open_entry")
300b.attach_kprobe(event="nfs_getattr", fn_name="trace_getattr_entry")
301
302b.attach_kretprobe(event="nfs_file_read", fn_name="trace_read_return")
303b.attach_kretprobe(event="nfs_file_write", fn_name="trace_write_return")
304b.attach_kretprobe(event="nfs4_file_open", fn_name="trace_file_open_return")
305b.attach_kretprobe(event="nfs_file_open", fn_name="trace_file_open_return")
306b.attach_kretprobe(event="nfs_getattr", fn_name="trace_getattr_return")
307
308if(csv):
309    print("ENDTIME_us,TASK,PID,TYPE,BYTES,OFFSET_b,LATENCY_us,FILE")
310else:
311    if min_ms == 0:
312        print("Tracing NFS operations... Ctrl-C to quit")
313    else:
314        print("""Tracing NFS operations that are slower than \
315%d ms... Ctrl-C to quit"""
316              % min_ms)
317    print("%-8s %-14s %-6s %1s %-7s %-8s %7s %s" % ("TIME",
318                                                    "COMM",
319                                                    "PID",
320                                                    "T",
321                                                    "BYTES",
322                                                    "OFF_KB",
323                                                    "LAT(ms)",
324                                                    "FILENAME"))
325
326b["events"].open_perf_buffer(print_event, page_cnt=64)
327while 1:
328    try:
329        b.perf_buffer_poll()
330    except KeyboardInterrupt:
331        exit()
332