1#!/usr/bin/python
2# @lint-avoid-python-3-compatibility-imports
3#
4# ext4slower  Trace slow ext4 operations.
5#             For Linux, uses BCC, eBPF.
6#
7# USAGE: ext4slower [-h] [-j] [-p PID] [min_ms]
8#
9# This script traces common ext4 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 ext4 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# By default, a minimum millisecond threshold of 10 is used.
20#
21# Copyright 2016 Netflix, Inc.
22# Licensed under the Apache License, Version 2.0 (the "License")
23#
24# 11-Feb-2016   Brendan Gregg   Created this.
25# 15-Oct-2016   Dina Goldshtein -p to filter by process ID.
26# 13-Jun-2018   Joe Yin modify generic_file_read_iter to ext4_file_read_iter.
27
28from __future__ import print_function
29from bcc import BPF
30import argparse
31from time import strftime
32import ctypes as ct
33
34# symbols
35kallsyms = "/proc/kallsyms"
36
37# arguments
38examples = """examples:
39    ./ext4slower             # trace operations slower than 10 ms (default)
40    ./ext4slower 1           # trace operations slower than 1 ms
41    ./ext4slower -j 1        # ... 1 ms, parsable output (csv)
42    ./ext4slower 0           # trace all operations (warning: verbose)
43    ./ext4slower -p 185      # trace PID 185 only
44"""
45parser = argparse.ArgumentParser(
46    description="Trace common ext4 file operations slower than a threshold",
47    formatter_class=argparse.RawDescriptionHelpFormatter,
48    epilog=examples)
49parser.add_argument("-j", "--csv", action="store_true",
50    help="just print fields: comma-separated values")
51parser.add_argument("-p", "--pid",
52    help="trace this PID only")
53parser.add_argument("min_ms", nargs="?", default='10',
54    help="minimum I/O duration to trace, in ms (default 10)")
55parser.add_argument("--ebpf", action="store_true",
56    help=argparse.SUPPRESS)
57args = parser.parse_args()
58min_ms = int(args.min_ms)
59pid = args.pid
60csv = args.csv
61debug = 0
62
63# define BPF program
64bpf_text = """
65#include <uapi/linux/ptrace.h>
66#include <linux/fs.h>
67#include <linux/sched.h>
68#include <linux/dcache.h>
69
70// XXX: switch these to char's when supported
71#define TRACE_READ      0
72#define TRACE_WRITE     1
73#define TRACE_OPEN      2
74#define TRACE_FSYNC     3
75
76struct val_t {
77    u64 ts;
78    u64 offset;
79    struct file *fp;
80};
81
82struct data_t {
83    // XXX: switch some to u32's when supported
84    u64 ts_us;
85    u64 type;
86    u64 size;
87    u64 offset;
88    u64 delta_us;
89    u64 pid;
90    char task[TASK_COMM_LEN];
91    char file[DNAME_INLINE_LEN];
92};
93
94BPF_HASH(entryinfo, u64, struct val_t);
95BPF_PERF_OUTPUT(events);
96
97//
98// Store timestamp and size on entry
99//
100
101// The current ext4 (Linux 4.5) uses generic_file_read_iter(), instead of it's
102// own function, for reads. So we need to trace that and then filter on ext4,
103// which I do by checking file->f_op.
104// The new Linux version (since form 4.10) uses ext4_file_read_iter(), And if the 'CONFIG_FS_DAX'
105// is not set ,then ext4_file_read_iter() will call generic_file_read_iter(), else it will call
106// ext4_dax_read_iter(), and trace generic_file_read_iter() will fail.
107int trace_read_entry(struct pt_regs *ctx, struct kiocb *iocb)
108{
109    u64 id =  bpf_get_current_pid_tgid();
110    u32 pid = id >> 32; // PID is higher part
111
112    if (FILTER_PID)
113        return 0;
114
115    // ext4 filter on file->f_op == ext4_file_operations
116    struct file *fp = iocb->ki_filp;
117    if ((u64)fp->f_op != EXT4_FILE_OPERATIONS)
118        return 0;
119
120    // store filep and timestamp by id
121    struct val_t val = {};
122    val.ts = bpf_ktime_get_ns();
123    val.fp = fp;
124    val.offset = iocb->ki_pos;
125    if (val.fp)
126        entryinfo.update(&id, &val);
127
128    return 0;
129}
130
131// ext4_file_write_iter():
132int trace_write_entry(struct pt_regs *ctx, struct kiocb *iocb)
133{
134    u64 id = bpf_get_current_pid_tgid();
135    u32 pid = id >> 32; // PID is higher part
136
137    if (FILTER_PID)
138        return 0;
139
140    // store filep and timestamp by id
141    struct val_t val = {};
142    val.ts = bpf_ktime_get_ns();
143    val.fp = iocb->ki_filp;
144    val.offset = iocb->ki_pos;
145    if (val.fp)
146        entryinfo.update(&id, &val);
147
148    return 0;
149}
150
151// ext4_file_open():
152int trace_open_entry(struct pt_regs *ctx, struct inode *inode,
153    struct file *file)
154{
155    u64 id = bpf_get_current_pid_tgid();
156    u32 pid = id >> 32; // PID is higher part
157
158    if (FILTER_PID)
159        return 0;
160
161    // store filep and timestamp by id
162    struct val_t val = {};
163    val.ts = bpf_ktime_get_ns();
164    val.fp = file;
165    val.offset = 0;
166    if (val.fp)
167        entryinfo.update(&id, &val);
168
169    return 0;
170}
171
172// ext4_sync_file():
173int trace_fsync_entry(struct pt_regs *ctx, struct file *file)
174{
175    u64 id = bpf_get_current_pid_tgid();
176    u32 pid = id >> 32; // PID is higher part
177
178    if (FILTER_PID)
179        return 0;
180
181    // store filep and timestamp by id
182    struct val_t val = {};
183    val.ts = bpf_ktime_get_ns();
184    val.fp = file;
185    val.offset = 0;
186    if (val.fp)
187        entryinfo.update(&id, &val);
188
189    return 0;
190}
191
192//
193// Output
194//
195
196static int trace_return(struct pt_regs *ctx, int type)
197{
198    struct val_t *valp;
199    u64 id = bpf_get_current_pid_tgid();
200    u32 pid = id >> 32; // PID is higher part
201
202    valp = entryinfo.lookup(&id);
203    if (valp == 0) {
204        // missed tracing issue or filtered
205        return 0;
206    }
207
208    // calculate delta
209    u64 ts = bpf_ktime_get_ns();
210    u64 delta_us = (ts - valp->ts) / 1000;
211    entryinfo.delete(&id);
212    if (FILTER_US)
213        return 0;
214
215    // populate output struct
216    u32 size = PT_REGS_RC(ctx);
217    struct data_t data = {.type = type, .size = size, .delta_us = delta_us,
218        .pid = pid};
219    data.ts_us = ts / 1000;
220    data.offset = valp->offset;
221    bpf_get_current_comm(&data.task, sizeof(data.task));
222
223    // workaround (rewriter should handle file to d_name in one step):
224    struct dentry *de = NULL;
225    struct qstr qs = {};
226    de = valp->fp->f_path.dentry;
227    qs = de->d_name;
228    if (qs.len == 0)
229        return 0;
230    bpf_probe_read(&data.file, sizeof(data.file), (void *)qs.name);
231
232    // output
233    events.perf_submit(ctx, &data, sizeof(data));
234
235    return 0;
236}
237
238int trace_read_return(struct pt_regs *ctx)
239{
240    return trace_return(ctx, TRACE_READ);
241}
242
243int trace_write_return(struct pt_regs *ctx)
244{
245    return trace_return(ctx, TRACE_WRITE);
246}
247
248int trace_open_return(struct pt_regs *ctx)
249{
250    return trace_return(ctx, TRACE_OPEN);
251}
252
253int trace_fsync_return(struct pt_regs *ctx)
254{
255    return trace_return(ctx, TRACE_FSYNC);
256}
257
258"""
259
260# code replacements
261with open(kallsyms) as syms:
262    ops = ''
263    for line in syms:
264        (addr, size, name) = line.rstrip().split(" ", 2)
265        name = name.split("\t")[0]
266        if name == "ext4_file_operations":
267            ops = "0x" + addr
268            break
269    if ops == '':
270        print("ERROR: no ext4_file_operations in /proc/kallsyms. Exiting.")
271        print("HINT: the kernel should be built with CONFIG_KALLSYMS_ALL.")
272        exit()
273    bpf_text = bpf_text.replace('EXT4_FILE_OPERATIONS', ops)
274if min_ms == 0:
275    bpf_text = bpf_text.replace('FILTER_US', '0')
276else:
277    bpf_text = bpf_text.replace('FILTER_US',
278        'delta_us <= %s' % str(min_ms * 1000))
279if args.pid:
280    bpf_text = bpf_text.replace('FILTER_PID', 'pid != %s' % pid)
281else:
282    bpf_text = bpf_text.replace('FILTER_PID', '0')
283if debug or args.ebpf:
284    print(bpf_text)
285    if args.ebpf:
286        exit()
287
288# kernel->user event data: struct data_t
289DNAME_INLINE_LEN = 32   # linux/dcache.h
290TASK_COMM_LEN = 16      # linux/sched.h
291class Data(ct.Structure):
292    _fields_ = [
293        ("ts_us", ct.c_ulonglong),
294        ("type", ct.c_ulonglong),
295        ("size", ct.c_ulonglong),
296        ("offset", ct.c_ulonglong),
297        ("delta_us", ct.c_ulonglong),
298        ("pid", ct.c_ulonglong),
299        ("task", ct.c_char * TASK_COMM_LEN),
300        ("file", ct.c_char * DNAME_INLINE_LEN)
301    ]
302
303# process event
304def print_event(cpu, data, size):
305    event = ct.cast(data, ct.POINTER(Data)).contents
306
307    type = 'R'
308    if event.type == 1:
309        type = 'W'
310    elif event.type == 2:
311        type = 'O'
312    elif event.type == 3:
313        type = 'S'
314
315    if (csv):
316        print("%d,%s,%d,%s,%d,%d,%d,%s" % (
317            event.ts_us, event.task.decode('utf-8', 'replace'), event.pid,
318            type, event.size, event.offset, event.delta_us,
319            event.file.decode('utf-8', 'replace')))
320        return
321    print("%-8s %-14.14s %-6s %1s %-7s %-8d %7.2f %s" % (strftime("%H:%M:%S"),
322        event.task.decode('utf-8', 'replace'), event.pid, type, event.size,
323        event.offset / 1024, float(event.delta_us) / 1000,
324        event.file.decode('utf-8', 'replace')))
325
326# initialize BPF
327b = BPF(text=bpf_text)
328
329# Common file functions. See earlier comment about generic_file_read_iter().
330if BPF.get_kprobe_functions(b'ext4_file_read_iter'):
331    b.attach_kprobe(event="ext4_file_read_iter", fn_name="trace_read_entry")
332else:
333    b.attach_kprobe(event="generic_file_read_iter", fn_name="trace_read_entry")
334b.attach_kprobe(event="ext4_file_write_iter", fn_name="trace_write_entry")
335b.attach_kprobe(event="ext4_file_open", fn_name="trace_open_entry")
336b.attach_kprobe(event="ext4_sync_file", fn_name="trace_fsync_entry")
337if BPF.get_kprobe_functions(b'ext4_file_read_iter'):
338    b.attach_kretprobe(event="ext4_file_read_iter", fn_name="trace_read_return")
339else:
340    b.attach_kretprobe(event="generic_file_read_iter", fn_name="trace_read_return")
341b.attach_kretprobe(event="ext4_file_write_iter", fn_name="trace_write_return")
342b.attach_kretprobe(event="ext4_file_open", fn_name="trace_open_return")
343b.attach_kretprobe(event="ext4_sync_file", fn_name="trace_fsync_return")
344
345# header
346if (csv):
347    print("ENDTIME_us,TASK,PID,TYPE,BYTES,OFFSET_b,LATENCY_us,FILE")
348else:
349    if min_ms == 0:
350        print("Tracing ext4 operations")
351    else:
352        print("Tracing ext4 operations slower than %d ms" % min_ms)
353    print("%-8s %-14s %-6s %1s %-7s %-8s %7s %s" % ("TIME", "COMM", "PID", "T",
354        "BYTES", "OFF_KB", "LAT(ms)", "FILENAME"))
355
356# read events
357b["events"].open_perf_buffer(print_event, page_cnt=64)
358while 1:
359    b.perf_buffer_poll()
360