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.OptionKey;
  50 import org.graalvm.compiler.options.OptionType;
  51 import org.graalvm.compiler.options.OptionValues;
  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 OptionKey<Boolean> GenericDynamicCounters = new OptionKey<>(false);
  97         @Option(help = "Turn on the benchmark counters, and displays the results every n milliseconds", type = OptionType.Debug)
  98         public static final OptionKey<Integer> TimedDynamicCounters = new OptionKey<>(-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 OptionKey<String> BenchmarkDynamicCounters = new OptionKey<>(null);
 106         @Option(help = "Use grouping separators for number printing", type = OptionType.Debug)
 107         public static final OptionKey<Boolean> DynamicCountersPrintGroupSeparator = new OptionKey<>(true);
 108         @Option(help = "Print in human readable format", type = OptionType.Debug)
 109         public static final OptionKey<Boolean> DynamicCountersHumanReadable = new OptionKey<>(true);
 110         @Option(help = "Benchmark counters log file (default is stdout)", type = OptionType.Debug)
 111         public static final OptionKey<String> BenchmarkCountersFile = new OptionKey<>(null);
 112         @Option(help = "Dump dynamic counters", type = OptionType.Debug)
 113         public static final OptionKey<Boolean> BenchmarkCountersDumpDynamic = new OptionKey<>(true);
 114         @Option(help = "Dump static counters", type = OptionType.Debug)
 115         public static final OptionKey<Boolean> BenchmarkCountersDumpStatic = new OptionKey<>(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(OptionValues options, PrintStream out, double seconds, long[] counters, int maxRows) {
 172         if (!counterMap.isEmpty()) {
 173             if (Options.DynamicCountersHumanReadable.getValue(options)) {
 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(options)) {
 181                         dumpCounters(options, out, seconds, counters, true, group, maxRows);
 182                     }
 183                     if (Options.BenchmarkCountersDumpDynamic.getValue(options)) {
 184                         dumpCounters(options, out, seconds, counters, false, group, maxRows);
 185                     }
 186                 }
 187             }
 188             if (Options.DynamicCountersHumanReadable.getValue(options)) {
 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(OptionValues options, 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(options)) {
 217             dumpHumanReadable(options, 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(OptionValues options, PrintStream out, double seconds, boolean staticCounter, String group, int maxRows, long[] array,
 228                     Set<Entry<String, Counter>> counterEntrySet) {
 229         // sort the counters by putting them into a sorted map
 230         TreeMap<Long, String> sorted = new TreeMap<>();
 231         long sum = 0;
 232         for (Map.Entry<String, Counter> entry : counterEntrySet) {
 233             Counter counter = entry.getValue();
 234             int index = counter.index;
 235             if (counter.group.equals(group)) {
 236                 sum += array[index];
 237                 sorted.put(array[index] * array.length + index, getName(entry.getKey(), group));
 238             }
 239         }
 240 
 241         if (sum > 0) {
 242             long cutoff = sorted.size() < 10 ? 1 : Math.max(1, sum / 100);
 243             int cnt = sorted.size();
 244 
 245             // remove everything below cutoff and keep at most maxRows
 246             Iterator<Map.Entry<Long, String>> iter = sorted.entrySet().iterator();
 247             while (iter.hasNext()) {
 248                 Map.Entry<Long, String> entry = iter.next();
 249                 long counter = entry.getKey() / array.length;
 250                 if (counter < cutoff || cnt > maxRows) {
 251                     iter.remove();
 252                 }
 253                 cnt--;
 254             }
 255 
 256             String numFmt = Options.DynamicCountersPrintGroupSeparator.getValue(options) ? "%,19d" : "%19d";
 257             if (staticCounter) {
 258                 out.println("=========== " + group + " (static counters):");
 259                 for (Map.Entry<Long, String> entry : sorted.entrySet()) {
 260                     long counter = entry.getKey() / array.length;
 261                     out.format(Locale.US, numFmt + " %3d%%  %s\n", counter, percentage(counter, sum), entry.getValue());
 262                 }
 263                 out.format(Locale.US, numFmt + " total\n", sum);
 264             } else {
 265                 if (group.startsWith("~")) {
 266                     out.println("=========== " + group + " (dynamic counters), time = " + seconds + " s:");
 267                     for (Map.Entry<Long, String> entry : sorted.entrySet()) {
 268                         long counter = entry.getKey() / array.length;
 269                         out.format(Locale.US, numFmt + "/s %3d%%  %s\n", (long) (counter / seconds), percentage(counter, sum), entry.getValue());
 270                     }
 271                     out.format(Locale.US, numFmt + "/s total\n", (long) (sum / seconds));
 272                 } else {
 273                     out.println("=========== " + group + " (dynamic counters):");
 274                     for (Map.Entry<Long, String> entry : sorted.entrySet()) {
 275                         long counter = entry.getKey() / array.length;
 276                         out.format(Locale.US, numFmt + " %3d%%  %s\n", counter, percentage(counter, sum), entry.getValue());
 277                     }
 278                     out.format(Locale.US, numFmt + " total\n", sum);
 279                 }
 280             }
 281         }
 282     }
 283 
 284     private static final String CSV_FMT = CSVUtil.buildFormatString("%s", "%s", "%s", "%d");
 285 
 286     private static void dumpComputerReadable(PrintStream out, boolean staticCounter, String group, long[] array, Set<Entry<String, Counter>> counterEntrySet) {
 287         String category = staticCounter ? "static counters" : "dynamic counters";
 288         for (Map.Entry<String, Counter> entry : counterEntrySet) {
 289             Counter counter = entry.getValue();
 290             if (counter.group.equals(group)) {
 291                 String name = getName(entry.getKey(), group);
 292                 int index = counter.index;
 293                 long value = array[index];
 294                 CSVUtil.Escape.println(out, CSV_FMT, category, group, name, value);
 295             }
 296         }
 297     }
 298 
 299     private static long percentage(long counter, long sum) {
 300         return (counter * 200 + 1) / sum / 2;
 301     }
 302 
 303     private abstract static class CallbackOutputStream extends OutputStream {
 304 
 305         protected final PrintStream delegate;
 306         private final byte[][] patterns;
 307         private final int[] positions;
 308 
 309         CallbackOutputStream(PrintStream delegate, String... patterns) {
 310             this.delegate = delegate;
 311             this.positions = new int[patterns.length];
 312             this.patterns = new byte[patterns.length][];
 313             for (int i = 0; i < patterns.length; i++) {
 314                 this.patterns[i] = patterns[i].getBytes();
 315             }
 316         }
 317 
 318         protected abstract void patternFound(int index);
 319 
 320         @Override
 321         public void write(int b) throws IOException {
 322             try {
 323                 delegate.write(b);
 324                 for (int i = 0; i < patterns.length; i++) {
 325                     int j = positions[i];
 326                     byte[] cs = patterns[i];
 327                     byte patternChar = cs[j];
 328                     if (patternChar == '~' && Character.isDigit(b)) {
 329                         // nothing to do...
 330                     } else {
 331                         if (patternChar == '~') {
 332                             patternChar = cs[++positions[i]];
 333                         }
 334                         if (b == patternChar) {
 335                             positions[i]++;
 336                         } else {
 337                             positions[i] = 0;
 338                         }
 339                     }
 340                     if (positions[i] == patterns[i].length) {
 341                         positions[i] = 0;
 342                         patternFound(i);
 343                     }
 344                 }
 345             } catch (RuntimeException e) {
 346                 e.printStackTrace(delegate);
 347                 throw e;
 348             }
 349         }
 350     }
 351 
 352     public static void initialize(final HotSpotJVMCIRuntime jvmciRuntime, OptionValues options) {
 353         final class BenchmarkCountersOutputStream extends CallbackOutputStream {
 354 
 355             private long startTime;
 356             private boolean running;
 357             private boolean waitingForEnd;
 358 
 359             private BenchmarkCountersOutputStream(PrintStream delegate, String start, String end) {
 360                 super(delegate, new String[]{"\n", end, start});
 361             }
 362 
 363             @Override
 364             protected void patternFound(int index) {
 365                 switch (index) {
 366                     case 2:
 367                         startTime = System.nanoTime();
 368                         BenchmarkCounters.clear(jvmciRuntime.collectCounters());
 369                         running = true;
 370                         break;
 371                     case 1:
 372                         if (running) {
 373                             waitingForEnd = true;
 374                         }
 375                         break;
 376                     case 0:
 377                         if (waitingForEnd) {
 378                             waitingForEnd = false;
 379                             running = false;
 380                             BenchmarkCounters.dump(options, getPrintStream(options), (System.nanoTime() - startTime) / 1000000000d, jvmciRuntime.collectCounters(), 100);
 381                         }
 382                         break;
 383                 }
 384             }
 385         }
 386 
 387         if (Options.BenchmarkDynamicCounters.getValue(options) != null) {
 388             String[] arguments = Options.BenchmarkDynamicCounters.getValue(options).split(",");
 389             if (arguments.length == 0 || (arguments.length % 3) != 0) {
 390                 throw new GraalError("invalid arguments to BenchmarkDynamicCounters: (err|out),start,end,(err|out),start,end,... (~ matches multiple digits)");
 391             }
 392             for (int i = 0; i < arguments.length; i += 3) {
 393                 if (arguments[i].equals("err")) {
 394                     System.setErr(new PrintStream(new BenchmarkCountersOutputStream(System.err, arguments[i + 1], arguments[i + 2])));
 395                 } else if (arguments[i].equals("out")) {
 396                     System.setOut(new PrintStream(new BenchmarkCountersOutputStream(System.out, arguments[i + 1], arguments[i + 2])));
 397                 } else {
 398                     throw new GraalError("invalid arguments to BenchmarkDynamicCounters: err|out");
 399                 }
 400             }
 401             enabled = true;
 402         }
 403         if (Options.GenericDynamicCounters.getValue(options)) {
 404             enabled = true;
 405         }
 406         if (Options.TimedDynamicCounters.getValue(options) > 0) {
 407             Thread thread = new Thread() {
 408                 long lastTime = System.nanoTime();
 409                 PrintStream out = getPrintStream(options);
 410 
 411                 @Override
 412                 public void run() {
 413                     while (true) {
 414                         try {
 415                             Thread.sleep(Options.TimedDynamicCounters.getValue(options));
 416                         } catch (InterruptedException e) {
 417                         }
 418                         long time = System.nanoTime();
 419                         dump(options, out, (time - lastTime) / 1000000000d, jvmciRuntime.collectCounters(), 10);
 420                         lastTime = time;
 421                     }
 422                 }
 423             };
 424             thread.setDaemon(true);
 425             thread.setPriority(Thread.MAX_PRIORITY);
 426             thread.start();
 427             enabled = true;
 428         }
 429         if (enabled) {
 430             clear(jvmciRuntime.collectCounters());
 431         }
 432     }
 433 
 434     public static void shutdown(HotSpotJVMCIRuntime jvmciRuntime, OptionValues options, long compilerStartTime) {
 435         if (Options.GenericDynamicCounters.getValue(options)) {
 436             dump(options, getPrintStream(options), (System.nanoTime() - compilerStartTime) / 1000000000d, jvmciRuntime.collectCounters(), 100);
 437         }
 438     }
 439 
 440     private static PrintStream getPrintStream(OptionValues options) {
 441         if (Options.BenchmarkCountersFile.getValue(options) != null) {
 442             try {
 443                 Path path = UniquePathUtilities.getPathGlobal(options, Options.BenchmarkCountersFile, GraalDebugConfig.Options.DumpPath, "csv");
 444                 TTY.println("Writing benchmark counters to '%s'", path);
 445                 return new PrintStream(path.toFile());
 446             } catch (FileNotFoundException e) {
 447                 TTY.out().println(e.getMessage());
 448                 TTY.out().println("Fallback to default");
 449             }
 450         }
 451         return TTY.out;
 452     }
 453 }