Merge pull request #961 from goldshtn/ugc-filters

ugc: Add -M for minimum time and -F for text filtering

man/man8/ugc.8

@@ -2,7 +2,7 @@
 .SH NAME
 ugc \- Trace garbage collection events in high-level languages.
 .SH SYNOPSIS
-.B ugc [-h] [-v] [-m] {java,python,ruby,node} pid
+.B ugc [-h] [-v] [-m] [-M MINIMUM] [-F FILTER] {java,python,ruby,node} pid
 .SH DESCRIPTION
 This traces garbage collection events as they occur, including their duration
 and any additional information (such as generation collected or type of GC)
@@ -24,6 +24,18 @@ Print the resulting BPF program, for debugging purposes.
 \-m
 Print times in milliseconds. The default is microseconds.
 .TP
+\-M MINIMUM
+Display only collections that are longer than this threshold. The value is
+given in milliseconds. The default is to display all collections.
+.TP
+\-F FILTER
+Display only collections whose textual description matches (contains) this
+string. The default is to display all collections. Note that the filtering here
+is performed in user-space, and not as part of the BPF program. This means that
+if you have thousands of collection events, specifying this filter will not
+reduce the amount of data that has to be transferred from the BPF program to
+the user-space script.
+.TP
 {java,python,ruby,node}
 The language to trace.
 .TP
@@ -39,16 +51,22 @@ Trace garbage collections in a specific Java process, and print GC times in
 milliseconds:
 #
 .B ugc -m java 6004
+.TP
+Trace garbage collections in a specific Java process, and display them only if
+they are longer than 10ms and have the string "Tenured" in their detailed
+description:
+#
+.B ugc -M 10 -F Tenured java 6004
 .SH FIELDS
 .TP
 START
 The start time of the GC, in seconds from the beginning of the trace.
 .TP
-DESCRIPTION
-The runtime-provided description of this garbage collection event.
-.TP
 TIME
 The duration of the garbage collection event.
+.TP
+DESCRIPTION
+The runtime-provided description of this garbage collection event.
 .SH OVERHEAD
 Garbage collection events, even if frequent, should not produce a considerable
 overhead when traced because they are still not very common. Even hundreds of 

tools/ugc.py

@@ -4,7 +4,7 @@
 # ugc  Summarize garbage collection events in high-level languages.
 #      For Linux, uses BCC, eBPF.
 #
-# USAGE: ugc [-v] [-m] {java,python,ruby,node} pid
+# 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")
@@ -20,6 +20,7 @@ import time
 examples = """examples:
     ./ugc java 185           # trace Java GCs in process 185
     ./ugc ruby 1344 -m       # trace Ruby GCs reporting in ms
+    ./ugc -M 10 java 185     # trace only Java GCs longer than 10ms
 """
 parser = argparse.ArgumentParser(
     description="Summarize garbage collection events in high-level languages.",
@@ -32,6 +33,10 @@ 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)
@@ -85,12 +90,16 @@ int trace_%s(struct pt_regs *ctx) {
         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, self.end_save)
