blob: f409f90dbabe9cf21854e1097c2f1e49f8a98fa5 [file] [log] [blame]
Brendan Gregg23c96fe2016-02-12 02:25:32 -08001#!/usr/bin/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")
Nathan Scottcf0792f2018-02-02 16:56:50 +110040parser.add_argument("--ebpf", action="store_true",
41 help=argparse.SUPPRESS)
Brendan Gregg23c96fe2016-02-12 02:25:32 -080042args = 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')
Nathan Scottcf0792f2018-02-02 16:56:50 +1100131if debug or args.ebpf:
Brendan Gregg23c96fe2016-02-12 02:25:32 -0800132 print(bpf_text)
Nathan Scottcf0792f2018-02-02 16:56:50 +1100133 if args.ebpf:
134 exit()
Brendan Gregg23c96fe2016-02-12 02:25:32 -0800135
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()