/
latency.py
executable file
·117 lines (100 loc) · 4.18 KB
/
latency.py
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
109
110
111
112
113
114
115
116
117
import argparse
from time import sleep
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 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("-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 verbose logging information.")
parser.set_defaults(verbose=False)
args = parser.parse_args()
this_pid = int(args.pid)
this_filter = str(args.filterstr)
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 Contains the latency data w.r.t. the complete operation from request to response.
*/
struct end_data_t
{
u64 operation_id; ///< The id of the operation.
char input[64]; ///< The request (input) string.
char output[64]; ///< The response (output) string.
u64 start; ///< The start timestamp of the operation.
u64 end; ///< The end timestamp of the operation.
u64 duration; ///< The duration of the operation.
};
/**
* The output buffer, which will be used to push the latency event data to user space.
*/
BPF_PERF_OUTPUT(operation_event);
/**
* @brief Reads the operation response arguments, calculates the latency event data, and writes it to the user output buffer.
* @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;
}
struct end_data_t end_data = {};
end_data.operation_id = operation_id;
bpf_usdt_readarg_p(2, ctx, &end_data.output, sizeof(end_data.output));
end_data.end = bpf_ktime_get_ns();
end_data.start = start_data->start;
end_data.duration = end_data.end - end_data.start;
__builtin_memcpy(&end_data.input, start_data->input, sizeof(end_data.input));
start_hash.delete(&end_data.operation_id);
operation_event.perf_submit(ctx, &end_data, sizeof(end_data));
return 0;
}
"""
bpf_text = bpf_text.replace("FILTER_STRING", this_filter)
if this_filter:
bpf_text = bpf_text.replace("FILTER", "if (!filter(start_data.input)) { return 0; }")
else:
bpf_text = bpf_text.replace("FILTER", "")
# Create USDT context
print("Attaching probes to pid %d" % this_pid)
usdt_ctx = USDT(pid=this_pid)
usdt_ctx.enable_probe(probe="operation_start", fn_name="trace_operation_start")
usdt_ctx.enable_probe(probe="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)
# Define latency event and print function
class OperationEventData(ct.Structure):
_fields_ = [("operation_id", ct.c_ulonglong),
("input", ct.c_char * 64),
("output", ct.c_char * 64),
("start", ct.c_ulonglong),
("end", ct.c_ulonglong),
("duration", ct.c_ulonglong)]
start = 0
def print_event(cpu, data, size):
global start
event = ct.cast(data, ct.POINTER(OperationEventData)).contents
if start == 0:
start = event.start
time_s = (float(event.start - start)) / 1000000000
latency = (float(event.duration) / 1000)
print("%-18.9f %-10d %-32s %-32s %16d %16d %16d" % (time_s, event.operation_id, event.input, event.output, event.start, event.end, latency))
# Print header
print("Tracing... Hit Ctrl-C to end.")
print("%-18s %-10s %-32s %-32s %16s %16s %16s" % ("time(s)", "id", "input", "output", "start (ns)", "end (ns)", "duration (us)"))
# Output latency events
bpf_ctx["operation_event"].open_perf_buffer(print_event)
while 1:
bpf_ctx.perf_buffer_poll()