1#!/usr/bin/env python
2# @lint-avoid-python-3-compatibility-imports
3#
4# btrfsdist  Summarize btrfs operation latency.
5#            For Linux, uses BCC, eBPF.
6#
7# USAGE: btrfsdist [-h] [-T] [-m] [-p PID] [interval] [count]
8#
9# Copyright 2016 Netflix, Inc.
10# Licensed under the Apache License, Version 2.0 (the "License")
11#
12# 15-Feb-2016   Brendan Gregg   Created this.
13
14from __future__ import print_function
15from bcc import BPF
16from time import sleep, strftime
17import argparse
18
19# symbols
20kallsyms = "/proc/kallsyms"
21
22# arguments
23examples = """examples:
24    ./btrfsdist            # show operation latency as a histogram
25    ./btrfsdist -p 181     # trace PID 181 only
26    ./btrfsdist 1 10       # print 1 second summaries, 10 times
27    ./btrfsdist -m 5       # 5s summaries, milliseconds
28"""
29parser = argparse.ArgumentParser(
30    description="Summarize btrfs operation latency",
31    formatter_class=argparse.RawDescriptionHelpFormatter,
32    epilog=examples)
33parser.add_argument("-T", "--notimestamp", action="store_true",
34    help="don't include timestamp on interval output")
35parser.add_argument("-m", "--milliseconds", action="store_true",
36    help="output in milliseconds")
37parser.add_argument("-p", "--pid",
38    help="trace this PID only")
39parser.add_argument("interval", nargs="?",
40    help="output interval, in seconds")
41parser.add_argument("count", nargs="?", default=99999999,
42    help="number of outputs")
43parser.add_argument("--ebpf", action="store_true",
44    help=argparse.SUPPRESS)
45args = parser.parse_args()
46pid = args.pid
47countdown = int(args.count)
48if args.milliseconds:
49    factor = 1000000
50    label = "msecs"
51else:
52    factor = 1000
53    label = "usecs"
54if args.interval and int(args.interval) == 0:
55    print("ERROR: interval 0. Exiting.")
56    exit()
57debug = 0
58
59# define BPF program
60bpf_text = """
61#include <uapi/linux/ptrace.h>
62#include <linux/fs.h>
63#include <linux/sched.h>
64
65#define OP_NAME_LEN 8
66typedef struct dist_key {
67    char op[OP_NAME_LEN];
68    u64 slot;
69} dist_key_t;
70BPF_HASH(start, u32);
71BPF_HISTOGRAM(dist, dist_key_t);
72
73// time operation
74int trace_entry(struct pt_regs *ctx)
75{
76    u32 pid = bpf_get_current_pid_tgid();
77    if (FILTER_PID)
78        return 0;
79    u64 ts = bpf_ktime_get_ns();
80    start.update(&pid, &ts);
81    return 0;
82}
83
84// The current btrfs (Linux 4.5) uses generic_file_read_iter() instead of it's
85// own read function. So we need to trace that and then filter on btrfs, which
86// I do by checking file->f_op.
87int trace_read_entry(struct pt_regs *ctx, struct kiocb *iocb)
88{
89    u32 pid = bpf_get_current_pid_tgid();
90    if (FILTER_PID)
91        return 0;
92
93    // btrfs filter on file->f_op == btrfs_file_operations
94    struct file *fp = iocb->ki_filp;
95    if ((u64)fp->f_op != BTRFS_FILE_OPERATIONS)
96        return 0;
97
98    u64 ts = bpf_ktime_get_ns();
99    start.update(&pid, &ts);
100    return 0;
101}
102
103// The current btrfs (Linux 4.5) uses generic_file_open(), instead of it's own
104// function. Same as with reads. Trace the generic path and filter:
105int trace_open_entry(struct pt_regs *ctx, struct inode *inode,
106    struct file *file)
107{
108    u32 pid;
109    pid = bpf_get_current_pid_tgid();
110    if (FILTER_PID)
111        return 0;
112
113    // btrfs filter on file->f_op == btrfs_file_operations
114    if ((u64)file->f_op != BTRFS_FILE_OPERATIONS)
115        return 0;
116
117    u64 ts = bpf_ktime_get_ns();
118    start.update(&pid, &ts);
119    return 0;
120}
121
122static int trace_return(struct pt_regs *ctx, const char *op)
123{
124    u64 *tsp;
125    u32 pid = bpf_get_current_pid_tgid();
126
127    // fetch timestamp and calculate delta
128    tsp = start.lookup(&pid);
129    if (tsp == 0) {
130        return 0;   // missed start or filtered
131    }
132    u64 delta = (bpf_ktime_get_ns() - *tsp) / FACTOR;
133
134    // store as histogram
135    dist_key_t key = {.slot = bpf_log2l(delta)};
136    __builtin_memcpy(&key.op, op, sizeof(key.op));
137    dist.increment(key);
138
139    start.delete(&pid);
140    return 0;
141}
142
143int trace_read_return(struct pt_regs *ctx)
144{
145    char *op = "read";
146    return trace_return(ctx, op);
147}
148
149int trace_write_return(struct pt_regs *ctx)
150{
151    char *op = "write";
152    return trace_return(ctx, op);
153}
154
155int trace_open_return(struct pt_regs *ctx)
156{
157    char *op = "open";
158    return trace_return(ctx, op);
159}
160
161int trace_fsync_return(struct pt_regs *ctx)
162{
163    char *op = "fsync";
164    return trace_return(ctx, op);
165}
166"""
167
168# code replacements
169with open(kallsyms) as syms:
170    ops = ''
171    for line in syms:
172        a = line.rstrip().split()
173        (addr, name) = (a[0], a[2])
174        name = name.split("\t")[0]
175        if name == "btrfs_file_operations":
176            ops = "0x" + addr
177            break
178    if ops == '':
179        print("ERROR: no btrfs_file_operations in /proc/kallsyms. Exiting.")
180        print("HINT: the kernel should be built with CONFIG_KALLSYMS_ALL.")
181        exit()
182    bpf_text = bpf_text.replace('BTRFS_FILE_OPERATIONS', ops)
183bpf_text = bpf_text.replace('FACTOR', str(factor))
184if args.pid:
185    bpf_text = bpf_text.replace('FILTER_PID', 'pid != %s' % pid)
186else:
187    bpf_text = bpf_text.replace('FILTER_PID', '0')
188if debug or args.ebpf:
189    print(bpf_text)
190    if args.ebpf:
191        exit()
192
193# load BPF program
194b = BPF(text=bpf_text)
195
196# Common file functions. See earlier comment about generic_file_read_iter().
197b.attach_kprobe(event="generic_file_read_iter", fn_name="trace_read_entry")
198b.attach_kprobe(event="btrfs_file_write_iter", fn_name="trace_entry")
199b.attach_kprobe(event="generic_file_open", fn_name="trace_open_entry")
200b.attach_kprobe(event="btrfs_sync_file", fn_name="trace_entry")
201b.attach_kretprobe(event="generic_file_read_iter", fn_name="trace_read_return")
202b.attach_kretprobe(event="btrfs_file_write_iter", fn_name="trace_write_return")
203b.attach_kretprobe(event="generic_file_open", fn_name="trace_open_return")
204b.attach_kretprobe(event="btrfs_sync_file", fn_name="trace_fsync_return")
205
206print("Tracing btrfs operation latency... Hit Ctrl-C to end.")
207
208# output
209exiting = 0
210dist = b.get_table("dist")
211while (1):
212    try:
213        if args.interval:
214            sleep(int(args.interval))
215        else:
216            sleep(99999999)
217    except KeyboardInterrupt:
218        exiting = 1
219
220    print()
221    if args.interval and (not args.notimestamp):
222        print(strftime("%H:%M:%S:"))
223
224    dist.print_log2_hist(label, "operation")
225    dist.clear()
226
227    countdown -= 1
228    if exiting or countdown == 0:
229        exit()
230