1#!/usr/bin/env python
2# @lint-avoid-python-3-compatibility-imports
3#
4# xfsdist  Summarize XFS operation latency.
5#          For Linux, uses BCC, eBPF.
6#
7# USAGE: xfsdist [-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# 12-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# arguments
20examples = """examples:
21    ./xfsdist            # show operation latency as a histogram
22    ./xfsdist -p 181     # trace PID 181 only
23    ./xfsdist 1 10       # print 1 second summaries, 10 times
24    ./xfsdist -m 5       # 5s summaries, milliseconds
25"""
26parser = argparse.ArgumentParser(
27    description="Summarize XFS operation latency",
28    formatter_class=argparse.RawDescriptionHelpFormatter,
29    epilog=examples)
30parser.add_argument("-T", "--notimestamp", action="store_true",
31    help="don't include timestamp on interval output")
32parser.add_argument("-m", "--milliseconds", action="store_true",
33    help="output in milliseconds")
34parser.add_argument("-p", "--pid",
35    help="trace this PID only")
36parser.add_argument("interval", nargs="?",
37    help="output interval, in seconds")
38parser.add_argument("count", nargs="?", default=99999999,
39    help="number of outputs")
40parser.add_argument("--ebpf", action="store_true",
41    help=argparse.SUPPRESS)
42args = parser.parse_args()
43pid = args.pid
44countdown = int(args.count)
45if args.milliseconds:
46    factor = 1000000
47    label = "msecs"
48else:
49    factor = 1000
50    label = "usecs"
51if args.interval and int(args.interval) == 0:
52    print("ERROR: interval 0. Exiting.")
53    exit()
54debug = 0
55
56# define BPF program
57bpf_text = """
58#include <uapi/linux/ptrace.h>
59#include <linux/fs.h>
60#include <linux/sched.h>
61
62#define OP_NAME_LEN 8
63typedef struct dist_key {
64    char op[OP_NAME_LEN];
65    u64 slot;
66} dist_key_t;
67BPF_HASH(start, u32);
68BPF_HISTOGRAM(dist, dist_key_t);
69
70// time operation
71int trace_entry(struct pt_regs *ctx)
72{
73    u32 pid = bpf_get_current_pid_tgid();
74    if (FILTER_PID)
75        return 0;
76    u64 ts = bpf_ktime_get_ns();
77    start.update(&pid, &ts);
78    return 0;
79}
80
81static int trace_return(struct pt_regs *ctx, const char *op)
82{
83    u64 *tsp;
84    u32 pid = bpf_get_current_pid_tgid();
85
86    // fetch timestamp and calculate delta
87    tsp = start.lookup(&pid);
88    if (tsp == 0) {
89        return 0;   // missed start or filtered
90    }
91    u64 delta = (bpf_ktime_get_ns() - *tsp) / FACTOR;
92
93    // store as histogram
94    dist_key_t key = {.slot = bpf_log2l(delta)};
95    __builtin_memcpy(&key.op, op, sizeof(key.op));
96    dist.increment(key);
97
98    start.delete(&pid);
99    return 0;
100}
101
102int trace_read_return(struct pt_regs *ctx)
103{
104    char *op = "read";
105    return trace_return(ctx, op);
106}
107
108int trace_write_return(struct pt_regs *ctx)
109{
110    char *op = "write";
111    return trace_return(ctx, op);
112}
113
114int trace_open_return(struct pt_regs *ctx)
115{
116    char *op = "open";
117    return trace_return(ctx, op);
118}
119
120int trace_fsync_return(struct pt_regs *ctx)
121{
122    char *op = "fsync";
123    return trace_return(ctx, op);
124}
125"""
126bpf_text = bpf_text.replace('FACTOR', str(factor))
127if args.pid:
128    bpf_text = bpf_text.replace('FILTER_PID', 'pid != %s' % pid)
129else:
130    bpf_text = bpf_text.replace('FILTER_PID', '0')
131if debug or args.ebpf:
132    print(bpf_text)
133    if args.ebpf:
134        exit()
135
136# load BPF program
137b = BPF(text=bpf_text)
138
139# common file functions
140b.attach_kprobe(event="xfs_file_read_iter", fn_name="trace_entry")
141b.attach_kprobe(event="xfs_file_write_iter", fn_name="trace_entry")
142b.attach_kprobe(event="xfs_file_open", fn_name="trace_entry")
143b.attach_kprobe(event="xfs_file_fsync", fn_name="trace_entry")
144b.attach_kretprobe(event="xfs_file_read_iter", fn_name="trace_read_return")
145b.attach_kretprobe(event="xfs_file_write_iter", fn_name="trace_write_return")
146b.attach_kretprobe(event="xfs_file_open", fn_name="trace_open_return")
147b.attach_kretprobe(event="xfs_file_fsync", fn_name="trace_fsync_return")
148
149print("Tracing XFS operation latency... Hit Ctrl-C to end.")
150
151# output
152exiting = 0
153dist = b.get_table("dist")
154while (1):
155    try:
156        if args.interval:
157            sleep(int(args.interval))
158        else:
159            sleep(99999999)
160    except KeyboardInterrupt:
161        exiting = 1
162
163    print()
164    if args.interval and (not args.notimestamp):
165        print(strftime("%H:%M:%S:"))
166
167    dist.print_log2_hist(label, "operation")
168    dist.clear()
169
170    countdown -= 1
171    if exiting or countdown == 0:
172        exit()
173