xref: /aosp_15_r20/external/bcc/tools/ext4dist.py (revision 387f9dfdfa2baef462e92476d413c7bc2470293e) 
1#!/usr/bin/env python
2# @lint-avoid-python-3-compatibility-imports
3#
4# ext4dist  Summarize ext4 operation latency.
5#           For Linux, uses BCC, eBPF.
6#
7# USAGE: ext4dist [-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# symbols
20kallsyms = "/proc/kallsyms"
21
22# arguments
23examples = """examples:
24    ./ext4dist            # show operation latency as a histogram
25    ./ext4dist -p 181     # trace PID 181 only
26    ./ext4dist 1 10       # print 1 second summaries, 10 times
27    ./ext4dist -m 5       # 5s summaries, milliseconds
28"""
29parser = argparse.ArgumentParser(
30    description="Summarize ext4 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    u64 pid_tgid = bpf_get_current_pid_tgid();
77    u32 pid = pid_tgid >> 32;
78    u32 tid = (u32)pid_tgid;
79
80    if (FILTER_PID)
81        return 0;
82    u64 ts = bpf_ktime_get_ns();
83    start.update(&tid, &ts);
84    return 0;
85}
86
87EXT4_TRACE_READ_CODE
88
89static int trace_return(struct pt_regs *ctx, const char *op)
90{
91    u64 *tsp;
92    u64 pid_tgid = bpf_get_current_pid_tgid();
93    u32 pid = pid_tgid >> 32;
94    u32 tid = (u32)pid_tgid;
95
96    // fetch timestamp and calculate delta
97    tsp = start.lookup(&tid);
98    if (tsp == 0) {
99        return 0;   // missed start or filtered
100    }
101    u64 delta = bpf_ktime_get_ns() - *tsp;
102    start.delete(&tid);
103
104    // Skip entries with backwards time: temp workaround for #728
105    if ((s64) delta < 0)
106        return 0;
107
108    delta /= FACTOR;
109
110    // store as histogram
111    dist_key_t key = {.slot = bpf_log2l(delta)};
112    __builtin_memcpy(&key.op, op, sizeof(key.op));
113    dist.atomic_increment(key);
114
115    return 0;
116}
117
118int trace_read_return(struct pt_regs *ctx)
119{
120    char *op = "read";
121    return trace_return(ctx, op);
122}
123
124int trace_write_return(struct pt_regs *ctx)
125{
126    char *op = "write";
127    return trace_return(ctx, op);
128}
129
130int trace_open_return(struct pt_regs *ctx)
131{
132    char *op = "open";
133    return trace_return(ctx, op);
134}
135
136int trace_fsync_return(struct pt_regs *ctx)
137{
138    char *op = "fsync";
139    return trace_return(ctx, op);
140}
141"""
142
143# Starting from Linux 4.10 ext4_file_operations.read_iter has been changed from
144# using generic_file_read_iter() to its own ext4_file_read_iter().
145#
146# To detect the proper function to trace check if ext4_file_read_iter() is
147# defined in /proc/kallsyms, if it's defined attach to that function, otherwise
148# use generic_file_read_iter() and inside the trace hook filter on ext4 read
149# events (checking if file->f_op == ext4_file_operations).
150if BPF.get_kprobe_functions(b'ext4_file_read_iter'):
151    ext4_read_fn = 'ext4_file_read_iter'
152    ext4_trace_read_fn = 'trace_entry'
153    ext4_trace_read_code = ''
154else:
155    ext4_read_fn = 'generic_file_read_iter'
156    ext4_trace_read_fn = 'trace_read_entry'
157    ext4_file_ops_addr = ''
158    with open(kallsyms) as syms:
159        for line in syms:
160            (addr, size, name) = line.rstrip().split(" ", 2)
161            name = name.split("\t")[0]
162            if name == "ext4_file_operations":
163                ext4_file_ops_addr = "0x" + addr
164                break
165        if ext4_file_ops_addr == '':
166            print("ERROR: no ext4_file_operations in /proc/kallsyms. Exiting.")
167            print("HINT: the kernel should be built with CONFIG_KALLSYMS_ALL.")
168            exit()
169    ext4_trace_read_code = """
170int trace_read_entry(struct pt_regs *ctx, struct kiocb *iocb)
171{
172    u64 pid_tgid = bpf_get_current_pid_tgid();
173    u32 pid = pid_tgid >> 32;
174    u32 tid = (u32)pid_tgid;
175
176    if (FILTER_PID)
177        return 0;
178
179    // ext4 filter on file->f_op == ext4_file_operations
180    struct file *fp = iocb->ki_filp;
181    if ((u64)fp->f_op != %s)
182        return 0;
183
184    u64 ts = bpf_ktime_get_ns();
185    start.update(&tid, &ts);
186    return 0;
187}""" % ext4_file_ops_addr
188
189# code replacements
190bpf_text = bpf_text.replace('EXT4_TRACE_READ_CODE', ext4_trace_read_code)
191bpf_text = bpf_text.replace('FACTOR', str(factor))
192if args.pid:
193    bpf_text = bpf_text.replace('FILTER_PID', 'pid != %s' % pid)
194else:
195    bpf_text = bpf_text.replace('FILTER_PID', '0')
196if debug or args.ebpf:
197    print(bpf_text)
198    if args.ebpf:
199        exit()
200
201# load BPF program
202b = BPF(text=bpf_text)
203
204b.attach_kprobe(event=ext4_read_fn, fn_name=ext4_trace_read_fn)
205b.attach_kprobe(event="ext4_file_write_iter", fn_name="trace_entry")
206b.attach_kprobe(event="ext4_file_open", fn_name="trace_entry")
207b.attach_kprobe(event="ext4_sync_file", fn_name="trace_entry")
208b.attach_kretprobe(event=ext4_read_fn, fn_name='trace_read_return')
209b.attach_kretprobe(event="ext4_file_write_iter", fn_name="trace_write_return")
210b.attach_kretprobe(event="ext4_file_open", fn_name="trace_open_return")
211b.attach_kretprobe(event="ext4_sync_file", fn_name="trace_fsync_return")
212
213print("Tracing ext4 operation latency... Hit Ctrl-C to end.")
214
215# output
216exiting = 0
217dist = b.get_table("dist")
218while (1):
219    try:
220        if args.interval:
221            sleep(int(args.interval))
222        else:
223            sleep(99999999)
224    except KeyboardInterrupt:
225        exiting = 1
226
227    print()
228    if args.interval and (not args.notimestamp):
229        print(strftime("%H:%M:%S:"))
230
231    dist.print_log2_hist(label, "operation", section_print_fn=bytes.decode)
232    dist.clear()
233
234    countdown -= 1
235    if exiting or countdown == 0:
236        exit()
237