1 /*
2 * Copyright (c) 2013, 2014, Oracle and/or its affiliates. All rights reserved.
3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
4 *
5 * This code is free software; you can redistribute it and/or modify it
6 * under the terms of the GNU General Public License version 2 only, as
7 * published by the Free Software Foundation.
8 *
9 * This code is distributed in the hope that it will be useful, but WITHOUT
10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
11 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
12 * version 2 for more details (a copy is included in the LICENSE file that
13 * accompanied this code).
14 *
15 * You should have received a copy of the GNU General Public License version
16 * 2 along with this work; if not, write to the Free Software Foundation,
17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
18 *
19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
20 * or visit www.oracle.com if you need additional information or have any
21 * questions.
22 */
23 package org.graalvm.compiler.hotspot.debug;
24
25 import java.io.FileNotFoundException;
26 import java.io.IOException;
27 import java.io.OutputStream;
28 import java.io.PrintStream;
29 import java.nio.file.Path;
30 import java.util.Iterator;
31 import java.util.Locale;
32 import java.util.Map;
33 import java.util.Map.Entry;
34 import java.util.Set;
35 import java.util.TreeMap;
36 import java.util.TreeSet;
37 import java.util.concurrent.ConcurrentHashMap;
38 import java.util.concurrent.atomic.AtomicLong;
39
40 import org.graalvm.compiler.core.common.SuppressFBWarnings;
41 import org.graalvm.compiler.debug.CSVUtil;
42 import org.graalvm.compiler.debug.GraalDebugConfig;
43 import org.graalvm.compiler.debug.GraalError;
44 import org.graalvm.compiler.debug.TTY;
45 import org.graalvm.compiler.hotspot.GraalHotSpotVMConfig;
46 import org.graalvm.compiler.hotspot.replacements.HotspotSnippetsOptions;
47 import org.graalvm.compiler.nodes.debug.DynamicCounterNode;
48 import org.graalvm.compiler.options.Option;
49 import org.graalvm.compiler.options.OptionType;
50 import org.graalvm.compiler.options.OptionValue;
51 import org.graalvm.compiler.options.StableOptionValue;
52 import org.graalvm.compiler.options.UniquePathUtilities;
53
54 import jdk.vm.ci.hotspot.HotSpotJVMCIRuntime;
55
56 //JaCoCo Exclude
57
58 /**
59 * This class contains infrastructure to maintain counters based on {@link DynamicCounterNode}s. The
60 * infrastructure is enabled by specifying either the GenericDynamicCounters or
61 * BenchmarkDynamicCounters option.
62 * <p>
63 *
64 * The counters are kept in a special area allocated for each native JavaThread object, and the
65 * number of counters is configured using {@code -XX:JVMCICounterSize=value}.
66 * {@code -XX:+/-JVMCICountersExcludeCompiler} configures whether to exclude compiler threads
67 * (defaults to true).
68 *
69 * The subsystems that use the logging need to have their own options to turn on the counters, and
70 * insert DynamicCounterNodes when they're enabled.
71 *
72 * Counters will be displayed as a rate (per second) if their group name starts with "~", otherwise
73 * they will be displayed as a total number.
74 *
75 * <h1>Example</h1> In order to create statistics about allocations within the DaCapo pmd benchmark
76 * the following steps are necessary:
77 * <ul>
78 * <li>Set {@code -XX:JVMCICounterSize=value}. The actual required value depends on the granularity
79 * of the profiling, 10000 should be enough for most cases.</li>
80 * <li>Also: {@code -XX:+/-JVMCICountersExcludeCompiler} specifies whether the numbers generated by
81 * compiler threads should be excluded (default: true).</li>
82 * <li>Start the DaCapo pmd benchmark with
83 * {@code "-Dgraal.BenchmarkDynamicCounters=err, starting ====, PASSED in "} and
84 * {@code -Dgraal.ProfileAllocations=true}.</li>
85 * <li>The numbers will only include allocation from compiled code!</li>
86 * <li>The counters can be further configured by modifying the
87 * {@link HotspotSnippetsOptions#ProfileAllocationsContext} flag..</li>
88 * </ul>
89 */
90 public class BenchmarkCounters {
91
92 static class Options {
93
94 //@formatter:off
95 @Option(help = "Turn on the benchmark counters, and displays the results on VM shutdown", type = OptionType.Debug)
96 public static final OptionValue<Boolean> GenericDynamicCounters = new OptionValue<>(false);
97 @Option(help = "Turn on the benchmark counters, and displays the results every n milliseconds", type = OptionType.Debug)
98 public static final OptionValue<Integer> TimedDynamicCounters = new OptionValue<>(-1);
99
100 @Option(help = "Turn on the benchmark counters, and listen for specific patterns on System.out/System.err:%n" +
101 "Format: (err|out),start pattern,end pattern (~ matches multiple digits)%n" +
102 "Examples:%n" +
103 " dacapo = 'err, starting =====, PASSED in'%n" +
104 " specjvm2008 = 'out,Iteration ~ (~s) begins:,Iteration ~ (~s) ends:'", type = OptionType.Debug)
105 public static final OptionValue<String> BenchmarkDynamicCounters = new OptionValue<>(null);
106 @Option(help = "Use grouping separators for number printing", type = OptionType.Debug)
107 public static final OptionValue<Boolean> DynamicCountersPrintGroupSeparator = new OptionValue<>(true);
108 @Option(help = "Print in human readable format", type = OptionType.Debug)
109 public static final OptionValue<Boolean> DynamicCountersHumanReadable = new OptionValue<>(true);
110 @Option(help = "Benchmark counters log file (default is stdout)", type = OptionType.Debug)
111 public static final OptionValue<String> BenchmarkCountersFile = new OptionValue<>(null);
112 @Option(help = "Dump dynamic counters", type = OptionType.Debug)
113 public static final StableOptionValue<Boolean> BenchmarkCountersDumpDynamic = new StableOptionValue<>(true);
114 @Option(help = "Dump static counters", type = OptionType.Debug)
115 public static final StableOptionValue<Boolean> BenchmarkCountersDumpStatic = new StableOptionValue<>(false);
116 //@formatter:on
117 }
118
119 public static boolean enabled = false;
120
121 private static class Counter {
122 public final int index;
123 public final String group;
124 public final AtomicLong staticCounters;
125
126 Counter(int index, String group, AtomicLong staticCounters) {
127 this.index = index;
128 this.group = group;
129 this.staticCounters = staticCounters;
130 }
131 }
132
133 public static final ConcurrentHashMap<String, Counter> counterMap = new ConcurrentHashMap<>();
134 public static long[] delta;
135
136 public static int getIndexConstantIncrement(String name, String group, GraalHotSpotVMConfig config, long increment) {
137 Counter counter = getCounter(name, group, config);
138 counter.staticCounters.addAndGet(increment);
139 return counter.index;
140 }
141
142 public static int getIndex(String name, String group, GraalHotSpotVMConfig config) {
143 Counter counter = getCounter(name, group, config);
144 return counter.index;
145 }
146
147 @SuppressFBWarnings(value = "AT_OPERATION_SEQUENCE_ON_CONCURRENT_ABSTRACTION", justification = "concurrent abstraction calls are in synchronized block")
148 private static Counter getCounter(String name, String group, GraalHotSpotVMConfig config) throws GraalError {
149 if (!enabled) {
150 throw new GraalError("cannot access count index when counters are not enabled: " + group + ", " + name);
151 }
152 String nameGroup = name + "#" + group;
153 Counter counter = counterMap.get(nameGroup);
154 if (counter == null) {
155 synchronized (BenchmarkCounters.class) {
156 counter = counterMap.get(nameGroup);
157 if (counter == null) {
158 counter = new Counter(counterMap.size(), group, new AtomicLong());
159 counterMap.put(nameGroup, counter);
160 }
161 }
162 }
163 assert counter.group.equals(group) : "mismatching groups: " + counter.group + " vs. " + group;
164 int countersSize = config.jvmciCountersSize;
165 if (counter.index >= countersSize) {
166 throw new GraalError("too many counters, reduce number of counters or increase -XX:JVMCICounterSize=... (current value: " + countersSize + ")");
167 }
168 return counter;
169 }
170
171 private static synchronized void dump(PrintStream out, double seconds, long[] counters, int maxRows) {
172 if (!counterMap.isEmpty()) {
173 if (Options.DynamicCountersHumanReadable.getValue()) {
174 out.println("====== dynamic counters (" + counterMap.size() + " in total) ======");
175 }
176 TreeSet<String> set = new TreeSet<>();
177 counterMap.forEach((nameGroup, counter) -> set.add(counter.group));
178 for (String group : set) {
179 if (group != null) {
180 if (Options.BenchmarkCountersDumpStatic.getValue()) {
181 dumpCounters(out, seconds, counters, true, group, maxRows);
182 }
183 if (Options.BenchmarkCountersDumpDynamic.getValue()) {
184 dumpCounters(out, seconds, counters, false, group, maxRows);
185 }
186 }
187 }
188 if (Options.DynamicCountersHumanReadable.getValue()) {
189 out.println("============================");
190 }
191
192 clear(counters);
193 }
194 }
195
196 private static synchronized void clear(long[] counters) {
197 delta = counters;
198 }
199
200 private static synchronized void dumpCounters(PrintStream out, double seconds, long[] counters, boolean staticCounter, String group, int maxRows) {
201
202 // collect the numbers
203 long[] array;
204 if (staticCounter) {
205 array = new long[counterMap.size()];
206 for (Counter counter : counterMap.values()) {
207 array[counter.index] = counter.staticCounters.get();
208 }
209 } else {
210 array = counters.clone();
211 for (int i = 0; i < array.length; i++) {
212 array[i] -= delta[i];
213 }
214 }
215 Set<Entry<String, Counter>> counterEntrySet = counterMap.entrySet();
216 if (Options.DynamicCountersHumanReadable.getValue()) {
217 dumpHumanReadable(out, seconds, staticCounter, group, maxRows, array, counterEntrySet);
218 } else {
219 dumpComputerReadable(out, staticCounter, group, array, counterEntrySet);
220 }
221 }
222
223 private static String getName(String nameGroup, String group) {
224 return nameGroup.substring(0, nameGroup.length() - group.length() - 1);
225 }
226
227 private static void dumpHumanReadable(PrintStream out, double seconds, boolean staticCounter, String group, int maxRows, long[] array, Set<Entry<String, Counter>> counterEntrySet) {
228 // sort the counters by putting them into a sorted map
229 TreeMap<Long, String> sorted = new TreeMap<>();
230 long sum = 0;
231 for (Map.Entry<String, Counter> entry : counterEntrySet) {
232 Counter counter = entry.getValue();
233 int index = counter.index;
234 if (counter.group.equals(group)) {
235 sum += array[index];
236 sorted.put(array[index] * array.length + index, getName(entry.getKey(), group));
237 }
238 }
239
240 if (sum > 0) {
241 long cutoff = sorted.size() < 10 ? 1 : Math.max(1, sum / 100);
242 int cnt = sorted.size();
243
244 // remove everything below cutoff and keep at most maxRows
245 Iterator<Map.Entry<Long, String>> iter = sorted.entrySet().iterator();
246 while (iter.hasNext()) {
247 Map.Entry<Long, String> entry = iter.next();
248 long counter = entry.getKey() / array.length;
249 if (counter < cutoff || cnt > maxRows) {
250 iter.remove();
251 }
252 cnt--;
253 }
254
255 String numFmt = Options.DynamicCountersPrintGroupSeparator.getValue() ? "%,19d" : "%19d";
256 if (staticCounter) {
257 out.println("=========== " + group + " (static counters):");
258 for (Map.Entry<Long, String> entry : sorted.entrySet()) {
259 long counter = entry.getKey() / array.length;
260 out.format(Locale.US, numFmt + " %3d%% %s\n", counter, percentage(counter, sum), entry.getValue());
261 }
262 out.format(Locale.US, numFmt + " total\n", sum);
263 } else {
264 if (group.startsWith("~")) {
265 out.println("=========== " + group + " (dynamic counters), time = " + seconds + " s:");
266 for (Map.Entry<Long, String> entry : sorted.entrySet()) {
267 long counter = entry.getKey() / array.length;
268 out.format(Locale.US, numFmt + "/s %3d%% %s\n", (long) (counter / seconds), percentage(counter, sum), entry.getValue());
269 }
270 out.format(Locale.US, numFmt + "/s total\n", (long) (sum / seconds));
271 } else {
272 out.println("=========== " + group + " (dynamic counters):");
273 for (Map.Entry<Long, String> entry : sorted.entrySet()) {
274 long counter = entry.getKey() / array.length;
275 out.format(Locale.US, numFmt + " %3d%% %s\n", counter, percentage(counter, sum), entry.getValue());
276 }
277 out.format(Locale.US, numFmt + " total\n", sum);
278 }
279 }
280 }
281 }
282
283 private static final String CSV_FMT = CSVUtil.buildFormatString("%s", "%s", "%s", "%d");
284
285 private static void dumpComputerReadable(PrintStream out, boolean staticCounter, String group, long[] array, Set<Entry<String, Counter>> counterEntrySet) {
286 String category = staticCounter ? "static counters" : "dynamic counters";
287 for (Map.Entry<String, Counter> entry : counterEntrySet) {
288 Counter counter = entry.getValue();
289 if (counter.group.equals(group)) {
290 String name = getName(entry.getKey(), group);
291 int index = counter.index;
292 long value = array[index];
293 CSVUtil.Escape.println(out, CSV_FMT, category, group, name, value);
294 }
295 }
296 }
297
298 private static long percentage(long counter, long sum) {
299 return (counter * 200 + 1) / sum / 2;
300 }
301
302 private abstract static class CallbackOutputStream extends OutputStream {
303
304 protected final PrintStream delegate;
305 private final byte[][] patterns;
306 private final int[] positions;
307
308 CallbackOutputStream(PrintStream delegate, String... patterns) {
309 this.delegate = delegate;
310 this.positions = new int[patterns.length];
311 this.patterns = new byte[patterns.length][];
312 for (int i = 0; i < patterns.length; i++) {
313 this.patterns[i] = patterns[i].getBytes();
314 }
315 }
316
317 protected abstract void patternFound(int index);
318
319 @Override
320 public void write(int b) throws IOException {
321 try {
322 delegate.write(b);
323 for (int i = 0; i < patterns.length; i++) {
324 int j = positions[i];
325 byte[] cs = patterns[i];
326 byte patternChar = cs[j];
327 if (patternChar == '~' && Character.isDigit(b)) {
328 // nothing to do...
329 } else {
330 if (patternChar == '~') {
331 patternChar = cs[++positions[i]];
332 }
333 if (b == patternChar) {
334 positions[i]++;
335 } else {
336 positions[i] = 0;
337 }
338 }
339 if (positions[i] == patterns[i].length) {
340 positions[i] = 0;
341 patternFound(i);
342 }
343 }
344 } catch (RuntimeException e) {
345 e.printStackTrace(delegate);
346 throw e;
347 }
348 }
349 }
350
351 public static void initialize(final HotSpotJVMCIRuntime jvmciRuntime) {
352 final class BenchmarkCountersOutputStream extends CallbackOutputStream {
353
354 private long startTime;
355 private boolean running;
356 private boolean waitingForEnd;
357
358 private BenchmarkCountersOutputStream(PrintStream delegate, String start, String end) {
359 super(delegate, new String[]{"\n", end, start});
360 }
361
362 @Override
363 protected void patternFound(int index) {
364 switch (index) {
365 case 2:
366 startTime = System.nanoTime();
367 BenchmarkCounters.clear(jvmciRuntime.collectCounters());
368 running = true;
369 break;
370 case 1:
371 if (running) {
372 waitingForEnd = true;
373 }
374 break;
375 case 0:
376 if (waitingForEnd) {
377 waitingForEnd = false;
378 running = false;
379 BenchmarkCounters.dump(getPrintStream(), (System.nanoTime() - startTime) / 1000000000d, jvmciRuntime.collectCounters(), 100);
380 }
381 break;
382 }
383 }
384 }
385
386 if (Options.BenchmarkDynamicCounters.getValue() != null) {
387 String[] arguments = Options.BenchmarkDynamicCounters.getValue().split(",");
388 if (arguments.length == 0 || (arguments.length % 3) != 0) {
389 throw new GraalError("invalid arguments to BenchmarkDynamicCounters: (err|out),start,end,(err|out),start,end,... (~ matches multiple digits)");
390 }
391 for (int i = 0; i < arguments.length; i += 3) {
392 if (arguments[i].equals("err")) {
393 System.setErr(new PrintStream(new BenchmarkCountersOutputStream(System.err, arguments[i + 1], arguments[i + 2])));
394 } else if (arguments[i].equals("out")) {
395 System.setOut(new PrintStream(new BenchmarkCountersOutputStream(System.out, arguments[i + 1], arguments[i + 2])));
396 } else {
397 throw new GraalError("invalid arguments to BenchmarkDynamicCounters: err|out");
398 }
399 }
400 enabled = true;
401 }
402 if (Options.GenericDynamicCounters.getValue()) {
403 enabled = true;
404 }
405 if (Options.TimedDynamicCounters.getValue() > 0) {
406 Thread thread = new Thread() {
407 long lastTime = System.nanoTime();
408 PrintStream out = getPrintStream();
409
410 @Override
411 public void run() {
412 while (true) {
413 try {
414 Thread.sleep(Options.TimedDynamicCounters.getValue());
415 } catch (InterruptedException e) {
416 }
417 long time = System.nanoTime();
418 dump(out, (time - lastTime) / 1000000000d, jvmciRuntime.collectCounters(), 10);
419 lastTime = time;
420 }
421 }
422 };
423 thread.setDaemon(true);
424 thread.setPriority(Thread.MAX_PRIORITY);
425 thread.start();
426 enabled = true;
427 }
428 if (enabled) {
429 clear(jvmciRuntime.collectCounters());
430 }
431 }
432
433 public static void shutdown(HotSpotJVMCIRuntime jvmciRuntime, long compilerStartTime) {
434 if (Options.GenericDynamicCounters.getValue()) {
435 dump(getPrintStream(), (System.nanoTime() - compilerStartTime) / 1000000000d, jvmciRuntime.collectCounters(), 100);
436 }
437 }
438
439 private static PrintStream getPrintStream() {
440 if (Options.BenchmarkCountersFile.getValue() != null) {
441 try {
442 Path path = UniquePathUtilities.getPathGlobal(Options.BenchmarkCountersFile, GraalDebugConfig.Options.DumpPath, "csv");
443 TTY.println("Writing benchmark counters to '%s'", path);
444 return new PrintStream(path.toFile());
445 } catch (FileNotFoundException e) {
446 TTY.out().println(e.getMessage());
447 TTY.out().println("Fallback to default");
448 }
449 }
450 return TTY.out;
451 }
452 }