1 /*
   2  * Copyright (c) 2015, 2016, 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.debug.internal.method;
  24 
  25 import java.io.PrintStream;
  26 import java.util.ArrayList;
  27 import java.util.Collection;
  28 import java.util.HashMap;
  29 import java.util.HashSet;
  30 import java.util.List;
  31 import java.util.Map;
  32 import java.util.Set;
  33 import java.util.stream.Collectors;
  34 
  35 import org.graalvm.compiler.debug.CSVUtil;
  36 import org.graalvm.compiler.debug.Debug;
  37 import org.graalvm.compiler.debug.DebugCounter;
  38 import org.graalvm.compiler.debug.DebugMethodMetrics;
  39 import org.graalvm.compiler.debug.GraalDebugConfig;
  40 import org.graalvm.compiler.debug.internal.DebugScope;
  41 
  42 import jdk.vm.ci.meta.ResolvedJavaMethod;
  43 
  44 public class MethodMetricsImpl implements DebugMethodMetrics {
  45 
  46     /**
  47      * A list capturing all method metrics data of all the compiler threads. Every thread registers
  48      * a reference to its thread local map of compilation metrics in this list. During metrics
  49      * dumping this list is globally locked and all method entries across all threads are merged to
  50      * a result.
  51      */
  52     private static final List<Map<ResolvedJavaMethod, CompilationData>> threadMaps = new ArrayList<>();
  53     /**
  54      * Every compiler thread carries its own map of metric data for each method and compilation it
  55      * compiles. This data is stored in {@link ThreadLocal} maps for each compiler thread that are
  56      * merged before metrics are reported. Storing compilation data thread locally reduces the
  57      * locking on access of a method metric object to one point for each thread, the first access
  58      * where the thread local is initialized.
  59      */
  60     private static final ThreadLocal<Map<ResolvedJavaMethod, CompilationData>> threadEntries = new ThreadLocal<>();
  61     /**
  62      * The lowest debug scope id that should be used during metric dumping. When a bootstrap is run
  63      * all compilations during bootstrap are also collected if the associated debug filters match.
  64      * Data collected during bootstrap should normally not be included in metrics for application
  65      * compilation, thus every compilation lower than this index is ignored during metric dumping.
  66      */
  67     private static long lowestCompilationDebugScopeId;
  68 
  69     public static class CompilationData {
  70         /**
  71          * A mapping of graph ids (unique ids used for the caching) to compilations.
  72          */
  73         private final Map<Long, Map<String, Long>> compilations;
  74         /**
  75          * A pointer to a {@code MethodMetricsImpl} object. This reference is created once for every
  76          * compilation of a method (and once for each thread, i.e. if method a is compiled by 8
  77          * compiler threads there will be 8 metrics objects for the given method, one local to every
  78          * thread, this avoids synchronizing on the metrics object on every access) accessing method
  79          * metrics for a given method.
  80          */
  81         private final MethodMetricsImpl metrics;
  82 
  83         CompilationData(ResolvedJavaMethod method) {
  84             compilations = new HashMap<>(8);
  85             metrics = new MethodMetricsImpl(method);
  86         }
  87 
  88         public Map<Long, Map<String, Long>> getCompilations() {
  89             return compilations;
  90         }
  91     }
  92 
  93     private static void addThreadCompilationData(Map<ResolvedJavaMethod, CompilationData> threadMap) {
  94         synchronized (threadMaps) {
  95             threadMaps.add(threadMap);
  96         }
  97     }
  98 
  99     /**
 100      * A reference to the {@link ResolvedJavaMethod} method object. This object's identity is used
 101      * to store metrics for each compilation.
 102      */
 103     private final ResolvedJavaMethod method;
 104     /**
 105      * A list of all recorded compilations. This is generated during metric dumping when all thread
 106      * local metrics are merged into one final method metrics object that is than reported
 107      */
 108     private List<Map<Long, Map<String, Long>>> collected;
 109     /**
 110      * A pointer to the current compilation data for the {@link MethodMetricsImpl#method} method
 111      * which allows to avoid synchronizing over the compilation data. This reference changes for
 112      * each compilation of the given method. It is set on the first access of this
 113      * {@link MethodMetricsImpl} object during the call to
 114      * {@link MethodMetricsImpl#getMethodMetrics(ResolvedJavaMethod)}.
 115      */
 116     private Map<String, Long> currentCompilation;
 117 
 118     MethodMetricsImpl(ResolvedJavaMethod method) {
 119         this.method = method;
 120     }
 121 
 122     private static void clearData() {
 123         lowestCompilationDebugScopeId = DebugScope.getCurrentGlobalScopeId();
 124     }
 125 
 126     @Override
 127     public void addToMetric(long value, String metricName) {
 128         if (!Debug.isMethodMeterEnabled() || value == 0) {
 129             return;
 130         }
 131         assert metricName != null;
 132         Long valueStored = currentCompilation.get(metricName);
 133         currentCompilation.put(metricName, valueStored == null ? value : value + valueStored);
 134     }
 135 
 136     @Override
 137     public long getCurrentMetricValue(String metricName) {
 138         assert metricName != null;
 139         Long valueStored = currentCompilation.get(metricName);
 140         return valueStored == null ? 0 : valueStored;
 141     }
 142 
 143     @Override
 144     public void addToMetric(long value, String format, Object arg1) {
 145         addToMetric(value, String.format(format, arg1));
 146     }
 147 
 148     @Override
 149     public void addToMetric(long value, String format, Object arg1, Object arg2) {
 150         addToMetric(value, String.format(format, arg1, arg2));
 151     }
 152 
 153     @Override
 154     public void addToMetric(long value, String format, Object arg1, Object arg2, Object arg3) {
 155         addToMetric(value, String.format(format, arg1, arg2, arg3));
 156     }
 157 
 158     @Override
 159     public void incrementMetric(String metricName) {
 160         addToMetric(1, metricName);
 161     }
 162 
 163     @Override
 164     public void incrementMetric(String format, Object arg1) {
 165         incrementMetric(String.format(format, arg1));
 166     }
 167 
 168     @Override
 169     public void incrementMetric(String format, Object arg1, Object arg2) {
 170         incrementMetric(String.format(format, arg1, arg2));
 171     }
 172 
 173     @Override
 174     public void incrementMetric(String format, Object arg1, Object arg2, Object arg3) {
 175         incrementMetric(String.format(format, arg1, arg2, arg3));
 176     }
 177 
 178     @Override
 179     public long getCurrentMetricValue(String format, Object arg1) {
 180         return getCurrentMetricValue(String.format(format, arg1));
 181     }
 182 
 183     @Override
 184     public long getCurrentMetricValue(String format, Object arg1, Object arg2) {
 185         return getCurrentMetricValue(String.format(format, arg1, arg2));
 186     }
 187 
 188     @Override
 189     public long getCurrentMetricValue(String format, Object arg1, Object arg2, Object arg3) {
 190         return getCurrentMetricValue(String.format(format, arg1, arg2, arg3));
 191     }
 192 
 193     @Override
 194     public ResolvedJavaMethod getMethod() {
 195         return method;
 196     }
 197 
 198     public static DebugMethodMetrics getMethodMetrics(ResolvedJavaMethod method) {
 199         assert method != null;
 200         Map<ResolvedJavaMethod, CompilationData> threadCache = threadEntries.get();
 201         if (threadCache == null) {
 202             // this branch will only be executed once for each compiler thread on the first request
 203             // of a method metric
 204             threadCache = new HashMap<>(GraalDebugConfig.Options.MethodFilter.getValue() == null ? 128 : 16);
 205             threadEntries.set(threadCache);
 206             addThreadCompilationData(threadCache);
 207         }
 208 
 209         CompilationData recorded = threadCache.get(method);
 210         if (recorded == null) {
 211             recorded = new CompilationData(method);
 212             threadCache.put(method, recorded);
 213         }
 214         // pre-generate the current compilation map to avoid doing it later every time we add to a
 215         // metric or read a current metric's value
 216         long compilationId = DebugScope.getInstance().scopeId();
 217         Map<String, Long> currentCompilation = recorded.compilations.get(compilationId);
 218         if (currentCompilation == null) {
 219             // this map is generated for every distinct compilation of a unique method
 220             currentCompilation = new HashMap<>(32);
 221             recorded.compilations.put(compilationId, currentCompilation);
 222             // we remember a reference to the current compilation to avoid the expensive lookup
 223             recorded.metrics.currentCompilation = currentCompilation;
 224         }
 225 
 226         return recorded.metrics;
 227     }
 228 
 229     public void dumpASCII(PrintStream p) {
 230         // we need to lock the threadmap as a concurrent call to #collectedMetrics can change the
 231         // content of this#collected
 232         synchronized (threadMaps) {
 233             String methodName = method.toString();
 234             int maxLen = methodName.length();
 235             int entrySum = 0;
 236             // get the longest entry
 237             for (Map<Long, Map<String, Long>> compilationThreadTable : collected) {
 238                 for (Map.Entry<Long, Map<String, Long>> compilationEntry : compilationThreadTable.entrySet()) {
 239                     Map<String, Long> table = compilationEntry.getValue();
 240                     if (table != null) {
 241                         for (Map.Entry<String, Long> entry : table.entrySet()) {
 242                             maxLen = Math.max(maxLen, entry.getKey().length());
 243                             entrySum += entry.getValue();
 244                         }
 245                     }
 246                 }
 247             }
 248             if (entrySum == 0) {
 249                 // nothing to report
 250                 return;
 251             }
 252             maxLen += 23;
 253             for (int j = 0; j < maxLen; j++) {
 254                 p.print("#");
 255             }
 256             p.println();
 257             p.println(methodName);
 258             for (int j = 0; j < maxLen; j++) {
 259                 p.print("~");
 260             }
 261             p.println();
 262             for (Map<Long, Map<String, Long>> compilationThreadTable : collected) {
 263                 for (Map.Entry<Long, Map<String, Long>> compilationEntry : compilationThreadTable.entrySet()) {
 264                     Map<String, Long> table = compilationEntry.getValue();
 265                     if (table != null) {
 266                         if (table.values().stream().filter(x -> x > 0).count() == 0) {
 267                             continue;
 268                         }
 269                         Set<Map.Entry<String, Long>> entries = table.entrySet();
 270                         for (Map.Entry<String, Long> entry : entries.stream().sorted((x, y) -> x.getKey().compareTo(y.getKey())).collect(Collectors.toList())) {
 271                             long value = entry.getValue();
 272                             // report timers in ms and memory in mb
 273                             if ((entry.getKey().endsWith("Accm") || entry.getKey().endsWith("Flat")) &&
 274                                             !entry.getKey().toLowerCase().contains("mem")) {
 275                                 value = value / 1000000;
 276                             }
 277                             if (value == 0) {
 278                                 continue;
 279                             }
 280                             p.print(String.format("%-" + String.valueOf(maxLen - 23) + "s = %20d", entry.getKey(), value));
 281                             p.println();
 282                         }
 283                         for (int j = 0; j < maxLen; j++) {
 284                             p.print("~");
 285                         }
 286                         p.println();
 287                     }
 288                 }
 289             }
 290             for (int j = 0; j < maxLen; j++) {
 291                 p.print("#");
 292             }
 293             p.println();
 294         }
 295     }
 296 
 297     private static final String FMT = CSVUtil.buildFormatString("%s", "%s", "%d", "%d", "%s", "%d");
 298 
 299     public void dumpCSV(PrintStream p) {
 300         // we need to lock the threadmap as a concurrent call to #collectedMetrics can change
 301         // the content of this#collected
 302         synchronized (threadMaps) {
 303             String methodName = method.format("%H.%n(%p)%R");
 304             /*
 305              * NOTE: the caching mechanism works by caching compilation data based on the identity
 306              * of the resolved java method object. The identity is based on the metaspace address of
 307              * the resolved java method object. If the class was loaded by different class loaders
 308              * or e.g. loaded - unloaded - loaded the identity will be different. Therefore we also
 309              * need to include the identity in the reporting of the data as it is an additional
 310              * dimension to <method,compilationId>.
 311              */
 312             String methodIdentity = String.valueOf(System.identityHashCode(method));
 313             int nrOfCompilations = 0;
 314             for (Map<Long, Map<String, Long>> compilationThreadTable : collected) {
 315                 for (Map.Entry<Long, Map<String, Long>> compilationEntry : compilationThreadTable.entrySet()) {
 316                     Map<String, Long> table = compilationEntry.getValue();
 317                     if (table != null) {
 318                         Set<Map.Entry<String, Long>> entries = table.entrySet();
 319                         for (Map.Entry<String, Long> entry : entries.stream().sorted((x, y) -> x.getKey().compareTo(y.getKey())).collect(Collectors.toList())) {
 320                             CSVUtil.Escape.println(p, FMT, methodName, methodIdentity, nrOfCompilations, compilationEntry.getKey(), entry.getKey(), entry.getValue());
 321                         }
 322                         nrOfCompilations++;
 323                     }
 324                 }
 325             }
 326         }
 327     }
 328 
 329     public static Collection<DebugMethodMetrics> collectedMetrics() {
 330         synchronized (threadMaps) {
 331             // imprecise excluding all compilations that follow, we simply do not report them
 332             final long lastId = DebugScope.getCurrentGlobalScopeId();
 333             List<DebugMethodMetrics> finalMetrics = new ArrayList<>();
 334             Set<ResolvedJavaMethod> methods = new HashSet<>();
 335 
 336             // gather all methods we found
 337             threadMaps.stream().forEach(x -> {
 338                 // snapshot the current compilations to only capture all methods compiled until now
 339                 HashMap<ResolvedJavaMethod, CompilationData> snapShot = new HashMap<>(x);
 340                 snapShot.keySet().forEach(y -> methods.add(y));
 341             });
 342 
 343             // for each method gather all metrics we want to report
 344             for (ResolvedJavaMethod method : methods) {
 345                 MethodMetricsImpl impl = new MethodMetricsImpl(method);
 346                 impl.collected = new ArrayList<>();
 347                 for (Map<ResolvedJavaMethod, CompilationData> threadMap : threadMaps) {
 348                     CompilationData threadMethodData = threadMap.get(method);
 349 
 350                     // not every method is necessarily compiled by all threads
 351                     if (threadMethodData != null) {
 352                         Map<Long, Map<String, Long>> snapshot = new HashMap<>(threadMethodData.compilations);
 353                         for (Map.Entry<Long, Map<String, Long>> entry : snapshot.entrySet()) {
 354                             if (entry.getKey() < lowestCompilationDebugScopeId || entry.getKey() > lastId) {
 355                                 entry.setValue(null);
 356                             }
 357                         }
 358                         impl.collected.add(snapshot);
 359                     }
 360                 }
 361                 finalMetrics.add(impl);
 362             }
 363 
 364             return finalMetrics;
 365         }
 366     }
 367 
 368     public static void clearMM() {
 369         clearData();
 370     }
 371 
 372     private static final String INLINEE_PREFIX = "INLINING_SCOPE_";
 373     private static final boolean TRACK_INLINED_SCOPES = false;
 374 
 375     public static void recordInlinee(ResolvedJavaMethod root, ResolvedJavaMethod caller, ResolvedJavaMethod inlinee) {
 376         if (TRACK_INLINED_SCOPES) {
 377             Debug.methodMetrics(root).addToMetric(1, "INLINED_METHOD_root: caller:%s inlinee:%s", caller, inlinee);
 378         }
 379     }
 380 
 381     private static final boolean COUNT_CACHE = false;
 382     private static final String HIT_MSG = "InterceptionCache_Hit";
 383     private static final String MISS_MSG = "InterceptionCache_Miss";
 384     private static final DebugCounter cacheHit = Debug.counter(HIT_MSG);
 385     private static final DebugCounter cacheMiss = Debug.counter(MISS_MSG);
 386     /**
 387      * To avoid the lookup of a method metrics through the
 388      * {@link MethodMetricsImpl#getMethodMetrics(ResolvedJavaMethod)} method on every global metric
 389      * interception we thread-locally cache the last (through metric interception)
 390      * {@link MethodMetricsImpl} object. This avoids additional map lookups and replaces them with a
 391      * {@link DebugScope#scopeId()} call and a numerical comparison in a cache hit case.
 392      */
 393     private static final ThreadLocal<Long> interceptionCache = new ThreadLocal<>();
 394     private static final ThreadLocal<MethodMetricsImpl> interceptionMetrics = new ThreadLocal<>();
 395 
 396     public static void addToCurrentScopeMethodMetrics(String metricName, long value) {
 397         if (COUNT_CACHE) {
 398             if (metricName.equals(HIT_MSG) || metricName.equals(MISS_MSG)) {
 399                 return;
 400             }
 401         }
 402         final DebugScope currScope = DebugScope.getInstance();
 403         final DebugScope.ExtraInfo metaInfo = currScope.getExtraInfo();
 404         final long currScopeId = currScope.scopeId();
 405         if (metaInfo instanceof MethodMetricsRootScopeInfo) {
 406             ResolvedJavaMethod rootMethod = ((MethodMetricsRootScopeInfo) metaInfo).getRootMethod();
 407             if (metaInfo instanceof MethodMetricsInlineeScopeInfo) {
 408                 /*
 409                  * if we make use of a method filter(s) together with interception we get a problem
 410                  * with inlined methods and their scopes. Inlining will put the inlinee(s) on the
 411                  * debug scope context thus Debug.areMethodMetricsEnabled() will yield true if an
 412                  * inlinee matches a method filter. Thus we must make sure the root is defined as
 413                  * this means the root matched a method filter and therefore the inlinee can be
 414                  * safely recorded.
 415                  */
 416                 if (TRACK_INLINED_SCOPES) {
 417                     if (threadEntries.get().get(rootMethod) != null) {
 418                         Debug.methodMetrics(rootMethod).addToMetric(value, "%s%s", INLINEE_PREFIX, metricName);
 419                     }
 420                 }
 421             } else {
 422                 // when unboxing the thread local on access it must not be null
 423                 Long cachedId = interceptionCache.get();
 424                 if (cachedId != null && cachedId == currScopeId) {
 425                     interceptionMetrics.get().addToMetric(value, metricName);
 426                     if (COUNT_CACHE) {
 427                         cacheHit.increment();
 428                     }
 429                 } else {
 430                     // avoid the lookup over Debug.methodMetrics
 431                     final MethodMetricsImpl impl = (MethodMetricsImpl) getMethodMetrics(rootMethod);
 432                     impl.addToMetric(value, metricName);
 433                     // cache for next access
 434                     interceptionCache.set(currScopeId);
 435                     interceptionMetrics.set(impl);
 436                     if (COUNT_CACHE) {
 437                         cacheMiss.increment();
 438                     }
 439                 }
 440             }
 441         }
 442     }
 443 
 444 }