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.core.test.debug; 24 25 import java.io.PrintStream; 26 import java.lang.reflect.Field; 27 import java.lang.reflect.Method; 28 import java.util.ArrayList; 29 import java.util.List; 30 import java.util.ListIterator; 31 import java.util.Map; 32 import java.util.stream.Collectors; 33 34 import org.junit.After; 35 import org.junit.Assert; 36 import org.junit.Before; 37 import org.junit.Test; 38 import org.graalvm.compiler.core.common.util.Util; 39 import org.graalvm.compiler.core.test.GraalCompilerTest; 40 import org.graalvm.compiler.debug.Debug; 41 import org.graalvm.compiler.debug.DebugCloseable; 42 import org.graalvm.compiler.debug.DebugConfig; 43 import org.graalvm.compiler.debug.DebugConfigScope; 44 import org.graalvm.compiler.debug.DebugCounter; 45 import org.graalvm.compiler.debug.DebugDumpHandler; 46 import org.graalvm.compiler.debug.DebugMethodMetrics; 47 import org.graalvm.compiler.debug.DebugTimer; 48 import org.graalvm.compiler.debug.DebugVerifyHandler; 49 import org.graalvm.compiler.debug.DelegatingDebugConfig; 50 import org.graalvm.compiler.debug.DelegatingDebugConfig.Feature; 51 import org.graalvm.compiler.debug.GraalDebugConfig; 52 import org.graalvm.compiler.debug.internal.DebugScope; 53 import org.graalvm.compiler.debug.internal.method.MethodMetricsImpl; 54 import org.graalvm.compiler.debug.internal.method.MethodMetricsImpl.CompilationData; 55 import org.graalvm.compiler.debug.internal.method.MethodMetricsInlineeScopeInfo; 56 import org.graalvm.compiler.debug.internal.method.MethodMetricsPrinter; 57 import org.graalvm.compiler.nodes.InvokeNode; 58 import org.graalvm.compiler.nodes.StructuredGraph; 59 import org.graalvm.compiler.nodes.calc.BinaryNode; 60 import org.graalvm.compiler.nodes.calc.FixedBinaryNode; 61 import org.graalvm.compiler.nodes.calc.MulNode; 62 import org.graalvm.compiler.nodes.calc.ShiftNode; 63 import org.graalvm.compiler.nodes.calc.SignedDivNode; 64 import org.graalvm.compiler.nodes.calc.SubNode; 65 import org.graalvm.compiler.options.OptionValues; 66 import org.graalvm.compiler.phases.BasePhase; 67 import org.graalvm.compiler.phases.Phase; 68 import org.graalvm.compiler.phases.PhaseSuite; 69 import org.graalvm.compiler.phases.common.CanonicalizerPhase; 70 import org.graalvm.compiler.phases.common.ConvertDeoptimizeToGuardPhase; 71 import org.graalvm.compiler.phases.schedule.SchedulePhase; 72 import org.graalvm.compiler.phases.schedule.SchedulePhase.SchedulingStrategy; 73 import org.graalvm.compiler.phases.tiers.HighTierContext; 74 import org.graalvm.compiler.phases.tiers.Suites; 75 76 import jdk.vm.ci.meta.ResolvedJavaMethod; 77 78 public abstract class MethodMetricsTest extends GraalCompilerTest { 79 static class TestApplication { 80 public static int m01(int x, int y) { 81 return x + y; 82 } 83 84 public static int m02(int x, int y) { 85 return x * y; 86 } 87 88 public static int m03(int x, int y) { 89 return x ^ y; 90 } 91 92 public static int m04(int x, int y) { 93 return x >> y; 94 } 95 96 public static int m05(int x, int y) { 97 return x >>> y; 98 } 99 100 public static int m06(int x, int y) { 101 return x << y; 102 } 103 104 public static int m07(int x, int y) { 105 return x > y ? 0 : 1; 106 } 107 108 public static int m08(int x, int y) { 109 return x % y; 110 } 111 112 public static int m09(int x, int y) { 113 return x / y; 114 } 115 116 public static int m10(int x, int y) { 117 return x - y; 118 } 119 120 } 121 122 public static final Class<?>[] testSignature = new Class<?>[]{int.class, int.class}; 123 public static final Object[] testArgs = new Object[]{10, 10}; 124 125 static class MethodMetricPhases { 126 static class CountingAddPhase extends Phase { 127 128 // typically those global metrics would be static final, but we need new timers every 129 // invocation if we override the debugvaluefactory 130 private final DebugCounter globalCounter = Debug.counter("GlobalMetric"); 131 private final DebugTimer globalTimer = Debug.timer("GlobalTimer"); 132 133 @Override 134 @SuppressWarnings("try") 135 protected void run(StructuredGraph graph) { 136 try (DebugCloseable d = globalTimer.start()) { 137 ResolvedJavaMethod method = graph.method(); 138 DebugMethodMetrics mm = Debug.methodMetrics(method); 139 mm.addToMetric(graph.getNodes().filter(InvokeNode.class).count(), "Invokes"); 140 mm.incrementMetric("PhaseRunsOnMethod"); 141 globalCounter.increment(); 142 } 143 } 144 } 145 146 static class CountingShiftPhase extends Phase { 147 @Override 148 protected void run(StructuredGraph graph) { 149 Debug.methodMetrics(graph.method()).addToMetric(graph.getNodes().filter(ShiftNode.class).count(), "Shifts"); 150 } 151 } 152 153 static class CountingMulPhase extends Phase { 154 @Override 155 protected void run(StructuredGraph graph) { 156 Debug.methodMetrics(graph.method()).addToMetric(graph.getNodes().filter(MulNode.class).count(), "Muls"); 157 } 158 } 159 160 static class CountingSubPhase extends Phase { 161 @Override 162 protected void run(StructuredGraph graph) { 163 Debug.methodMetrics(graph.method()).addToMetric(graph.getNodes().filter(SubNode.class).count(), "Subs"); 164 } 165 } 166 167 static class CountingDivPhase extends Phase { 168 @Override 169 protected void run(StructuredGraph graph) { 170 Debug.methodMetrics(graph.method()).addToMetric(graph.getNodes().filter(SignedDivNode.class).count(), "Divs"); 171 } 172 } 173 174 static class CountingBinOpPhase extends Phase { 175 @Override 176 protected void run(StructuredGraph graph) { 177 Debug.methodMetrics(graph.method()).addToMetric(graph.getNodes().filter(x -> x instanceof BinaryNode || x instanceof FixedBinaryNode).count(), "BinOps"); 178 } 179 } 180 181 static class ScopeTestPhase extends Phase { 182 // typically those global metrics would be static final, but we need new timers every 183 // invocation if we override the debugvaluefactory 184 private final DebugTimer timer = Debug.timer("GlobalTimer1"); 185 private final DebugTimer scopedTimer = Debug.timer("GlobalTimer2"); 186 private final DebugTimer scopedScopedTimer = Debug.timer("GlobalTimer3"); 187 private final DebugTimer scopedScopedScopeTimer = Debug.timer("GlobalTimer4"); 188 189 private final DebugTimer timer1 = Debug.timer("GlobalTimer1_WithoutInlineEnhancement"); 190 private final DebugTimer scopedTimer1 = Debug.timer("GlobalTimer2_WithoutInlineEnhancement"); 191 private final DebugTimer scopedScopedTimer1 = Debug.timer("GlobalTimer3_WithoutInlineEnhancement"); 192 private final DebugTimer scopedScopedScopeTimer1 = Debug.timer("GlobalTimer4_WithoutInlineEnhancement"); 193 194 @Override 195 @SuppressWarnings("try") 196 protected void run(StructuredGraph graph) { 197 // we are in an enhanced debug scope from graal compiler 198 // now we open multiple inlining scopes, record their time 199 try (DebugCloseable c1 = timer.start()) { 200 try (DebugCloseable c2 = scopedTimer.start()) { 201 try (DebugCloseable c3 = scopedScopedTimer.start()) { 202 // do sth unnecessary long allocating many inlinee scopes 203 for (int i = 0; i < 50; i++) { 204 try (Debug.Scope s1 = Debug.methodMetricsScope("InlineEnhancement1", MethodMetricsInlineeScopeInfo.create(graph.method()), false)) { 205 try (DebugCloseable c4 = scopedScopedScopeTimer.start()) { 206 new SchedulePhase(SchedulingStrategy.LATEST_OUT_OF_LOOPS).apply(graph); 207 // double scoped inlinee scopes should not make problems 208 // with the data 209 try (Debug.Scope s2 = Debug.methodMetricsScope("InlineEnhancement2", MethodMetricsInlineeScopeInfo.create(graph.method()), 210 false)) { 211 new SchedulePhase(SchedulingStrategy.LATEST_OUT_OF_LOOPS).apply(graph); 212 } 213 } 214 } 215 } 216 } 217 } 218 } 219 220 // now lets try different counters without the inline enhancement 221 try (DebugCloseable c1 = timer1.start()) { 222 try (DebugCloseable c2 = scopedTimer1.start()) { 223 try (DebugCloseable c3 = scopedScopedTimer1.start()) { 224 // do sth unnecessary long allocating many inlinee scopes 225 for (int i = 0; i < 50; i++) { 226 try (DebugCloseable c4 = scopedScopedScopeTimer1.start()) { 227 new SchedulePhase(SchedulingStrategy.LATEST_OUT_OF_LOOPS).apply(graph); 228 new SchedulePhase(SchedulingStrategy.LATEST_OUT_OF_LOOPS).apply(graph); 229 } 230 } 231 } 232 } 233 } 234 } 235 236 } 237 } 238 239 static DebugConfig overrideGraalDebugConfig(PrintStream log, String methodFilter, String methodMeter) { 240 List<DebugDumpHandler> dumpHandlers = new ArrayList<>(); 241 List<DebugVerifyHandler> verifyHandlers = new ArrayList<>(); 242 OptionValues options = getInitialOptions(); 243 GraalDebugConfig debugConfig = new GraalDebugConfig( 244 options, 245 GraalDebugConfig.Options.Log.getValue(options), 246 GraalDebugConfig.Options.Count.getValue(options), 247 GraalDebugConfig.Options.TrackMemUse.getValue(options), 248 GraalDebugConfig.Options.Time.getValue(options), 249 GraalDebugConfig.Options.Dump.getValue(options), 250 GraalDebugConfig.Options.Verify.getValue(options), 251 methodFilter, 252 methodMeter, 253 log, dumpHandlers, verifyHandlers); 254 return debugConfig; 255 } 256 257 abstract Phase additionalPhase(); 258 259 @Override 260 protected Suites createSuites(OptionValues options) { 261 Suites ret = super.createSuites(options); 262 ListIterator<BasePhase<? super HighTierContext>> iter = ret.getHighTier().findPhase(ConvertDeoptimizeToGuardPhase.class, true); 263 PhaseSuite.findNextPhase(iter, CanonicalizerPhase.class); 264 iter.add(additionalPhase()); 265 return ret; 266 } 267 268 @Test 269 @SuppressWarnings("try") 270 public void test() throws Throwable { 271 try (DebugConfigScope s = Debug.setConfig(getConfig())) { 272 executeMethod(TestApplication.class.getMethod("m01", testSignature), null, testArgs); 273 executeMethod(TestApplication.class.getMethod("m02", testSignature), null, testArgs); 274 executeMethod(TestApplication.class.getMethod("m03", testSignature), null, testArgs); 275 executeMethod(TestApplication.class.getMethod("m04", testSignature), null, testArgs); 276 executeMethod(TestApplication.class.getMethod("m05", testSignature), null, testArgs); 277 executeMethod(TestApplication.class.getMethod("m06", testSignature), null, testArgs); 278 executeMethod(TestApplication.class.getMethod("m07", testSignature), null, testArgs); 279 executeMethod(TestApplication.class.getMethod("m08", testSignature), null, testArgs); 280 executeMethod(TestApplication.class.getMethod("m09", testSignature), null, testArgs); 281 executeMethod(TestApplication.class.getMethod("m10", testSignature), null, testArgs); 282 assertValues(); 283 } 284 } 285 286 void executeMethod(Method m, Object receiver, Object... args) { 287 OptionValues options = new OptionValues(getInitialOptions(), MethodMetricsPrinter.Options.MethodMeterPrintAscii, true); 288 test(options, asResolvedJavaMethod(m), receiver, args); 289 } 290 291 @Before 292 public void rememberScopeId() { 293 scopeIdBeforeAccess = DebugScope.getCurrentGlobalScopeId(); 294 } 295 296 @After 297 public void clearMMCache() { 298 MethodMetricsImpl.clearMM(); 299 } 300 301 abstract DebugConfig getConfig(); 302 303 abstract void assertValues() throws Throwable; 304 305 @SuppressWarnings("unchecked") 306 private static Map<ResolvedJavaMethod, CompilationData> readMethodMetricsImplData() { 307 Map<ResolvedJavaMethod, CompilationData> threadLocalMap = null; 308 for (Field f : MethodMetricsImpl.class.getDeclaredFields()) { 309 if (f.getName().equals("threadEntries")) { 310 Util.setAccessible(f, true); 311 Object map; 312 try { 313 map = ((ThreadLocal<?>) f.get(null)).get(); 314 } catch (Throwable t) { 315 throw new RuntimeException(t); 316 } 317 threadLocalMap = (Map<ResolvedJavaMethod, CompilationData>) map; 318 break; 319 } 320 } 321 return threadLocalMap; 322 } 323 324 private long scopeIdBeforeAccess; 325 private long scopeIdAfterAccess; 326 327 protected long readValFromCurrThread(ResolvedJavaMethod method, String metricName) { 328 329 Map<ResolvedJavaMethod, CompilationData> threadLocalMap = readMethodMetricsImplData(); 330 assert threadLocalMap != null; 331 CompilationData compilationData = threadLocalMap.get(method); 332 assert compilationData != null; 333 Map<Long, Map<String, Long>> compilations = compilationData.getCompilations(); 334 List<Map<String, Long>> compilationEntries = new ArrayList<>(); 335 compilations.forEach((x, y) -> { 336 if (x >= scopeIdBeforeAccess && x <= scopeIdAfterAccess) { 337 compilationEntries.add(y); 338 } 339 }); 340 List<Map<String, Long>> listView = compilationEntries.stream().filter(x -> x.size() > 0).collect(Collectors.toList()); 341 assert listView.size() <= 1 : "There must be at most one none empty compilation data point present:" + listView.size(); 342 /* 343 * NOTE: Using the pre-generation of compilation entries for a method has the disadvantage 344 * that during testing we have different points in time when we request the metric. First, 345 * properly, when we use it and then when we want to know the result, but when we check the 346 * result the debug context no longer holds a correct scope with the unique id, so we return 347 * the first compilation entry that is not empty. 348 */ 349 Map<String, Long> entries = listView.size() > 0 ? listView.get(0) : null; 350 Long res = entries != null ? entries.get(metricName) : null; 351 return res != null ? res : 0; 352 } 353 354 @SuppressWarnings("try") 355 void assertValues(String metricName, long[] vals) { 356 scopeIdAfterAccess = DebugScope.getCurrentGlobalScopeId(); 357 try (DebugConfigScope s = Debug.setConfig(new DelegatingDebugConfig().enable(Feature.METHOD_METRICS))) { 358 Assert.assertEquals(vals[0], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m01", testSignature)), metricName)); 359 Assert.assertEquals(vals[1], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m02", testSignature)), metricName)); 360 Assert.assertEquals(vals[2], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m03", testSignature)), metricName)); 361 Assert.assertEquals(vals[3], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m04", testSignature)), metricName)); 362 Assert.assertEquals(vals[4], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m05", testSignature)), metricName)); 363 Assert.assertEquals(vals[5], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m06", testSignature)), metricName)); 364 Assert.assertEquals(vals[6], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m07", testSignature)), metricName)); 365 Assert.assertEquals(vals[7], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m08", testSignature)), metricName)); 366 Assert.assertEquals(vals[8], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m09", testSignature)), metricName)); 367 } catch (Throwable t) { 368 throw new RuntimeException(t); 369 } 370 } 371 }