• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
1#!/usr/bin/env python
2# @lint-avoid-python-3-compatibility-imports
3#
4# ucalls  Summarize method calls in high-level languages and/or system calls.
5#         For Linux, uses BCC, eBPF.
6#
7# USAGE: ucalls [-l {java,perl,php,python,ruby,tcl}] [-h] [-T TOP] [-L] [-S] [-v] [-m]
8#        pid [interval]
9#
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
15from __future__ import print_function
16import argparse
17from time import sleep
18from bcc import BPF, USDT, utils, syscall_name
19
20languages = ["java", "perl", "php", "python", "ruby", "tcl"]
21
22examples = """examples:
23    ./ucalls -l java 185        # trace Java calls and print statistics on ^C
24    ./ucalls -l python 2020 1   # trace Python calls and print every second
25    ./ucalls -l java 185 -S     # trace Java calls and syscalls
26    ./ucalls 6712 -S            # trace only syscall counts
27    ./ucalls -l ruby 1344 -T 10 # trace top 10 Ruby method calls
28    ./ucalls -l ruby 1344 -L    # trace Ruby calls including latency
29    ./ucalls -l php 443 -LS     # trace PHP calls and syscalls with latency
30    ./ucalls -l python 2020 -mL # trace Python calls including latency in ms
31"""
32parser = argparse.ArgumentParser(
33    description="Summarize method calls in high-level languages.",
34    formatter_class=argparse.RawDescriptionHelpFormatter,
35    epilog=examples)
36parser.add_argument("pid", type=int, help="process id to attach to")
37parser.add_argument("interval", type=int, nargs='?',
38    help="print every specified number of seconds")
39parser.add_argument("-l", "--language", choices=languages + ["none"],
40    help="language to trace (if none, trace syscalls only)")
41parser.add_argument("-T", "--top", type=int,
42    help="number of most frequent/slow calls to print")
43parser.add_argument("-L", "--latency", action="store_true",
44    help="record method latency from enter to exit (except recursive calls)")
45parser.add_argument("-S", "--syscalls", action="store_true",
46    help="record syscall latency (adds overhead)")
47parser.add_argument("-v", "--verbose", action="store_true",
48    help="verbose mode: print the BPF program (for debugging purposes)")
49parser.add_argument("-m", "--milliseconds", action="store_true",
50    help="report times in milliseconds (default is microseconds)")
51parser.add_argument("--ebpf", action="store_true",
52    help=argparse.SUPPRESS)
53args = parser.parse_args()
54
55language = args.language
56if not language:
57    language = utils.detect_language(languages, args.pid)
58
59# We assume that the entry and return probes have the same arguments. This is
60# the case for Java, Python, Ruby, and PHP. If there's a language where it's
61# not the case, we will need to build a custom correlator from entry to exit.
62extra_message = ""
63if language == "java":
64    # TODO for JVM entries, we actually have the real length of the class
65    #      and method strings in arg3 and arg5 respectively, so we can insert
66    #      the null terminator in its proper position.
67    entry_probe = "method__entry"
68    return_probe = "method__return"
69    read_class = "bpf_usdt_readarg(2, ctx, &clazz);"
70    read_method = "bpf_usdt_readarg(4, ctx, &method);"
71    extra_message = ("If you do not see any results, make sure you ran java"
72                     " with option -XX:+ExtendedDTraceProbes")
73elif language == "perl":
74    entry_probe = "sub__entry"
75    return_probe = "sub__return"
76    read_class = "bpf_usdt_readarg(2, ctx, &clazz);"    # filename really
77    read_method = "bpf_usdt_readarg(1, ctx, &method);"
78elif language == "php":
79    entry_probe = "function__entry"
80    return_probe = "function__return"
81    read_class = "bpf_usdt_readarg(4, ctx, &clazz);"
82    read_method = "bpf_usdt_readarg(1, ctx, &method);"
83    extra_message = ("If you do not see any results, make sure the environment"
84                     " variable USE_ZEND_DTRACE is set to 1")
85elif language == "python":
86    entry_probe = "function__entry"
87    return_probe = "function__return"
88    read_class = "bpf_usdt_readarg(1, ctx, &clazz);"    # filename really
89    read_method = "bpf_usdt_readarg(2, ctx, &method);"
90elif language == "ruby":
91    # TODO Also probe cmethod__entry and cmethod__return with same arguments
92    entry_probe = "method__entry"
93    return_probe = "method__return"
94    read_class = "bpf_usdt_readarg(1, ctx, &clazz);"
95    read_method = "bpf_usdt_readarg(2, ctx, &method);"
96elif language == "tcl":
97    # TODO Also consider probe cmd__entry and cmd__return with same arguments
98    entry_probe = "proc__entry"
99    return_probe = "proc__return"
100    read_class = ""  # no class/file info available
101    read_method = "bpf_usdt_readarg(1, ctx, &method);"
102elif not language or language == "none":
103    if not args.syscalls:
104        print("Nothing to do; use -S to trace syscalls.")
105        exit(1)
106    entry_probe, return_probe, read_class, read_method = ("", "", "", "")
107    if language:
108        language = None
109
110program = """
111#include <linux/ptrace.h>
112
113#define MAX_STRING_LENGTH 80
114DEFINE_NOLANG
115DEFINE_LATENCY
116DEFINE_SYSCALLS
117
118struct method_t {
119    char clazz[MAX_STRING_LENGTH];
120    char method[MAX_STRING_LENGTH];
121};
122struct entry_t {
123    u64 pid;
124    struct method_t method;
125};
126struct info_t {
127    u64 num_calls;
128    u64 total_ns;
129};
130struct syscall_entry_t {
131    u64 timestamp;
132    u64 id;
133};
134
135#ifndef LATENCY
136  BPF_HASH(counts, struct method_t, u64);            // number of calls
137  #ifdef SYSCALLS
138    BPF_HASH(syscounts, u64, u64);                   // number of calls per IP
139  #endif  // SYSCALLS
140#else
141  BPF_HASH(times, struct method_t, struct info_t);
142  BPF_HASH(entry, struct entry_t, u64);              // timestamp at entry
143  #ifdef SYSCALLS
144    BPF_HASH(systimes, u64, struct info_t);          // latency per IP
145    BPF_HASH(sysentry, u64, struct syscall_entry_t); // ts + IP at entry
146  #endif  // SYSCALLS
147#endif
148
149#ifndef NOLANG
150int trace_entry(struct pt_regs *ctx) {
151    u64 clazz = 0, method = 0, val = 0;
152    u64 *valp;
153    struct entry_t data = {0};
154#ifdef LATENCY
155    u64 timestamp = bpf_ktime_get_ns();
156    data.pid = bpf_get_current_pid_tgid();
157#endif
158    READ_CLASS
159    READ_METHOD
160    bpf_probe_read(&data.method.clazz, sizeof(data.method.clazz),
161                   (void *)clazz);
162    bpf_probe_read(&data.method.method, sizeof(data.method.method),
163                   (void *)method);
164#ifndef LATENCY
165    valp = counts.lookup_or_init(&data.method, &val);
166    ++(*valp);
167#endif
168#ifdef LATENCY
169    entry.update(&data, &timestamp);
170#endif
171    return 0;
172}
173
174#ifdef LATENCY
175int trace_return(struct pt_regs *ctx) {
176    u64 *entry_timestamp, clazz = 0, method = 0;
177    struct info_t *info, zero = {};
178    struct entry_t data = {};
179    data.pid = bpf_get_current_pid_tgid();
180    READ_CLASS
181    READ_METHOD
182    bpf_probe_read(&data.method.clazz, sizeof(data.method.clazz),
183                   (void *)clazz);
184    bpf_probe_read(&data.method.method, sizeof(data.method.method),
185                   (void *)method);
186    entry_timestamp = entry.lookup(&data);
187    if (!entry_timestamp) {
188        return 0;   // missed the entry event
189    }
190    info = times.lookup_or_init(&data.method, &zero);
191    info->num_calls += 1;
192    info->total_ns += bpf_ktime_get_ns() - *entry_timestamp;
193    entry.delete(&data);
194    return 0;
195}
196#endif  // LATENCY
197#endif  // NOLANG
198
199#ifdef SYSCALLS
200TRACEPOINT_PROBE(raw_syscalls, sys_enter) {
201    u64 pid = bpf_get_current_pid_tgid();
202    u64 *valp, id = args->id, val = 0;
203    PID_FILTER
204#ifdef LATENCY
205    struct syscall_entry_t data = {};
206    data.timestamp = bpf_ktime_get_ns();
207    data.id = id;
208    sysentry.update(&pid, &data);
209#endif
210#ifndef LATENCY
211    valp = syscounts.lookup_or_init(&id, &val);
212    ++(*valp);
213#endif
214    return 0;
215}
216
217#ifdef LATENCY
218TRACEPOINT_PROBE(raw_syscalls, sys_exit) {
219    struct syscall_entry_t *e;
220    struct info_t *info, zero = {};
221    u64 pid = bpf_get_current_pid_tgid(), id;
222    PID_FILTER
223    e = sysentry.lookup(&pid);
224    if (!e) {
225        return 0;   // missed the entry event
226    }
227    id = e->id;
228    info = systimes.lookup_or_init(&id, &zero);
229    info->num_calls += 1;
230    info->total_ns += bpf_ktime_get_ns() - e->timestamp;
231    sysentry.delete(&pid);
232    return 0;
233}
234#endif  // LATENCY
235#endif  // SYSCALLS
236""".replace("READ_CLASS", read_class) \
237   .replace("READ_METHOD", read_method) \
238   .replace("PID_FILTER", "if ((pid >> 32) != %d) { return 0; }" % args.pid) \
239   .replace("DEFINE_NOLANG", "#define NOLANG" if not language else "") \
240   .replace("DEFINE_LATENCY", "#define LATENCY" if args.latency else "") \
241   .replace("DEFINE_SYSCALLS", "#define SYSCALLS" if args.syscalls else "")
242
243if language:
244    usdt = USDT(pid=args.pid)
245    usdt.enable_probe_or_bail(entry_probe, "trace_entry")
246    if args.latency:
247        usdt.enable_probe_or_bail(return_probe, "trace_return")
248else:
249    usdt = None
250
251if args.ebpf or args.verbose:
252    if args.verbose and usdt:
253        print(usdt.get_text())
254    print(program)
255    if args.ebpf:
256        exit()
257
258bpf = BPF(text=program, usdt_contexts=[usdt] if usdt else [])
259if args.syscalls:
260    print("Attached kernel tracepoints for syscall tracing.")
261
262def get_data():
263    # Will be empty when no language was specified for tracing
264    if args.latency:
265        data = list(map(lambda kv: (kv[0].clazz.decode('utf-8', 'replace') \
266                                    + "." + \
267                                    kv[0].method.decode('utf-8', 'replace'),
268                                   (kv[1].num_calls, kv[1].total_ns)),
269                   bpf["times"].items()))
270    else:
271        data = list(map(lambda kv: (kv[0].clazz.decode('utf-8', 'replace') \
272                                    + "." + \
273                                    kv[0].method.decode('utf-8', 'replace'),
274                                   (kv[1].value, 0)),
275                   bpf["counts"].items()))
276
277    if args.syscalls:
278        if args.latency:
279            syscalls = map(lambda kv: (syscall_name(kv[0].value).decode('utf-8', 'replace'),
280                                       (kv[1].num_calls, kv[1].total_ns)),
281                           bpf["systimes"].items())
282            data.extend(syscalls)
283        else:
284            syscalls = map(lambda kv: (syscall_name(kv[0].value).decode('utf-8', 'replace'),
285                                       (kv[1].value, 0)),
286                           bpf["syscounts"].items())
287            data.extend(syscalls)
288
289    return sorted(data, key=lambda kv: kv[1][1 if args.latency else 0])
290
291def clear_data():
292    if args.latency:
293        bpf["times"].clear()
294    else:
295        bpf["counts"].clear()
296
297    if args.syscalls:
298        if args.latency:
299            bpf["systimes"].clear()
300        else:
301            bpf["syscounts"].clear()
302
303exit_signaled = False
304print("Tracing calls in process %d (language: %s)... Ctrl-C to quit." %
305      (args.pid, language or "none"))
306if extra_message:
307    print(extra_message)
308while True:
309    try:
310        sleep(args.interval or 99999999)
311    except KeyboardInterrupt:
312        exit_signaled = True
313    print()
314    data = get_data()   # [(function, (num calls, latency in ns))]
315    if args.latency:
316        time_col = "TIME (ms)" if args.milliseconds else "TIME (us)"
317        print("%-50s %8s %8s" % ("METHOD", "# CALLS", time_col))
318    else:
319        print("%-50s %8s" % ("METHOD", "# CALLS"))
320    if args.top:
321        data = data[-args.top:]
322    for key, value in data:
323        if args.latency:
324            time = value[1] / 1000000.0 if args.milliseconds else \
325                   value[1] / 1000.0
326            print("%-50s %8d %6.2f" % (key, value[0], time))
327        else:
328            print("%-50s %8d" % (key, value[0]))
329    if args.interval and not exit_signaled:
330        clear_data()
331    else:
332        if args.syscalls:
333            print("Detaching kernel probes, please wait...")
334        exit()
335