• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1#!/usr/bin/python
2# @lint-avoid-python-3-compatibility-imports
3#
4# zfsdist  Summarize ZFS operation latency.
5#          For Linux, uses BCC, eBPF.
6#
7# USAGE: zfsdist [-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# 14-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    ./zfsdist            # show operation latency as a histogram
22    ./zfsdist -p 181     # trace PID 181 only
23    ./zfsdist 1 10       # print 1 second summaries, 10 times
24    ./zfsdist -m 5       # 5s summaries, milliseconds
25"""
26parser = argparse.ArgumentParser(
27    description="Summarize ZFS 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
140if BPF.get_kprobe_functions(b'zpl_iter'):
141    b.attach_kprobe(event="zpl_iter_read", fn_name="trace_entry")
142    b.attach_kprobe(event="zpl_iter_write", fn_name="trace_entry")
143elif BPF.get_kprobe_functions(b'zpl_aio'):
144    b.attach_kprobe(event="zpl_aio_read", fn_name="trace_entry")
145    b.attach_kprobe(event="zpl_aio_write", fn_name="trace_entry")
146else:
147    b.attach_kprobe(event="zpl_read", fn_name="trace_entry")
148    b.attach_kprobe(event="zpl_write", fn_name="trace_entry")
149b.attach_kprobe(event="zpl_open", fn_name="trace_entry")
150b.attach_kprobe(event="zpl_fsync", fn_name="trace_entry")
151if BPF.get_kprobe_functions(b'zpl_iter'):
152    b.attach_kretprobe(event="zpl_iter_read", fn_name="trace_read_return")
153    b.attach_kretprobe(event="zpl_iter_write", fn_name="trace_write_return")
154elif BPF.get_kprobe_functions(b'zpl_aio'):
155    b.attach_kretprobe(event="zpl_aio_read", fn_name="trace_read_return")
156    b.attach_kretprobe(event="zpl_aio_write", fn_name="trace_write_return")
157else:
158    b.attach_kretprobe(event="zpl_read", fn_name="trace_read_return")
159    b.attach_kretprobe(event="zpl_write", fn_name="trace_write_return")
160b.attach_kretprobe(event="zpl_open", fn_name="trace_open_return")
161b.attach_kretprobe(event="zpl_fsync", fn_name="trace_fsync_return")
162
163print("Tracing ZFS operation latency... Hit Ctrl-C to end.")
164
165# output
166exiting = 0
167dist = b.get_table("dist")
168while (1):
169    try:
170        if args.interval:
171            sleep(int(args.interval))
172        else:
173            sleep(99999999)
174    except KeyboardInterrupt:
175        exiting = 1
176
177    print()
178    if args.interval and (not args.notimestamp):
179        print(strftime("%H:%M:%S:"))
180
181    dist.print_log2_hist(label, "operation")
182    dist.clear()
183
184    countdown -= 1
185    if exiting or countdown == 0:
186        exit()
187