+        """ % (self.begin, self.begin_save, self.end,
+               args.minimum * 1000000, self.end_save)
         return text
 
     def attach(self):
@@ -187,7 +196,7 @@ 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 %-40s %-8s" % ("START", "DESCRIPTION", time_col))
+print("%-8s %-8s %-40s" % ("START", time_col, "DESCRIPTION"))
 
 class GCEvent(ct.Structure):
     _fields_ = [
@@ -207,9 +216,10 @@ 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
-    print("%-8.3f %-40s %-8.2f" % (time.time() - start_ts,
-                                   probes[event.probe_index].format(event),
-                                   elapsed))
+    description = probes[event.probe_index].format(event)
+    if args.filter and not args.filter in description:
+        return
+    print("%-8.3f %-8.2f %s" % (time.time() - start_ts, elapsed, description))
 
 bpf["gcs"].open_perf_buffer(print_event)
 while 1:

tools/ugc_example.txt

@@ -8,45 +8,68 @@ the GC event is also provided.
 
 For example, to trace all garbage collection events in a specific Node process:
 
-# ./ugc node $(pidof node)
-Tracing garbage collections in node process 3018... Ctrl-C to quit.
-START    DESCRIPTION                              TIME (us)
-3.864    GC mark-sweep-compact                    3189.00 
-4.937    GC scavenge                              1254.00 
-4.940    GC scavenge                              1657.00 
-4.943    GC scavenge                              1171.00 
-4.949    GC scavenge                              2216.00 
-4.954    GC scavenge                              2515.00 
-4.960    GC scavenge                              2243.00 
-4.966    GC scavenge                              2410.00 
-4.976    GC scavenge                              3003.00 
-4.986    GC scavenge                              4174.00 
-4.994    GC scavenge                              1508.00 
-5.003    GC scavenge                              1966.00 
-5.010    GC scavenge                              1636.00 
-5.022    GC scavenge                              3564.00 
-5.035    GC scavenge                              3275.00 
-5.045    GC incremental mark                      157.00  
-5.049    GC mark-sweep-compact                    3248.00 
-5.060    GC scavenge                              4785.00 
-5.081    GC scavenge                              6616.00 
-5.094    GC scavenge                              8570.00 
-5.144    GC scavenge                              456.00  
-7.188    GC scavenge                              2345.00 
-7.227    GC scavenge                              12054.00
-7.253    GC scavenge                              15626.00
-7.304    GC scavenge                              15329.00
-7.384    GC scavenge                              7168.00 
-7.411    GC scavenge                              3794.00 
-7.414    GC incremental mark                      123.00  
-7.430    GC mark-sweep-compact                    7110.00 
+# ugc node $(pidof node)
+Tracing garbage collections in node process 30012... Ctrl-C to quit.
+START    TIME (us) DESCRIPTION                             
+1.500    1181.00  GC scavenge
+1.505    1704.00  GC scavenge
+1.509    1534.00  GC scavenge
+1.515    1953.00  GC scavenge
+1.519    2155.00  GC scavenge
+1.525    2055.00  GC scavenge
+1.530    2164.00  GC scavenge
+1.536    2170.00  GC scavenge
+1.541    2237.00  GC scavenge
+1.547    1982.00  GC scavenge
+1.551    2333.00  GC scavenge
+1.557    2043.00  GC scavenge
+1.561    2028.00  GC scavenge
+1.573    3650.00  GC scavenge
+1.580    4443.00  GC scavenge
+1.604    6236.00  GC scavenge
+1.615    8324.00  GC scavenge
+1.659    11249.00 GC scavenge
+1.678    16084.00 GC scavenge
+1.747    15250.00 GC scavenge
+1.937    191.00   GC incremental mark
+2.001    63120.00 GC mark-sweep-compact
+3.185    153.00   GC incremental mark
+3.207    20847.00 GC mark-sweep-compact
+^C
+
+The above output shows some fairly long GCs, notably around 2 seconds in there
+is a collection that takes over 60ms (mark-sweep-compact).
+
+Occasionally, it might be useful to filter out collections that are very short,
+or display only collections that have a specific description. The -M and -F
+switches can be useful for this:
+
+# ugc -F Tenured java $(pidof java)
+Tracing garbage collections in java process 29907... Ctrl-C to quit.
+START    TIME (us) DESCRIPTION                             
+0.360    4309.00  MarkSweepCompact Tenured Gen used=287528->287528 max=173408256->173408256
+2.459    4232.00  MarkSweepCompact Tenured Gen used=287528->287528 max=173408256->173408256
+4.648    4139.00  MarkSweepCompact Tenured Gen used=287528->287528 max=173408256->173408256
+^C
+
+# ugc -M 1 java $(pidof java)
+Tracing garbage collections in java process 29907... Ctrl-C to quit.
+START    TIME (us) DESCRIPTION                             
+0.160    3715.00  MarkSweepCompact Code Cache used=287528->3209472 max=173408256->251658240
+0.160    3975.00  MarkSweepCompact Metaspace used=287528->3092104 max=173408256->18446744073709551615
+0.160    4058.00  MarkSweepCompact Compressed Class Space used=287528->266840 max=173408256->1073741824
+0.160    4110.00  MarkSweepCompact Eden Space used=287528->0 max=173408256->69337088
+0.160    4159.00  MarkSweepCompact Survivor Space used=287528->0 max=173408256->8650752
+0.160    4207.00  MarkSweepCompact Tenured Gen used=287528->287528 max=173408256->173408256
+0.160    4289.00    used=0->0 max=0->0
 ^C
 
 
 USAGE message:
 
-# ./ugc -h
-usage: ugc.py [-h] [-v] [-m] {java,python,ruby,node} pid
+# ugc -h
+usage: ugc.py [-h] [-v] [-m] [-M MINIMUM] [-F FILTER]
+              {java,python,ruby,node} pid
 
 Summarize garbage collection events in high-level languages.
 
@@ -60,7 +83,12 @@ optional arguments:
   -v, --verbose         verbose mode: print the BPF program (for debugging
                         purposes)
   -m, --milliseconds    report times in milliseconds (default is microseconds)
+  -M MINIMUM, --minimum MINIMUM
+                        display only GCs longer than this many milliseconds
+  -F FILTER, --filter FILTER
+                        display only GCs whose description contains this text
 
 examples:
     ./ugc java 185           # trace Java GCs in process 185
     ./ugc ruby 1344 -m       # trace Ruby GCs reporting in ms
+    ./ugc -M 10 java 185     # trace only Java GCs longer than 10ms