blob: 0f836afcadbba93585f2538d5d01a0ea7f01635c [file] [log] [blame]
samuelnair166bf0f2017-09-05 00:57:49 +08001#!/usr/bin/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)")
Nathan Scottcf0792f2018-02-02 16:56:50 +110056parser.add_argument("--ebpf", action="store_true",
57 help=argparse.SUPPRESS)
samuelnair166bf0f2017-09-05 00:57:49 +080058args = 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')
Nathan Scottcf0792f2018-02-02 16:56:50 +1100241if debug or args.ebpf:
samuelnair166bf0f2017-09-05 00:57:49 +0800242 print(bpf_text)
Nathan Scottcf0792f2018-02-02 16:56:50 +1100243 if args.ebpf:
244 exit()
samuelnair166bf0f2017-09-05 00:57:49 +0800245
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(),
284 event.pid,
285 type,
286 event.size,
287 event.offset / 1024,
288 float(event.delta_us) / 1000,
289 event.file.decode()))
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"))
Paul Chaignon044ccea2017-10-07 11:07:29 +0200325
samuelnair166bf0f2017-09-05 00:57:49 +0800326b["events"].open_perf_buffer(print_event, page_cnt=64)
327while 1:
Teng Qindbf00292018-02-28 21:47:50 -0800328 b.perf_buffer_poll()