1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
|
#!/usr/bin/python
import argparse
from time import sleep, strftime
from sys import argv
import ctypes as ct
from bcc import BPF, USDT
import inspect
import os
# Parse command line arguments
parser = argparse.ArgumentParser(description="Trace the latency distribution of an operation using usdt probes.",
formatter_class=argparse.RawDescriptionHelpFormatter)
parser.add_argument("-p", "--pid", type=int, help="The id of the process to trace.")
parser.add_argument("-i", "--interval", type=int, help="The interval in seconds on which to report the latency distribution.")
parser.add_argument("-f", "--filterstr", type=str, default="", help="The prefix filter for the operation input. If specified, only operations for which the input string starts with the filterstr are traced.")
parser.add_argument("-v", "--verbose", dest="verbose", action="store_true", help="If true, will output generated bpf program and verbose logging information.")
parser.add_argument("-s", "--sdt", dest="sdt", action="store_true", help="If true, will use the probes, created by systemtap's dtrace.")
parser.set_defaults(verbose=False)
args = parser.parse_args()
this_pid = int(args.pid)
this_interval = int(args.interval)
this_filter = str(args.filterstr)
if this_interval < 1:
print("Invalid value for interval, using 1.")
this_interval = 1
debugLevel=0
if args.verbose:
debugLevel=4
# BPF program
bpf_text_shared = "%s/bpf_text_shared.c" % os.path.dirname(os.path.abspath(inspect.getfile(inspect.currentframe())))
bpf_text = open(bpf_text_shared, 'r').read()
bpf_text += """
/**
* @brief The key to use for the latency histogram.
*/
struct dist_key_t
{
char input[64]; ///< The input string of the request.
u64 slot; ///< The histogram slot.
};
/**
* @brief Contains the histogram for the operation latencies.
*/
BPF_HISTOGRAM(dist, struct dist_key_t);
/**
* @brief Reads the operation response arguments, calculates the latency, and stores it in the histogram.
* @param ctx The BPF context.
*/
int trace_operation_end(struct pt_regs* ctx)
{
u64 operation_id;
bpf_usdt_readarg(1, ctx, &operation_id);
struct start_data_t* start_data = start_hash.lookup(&operation_id);
if (0 == start_data) {
return 0;
}
u64 duration = bpf_ktime_get_ns() - start_data->start;
struct dist_key_t dist_key = {};
__builtin_memcpy(&dist_key.input, start_data->input, sizeof(dist_key.input));
dist_key.slot = bpf_log2l(duration / 1000);
start_hash.delete(&operation_id);
dist.atomic_increment(dist_key);
return 0;
}
"""
bpf_text = bpf_text.replace("FILTER_STRING", this_filter)
if this_filter:
bpf_text = bpf_text.replace("FILTER_STATEMENT", "if (!filter(start_data.input)) { return 0; }")
else:
bpf_text = bpf_text.replace("FILTER_STATEMENT", "")
# Create USDT context
print("lat_dist.py - Attaching probes to pid: %d; filter: %s" % (this_pid, this_filter))
usdt_ctx = USDT(pid=this_pid)
if args.sdt:
usdt_ctx.enable_probe(probe="usdt_sample_lib1_sdt:operation_start_sdt", fn_name="trace_operation_start")
usdt_ctx.enable_probe(probe="usdt_sample_lib1_sdt:operation_end_sdt", fn_name="trace_operation_end")
else:
usdt_ctx.enable_probe(probe="usdt_sample_lib1:operation_start", fn_name="trace_operation_start")
usdt_ctx.enable_probe(probe="usdt_sample_lib1:operation_end", fn_name="trace_operation_end")
# Create BPF context, load BPF program
bpf_ctx = BPF(text=bpf_text, usdt_contexts=[usdt_ctx], debug=debugLevel)
print("Tracing... Hit Ctrl-C to end.")
start = 0
dist = bpf_ctx.get_table("dist")
while (1):
try:
sleep(this_interval)
except KeyboardInterrupt:
exit()
print("[%s]" % strftime("%H:%M:%S"))
dist.print_log2_hist("latency (us)")
|
