ugc.py

#!/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,python,ruby,node} 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", "python", "ruby", "node"]

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")
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"))
#
# 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"))
#
# 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])))

else:
    print("No language detected; use -l to trace a language.")
    exit(1)


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." %
      (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()