001/* 002 * Copyright (c) 2013, 2014, Oracle and/or its affiliates. All rights reserved. 003 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. 004 * 005 * This code is free software; you can redistribute it and/or modify it 006 * under the terms of the GNU General Public License version 2 only, as 007 * published by the Free Software Foundation. 008 * 009 * This code is distributed in the hope that it will be useful, but WITHOUT 010 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or 011 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License 012 * version 2 for more details (a copy is included in the LICENSE file that 013 * accompanied this code). 014 * 015 * You should have received a copy of the GNU General Public License version 016 * 2 along with this work; if not, write to the Free Software Foundation, 017 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. 018 * 019 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA 020 * or visit www.oracle.com if you need additional information or have any 021 * questions. 022 */ 023package com.oracle.graal.hotspot.debug; 024 025import java.io.*; 026import java.util.*; 027import java.util.Map.Entry; 028import java.util.concurrent.*; 029import java.util.concurrent.atomic.*; 030 031import jdk.internal.jvmci.common.*; 032import jdk.internal.jvmci.hotspot.*; 033import jdk.internal.jvmci.options.*; 034 035import com.oracle.graal.debug.*; 036import com.oracle.graal.hotspot.replacements.*; 037import com.oracle.graal.nodes.debug.*; 038 039//JaCoCo Exclude 040 041/** 042 * This class contains infrastructure to maintain counters based on {@link DynamicCounterNode}s. The 043 * infrastructure is enabled by specifying either the GenericDynamicCounters or 044 * BenchmarkDynamicCounters option. 045 * <p> 046 * 047 * The counters are kept in a special area allocated for each native JavaThread object, and the 048 * number of counters is configured using {@code -XX:GraalCounterSize=value}. 049 * {@code -XX:+/-GraalCountersExcludeCompiler} configures whether to exclude compiler threads 050 * (defaults to true). 051 * 052 * The subsystems that use the logging need to have their own options to turn on the counters, and 053 * insert DynamicCounterNodes when they're enabled. 054 * 055 * Counters will be displayed as a rate (per second) if their group name starts with "~", otherwise 056 * they will be displayed as a total number. 057 * 058 * <h1>Example</h1> In order to create statistics about allocations within the DaCapo pmd benchmark 059 * the following steps are necessary: 060 * <ul> 061 * <li>Set {@code -XX:GraalCounterSize=value}. The actual required value depends on the granularity 062 * of the profiling, 10000 should be enough for most cases.</li> 063 * <li>Also: {@code -XX:+/-GraalCountersExcludeCompiler} specifies whether the numbers generated by 064 * compiler threads should be excluded (default: true).</li> 065 * <li>Start the DaCapo pmd benchmark with 066 * {@code "-G:BenchmarkDynamicCounters=err, starting ====, PASSED in "} and 067 * {@code -G:+ProfileAllocations}.</li> 068 * <li>The numbers will only include allocation from compiled code!</li> 069 * <li>The counters can be further configured by modifying the 070 * {@link NewObjectSnippets#PROFILE_MODE} field.</li> 071 * </ul> 072 */ 073public class BenchmarkCounters { 074 075 static class Options { 076 077 //@formatter:off 078 @Option(help = "Turn on the benchmark counters, and displays the results on VM shutdown", type = OptionType.Debug) 079 private static final OptionValue<Boolean> GenericDynamicCounters = new OptionValue<>(false); 080 @Option(help = "Turn on the benchmark counters, and displays the results every n milliseconds", type = OptionType.Debug) 081 private static final OptionValue<Integer> TimedDynamicCounters = new OptionValue<>(-1); 082 083 @Option(help = "Turn on the benchmark counters, and listen for specific patterns on System.out/System.err:%n" + 084 "Format: (err|out),start pattern,end pattern (~ matches multiple digits)%n" + 085 "Examples:%n" + 086 " dacapo = 'err, starting =====, PASSED in'%n" + 087 " specjvm2008 = 'out,Iteration ~ (~s) begins:,Iteration ~ (~s) ends:'", type = OptionType.Debug) 088 private static final OptionValue<String> BenchmarkDynamicCounters = new OptionValue<>(null); 089 @Option(help = "Use grouping separators for number printing", type = OptionType.Debug) 090 private static final OptionValue<Boolean> DynamicCountersPrintGroupSeparator = new OptionValue<>(true); 091 @Option(help = "Print in human readable format", type = OptionType.Debug) 092 private static final OptionValue<Boolean> DynamicCountersHumanReadable = new OptionValue<>(true); 093 //@formatter:on 094 } 095 096 private static final boolean DUMP_STATIC = false; 097 098 public static boolean enabled = false; 099 100 private static class Counter { 101 public final int index; 102 public final String group; 103 public final AtomicLong staticCounters; 104 105 public Counter(int index, String group, AtomicLong staticCounters) { 106 this.index = index; 107 this.group = group; 108 this.staticCounters = staticCounters; 109 } 110 } 111 112 public static final ConcurrentHashMap<String, Counter> counterMap = new ConcurrentHashMap<>(); 113 public static long[] delta; 114 115 public static int getIndexConstantIncrement(String name, String group, HotSpotVMConfig config, long increment) { 116 Counter counter = getCounter(name, group, config); 117 counter.staticCounters.addAndGet(increment); 118 return counter.index; 119 } 120 121 public static int getIndex(String name, String group, HotSpotVMConfig config) { 122 Counter counter = getCounter(name, group, config); 123 return counter.index; 124 } 125 126 @SuppressFBWarnings(value = "AT_OPERATION_SEQUENCE_ON_CONCURRENT_ABSTRACTION", justification = "concurrent abstraction calls are in synchronized block") 127 private static Counter getCounter(String name, String group, HotSpotVMConfig config) throws JVMCIError { 128 if (!enabled) { 129 throw new JVMCIError("cannot access count index when counters are not enabled: " + group + ", " + name); 130 } 131 String nameGroup = name + "#" + group; 132 Counter counter = counterMap.get(nameGroup); 133 if (counter == null) { 134 synchronized (BenchmarkCounters.class) { 135 counter = counterMap.get(nameGroup); 136 if (counter == null) { 137 counter = new Counter(counterMap.size(), group, new AtomicLong()); 138 counterMap.put(nameGroup, counter); 139 } 140 } 141 } 142 assert counter.group.equals(group) : "mismatching groups: " + counter.group + " vs. " + group; 143 int countersSize = config.jvmciCountersSize; 144 if (counter.index >= countersSize) { 145 throw new JVMCIError("too many counters, reduce number of counters or increase -XX:GraalCounterSize=... (current value: " + countersSize + ")"); 146 } 147 return counter; 148 } 149 150 private static synchronized void dump(PrintStream out, double seconds, long[] counters, int maxRows) { 151 if (!counterMap.isEmpty()) { 152 out.println("====== dynamic counters (" + counterMap.size() + " in total) ======"); 153 TreeSet<String> set = new TreeSet<>(); 154 counterMap.forEach((nameGroup, counter) -> set.add(counter.group)); 155 for (String group : set) { 156 if (group != null) { 157 if (DUMP_STATIC) { 158 dumpCounters(out, seconds, counters, true, group, maxRows); 159 } 160 dumpCounters(out, seconds, counters, false, group, maxRows); 161 } 162 } 163 out.println("============================"); 164 165 clear(counters); 166 } 167 } 168 169 private static synchronized void clear(long[] counters) { 170 delta = counters; 171 } 172 173 private static synchronized void dumpCounters(PrintStream out, double seconds, long[] counters, boolean staticCounter, String group, int maxRows) { 174 175 // collect the numbers 176 long[] array; 177 if (staticCounter) { 178 array = new long[counterMap.size()]; 179 for (Counter counter : counterMap.values()) { 180 array[counter.index] = counter.staticCounters.get(); 181 } 182 } else { 183 array = counters.clone(); 184 for (int i = 0; i < array.length; i++) { 185 array[i] -= delta[i]; 186 } 187 } 188 Set<Entry<String, Counter>> counterEntrySet = counterMap.entrySet(); 189 if (Options.DynamicCountersHumanReadable.getValue()) { 190 dumpHumanReadable(out, seconds, staticCounter, group, maxRows, array, counterEntrySet); 191 } else { 192 dumpComputerReadable(out, staticCounter, group, array, counterEntrySet); 193 } 194 } 195 196 private static String getName(String nameGroup, String group) { 197 return nameGroup.substring(0, nameGroup.length() - group.length() - 1); 198 } 199 200 private static void dumpHumanReadable(PrintStream out, double seconds, boolean staticCounter, String group, int maxRows, long[] array, Set<Entry<String, Counter>> counterEntrySet) { 201 // sort the counters by putting them into a sorted map 202 TreeMap<Long, String> sorted = new TreeMap<>(); 203 long sum = 0; 204 for (Map.Entry<String, Counter> entry : counterEntrySet) { 205 Counter counter = entry.getValue(); 206 int index = counter.index; 207 if (counter.group.equals(group)) { 208 sum += array[index]; 209 sorted.put(array[index] * array.length + index, getName(entry.getKey(), group)); 210 } 211 } 212 213 if (sum > 0) { 214 long cutoff = sorted.size() < 10 ? 1 : Math.max(1, sum / 100); 215 int cnt = sorted.size(); 216 217 // remove everything below cutoff and keep at most maxRows 218 Iterator<Map.Entry<Long, String>> iter = sorted.entrySet().iterator(); 219 while (iter.hasNext()) { 220 Map.Entry<Long, String> entry = iter.next(); 221 long counter = entry.getKey() / array.length; 222 if (counter < cutoff || cnt > maxRows) { 223 iter.remove(); 224 } 225 cnt--; 226 } 227 228 String numFmt = Options.DynamicCountersPrintGroupSeparator.getValue() ? "%,19d" : "%19d"; 229 if (staticCounter) { 230 out.println("=========== " + group + " (static counters):"); 231 for (Map.Entry<Long, String> entry : sorted.entrySet()) { 232 long counter = entry.getKey() / array.length; 233 out.format(Locale.US, numFmt + " %3d%% %s\n", counter, percentage(counter, sum), entry.getValue()); 234 } 235 out.format(Locale.US, numFmt + " total\n", sum); 236 } else { 237 if (group.startsWith("~")) { 238 out.println("=========== " + group + " (dynamic counters), time = " + seconds + " s:"); 239 for (Map.Entry<Long, String> entry : sorted.entrySet()) { 240 long counter = entry.getKey() / array.length; 241 out.format(Locale.US, numFmt + "/s %3d%% %s\n", (long) (counter / seconds), percentage(counter, sum), entry.getValue()); 242 } 243 out.format(Locale.US, numFmt + "/s total\n", (long) (sum / seconds)); 244 } else { 245 out.println("=========== " + group + " (dynamic counters):"); 246 for (Map.Entry<Long, String> entry : sorted.entrySet()) { 247 long counter = entry.getKey() / array.length; 248 out.format(Locale.US, numFmt + " %3d%% %s\n", counter, percentage(counter, sum), entry.getValue()); 249 } 250 out.format(Locale.US, numFmt + " total\n", sum); 251 } 252 } 253 } 254 } 255 256 private static void dumpComputerReadable(PrintStream out, boolean staticCounter, String group, long[] array, Set<Entry<String, Counter>> counterEntrySet) { 257 String category = staticCounter ? "static counters" : "dynamic counters"; 258 for (Map.Entry<String, Counter> entry : counterEntrySet) { 259 Counter counter = entry.getValue(); 260 if (counter.group.equals(group)) { 261 String name = getName(entry.getKey(), group); 262 int index = counter.index; 263 long value = array[index]; 264 // TODO(je): escape strings 265 out.printf("%s;%s;%s;%d\n", category, group, name, value); 266 } 267 } 268 } 269 270 private static long percentage(long counter, long sum) { 271 return (counter * 200 + 1) / sum / 2; 272 } 273 274 private abstract static class CallbackOutputStream extends OutputStream { 275 276 protected final PrintStream delegate; 277 private final byte[][] patterns; 278 private final int[] positions; 279 280 public CallbackOutputStream(PrintStream delegate, String... patterns) { 281 this.delegate = delegate; 282 this.positions = new int[patterns.length]; 283 this.patterns = new byte[patterns.length][]; 284 for (int i = 0; i < patterns.length; i++) { 285 this.patterns[i] = patterns[i].getBytes(); 286 } 287 } 288 289 protected abstract void patternFound(int index); 290 291 @Override 292 public void write(int b) throws IOException { 293 try { 294 delegate.write(b); 295 for (int i = 0; i < patterns.length; i++) { 296 int j = positions[i]; 297 byte[] cs = patterns[i]; 298 byte patternChar = cs[j]; 299 if (patternChar == '~' && Character.isDigit(b)) { 300 // nothing to do... 301 } else { 302 if (patternChar == '~') { 303 patternChar = cs[++positions[i]]; 304 } 305 if (b == patternChar) { 306 positions[i]++; 307 } else { 308 positions[i] = 0; 309 } 310 } 311 if (positions[i] == patterns[i].length) { 312 positions[i] = 0; 313 patternFound(i); 314 } 315 } 316 } catch (RuntimeException e) { 317 e.printStackTrace(delegate); 318 throw e; 319 } 320 } 321 } 322 323 public static void initialize(final CompilerToVM compilerToVM) { 324 final class BenchmarkCountersOutputStream extends CallbackOutputStream { 325 326 private long startTime; 327 private boolean running; 328 private boolean waitingForEnd; 329 330 private BenchmarkCountersOutputStream(PrintStream delegate, String start, String end) { 331 super(delegate, new String[]{"\n", end, start}); 332 } 333 334 @Override 335 protected void patternFound(int index) { 336 switch (index) { 337 case 2: 338 startTime = System.nanoTime(); 339 BenchmarkCounters.clear(compilerToVM.collectCounters()); 340 running = true; 341 break; 342 case 1: 343 if (running) { 344 waitingForEnd = true; 345 } 346 break; 347 case 0: 348 if (waitingForEnd) { 349 waitingForEnd = false; 350 running = false; 351 BenchmarkCounters.dump(delegate, (System.nanoTime() - startTime) / 1000000000d, compilerToVM.collectCounters(), 100); 352 } 353 break; 354 } 355 } 356 } 357 358 if (Options.BenchmarkDynamicCounters.getValue() != null) { 359 String[] arguments = Options.BenchmarkDynamicCounters.getValue().split(","); 360 if (arguments.length == 0 || (arguments.length % 3) != 0) { 361 throw new JVMCIError("invalid arguments to BenchmarkDynamicCounters: (err|out),start,end,(err|out),start,end,... (~ matches multiple digits)"); 362 } 363 for (int i = 0; i < arguments.length; i += 3) { 364 if (arguments[i].equals("err")) { 365 System.setErr(new PrintStream(new BenchmarkCountersOutputStream(System.err, arguments[i + 1], arguments[i + 2]))); 366 } else if (arguments[i].equals("out")) { 367 System.setOut(new PrintStream(new BenchmarkCountersOutputStream(System.out, arguments[i + 1], arguments[i + 2]))); 368 } else { 369 throw new JVMCIError("invalid arguments to BenchmarkDynamicCounters: err|out"); 370 } 371 } 372 enabled = true; 373 } 374 if (Options.GenericDynamicCounters.getValue()) { 375 enabled = true; 376 } 377 if (Options.TimedDynamicCounters.getValue() > 0) { 378 Thread thread = new Thread() { 379 long lastTime = System.nanoTime(); 380 PrintStream out = TTY.out; 381 382 @Override 383 public void run() { 384 while (true) { 385 try { 386 Thread.sleep(Options.TimedDynamicCounters.getValue()); 387 } catch (InterruptedException e) { 388 } 389 long time = System.nanoTime(); 390 dump(out, (time - lastTime) / 1000000000d, compilerToVM.collectCounters(), 10); 391 lastTime = time; 392 } 393 } 394 }; 395 thread.setDaemon(true); 396 thread.setPriority(Thread.MAX_PRIORITY); 397 thread.start(); 398 enabled = true; 399 } 400 if (enabled) { 401 clear(compilerToVM.collectCounters()); 402 } 403 } 404 405 public static void shutdown(CompilerToVM compilerToVM, long compilerStartTime) { 406 if (Options.GenericDynamicCounters.getValue()) { 407 dump(TTY.out, (System.nanoTime() - compilerStartTime) / 1000000000d, compilerToVM.collectCounters(), 100); 408 } 409 } 410}