1#!/usr/bin/env python
2# @lint-avoid-python-3-compatibility-imports
3#
4# ugc  Summarize garbage collection events in high-level languages.
5#      For Linux, uses BCC, eBPF.
6#
7# USAGE: ugc [-v] [-m] [-M MSEC] [-F FILTER] {java,node,python,ruby} pid
8#
9# Copyright 2016 Sasha Goldshtein
10# Licensed under the Apache License, Version 2.0 (the "License")
11#
12# 19-Oct-2016   Sasha Goldshtein   Created this.
13
14from __future__ import print_function
15import argparse
16from bcc import BPF, USDT, utils
17import ctypes as ct
18import time
19import os
20
21languages = ["java", "node", "python", "ruby"]
22
23examples = """examples:
24    ./ugc -l java 185        # trace Java GCs in process 185
25    ./ugc -l ruby 1344 -m    # trace Ruby GCs reporting in ms
26    ./ugc -M 10 -l java 185  # trace only Java GCs longer than 10ms
27"""
28parser = argparse.ArgumentParser(
29    description="Summarize garbage collection events in high-level languages.",
30    formatter_class=argparse.RawDescriptionHelpFormatter,
31    epilog=examples)
32parser.add_argument("-l", "--language", choices=languages,
33    help="language to trace")
34parser.add_argument("pid", type=int, help="process id to attach to")
35parser.add_argument("-v", "--verbose", action="store_true",
36    help="verbose mode: print the BPF program (for debugging purposes)")
37parser.add_argument("-m", "--milliseconds", action="store_true",
38    help="report times in milliseconds (default is microseconds)")
39parser.add_argument("-M", "--minimum", type=int, default=0,
40    help="display only GCs longer than this many milliseconds")
41parser.add_argument("-F", "--filter", type=str,
42    help="display only GCs whose description contains this text")
43parser.add_argument("--ebpf", action="store_true",
44    help=argparse.SUPPRESS)
45args = parser.parse_args()
46
47usdt = USDT(pid=args.pid)
48
49program = """
50struct gc_event_t {
51    u64 probe_index;
52    u64 elapsed_ns;
53    u64 field1;
54    u64 field2;
55    u64 field3;
56    u64 field4;
57    char string1[32];
58    char string2[32];
59};
60struct entry_t {
61    u64 start_ns;
62    u64 field1;
63    u64 field2;
64};
65
66BPF_PERF_OUTPUT(gcs);
67BPF_HASH(entry, u64, struct entry_t);
68"""
69
70class Probe(object):
71    def __init__(self, begin, end, begin_save, end_save, formatter):
72        self.begin = begin
73        self.end = end
74        self.begin_save = begin_save
75        self.end_save = end_save
76        self.formatter = formatter
77
78    def generate(self):
79        text = """
80int trace_%s(struct pt_regs *ctx) {
81    u64 pid = bpf_get_current_pid_tgid();
82    struct entry_t e = {};
83    e.start_ns = bpf_ktime_get_ns();
84    %s
85    entry.update(&pid, &e);
86    return 0;
87}
88int trace_%s(struct pt_regs *ctx) {
89    u64 elapsed;
90    struct entry_t *e;
91    struct gc_event_t event = {};
92    u64 pid = bpf_get_current_pid_tgid();
93    e = entry.lookup(&pid);
94    if (!e) {
95        return 0;   // missed the entry event on this thread
96    }
97    elapsed = bpf_ktime_get_ns() - e->start_ns;
98    if (elapsed < %d) {
99        return 0;
100    }
101    event.elapsed_ns = elapsed;
102    %s
103    gcs.perf_submit(ctx, &event, sizeof(event));
104    return 0;
105}
106        """ % (self.begin, self.begin_save, self.end,
107               args.minimum * 1000000, self.end_save)
108        return text
109
110    def attach(self):
111        usdt.enable_probe_or_bail(self.begin, "trace_%s" % self.begin)
112        usdt.enable_probe_or_bail(self.end, "trace_%s" % self.end)
113
114    def format(self, data):
115        return self.formatter(data)
116
117probes = []
118
119language = args.language
120if not language:
121    language = utils.detect_language(languages, args.pid)
122
123#
124# Java
125#
126if language == "java":
127    # Oddly, the gc__begin/gc__end probes don't really have any useful
128    # information, while the mem__pool* ones do. There's also a bunch of
129    # probes described in the hotspot_gc*.stp file which aren't there
130    # when looking at a live Java process.
131    begin_save = """
132    bpf_usdt_readarg(6, ctx, &e.field1);    // used bytes
133    bpf_usdt_readarg(8, ctx, &e.field2);    // max bytes
134    """
135    end_save = """
136    event.field1 = e->field1;                  // used bytes at start
137    event.field2 = e->field2;                  // max bytes at start
138    bpf_usdt_readarg(6, ctx, &event.field3);   // used bytes at end
139    bpf_usdt_readarg(8, ctx, &event.field4);   // max bytes at end
140    u64 manager = 0, pool = 0;
141    bpf_usdt_readarg(1, ctx, &manager);        // ptr to manager name
142    bpf_usdt_readarg(3, ctx, &pool);           // ptr to pool name
143    bpf_probe_read(&event.string1, sizeof(event.string1), (void *)manager);
144    bpf_probe_read(&event.string2, sizeof(event.string2), (void *)pool);
145    """
146
147    def formatter(e):
148        "%s %s used=%d->%d max=%d->%d" % \
149            (e.string1, e.string2, e.field1, e.field3, e.field2, e.field4)
150    probes.append(Probe("mem__pool__gc__begin", "mem__pool__gc__end",
151                        begin_save, end_save, formatter))
152    probes.append(Probe("gc__begin", "gc__end",
153                        "", "", lambda _: "no additional info available"))
154#
155# Node
156#
157elif language == "node":
158    end_save = """
159    u32 gc_type = 0;
160    bpf_usdt_readarg(1, ctx, &gc_type);
161    event.field1 = gc_type;
162    """
163    descs = {"GC scavenge": 1, "GC mark-sweep-compact": 2,
164             "GC incremental mark": 4, "GC weak callbacks": 8}
165    probes.append(Probe("gc__start", "gc__done", "", end_save,
166                  lambda e: str.join(", ",
167                                     [desc for desc, val in descs.items()
168                                      if e.field1 & val != 0])))
169#
170# Python
171#
172elif language == "python":
173    begin_save = """
174    int gen = 0;
175    bpf_usdt_readarg(1, ctx, &gen);
176    e.field1 = gen;
177    """
178    end_save = """
179    long objs = 0;
180    bpf_usdt_readarg(1, ctx, &objs);
181    event.field1 = e->field1;
182    event.field2 = objs;
183    """
184
185    def formatter(event):
186        "gen %d GC collected %d objects" % \
187            (event.field1, event.field2)
188    probes.append(Probe("gc__start", "gc__done",
189                        begin_save, end_save, formatter))
190#
191# Ruby
192#
193elif language == "ruby":
194    # Ruby GC probes do not have any additional information available.
195    probes.append(Probe("gc__mark__begin", "gc__mark__end",
196                        "", "", lambda _: "GC mark stage"))
197    probes.append(Probe("gc__sweep__begin", "gc__sweep__end",
198                        "", "", lambda _: "GC sweep stage"))
199
200else:
201    print("No language detected; use -l to trace a language.")
202    exit(1)
203
204
205for probe in probes:
206    program += probe.generate()
207    probe.attach()
208
209if args.ebpf or args.verbose:
210    if args.verbose:
211        print(usdt.get_text())
212    print(program)
213    if args.ebpf:
214        exit()
215
216bpf = BPF(text=program, usdt_contexts=[usdt])
217print("Tracing garbage collections in %s process %d... Ctrl-C to quit." %
218      (language, args.pid))
219time_col = "TIME (ms)" if args.milliseconds else "TIME (us)"
220print("%-8s %-8s %-40s" % ("START", time_col, "DESCRIPTION"))
221
222class GCEvent(ct.Structure):
223    _fields_ = [
224        ("probe_index", ct.c_ulonglong),
225        ("elapsed_ns", ct.c_ulonglong),
226        ("field1", ct.c_ulonglong),
227        ("field2", ct.c_ulonglong),
228        ("field3", ct.c_ulonglong),
229        ("field4", ct.c_ulonglong),
230        ("string1", ct.c_char * 32),
231        ("string2", ct.c_char * 32)
232        ]
233
234start_ts = time.time()
235
236def print_event(cpu, data, size):
237    event = ct.cast(data, ct.POINTER(GCEvent)).contents
238    elapsed = event.elapsed_ns / 1000000 if args.milliseconds else \
239              event.elapsed_ns / 1000
240    description = probes[event.probe_index].format(event)
241    if args.filter and args.filter not in description:
242        return
243    print("%-8.3f %-8.2f %s" % (time.time() - start_ts, elapsed, description))
244
245bpf["gcs"].open_perf_buffer(print_event)
246while 1:
247    try:
248        bpf.perf_buffer_poll()
249    except KeyboardInterrupt:
250        exit()
251