#!/usr/bin/python # @lint-avoid-python-3-compatibility-imports # # ugc Summarize garbage collection events in high-level languages. # For Linux, uses BCC, eBPF. # # USAGE: ugc [-v] [-m] [-M MSEC] [-F FILTER] {java,node,python,ruby} pid # # 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 import ctypes as ct import time import os languages = ["java", "node", "python", "ruby"] examples = """examples: ./ugc -l java 185 # trace Java GCs in process 185 ./ugc -l ruby 1344 -m # trace Ruby GCs reporting in ms ./ugc -M 10 -l java 185 # trace only Java GCs longer than 10ms """ parser = argparse.ArgumentParser( description="Summarize garbage collection events in high-level languages.", formatter_class=argparse.RawDescriptionHelpFormatter, epilog=examples) parser.add_argument("-l", "--language", choices=languages, help="language to trace") parser.add_argument("pid", type=int, help="process id to attach to") 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("-M", "--minimum", type=int, default=0, help="display only GCs longer than this many milliseconds") parser.add_argument("-F", "--filter", type=str, help="display only GCs whose description contains this text") parser.add_argument("--ebpf", action="store_true", help=argparse.SUPPRESS) args = parser.parse_args() usdt = USDT(pid=args.pid) program = """ struct gc_event_t { u64 probe_index; u64 elapsed_ns; u64 field1; u64 field2; u64 field3; u64 field4; char string1[32]; char string2[32]; }; struct entry_t { u64 start_ns; u64 field1; u64 field2; }; BPF_PERF_OUTPUT(gcs); BPF_HASH(entry, u64, struct entry_t); """ class Probe(object): def __init__(self, begin, end, begin_save, end_save, formatter): self.begin = begin self.end = end self.begin_save = begin_save self.end_save = end_save self.formatter = formatter def generate(self): text = """ int trace_%s(struct pt_regs *ctx) { u64 pid = bpf_get_current_pid_tgid(); struct entry_t e = {}; e.start_ns = bpf_ktime_get_ns(); %s entry.update(&pid, &e); return 0; } int trace_%s(struct pt_regs *ctx) { u64 elapsed; struct entry_t *e; struct gc_event_t event = {}; u64 pid = bpf_get_current_pid_tgid(); e = entry.lookup(&pid); if (!e) { return 0; // missed the entry event on this thread } elapsed = bpf_ktime_get_ns() - e->start_ns; if (elapsed < %d) { return 0; } event.elapsed_ns = elapsed; %s gcs.perf_submit(ctx, &event, sizeof(event)); return 0; } """ % (self.begin, self.begin_save, self.end, args.minimum * 1000000, self.end_save) return text def attach(self): usdt.enable_probe_or_bail(self.begin, "trace_%s" % self.begin) usdt.enable_probe_or_bail(self.end, "trace_%s" % self.end) def format(self, data): return self.formatter(data) probes = [] language = args.language if not language: language = utils.detect_language(languages, args.pid) # # Java # if language == "java": # Oddly, the gc__begin/gc__end probes don't really have any useful # information, while the mem__pool* ones do. There's also a bunch of # probes described in the hotspot_gc*.stp file which aren't there # when looking at a live Java process. begin_save = """ bpf_usdt_readarg(6, ctx, &e.field1); // used bytes bpf_usdt_readarg(8, ctx, &e.field2); // max bytes """ end_save = """ event.field1 = e->field1; // used bytes at start event.field2 = e->field2; // max bytes at start bpf_usdt_readarg(6, ctx, &event.field3); // used bytes at end bpf_usdt_readarg(8, ctx, &event.field4); // max bytes at end u64 manager = 0, pool = 0; bpf_usdt_readarg(1, ctx, &manager); // ptr to manager name bpf_usdt_readarg(3, ctx, &pool); // ptr to pool name bpf_probe_read(&event.string1, sizeof(event.string1), (void *)manager); bpf_probe_read(&event.string2, sizeof(event.string2), (void *)pool); """ def formatter(e): "%s %s used=%d->%d max=%d->%d" % \ (e.string1, e.string2, e.field1, e.field3, e.field2, e.field4) probes.append(Probe("mem__pool__gc__begin", "mem__pool__gc__end", begin_save, end_save, formatter)) probes.append(Probe("gc__begin", "gc__end", "", "", lambda _: "no additional info available")) # # Node # elif language == "node": end_save = """ u32 gc_type = 0; bpf_usdt_readarg(1, ctx, &gc_type); event.field1 = gc_type; """ descs = {"GC scavenge": 1, "GC mark-sweep-compact": 2, "GC incremental mark": 4, "GC weak callbacks": 8} probes.append(Probe("gc__start", "gc__done", "", end_save, lambda e: str.join(", ", [desc for desc, val in descs.items() if e.field1 & val != 0]))) # # Python # elif language == "python": begin_save = """ int gen = 0; bpf_usdt_readarg(1, ctx, &gen); e.field1 = gen; """ end_save = """ long objs = 0; bpf_usdt_readarg(1, ctx, &objs); event.field1 = e->field1; event.field2 = objs; """ def formatter(event): "gen %d GC collected %d objects" % \ (event.field1, event.field2) probes.append(Probe("gc__start", "gc__done", begin_save, end_save, formatter)) # # Ruby # elif language == "ruby": # Ruby GC probes do not have any additional information available. probes.append(Probe("gc__mark__begin", "gc__mark__end", "", "", lambda _: "GC mark stage")) probes.append(Probe("gc__sweep__begin", "gc__sweep__end", "", "", lambda _: "GC sweep stage")) else: print("No language detected; use -l to trace a language.") exit(1) for probe in probes: program += probe.generate() probe.attach() if args.ebpf or args.verbose: if args.verbose: print(usdt.get_text()) print(program) if args.ebpf: exit() bpf = BPF(text=program, usdt_contexts=[usdt]) print("Tracing garbage collections in %s process %d... Ctrl-C to quit." % (language, args.pid)) time_col = "TIME (ms)" if args.milliseconds else "TIME (us)" print("%-8s %-8s %-40s" % ("START", time_col, "DESCRIPTION")) class GCEvent(ct.Structure): _fields_ = [ ("probe_index", ct.c_ulonglong), ("elapsed_ns", ct.c_ulonglong), ("field1", ct.c_ulonglong), ("field2", ct.c_ulonglong), ("field3", ct.c_ulonglong), ("field4", ct.c_ulonglong), ("string1", ct.c_char * 32), ("string2", ct.c_char * 32) ] start_ts = time.time() def print_event(cpu, data, size): event = ct.cast(data, ct.POINTER(GCEvent)).contents elapsed = event.elapsed_ns / 1000000 if args.milliseconds else \ event.elapsed_ns / 1000 description = probes[event.probe_index].format(event) if args.filter and args.filter not in description: return print("%-8.3f %-8.2f %s" % (time.time() - start_ts, elapsed, description)) bpf["gcs"].open_perf_buffer(print_event) while 1: bpf.perf_buffer_poll()