Commit c325200c authored by Sasha Goldshtein's avatar Sasha Goldshtein

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

Filter out collections that are shorter than x milliseconds by using
`ugc -M x`. Display only collections that contain a certain string s
in their description by using `ugc -F s`. The latter option is not
implemented in the kernel, but rather just before printing the event
in the user script (for simplicity), and documented as such.
parent 5467ccf4
...@@ -2,7 +2,7 @@ ...@@ -2,7 +2,7 @@
.SH NAME .SH NAME
ugc \- Trace garbage collection events in high-level languages. ugc \- Trace garbage collection events in high-level languages.
.SH SYNOPSIS .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 .SH DESCRIPTION
This traces garbage collection events as they occur, including their duration This traces garbage collection events as they occur, including their duration
and any additional information (such as generation collected or type of GC) and any additional information (such as generation collected or type of GC)
...@@ -24,6 +24,18 @@ Print the resulting BPF program, for debugging purposes. ...@@ -24,6 +24,18 @@ Print the resulting BPF program, for debugging purposes.
\-m \-m
Print times in milliseconds. The default is microseconds. Print times in milliseconds. The default is microseconds.
.TP .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} {java,python,ruby,node}
The language to trace. The language to trace.
.TP .TP
...@@ -39,16 +51,22 @@ Trace garbage collections in a specific Java process, and print GC times in ...@@ -39,16 +51,22 @@ Trace garbage collections in a specific Java process, and print GC times in
milliseconds: milliseconds:
# #
.B ugc -m java 6004 .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 .SH FIELDS
.TP .TP
START START
The start time of the GC, in seconds from the beginning of the trace. The start time of the GC, in seconds from the beginning of the trace.
.TP .TP
DESCRIPTION
The runtime-provided description of this garbage collection event.
.TP
TIME TIME
The duration of the garbage collection event. The duration of the garbage collection event.
.TP
DESCRIPTION
The runtime-provided description of this garbage collection event.
.SH OVERHEAD .SH OVERHEAD
Garbage collection events, even if frequent, should not produce a considerable Garbage collection events, even if frequent, should not produce a considerable
overhead when traced because they are still not very common. Even hundreds of overhead when traced because they are still not very common. Even hundreds of
......
...@@ -4,7 +4,7 @@ ...@@ -4,7 +4,7 @@
# ugc Summarize garbage collection events in high-level languages. # ugc Summarize garbage collection events in high-level languages.
# For Linux, uses BCC, eBPF. # 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 # Copyright 2016 Sasha Goldshtein
# Licensed under the Apache License, Version 2.0 (the "License") # Licensed under the Apache License, Version 2.0 (the "License")
...@@ -20,6 +20,7 @@ import time ...@@ -20,6 +20,7 @@ import time
examples = """examples: examples = """examples:
./ugc java 185 # trace Java GCs in process 185 ./ugc java 185 # trace Java GCs in process 185
./ugc ruby 1344 -m # trace Ruby GCs reporting in ms ./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( parser = argparse.ArgumentParser(
description="Summarize garbage collection events in high-level languages.", description="Summarize garbage collection events in high-level languages.",
...@@ -32,6 +33,10 @@ parser.add_argument("-v", "--verbose", action="store_true", ...@@ -32,6 +33,10 @@ parser.add_argument("-v", "--verbose", action="store_true",
help="verbose mode: print the BPF program (for debugging purposes)") help="verbose mode: print the BPF program (for debugging purposes)")
parser.add_argument("-m", "--milliseconds", action="store_true", parser.add_argument("-m", "--milliseconds", action="store_true",
help="report times in milliseconds (default is microseconds)") 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() args = parser.parse_args()
usdt = USDT(pid=args.pid) usdt = USDT(pid=args.pid)
...@@ -85,12 +90,16 @@ int trace_%s(struct pt_regs *ctx) { ...@@ -85,12 +90,16 @@ int trace_%s(struct pt_regs *ctx) {
return 0; // missed the entry event on this thread return 0; // missed the entry event on this thread
} }
elapsed = bpf_ktime_get_ns() - e->start_ns; elapsed = bpf_ktime_get_ns() - e->start_ns;
if (elapsed < %d) {
return 0;
}
event.elapsed_ns = elapsed; event.elapsed_ns = elapsed;
%s %s
gcs.perf_submit(ctx, &event, sizeof(event)); gcs.perf_submit(ctx, &event, sizeof(event));
return 0; 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 return text
def attach(self): def attach(self):
...@@ -187,7 +196,7 @@ bpf = BPF(text=program, usdt_contexts=[usdt]) ...@@ -187,7 +196,7 @@ bpf = BPF(text=program, usdt_contexts=[usdt])
print("Tracing garbage collections in %s process %d... Ctrl-C to quit." % print("Tracing garbage collections in %s process %d... Ctrl-C to quit." %
(args.language, args.pid)) (args.language, args.pid))
time_col = "TIME (ms)" if args.milliseconds else "TIME (us)" 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): class GCEvent(ct.Structure):
_fields_ = [ _fields_ = [
...@@ -207,9 +216,10 @@ def print_event(cpu, data, size): ...@@ -207,9 +216,10 @@ def print_event(cpu, data, size):
event = ct.cast(data, ct.POINTER(GCEvent)).contents event = ct.cast(data, ct.POINTER(GCEvent)).contents
elapsed = event.elapsed_ns/1000000 if args.milliseconds else \ elapsed = event.elapsed_ns/1000000 if args.milliseconds else \
event.elapsed_ns/1000 event.elapsed_ns/1000
print("%-8.3f %-40s %-8.2f" % (time.time() - start_ts, description = probes[event.probe_index].format(event)
probes[event.probe_index].format(event), if args.filter and not args.filter in description:
elapsed)) return
print("%-8.3f %-8.2f %s" % (time.time() - start_ts, elapsed, description))
bpf["gcs"].open_perf_buffer(print_event) bpf["gcs"].open_perf_buffer(print_event)
while 1: while 1:
......
...@@ -8,45 +8,68 @@ the GC event is also provided. ...@@ -8,45 +8,68 @@ the GC event is also provided.
For example, to trace all garbage collection events in a specific Node process: For example, to trace all garbage collection events in a specific Node process:
# ./ugc node $(pidof node) # ugc node $(pidof node)
Tracing garbage collections in node process 3018... Ctrl-C to quit. Tracing garbage collections in node process 30012... Ctrl-C to quit.
START DESCRIPTION TIME (us) START TIME (us) DESCRIPTION
3.864 GC mark-sweep-compact 3189.00 1.500 1181.00 GC scavenge
4.937 GC scavenge 1254.00 1.505 1704.00 GC scavenge
4.940 GC scavenge 1657.00 1.509 1534.00 GC scavenge
4.943 GC scavenge 1171.00 1.515 1953.00 GC scavenge
4.949 GC scavenge 2216.00 1.519 2155.00 GC scavenge
4.954 GC scavenge 2515.00 1.525 2055.00 GC scavenge
4.960 GC scavenge 2243.00 1.530 2164.00 GC scavenge
4.966 GC scavenge 2410.00 1.536 2170.00 GC scavenge
4.976 GC scavenge 3003.00 1.541 2237.00 GC scavenge
4.986 GC scavenge 4174.00 1.547 1982.00 GC scavenge
4.994 GC scavenge 1508.00 1.551 2333.00 GC scavenge
5.003 GC scavenge 1966.00 1.557 2043.00 GC scavenge
5.010 GC scavenge 1636.00 1.561 2028.00 GC scavenge
5.022 GC scavenge 3564.00 1.573 3650.00 GC scavenge
5.035 GC scavenge 3275.00 1.580 4443.00 GC scavenge
5.045 GC incremental mark 157.00 1.604 6236.00 GC scavenge
5.049 GC mark-sweep-compact 3248.00 1.615 8324.00 GC scavenge
5.060 GC scavenge 4785.00 1.659 11249.00 GC scavenge
5.081 GC scavenge 6616.00 1.678 16084.00 GC scavenge
5.094 GC scavenge 8570.00 1.747 15250.00 GC scavenge
5.144 GC scavenge 456.00 1.937 191.00 GC incremental mark
7.188 GC scavenge 2345.00 2.001 63120.00 GC mark-sweep-compact
7.227 GC scavenge 12054.00 3.185 153.00 GC incremental mark
7.253 GC scavenge 15626.00 3.207 20847.00 GC mark-sweep-compact
7.304 GC scavenge 15329.00 ^C
7.384 GC scavenge 7168.00
7.411 GC scavenge 3794.00 The above output shows some fairly long GCs, notably around 2 seconds in there
7.414 GC incremental mark 123.00 is a collection that takes over 60ms (mark-sweep-compact).
7.430 GC mark-sweep-compact 7110.00
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 ^C
USAGE message: USAGE message:
# ./ugc -h # ugc -h
usage: ugc.py [-h] [-v] [-m] {java,python,ruby,node} pid usage: ugc.py [-h] [-v] [-m] [-M MINIMUM] [-F FILTER]
{java,python,ruby,node} pid
Summarize garbage collection events in high-level languages. Summarize garbage collection events in high-level languages.
...@@ -60,7 +83,12 @@ optional arguments: ...@@ -60,7 +83,12 @@ optional arguments:
-v, --verbose verbose mode: print the BPF program (for debugging -v, --verbose verbose mode: print the BPF program (for debugging
purposes) purposes)
-m, --milliseconds report times in milliseconds (default is microseconds) -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: examples:
./ugc java 185 # trace Java GCs in process 185 ./ugc java 185 # trace Java GCs in process 185
./ugc ruby 1344 -m # trace Ruby GCs reporting in ms ./ugc ruby 1344 -m # trace Ruby GCs reporting in ms
./ugc -M 10 java 185 # trace only Java GCs longer than 10ms
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment