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 }