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, ×tamp); 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