--- /dev/null 2016-05-31 09:42:47.975716356 -0700 +++ new/src/jdk.vm.compiler/share/classes/org.graalvm.compiler.debug/src/org/graalvm/compiler/debug/internal/method/MethodMetricsImpl.java 2016-12-09 00:48:19.507235839 -0800 @@ -0,0 +1,444 @@ +/* + * Copyright (c) 2015, 2016, Oracle and/or its affiliates. All rights reserved. + * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. + * + * This code is free software; you can redistribute it and/or modify it + * under the terms of the GNU General Public License version 2 only, as + * published by the Free Software Foundation. + * + * This code is distributed in the hope that it will be useful, but WITHOUT + * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or + * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License + * version 2 for more details (a copy is included in the LICENSE file that + * accompanied this code). + * + * You should have received a copy of the GNU General Public License version + * 2 along with this work; if not, write to the Free Software Foundation, + * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. + * + * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA + * or visit www.oracle.com if you need additional information or have any + * questions. + */ +package org.graalvm.compiler.debug.internal.method; + +import java.io.PrintStream; +import java.util.ArrayList; +import java.util.Collection; +import java.util.HashMap; +import java.util.HashSet; +import java.util.List; +import java.util.Map; +import java.util.Set; +import java.util.stream.Collectors; + +import org.graalvm.compiler.debug.CSVUtil; +import org.graalvm.compiler.debug.Debug; +import org.graalvm.compiler.debug.DebugCounter; +import org.graalvm.compiler.debug.DebugMethodMetrics; +import org.graalvm.compiler.debug.GraalDebugConfig; +import org.graalvm.compiler.debug.internal.DebugScope; + +import jdk.vm.ci.meta.ResolvedJavaMethod; + +public class MethodMetricsImpl implements DebugMethodMetrics { + + /** + * A list capturing all method metrics data of all the compiler threads. Every thread registers + * a reference to its thread local map of compilation metrics in this list. During metrics + * dumping this list is globally locked and all method entries across all threads are merged to + * a result. + */ + private static final List> threadMaps = new ArrayList<>(); + /** + * Every compiler thread carries its own map of metric data for each method and compilation it + * compiles. This data is stored in {@link ThreadLocal} maps for each compiler thread that are + * merged before metrics are reported. Storing compilation data thread locally reduces the + * locking on access of a method metric object to one point for each thread, the first access + * where the thread local is initialized. + */ + private static final ThreadLocal> threadEntries = new ThreadLocal<>(); + /** + * The lowest debug scope id that should be used during metric dumping. When a bootstrap is run + * all compilations during bootstrap are also collected if the associated debug filters match. + * Data collected during bootstrap should normally not be included in metrics for application + * compilation, thus every compilation lower than this index is ignored during metric dumping. + */ + private static long lowestCompilationDebugScopeId; + + public static class CompilationData { + /** + * A mapping of graph ids (unique ids used for the caching) to compilations. + */ + private final Map> compilations; + /** + * A pointer to a {@code MethodMetricsImpl} object. This reference is created once for every + * compilation of a method (and once for each thread, i.e. if method a is compiled by 8 + * compiler threads there will be 8 metrics objects for the given method, one local to every + * thread, this avoids synchronizing on the metrics object on every access) accessing method + * metrics for a given method. + */ + private final MethodMetricsImpl metrics; + + CompilationData(ResolvedJavaMethod method) { + compilations = new HashMap<>(8); + metrics = new MethodMetricsImpl(method); + } + + public Map> getCompilations() { + return compilations; + } + } + + private static void addThreadCompilationData(Map threadMap) { + synchronized (threadMaps) { + threadMaps.add(threadMap); + } + } + + /** + * A reference to the {@link ResolvedJavaMethod} method object. This object's identity is used + * to store metrics for each compilation. + */ + private final ResolvedJavaMethod method; + /** + * A list of all recorded compilations. This is generated during metric dumping when all thread + * local metrics are merged into one final method metrics object that is than reported + */ + private List>> collected; + /** + * A pointer to the current compilation data for the {@link MethodMetricsImpl#method} method + * which allows to avoid synchronizing over the compilation data. This reference changes for + * each compilation of the given method. It is set on the first access of this + * {@link MethodMetricsImpl} object during the call to + * {@link MethodMetricsImpl#getMethodMetrics(ResolvedJavaMethod)}. + */ + private Map currentCompilation; + + MethodMetricsImpl(ResolvedJavaMethod method) { + this.method = method; + } + + private static void clearData() { + lowestCompilationDebugScopeId = DebugScope.getCurrentGlobalScopeId(); + } + + @Override + public void addToMetric(long value, String metricName) { + if (!Debug.isMethodMeterEnabled() || value == 0) { + return; + } + assert metricName != null; + Long valueStored = currentCompilation.get(metricName); + currentCompilation.put(metricName, valueStored == null ? value : value + valueStored); + } + + @Override + public long getCurrentMetricValue(String metricName) { + assert metricName != null; + Long valueStored = currentCompilation.get(metricName); + return valueStored == null ? 0 : valueStored; + } + + @Override + public void addToMetric(long value, String format, Object arg1) { + addToMetric(value, String.format(format, arg1)); + } + + @Override + public void addToMetric(long value, String format, Object arg1, Object arg2) { + addToMetric(value, String.format(format, arg1, arg2)); + } + + @Override + public void addToMetric(long value, String format, Object arg1, Object arg2, Object arg3) { + addToMetric(value, String.format(format, arg1, arg2, arg3)); + } + + @Override + public void incrementMetric(String metricName) { + addToMetric(1, metricName); + } + + @Override + public void incrementMetric(String format, Object arg1) { + incrementMetric(String.format(format, arg1)); + } + + @Override + public void incrementMetric(String format, Object arg1, Object arg2) { + incrementMetric(String.format(format, arg1, arg2)); + } + + @Override + public void incrementMetric(String format, Object arg1, Object arg2, Object arg3) { + incrementMetric(String.format(format, arg1, arg2, arg3)); + } + + @Override + public long getCurrentMetricValue(String format, Object arg1) { + return getCurrentMetricValue(String.format(format, arg1)); + } + + @Override + public long getCurrentMetricValue(String format, Object arg1, Object arg2) { + return getCurrentMetricValue(String.format(format, arg1, arg2)); + } + + @Override + public long getCurrentMetricValue(String format, Object arg1, Object arg2, Object arg3) { + return getCurrentMetricValue(String.format(format, arg1, arg2, arg3)); + } + + @Override + public ResolvedJavaMethod getMethod() { + return method; + } + + public static DebugMethodMetrics getMethodMetrics(ResolvedJavaMethod method) { + assert method != null; + Map threadCache = threadEntries.get(); + if (threadCache == null) { + // this branch will only be executed once for each compiler thread on the first request + // of a method metric + threadCache = new HashMap<>(GraalDebugConfig.Options.MethodFilter.getValue() == null ? 128 : 16); + threadEntries.set(threadCache); + addThreadCompilationData(threadCache); + } + + CompilationData recorded = threadCache.get(method); + if (recorded == null) { + recorded = new CompilationData(method); + threadCache.put(method, recorded); + } + // pre-generate the current compilation map to avoid doing it later every time we add to a + // metric or read a current metric's value + long compilationId = DebugScope.getInstance().scopeId(); + Map currentCompilation = recorded.compilations.get(compilationId); + if (currentCompilation == null) { + // this map is generated for every distinct compilation of a unique method + currentCompilation = new HashMap<>(32); + recorded.compilations.put(compilationId, currentCompilation); + // we remember a reference to the current compilation to avoid the expensive lookup + recorded.metrics.currentCompilation = currentCompilation; + } + + return recorded.metrics; + } + + public void dumpASCII(PrintStream p) { + // we need to lock the threadmap as a concurrent call to #collectedMetrics can change the + // content of this#collected + synchronized (threadMaps) { + String methodName = method.toString(); + int maxLen = methodName.length(); + int entrySum = 0; + // get the longest entry + for (Map> compilationThreadTable : collected) { + for (Map.Entry> compilationEntry : compilationThreadTable.entrySet()) { + Map table = compilationEntry.getValue(); + if (table != null) { + for (Map.Entry entry : table.entrySet()) { + maxLen = Math.max(maxLen, entry.getKey().length()); + entrySum += entry.getValue(); + } + } + } + } + if (entrySum == 0) { + // nothing to report + return; + } + maxLen += 23; + for (int j = 0; j < maxLen; j++) { + p.print("#"); + } + p.println(); + p.println(methodName); + for (int j = 0; j < maxLen; j++) { + p.print("~"); + } + p.println(); + for (Map> compilationThreadTable : collected) { + for (Map.Entry> compilationEntry : compilationThreadTable.entrySet()) { + Map table = compilationEntry.getValue(); + if (table != null) { + if (table.values().stream().filter(x -> x > 0).count() == 0) { + continue; + } + Set> entries = table.entrySet(); + for (Map.Entry entry : entries.stream().sorted((x, y) -> x.getKey().compareTo(y.getKey())).collect(Collectors.toList())) { + long value = entry.getValue(); + // report timers in ms and memory in mb + if ((entry.getKey().endsWith("Accm") || entry.getKey().endsWith("Flat")) && + !entry.getKey().toLowerCase().contains("mem")) { + value = value / 1000000; + } + if (value == 0) { + continue; + } + p.print(String.format("%-" + String.valueOf(maxLen - 23) + "s = %20d", entry.getKey(), value)); + p.println(); + } + for (int j = 0; j < maxLen; j++) { + p.print("~"); + } + p.println(); + } + } + } + for (int j = 0; j < maxLen; j++) { + p.print("#"); + } + p.println(); + } + } + + private static final String FMT = CSVUtil.buildFormatString("%s", "%s", "%d", "%d", "%s", "%d"); + + public void dumpCSV(PrintStream p) { + // we need to lock the threadmap as a concurrent call to #collectedMetrics can change + // the content of this#collected + synchronized (threadMaps) { + String methodName = method.format("%H.%n(%p)%R"); + /* + * NOTE: the caching mechanism works by caching compilation data based on the identity + * of the resolved java method object. The identity is based on the metaspace address of + * the resolved java method object. If the class was loaded by different class loaders + * or e.g. loaded - unloaded - loaded the identity will be different. Therefore we also + * need to include the identity in the reporting of the data as it is an additional + * dimension to . + */ + String methodIdentity = String.valueOf(System.identityHashCode(method)); + int nrOfCompilations = 0; + for (Map> compilationThreadTable : collected) { + for (Map.Entry> compilationEntry : compilationThreadTable.entrySet()) { + Map table = compilationEntry.getValue(); + if (table != null) { + Set> entries = table.entrySet(); + for (Map.Entry entry : entries.stream().sorted((x, y) -> x.getKey().compareTo(y.getKey())).collect(Collectors.toList())) { + CSVUtil.Escape.println(p, FMT, methodName, methodIdentity, nrOfCompilations, compilationEntry.getKey(), entry.getKey(), entry.getValue()); + } + nrOfCompilations++; + } + } + } + } + } + + public static Collection collectedMetrics() { + synchronized (threadMaps) { + // imprecise excluding all compilations that follow, we simply do not report them + final long lastId = DebugScope.getCurrentGlobalScopeId(); + List finalMetrics = new ArrayList<>(); + Set methods = new HashSet<>(); + + // gather all methods we found + threadMaps.stream().forEach(x -> { + // snapshot the current compilations to only capture all methods compiled until now + HashMap snapShot = new HashMap<>(x); + snapShot.keySet().forEach(y -> methods.add(y)); + }); + + // for each method gather all metrics we want to report + for (ResolvedJavaMethod method : methods) { + MethodMetricsImpl impl = new MethodMetricsImpl(method); + impl.collected = new ArrayList<>(); + for (Map threadMap : threadMaps) { + CompilationData threadMethodData = threadMap.get(method); + + // not every method is necessarily compiled by all threads + if (threadMethodData != null) { + Map> snapshot = new HashMap<>(threadMethodData.compilations); + for (Map.Entry> entry : snapshot.entrySet()) { + if (entry.getKey() < lowestCompilationDebugScopeId || entry.getKey() > lastId) { + entry.setValue(null); + } + } + impl.collected.add(snapshot); + } + } + finalMetrics.add(impl); + } + + return finalMetrics; + } + } + + public static void clearMM() { + clearData(); + } + + private static final String INLINEE_PREFIX = "INLINING_SCOPE_"; + private static final boolean TRACK_INLINED_SCOPES = false; + + public static void recordInlinee(ResolvedJavaMethod root, ResolvedJavaMethod caller, ResolvedJavaMethod inlinee) { + if (TRACK_INLINED_SCOPES) { + Debug.methodMetrics(root).addToMetric(1, "INLINED_METHOD_root: caller:%s inlinee:%s", caller, inlinee); + } + } + + private static final boolean COUNT_CACHE = false; + private static final String HIT_MSG = "InterceptionCache_Hit"; + private static final String MISS_MSG = "InterceptionCache_Miss"; + private static final DebugCounter cacheHit = Debug.counter(HIT_MSG); + private static final DebugCounter cacheMiss = Debug.counter(MISS_MSG); + /** + * To avoid the lookup of a method metrics through the + * {@link MethodMetricsImpl#getMethodMetrics(ResolvedJavaMethod)} method on every global metric + * interception we thread-locally cache the last (through metric interception) + * {@link MethodMetricsImpl} object. This avoids additional map lookups and replaces them with a + * {@link DebugScope#scopeId()} call and a numerical comparison in a cache hit case. + */ + private static final ThreadLocal interceptionCache = new ThreadLocal<>(); + private static final ThreadLocal interceptionMetrics = new ThreadLocal<>(); + + public static void addToCurrentScopeMethodMetrics(String metricName, long value) { + if (COUNT_CACHE) { + if (metricName.equals(HIT_MSG) || metricName.equals(MISS_MSG)) { + return; + } + } + final DebugScope currScope = DebugScope.getInstance(); + final DebugScope.ExtraInfo metaInfo = currScope.getExtraInfo(); + final long currScopeId = currScope.scopeId(); + if (metaInfo instanceof MethodMetricsRootScopeInfo) { + ResolvedJavaMethod rootMethod = ((MethodMetricsRootScopeInfo) metaInfo).getRootMethod(); + if (metaInfo instanceof MethodMetricsInlineeScopeInfo) { + /* + * if we make use of a method filter(s) together with interception we get a problem + * with inlined methods and their scopes. Inlining will put the inlinee(s) on the + * debug scope context thus Debug.areMethodMetricsEnabled() will yield true if an + * inlinee matches a method filter. Thus we must make sure the root is defined as + * this means the root matched a method filter and therefore the inlinee can be + * safely recorded. + */ + if (TRACK_INLINED_SCOPES) { + if (threadEntries.get().get(rootMethod) != null) { + Debug.methodMetrics(rootMethod).addToMetric(value, "%s%s", INLINEE_PREFIX, metricName); + } + } + } else { + // when unboxing the thread local on access it must not be null + Long cachedId = interceptionCache.get(); + if (cachedId != null && cachedId == currScopeId) { + interceptionMetrics.get().addToMetric(value, metricName); + if (COUNT_CACHE) { + cacheHit.increment(); + } + } else { + // avoid the lookup over Debug.methodMetrics + final MethodMetricsImpl impl = (MethodMetricsImpl) getMethodMetrics(rootMethod); + impl.addToMetric(value, metricName); + // cache for next access + interceptionCache.set(currScopeId); + interceptionMetrics.set(impl); + if (COUNT_CACHE) { + cacheMiss.increment(); + } + } + } + } + } + +}