| #!/usr/bin/python |
| # @lint-avoid-python-3-compatibility-imports |
| # |
| # ucalls Summarize method calls in high-level languages and/or system calls. |
| # For Linux, uses BCC, eBPF. |
| # |
| # USAGE: ucalls [-l {java,perl,php,python,ruby,tcl}] [-h] [-T TOP] [-L] [-S] [-v] [-m] |
| # pid [interval] |
| # |
| # Copyright 2016 Sasha Goldshtein |
| # Licensed under the Apache License, Version 2.0 (the "License") |
| # |
| # 19-Oct-2016 Sasha Goldshtein Created this. |
| |
| from __future__ import print_function |
| import argparse |
| from bcc import BPF, USDT, utils |
| from time import sleep |
| import os |
| |
| languages = ["java", "perl", "php", "python", "ruby", "tcl"] |
| |
| examples = """examples: |
| ./ucalls -l java 185 # trace Java calls and print statistics on ^C |
| ./ucalls -l python 2020 1 # trace Python calls and print every second |
| ./ucalls -l java 185 -S # trace Java calls and syscalls |
| ./ucalls 6712 -S # trace only syscall counts |
| ./ucalls -l ruby 1344 -T 10 # trace top 10 Ruby method calls |
| ./ucalls -l ruby 1344 -L # trace Ruby calls including latency |
| ./ucalls -l php 443 -LS # trace PHP calls and syscalls with latency |
| ./ucalls -l python 2020 -mL # trace Python calls including latency in ms |
| """ |
| parser = argparse.ArgumentParser( |
| description="Summarize method calls in high-level languages.", |
| formatter_class=argparse.RawDescriptionHelpFormatter, |
| epilog=examples) |
| parser.add_argument("pid", type=int, help="process id to attach to") |
| parser.add_argument("interval", type=int, nargs='?', |
| help="print every specified number of seconds") |
| parser.add_argument("-l", "--language", choices=languages + ["none"], |
| help="language to trace (if none, trace syscalls only)") |
| parser.add_argument("-T", "--top", type=int, |
| help="number of most frequent/slow calls to print") |
| parser.add_argument("-L", "--latency", action="store_true", |
| help="record method latency from enter to exit (except recursive calls)") |
| parser.add_argument("-S", "--syscalls", action="store_true", |
| help="record syscall latency (adds overhead)") |
| parser.add_argument("-v", "--verbose", action="store_true", |
| help="verbose mode: print the BPF program (for debugging purposes)") |
| parser.add_argument("-m", "--milliseconds", action="store_true", |
| help="report times in milliseconds (default is microseconds)") |
| parser.add_argument("--ebpf", action="store_true", |
| help=argparse.SUPPRESS) |
| args = parser.parse_args() |
| |
| language = args.language |
| if not language: |
| language = utils.detect_language(languages, args.pid) |
| |
| # We assume that the entry and return probes have the same arguments. This is |
| # the case for Java, Python, Ruby, and PHP. If there's a language where it's |
| # not the case, we will need to build a custom correlator from entry to exit. |
| extra_message = "" |
| if language == "java": |
| # TODO for JVM entries, we actually have the real length of the class |
| # and method strings in arg3 and arg5 respectively, so we can insert |
| # the null terminator in its proper position. |
| entry_probe = "method__entry" |
| return_probe = "method__return" |
| read_class = "bpf_usdt_readarg(2, ctx, &clazz);" |
| read_method = "bpf_usdt_readarg(4, ctx, &method);" |
| extra_message = ("If you do not see any results, make sure you ran java" |
| " with option -XX:+ExtendedDTraceProbes") |
| elif language == "perl": |
| entry_probe = "sub__entry" |
| return_probe = "sub__return" |
| read_class = "bpf_usdt_readarg(2, ctx, &clazz);" # filename really |
| read_method = "bpf_usdt_readarg(1, ctx, &method);" |
| elif language == "php": |
| entry_probe = "function__entry" |
| return_probe = "function__return" |
| read_class = "bpf_usdt_readarg(4, ctx, &clazz);" |
| read_method = "bpf_usdt_readarg(1, ctx, &method);" |
| extra_message = ("If you do not see any results, make sure the environment" |
| " variable USE_ZEND_DTRACE is set to 1") |
| elif language == "python": |
| entry_probe = "function__entry" |
| return_probe = "function__return" |
| read_class = "bpf_usdt_readarg(1, ctx, &clazz);" # filename really |
| read_method = "bpf_usdt_readarg(2, ctx, &method);" |
| elif language == "ruby": |
| # TODO Also probe cmethod__entry and cmethod__return with same arguments |
| entry_probe = "method__entry" |
| return_probe = "method__return" |
| read_class = "bpf_usdt_readarg(1, ctx, &clazz);" |
| read_method = "bpf_usdt_readarg(2, ctx, &method);" |
| elif language == "tcl": |
| # TODO Also consider probe cmd__entry and cmd__return with same arguments |
| entry_probe = "proc__entry" |
| return_probe = "proc__return" |
| read_class = "" # no class/file info available |
| read_method = "bpf_usdt_readarg(1, ctx, &method);" |
| elif not language or language == "none": |
| if not args.syscalls: |
| print("Nothing to do; use -S to trace syscalls.") |
| exit(1) |
| entry_probe, return_probe, read_class, read_method = ("", "", "", "") |
| if language: |
| language = None |
| |
| program = """ |
| #include <linux/ptrace.h> |
| |
| #define MAX_STRING_LENGTH 80 |
| DEFINE_NOLANG |
| DEFINE_LATENCY |
| DEFINE_SYSCALLS |
| |
| struct method_t { |
| char clazz[MAX_STRING_LENGTH]; |
| char method[MAX_STRING_LENGTH]; |
| }; |
| struct entry_t { |
| u64 pid; |
| struct method_t method; |
| }; |
| struct info_t { |
| u64 num_calls; |
| u64 total_ns; |
| }; |
| struct syscall_entry_t { |
| u64 timestamp; |
| u64 ip; |
| }; |
| |
| #ifndef LATENCY |
| BPF_HASH(counts, struct method_t, u64); // number of calls |
| #ifdef SYSCALLS |
| BPF_HASH(syscounts, u64, u64); // number of calls per IP |
| #endif // SYSCALLS |
| #else |
| BPF_HASH(times, struct method_t, struct info_t); |
| BPF_HASH(entry, struct entry_t, u64); // timestamp at entry |
| #ifdef SYSCALLS |
| BPF_HASH(systimes, u64, struct info_t); // latency per IP |
| BPF_HASH(sysentry, u64, struct syscall_entry_t); // ts + IP at entry |
| #endif // SYSCALLS |
| #endif |
| |
| #ifndef NOLANG |
| int trace_entry(struct pt_regs *ctx) { |
| u64 clazz = 0, method = 0, val = 0; |
| u64 *valp; |
| struct entry_t data = {0}; |
| #ifdef LATENCY |
| u64 timestamp = bpf_ktime_get_ns(); |
| data.pid = bpf_get_current_pid_tgid(); |
| #endif |
| READ_CLASS |
| READ_METHOD |
| bpf_probe_read(&data.method.clazz, sizeof(data.method.clazz), |
| (void *)clazz); |
| bpf_probe_read(&data.method.method, sizeof(data.method.method), |
| (void *)method); |
| #ifndef LATENCY |
| valp = counts.lookup_or_init(&data.method, &val); |
| ++(*valp); |
| #endif |
| #ifdef LATENCY |
| entry.update(&data, ×tamp); |
| #endif |
| return 0; |
| } |
| |
| #ifdef LATENCY |
| int trace_return(struct pt_regs *ctx) { |
| u64 *entry_timestamp, clazz = 0, method = 0; |
| struct info_t *info, zero = {}; |
| struct entry_t data = {}; |
| data.pid = bpf_get_current_pid_tgid(); |
| READ_CLASS |
| READ_METHOD |
| bpf_probe_read(&data.method.clazz, sizeof(data.method.clazz), |
| (void *)clazz); |
| bpf_probe_read(&data.method.method, sizeof(data.method.method), |
| (void *)method); |
| entry_timestamp = entry.lookup(&data); |
| if (!entry_timestamp) { |
| return 0; // missed the entry event |
| } |
| info = times.lookup_or_init(&data.method, &zero); |
| info->num_calls += 1; |
| info->total_ns += bpf_ktime_get_ns() - *entry_timestamp; |
| entry.delete(&data); |
| return 0; |
| } |
| #endif // LATENCY |
| #endif // NOLANG |
| |
| #ifdef SYSCALLS |
| int syscall_entry(struct pt_regs *ctx) { |
| u64 pid = bpf_get_current_pid_tgid(); |
| u64 *valp, ip = PT_REGS_IP(ctx), val = 0; |
| PID_FILTER |
| #ifdef LATENCY |
| struct syscall_entry_t data = {}; |
| data.timestamp = bpf_ktime_get_ns(); |
| data.ip = ip; |
| #endif |
| #ifndef LATENCY |
| valp = syscounts.lookup_or_init(&ip, &val); |
| ++(*valp); |
| #endif |
| #ifdef LATENCY |
| sysentry.update(&pid, &data); |
| #endif |
| return 0; |
| } |
| |
| #ifdef LATENCY |
| int syscall_return(struct pt_regs *ctx) { |
| struct syscall_entry_t *e; |
| struct info_t *info, zero = {}; |
| u64 pid = bpf_get_current_pid_tgid(), ip; |
| PID_FILTER |
| e = sysentry.lookup(&pid); |
| if (!e) { |
| return 0; // missed the entry event |
| } |
| ip = e->ip; |
| info = systimes.lookup_or_init(&ip, &zero); |
| info->num_calls += 1; |
| info->total_ns += bpf_ktime_get_ns() - e->timestamp; |
| sysentry.delete(&pid); |
| return 0; |
| } |
| #endif // LATENCY |
| #endif // SYSCALLS |
| """.replace("READ_CLASS", read_class) \ |
| .replace("READ_METHOD", read_method) \ |
| .replace("PID_FILTER", "if ((pid >> 32) != %d) { return 0; }" % args.pid) \ |
| .replace("DEFINE_NOLANG", "#define NOLANG" if not language else "") \ |
| .replace("DEFINE_LATENCY", "#define LATENCY" if args.latency else "") \ |
| .replace("DEFINE_SYSCALLS", "#define SYSCALLS" if args.syscalls else "") |
| |
| if language: |
| usdt = USDT(pid=args.pid) |
| usdt.enable_probe_or_bail(entry_probe, "trace_entry") |
| if args.latency: |
| usdt.enable_probe_or_bail(return_probe, "trace_return") |
| else: |
| usdt = None |
| |
| if args.ebpf or args.verbose: |
| if args.verbose and usdt: |
| print(usdt.get_text()) |
| print(program) |
| if args.ebpf: |
| exit() |
| |
| bpf = BPF(text=program, usdt_contexts=[usdt] if usdt else []) |
| if args.syscalls: |
| syscall_regex = "^[Ss]y[Ss]_.*" |
| bpf.attach_kprobe(event_re=syscall_regex, fn_name="syscall_entry") |
| if args.latency: |
| bpf.attach_kretprobe(event_re=syscall_regex, fn_name="syscall_return") |
| print("Attached %d kernel probes for syscall tracing." % |
| bpf.num_open_kprobes()) |
| |
| def get_data(): |
| # Will be empty when no language was specified for tracing |
| if args.latency: |
| data = list(map(lambda kv: (kv[0].clazz.decode('utf-8', 'replace') \ |
| + "." + \ |
| kv[0].method.decode('utf-8', 'replace'), |
| (kv[1].num_calls, kv[1].total_ns)), |
| bpf["times"].items())) |
| else: |
| data = list(map(lambda kv: (kv[0].clazz.decode('utf-8', 'replace') \ |
| + "." + \ |
| kv[0].method.decode('utf-8', 'replace'), |
| (kv[1].value, 0)), |
| bpf["counts"].items())) |
| |
| if args.syscalls: |
| if args.latency: |
| syscalls = map(lambda kv: (bpf.ksym(kv[0].value), |
| (kv[1].num_calls, kv[1].total_ns)), |
| bpf["systimes"].items()) |
| data.extend(syscalls) |
| else: |
| syscalls = map(lambda kv: (bpf.ksym(kv[0].value), |
| (kv[1].value, 0)), |
| bpf["syscounts"].items()) |
| data.extend(syscalls) |
| |
| return sorted(data, key=lambda kv: kv[1][1 if args.latency else 0]) |
| |
| def clear_data(): |
| if args.latency: |
| bpf["times"].clear() |
| else: |
| bpf["counts"].clear() |
| |
| if args.syscalls: |
| if args.latency: |
| bpf["systimes"].clear() |
| else: |
| bpf["syscounts"].clear() |
| |
| exit_signaled = False |
| print("Tracing calls in process %d (language: %s)... Ctrl-C to quit." % |
| (args.pid, language or "none")) |
| if extra_message: |
| print(extra_message) |
| while True: |
| try: |
| sleep(args.interval or 99999999) |
| except KeyboardInterrupt: |
| exit_signaled = True |
| print() |
| data = get_data() # [(function, (num calls, latency in ns))] |
| if args.latency: |
| time_col = "TIME (ms)" if args.milliseconds else "TIME (us)" |
| print("%-50s %8s %8s" % ("METHOD", "# CALLS", time_col)) |
| else: |
| print("%-50s %8s" % ("METHOD", "# CALLS")) |
| if args.top: |
| data = data[-args.top:] |
| for key, value in data: |
| if args.latency: |
| time = value[1] / 1000000.0 if args.milliseconds else \ |
| value[1] / 1000.0 |
| print("%-50s %8d %6.2f" % (key, value[0], time)) |
| else: |
| print("%-50s %8d" % (key, value[0])) |
| if args.interval and not exit_signaled: |
| clear_data() |
| else: |
| if args.syscalls: |
| print("Detaching kernel probes, please wait...") |
| exit() |
