blob: 4c81200ef1f6c23d5f70f92fcdff0ab59fdfe34e [file] [log] [blame]
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -07001#!/usr/bin/python
2# @lint-avoid-python-3-compatibility-imports
3#
Sasha Goldshteina245c792016-10-25 02:18:35 -07004# ucalls Summarize method calls in high-level languages and/or system calls.
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -07005# For Linux, uses BCC, eBPF.
6#
Sasha Goldshteincfb5ee72017-02-08 14:32:51 -05007# USAGE: ucalls [-l {java,python,ruby,php}] [-h] [-T TOP] [-L] [-S] [-v] [-m]
Sasha Goldshteina245c792016-10-25 02:18:35 -07008# pid [interval]
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -07009#
10# Copyright 2016 Sasha Goldshtein
11# Licensed under the Apache License, Version 2.0 (the "License")
12#
13# 19-Oct-2016 Sasha Goldshtein Created this.
14
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -070015from __future__ import print_function
16import argparse
Paul Chaignon4bb6d7f2017-03-30 19:05:40 +020017from bcc import BPF, USDT, utils
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -070018from time import sleep
Paul Chaignon4bb6d7f2017-03-30 19:05:40 +020019import os
20
21languages = ["java", "python", "ruby", "php"]
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -070022
23examples = """examples:
Sasha Goldshteina245c792016-10-25 02:18:35 -070024 ./ucalls -l java 185 # trace Java calls and print statistics on ^C
25 ./ucalls -l python 2020 1 # trace Python calls and print every second
26 ./ucalls -l java 185 -S # trace Java calls and syscalls
27 ./ucalls 6712 -S # trace only syscall counts
28 ./ucalls -l ruby 1344 -T 10 # trace top 10 Ruby method calls
29 ./ucalls -l ruby 1344 -L # trace Ruby calls including latency
Sasha Goldshteincfb5ee72017-02-08 14:32:51 -050030 ./ucalls -l php 443 -LS # trace PHP calls and syscalls with latency
Sasha Goldshteina245c792016-10-25 02:18:35 -070031 ./ucalls -l python 2020 -mL # trace Python calls including latency in ms
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -070032"""
33parser = argparse.ArgumentParser(
34 description="Summarize method calls in high-level languages.",
35 formatter_class=argparse.RawDescriptionHelpFormatter,
36 epilog=examples)
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -070037parser.add_argument("pid", type=int, help="process id to attach to")
38parser.add_argument("interval", type=int, nargs='?',
39 help="print every specified number of seconds")
Paul Chaignon4bb6d7f2017-03-30 19:05:40 +020040parser.add_argument("-l", "--language", choices=languages + ["none"],
Sasha Goldshteina245c792016-10-25 02:18:35 -070041 help="language to trace (if none, trace syscalls only)")
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -070042parser.add_argument("-T", "--top", type=int,
43 help="number of most frequent/slow calls to print")
44parser.add_argument("-L", "--latency", action="store_true",
45 help="record method latency from enter to exit (except recursive calls)")
Sasha Goldshteina245c792016-10-25 02:18:35 -070046parser.add_argument("-S", "--syscalls", action="store_true",
47 help="record syscall latency (adds overhead)")
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -070048parser.add_argument("-v", "--verbose", action="store_true",
49 help="verbose mode: print the BPF program (for debugging purposes)")
50parser.add_argument("-m", "--milliseconds", action="store_true",
51 help="report times in milliseconds (default is microseconds)")
52args = parser.parse_args()
53
Paul Chaignon4bb6d7f2017-03-30 19:05:40 +020054language = args.language
55if not language:
56 language = utils.detect_language(languages, args.pid)
57
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -070058# We assume that the entry and return probes have the same arguments. This is
Sasha Goldshteincfb5ee72017-02-08 14:32:51 -050059# the case for Java, Python, Ruby, and PHP. If there's a language where it's
60# not the case, we will need to build a custom correlator from entry to exit.
Geneviève Bastien830c1f72017-07-14 16:04:12 -040061extra_message = ""
Paul Chaignon4bb6d7f2017-03-30 19:05:40 +020062if language == "java":
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -070063 # TODO for JVM entries, we actually have the real length of the class
Sasha Goldshteina245c792016-10-25 02:18:35 -070064 # and method strings in arg3 and arg5 respectively, so we can insert
65 # the null terminator in its proper position.
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -070066 entry_probe = "method__entry"
67 return_probe = "method__return"
68 read_class = "bpf_usdt_readarg(2, ctx, &clazz);"
69 read_method = "bpf_usdt_readarg(4, ctx, &method);"
Paul Chaignonc8b4f672017-10-07 11:51:45 +020070 extra_message = ("If you do not see any results, make sure you ran java"
71 " with option -XX:+ExtendedDTraceProbes")
Paul Chaignon4bb6d7f2017-03-30 19:05:40 +020072elif language == "python":
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -070073 entry_probe = "function__entry"
74 return_probe = "function__return"
75 read_class = "bpf_usdt_readarg(1, ctx, &clazz);" # filename really
76 read_method = "bpf_usdt_readarg(2, ctx, &method);"
Paul Chaignon4bb6d7f2017-03-30 19:05:40 +020077elif language == "ruby":
Sasha Goldshtein6e5c6212016-10-25 04:30:54 -070078 # TODO Also probe cmethod__entry and cmethod__return with same arguments
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -070079 entry_probe = "method__entry"
80 return_probe = "method__return"
81 read_class = "bpf_usdt_readarg(1, ctx, &clazz);"
82 read_method = "bpf_usdt_readarg(2, ctx, &method);"
Paul Chaignon4bb6d7f2017-03-30 19:05:40 +020083elif language == "php":
Sasha Goldshteincfb5ee72017-02-08 14:32:51 -050084 entry_probe = "function__entry"
85 return_probe = "function__return"
86 read_class = "bpf_usdt_readarg(4, ctx, &clazz);"
87 read_method = "bpf_usdt_readarg(1, ctx, &method);"
Paul Chaignonc8b4f672017-10-07 11:51:45 +020088 extra_message = ("If you do not see any results, make sure the environment"
89 " variable USE_ZEND_DTRACE is set to 1")
Paul Chaignon4bb6d7f2017-03-30 19:05:40 +020090elif not language or language == "none":
Sasha Goldshteina245c792016-10-25 02:18:35 -070091 if not args.syscalls:
92 print("Nothing to do; use -S to trace syscalls.")
93 exit(1)
94 entry_probe, return_probe, read_class, read_method = ("", "", "", "")
Paul Chaignon4bb6d7f2017-03-30 19:05:40 +020095 if language:
96 language = None
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -070097
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -070098program = """
Sasha Goldshteina245c792016-10-25 02:18:35 -070099#include <linux/ptrace.h>
100
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700101#define MAX_STRING_LENGTH 80
Sasha Goldshteina245c792016-10-25 02:18:35 -0700102DEFINE_NOLANG
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700103DEFINE_LATENCY
Sasha Goldshteina245c792016-10-25 02:18:35 -0700104DEFINE_SYSCALLS
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700105
106struct method_t {
107 char clazz[MAX_STRING_LENGTH];
108 char method[MAX_STRING_LENGTH];
109};
110struct entry_t {
111 u64 pid;
112 struct method_t method;
113};
114struct info_t {
115 u64 num_calls;
116 u64 total_ns;
117};
Sasha Goldshteina245c792016-10-25 02:18:35 -0700118struct syscall_entry_t {
119 u64 timestamp;
120 u64 ip;
121};
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700122
123#ifndef LATENCY
Sasha Goldshteina245c792016-10-25 02:18:35 -0700124 BPF_HASH(counts, struct method_t, u64); // number of calls
125 #ifdef SYSCALLS
126 BPF_HASH(syscounts, u64, u64); // number of calls per IP
127 #endif // SYSCALLS
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700128#else
Sasha Goldshteina245c792016-10-25 02:18:35 -0700129 BPF_HASH(times, struct method_t, struct info_t);
130 BPF_HASH(entry, struct entry_t, u64); // timestamp at entry
131 #ifdef SYSCALLS
132 BPF_HASH(systimes, u64, struct info_t); // latency per IP
133 BPF_HASH(sysentry, u64, struct syscall_entry_t); // ts + IP at entry
134 #endif // SYSCALLS
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700135#endif
136
Sasha Goldshteina245c792016-10-25 02:18:35 -0700137#ifndef NOLANG
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700138int trace_entry(struct pt_regs *ctx) {
139 u64 clazz = 0, method = 0, val = 0;
140 u64 *valp;
141 struct entry_t data = {0};
142#ifdef LATENCY
143 u64 timestamp = bpf_ktime_get_ns();
144 data.pid = bpf_get_current_pid_tgid();
145#endif
146 READ_CLASS
147 READ_METHOD
148 bpf_probe_read(&data.method.clazz, sizeof(data.method.clazz),
149 (void *)clazz);
150 bpf_probe_read(&data.method.method, sizeof(data.method.method),
151 (void *)method);
152#ifndef LATENCY
153 valp = counts.lookup_or_init(&data.method, &val);
154 ++(*valp);
155#endif
156#ifdef LATENCY
157 entry.update(&data, &timestamp);
158#endif
159 return 0;
160}
161
162#ifdef LATENCY
163int trace_return(struct pt_regs *ctx) {
164 u64 *entry_timestamp, clazz = 0, method = 0;
165 struct info_t *info, zero = {};
166 struct entry_t data = {};
167 data.pid = bpf_get_current_pid_tgid();
168 READ_CLASS
169 READ_METHOD
170 bpf_probe_read(&data.method.clazz, sizeof(data.method.clazz),
171 (void *)clazz);
172 bpf_probe_read(&data.method.method, sizeof(data.method.method),
173 (void *)method);
174 entry_timestamp = entry.lookup(&data);
175 if (!entry_timestamp) {
176 return 0; // missed the entry event
177 }
178 info = times.lookup_or_init(&data.method, &zero);
179 info->num_calls += 1;
180 info->total_ns += bpf_ktime_get_ns() - *entry_timestamp;
181 entry.delete(&data);
182 return 0;
183}
Sasha Goldshteina245c792016-10-25 02:18:35 -0700184#endif // LATENCY
185#endif // NOLANG
186
187#ifdef SYSCALLS
188int syscall_entry(struct pt_regs *ctx) {
189 u64 pid = bpf_get_current_pid_tgid();
Yonghong Songeb6ddc02017-10-26 22:33:24 -0700190 u64 *valp, ip = PT_REGS_IP(ctx), val = 0;
Sasha Goldshteina245c792016-10-25 02:18:35 -0700191 PID_FILTER
192#ifdef LATENCY
193 struct syscall_entry_t data = {};
194 data.timestamp = bpf_ktime_get_ns();
195 data.ip = ip;
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700196#endif
Sasha Goldshteina245c792016-10-25 02:18:35 -0700197#ifndef LATENCY
198 valp = syscounts.lookup_or_init(&ip, &val);
199 ++(*valp);
200#endif
201#ifdef LATENCY
202 sysentry.update(&pid, &data);
203#endif
204 return 0;
205}
206
207#ifdef LATENCY
208int syscall_return(struct pt_regs *ctx) {
209 struct syscall_entry_t *e;
210 struct info_t *info, zero = {};
211 u64 pid = bpf_get_current_pid_tgid(), ip;
212 PID_FILTER
213 e = sysentry.lookup(&pid);
214 if (!e) {
215 return 0; // missed the entry event
216 }
217 ip = e->ip;
218 info = systimes.lookup_or_init(&ip, &zero);
219 info->num_calls += 1;
220 info->total_ns += bpf_ktime_get_ns() - e->timestamp;
221 sysentry.delete(&pid);
222 return 0;
223}
224#endif // LATENCY
225#endif // SYSCALLS
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700226""".replace("READ_CLASS", read_class) \
227 .replace("READ_METHOD", read_method) \
Sasha Goldshteina245c792016-10-25 02:18:35 -0700228 .replace("PID_FILTER", "if ((pid >> 32) != %d) { return 0; }" % args.pid) \
Paul Chaignon4bb6d7f2017-03-30 19:05:40 +0200229 .replace("DEFINE_NOLANG", "#define NOLANG" if not language else "") \
Sasha Goldshteina245c792016-10-25 02:18:35 -0700230 .replace("DEFINE_LATENCY", "#define LATENCY" if args.latency else "") \
231 .replace("DEFINE_SYSCALLS", "#define SYSCALLS" if args.syscalls else "")
232
Paul Chaignon4bb6d7f2017-03-30 19:05:40 +0200233if language:
Sasha Goldshteina245c792016-10-25 02:18:35 -0700234 usdt = USDT(pid=args.pid)
Sasha Goldshteindc3a57c2017-02-08 16:02:11 -0500235 usdt.enable_probe_or_bail(entry_probe, "trace_entry")
Sasha Goldshteina245c792016-10-25 02:18:35 -0700236 if args.latency:
Sasha Goldshteindc3a57c2017-02-08 16:02:11 -0500237 usdt.enable_probe_or_bail(return_probe, "trace_return")
Sasha Goldshteina245c792016-10-25 02:18:35 -0700238else:
239 usdt = None
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700240
241if args.verbose:
Sasha Goldshteina245c792016-10-25 02:18:35 -0700242 if usdt:
243 print(usdt.get_text())
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700244 print(program)
245
Sasha Goldshteina245c792016-10-25 02:18:35 -0700246bpf = BPF(text=program, usdt_contexts=[usdt] if usdt else [])
247if args.syscalls:
248 syscall_regex = "^[Ss]y[Ss]_.*"
249 bpf.attach_kprobe(event_re=syscall_regex, fn_name="syscall_entry")
250 if args.latency:
251 bpf.attach_kretprobe(event_re=syscall_regex, fn_name="syscall_return")
252 print("Attached %d kernel probes for syscall tracing." %
253 bpf.num_open_kprobes())
254
255def get_data():
256 # Will be empty when no language was specified for tracing
257 if args.latency:
Rafael Fonseca99d14682017-12-15 16:49:32 +0100258 data = list(map(lambda kv: (kv[0].clazz.decode() + "." + \
259 kv[0].method.decode(),
Rafael Fonseca0d669062017-02-13 15:52:04 +0100260 (kv[1].num_calls, kv[1].total_ns)),
Rafael Fonseca42900ae2017-02-13 15:46:54 +0100261 bpf["times"].items()))
Sasha Goldshteina245c792016-10-25 02:18:35 -0700262 else:
Rafael Fonseca99d14682017-12-15 16:49:32 +0100263 data = list(map(lambda kv: (kv[0].clazz.decode() + "." + \
264 kv[0].method.decode(),
Rafael Fonseca0d669062017-02-13 15:52:04 +0100265 (kv[1].value, 0)),
Rafael Fonseca42900ae2017-02-13 15:46:54 +0100266 bpf["counts"].items()))
Sasha Goldshteina245c792016-10-25 02:18:35 -0700267
268 if args.syscalls:
269 if args.latency:
Rafael Fonseca0d669062017-02-13 15:52:04 +0100270 syscalls = map(lambda kv: (bpf.ksym(kv[0].value),
271 (kv[1].num_calls, kv[1].total_ns)),
Sasha Goldshteina245c792016-10-25 02:18:35 -0700272 bpf["systimes"].items())
273 data.extend(syscalls)
274 else:
Paul Chaignon956ca1c2017-03-04 20:07:56 +0100275 syscalls = map(lambda kv: (bpf.ksym(kv[0].value),
276 (kv[1].value, 0)),
Sasha Goldshteina245c792016-10-25 02:18:35 -0700277 bpf["syscounts"].items())
278 data.extend(syscalls)
279
Rafael Fonseca0d669062017-02-13 15:52:04 +0100280 return sorted(data, key=lambda kv: kv[1][1 if args.latency else 0])
Sasha Goldshteina245c792016-10-25 02:18:35 -0700281
282def clear_data():
283 if args.latency:
284 bpf["times"].clear()
285 else:
286 bpf["counts"].clear()
287
288 if args.syscalls:
289 if args.latency:
290 bpf["systimes"].clear()
291 else:
292 bpf["syscounts"].clear()
293
294exit_signaled = False
295print("Tracing calls in process %d (language: %s)... Ctrl-C to quit." %
Paul Chaignon4bb6d7f2017-03-30 19:05:40 +0200296 (args.pid, language or "none"))
Geneviève Bastien830c1f72017-07-14 16:04:12 -0400297if extra_message:
298 print(extra_message)
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700299while True:
300 try:
301 sleep(args.interval or 99999999)
302 except KeyboardInterrupt:
Sasha Goldshteina245c792016-10-25 02:18:35 -0700303 exit_signaled = True
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700304 print()
Sasha Goldshteina245c792016-10-25 02:18:35 -0700305 data = get_data() # [(function, (num calls, latency in ns))]
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700306 if args.latency:
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700307 time_col = "TIME (ms)" if args.milliseconds else "TIME (us)"
308 print("%-50s %8s %8s" % ("METHOD", "# CALLS", time_col))
309 else:
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700310 print("%-50s %8s" % ("METHOD", "# CALLS"))
311 if args.top:
312 data = data[-args.top:]
313 for key, value in data:
314 if args.latency:
Paul Chaignon956ca1c2017-03-04 20:07:56 +0100315 time = value[1] / 1000000.0 if args.milliseconds else \
316 value[1] / 1000.0
Sasha Goldshteina245c792016-10-25 02:18:35 -0700317 print("%-50s %8d %6.2f" % (key, value[0], time))
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700318 else:
Sasha Goldshteina245c792016-10-25 02:18:35 -0700319 print("%-50s %8d" % (key, value[0]))
320 if args.interval and not exit_signaled:
321 clear_data()
322 else:
323 if args.syscalls:
324 print("Detaching kernel probes, please wait...")
Sasha Goldshteinc13d14f2016-10-17 04:13:48 -0700325 exit()