From e5d9d99a134901a3af2fb78821eb6989c7f3a17d Mon Sep 17 00:00:00 2001 From: Sasha Goldshtein Date: Mon, 17 Oct 2016 09:04:37 -0700 Subject: [PATCH] ugc: Monitor GC events in high-level languages `ugc` monitors GC start and end events in Java, Python, and Ruby, printing out a message when a GC cycle completes along with the duration of the GC and an optional additional description that depends on the target language. NOTE: This WIP does not have any interesting additional descriptions yet. Usage example: ``` ugc java 1448 # monitor Java GCs in process 1448 ``` --- tools/ugc.py | 135 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 135 insertions(+) create mode 100755 tools/ugc.py diff --git a/tools/ugc.py b/tools/ugc.py new file mode 100755 index 0000000..93464f4 --- /dev/null +++ b/tools/ugc.py @@ -0,0 +1,135 @@ +#!/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 {java,python,ruby} PID [-v] [-m] +# +# 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 +import ctypes as ct +import time + +examples = """examples: + ./ugc java 185 # trace Java GCs in process 185 + ./ugc ruby 1344 -m # trace Ruby GCs reporting in ms +""" +parser = argparse.ArgumentParser( + description="Summarize garbage collection events in high-level languages.", + formatter_class=argparse.RawDescriptionHelpFormatter, + epilog=examples) +parser.add_argument("language", choices=["java", "python", "ruby"], + 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)") +args = parser.parse_args() + +usdt = USDT(pid=args.pid) + +program = """ +struct gc_event_t { + u64 elapsed_ns; + char description[80]; +}; + +BPF_PERF_OUTPUT(gcs); +BPF_HASH(entry, u64, u64); // pid to start timestamp +""" + +class Probe(object): + def __init__(self, begin, end, description): + self.begin = begin + self.end = end + self.description = description + + def generate(self): + text = """ +int trace_%s(struct pt_regs *ctx) { + u64 pid = bpf_get_current_pid_tgid(); + u64 timestamp = bpf_ktime_get_ns(); + entry.update(&pid, ×tamp); + return 0; +} +int trace_%s(struct pt_regs *ctx) { + u64 *start, elapsed; + char description[] = "%s"; + struct gc_event_t event = {}; + u64 pid = bpf_get_current_pid_tgid(); + start = entry.lookup(&pid); + if (!start) { + return 0; // missed the entry event on this thread + } + elapsed = bpf_ktime_get_ns() - *start; + __builtin_memcpy(&event.description, description, sizeof(description)); + event.elapsed_ns = elapsed; + gcs.perf_submit(ctx, &event, sizeof(event)); + return 0; +} + """ % (self.begin, self.end, self.description) + return text + + def attach(self): + usdt.enable_probe(self.begin, "trace_%s" % self.begin) + usdt.enable_probe(self.end, "trace_%s" % self.end) + +probes = [] + +if args.language == "java": + # TODO Extract additional info like mark/sweep/compact/generation etc. + # 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. + probes.append(Probe("mem__pool__gc__begin", "mem__pool__gc__end", "TODO")) + probes.append(Probe("gc__begin", "gc__end", "TODO")) +elif args.language == "python": + # TODO In gc__start, arg1 is the generation to collect. In gc__end, + # arg1 is the number of collected objects. + probes.append(Probe("gc__start", "gc__done", "GC")) +elif args.language == "ruby": + # Ruby GC probes do not have any additional information available. + probes.append(Probe("gc__mark__begin", "gc__mark__end", "mark")) + probes.append(Probe("gc__sweep__begin", "gc__sweep__end", "sweep")) + +for probe in probes: + program += probe.generate() + probe.attach() + +if args.verbose: + print(usdt.get_text()) + print(program) + +bpf = BPF(text=program, usdt_contexts=[usdt]) +print("Tracing garbage collections in %s process %d... Ctrl-C to quit." % + (args.language, args.pid)) +time_col = "TIME (ms)" if args.milliseconds else "TIME (us)" +print("%-8s %-30s %-8s" % ("START", "DESCRIPTION", time_col)) + +class Data(ct.Structure): + _fields_ = [ + ("elapsed_ns", ct.c_ulonglong), + ("description", ct.c_char * 80) + ] + +start_ts = time.time() + +def print_event(cpu, data, size): + event = ct.cast(data, ct.POINTER(Data)).contents + elapsed = event.elapsed_ns/1000000 if args.milliseconds else \ + event.elapsed_ns/1000 + print("%-8.3f %-30s %-8.2f" % (time.time() - start_ts, + event.description, elapsed)) + +bpf["gcs"].open_perf_buffer(print_event) +while 1: + bpf.kprobe_poll() -- 2.7.4