/* * 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.core.test.debug; import java.io.PrintStream; import java.lang.reflect.Field; import java.lang.reflect.Method; import java.util.ArrayList; import java.util.List; import java.util.ListIterator; import java.util.Map; import java.util.stream.Collectors; import org.junit.After; import org.junit.Assert; import org.junit.Before; import org.junit.Test; import org.graalvm.compiler.core.common.util.Util; import org.graalvm.compiler.core.test.GraalCompilerTest; import org.graalvm.compiler.debug.Debug; import org.graalvm.compiler.debug.DebugCloseable; import org.graalvm.compiler.debug.DebugConfig; import org.graalvm.compiler.debug.DebugConfigScope; import org.graalvm.compiler.debug.DebugCounter; import org.graalvm.compiler.debug.DebugDumpHandler; import org.graalvm.compiler.debug.DebugMethodMetrics; import org.graalvm.compiler.debug.DebugTimer; import org.graalvm.compiler.debug.DebugVerifyHandler; import org.graalvm.compiler.debug.DelegatingDebugConfig; import org.graalvm.compiler.debug.DelegatingDebugConfig.Feature; import org.graalvm.compiler.debug.GraalDebugConfig; import org.graalvm.compiler.debug.internal.DebugScope; import org.graalvm.compiler.debug.internal.method.MethodMetricsImpl; import org.graalvm.compiler.debug.internal.method.MethodMetricsImpl.CompilationData; import org.graalvm.compiler.debug.internal.method.MethodMetricsInlineeScopeInfo; import org.graalvm.compiler.debug.internal.method.MethodMetricsPrinter; import org.graalvm.compiler.nodes.InvokeNode; import org.graalvm.compiler.nodes.StructuredGraph; import org.graalvm.compiler.nodes.calc.BinaryNode; import org.graalvm.compiler.nodes.calc.FixedBinaryNode; import org.graalvm.compiler.nodes.calc.MulNode; import org.graalvm.compiler.nodes.calc.ShiftNode; import org.graalvm.compiler.nodes.calc.SignedDivNode; import org.graalvm.compiler.nodes.calc.SubNode; import org.graalvm.compiler.options.OptionValues; import org.graalvm.compiler.phases.BasePhase; import org.graalvm.compiler.phases.Phase; import org.graalvm.compiler.phases.PhaseSuite; import org.graalvm.compiler.phases.common.CanonicalizerPhase; import org.graalvm.compiler.phases.common.ConvertDeoptimizeToGuardPhase; import org.graalvm.compiler.phases.schedule.SchedulePhase; import org.graalvm.compiler.phases.schedule.SchedulePhase.SchedulingStrategy; import org.graalvm.compiler.phases.tiers.HighTierContext; import org.graalvm.compiler.phases.tiers.Suites; import jdk.vm.ci.meta.ResolvedJavaMethod; public abstract class MethodMetricsTest extends GraalCompilerTest { static class TestApplication { public static int m01(int x, int y) { return x + y; } public static int m02(int x, int y) { return x * y; } public static int m03(int x, int y) { return x ^ y; } public static int m04(int x, int y) { return x >> y; } public static int m05(int x, int y) { return x >>> y; } public static int m06(int x, int y) { return x << y; } public static int m07(int x, int y) { return x > y ? 0 : 1; } public static int m08(int x, int y) { return x % y; } public static int m09(int x, int y) { return x / y; } public static int m10(int x, int y) { return x - y; } } public static final Class<?>[] testSignature = new Class<?>[]{int.class, int.class}; public static final Object[] testArgs = new Object[]{10, 10}; static class MethodMetricPhases { static class CountingAddPhase extends Phase { // typically those global metrics would be static final, but we need new timers every // invocation if we override the debugvaluefactory private final DebugCounter globalCounter = Debug.counter("GlobalMetric"); private final DebugTimer globalTimer = Debug.timer("GlobalTimer"); @Override @SuppressWarnings("try") protected void run(StructuredGraph graph) { try (DebugCloseable d = globalTimer.start()) { ResolvedJavaMethod method = graph.method(); DebugMethodMetrics mm = Debug.methodMetrics(method); mm.addToMetric(graph.getNodes().filter(InvokeNode.class).count(), "Invokes"); mm.incrementMetric("PhaseRunsOnMethod"); globalCounter.increment(); } } } static class CountingShiftPhase extends Phase { @Override protected void run(StructuredGraph graph) { Debug.methodMetrics(graph.method()).addToMetric(graph.getNodes().filter(ShiftNode.class).count(), "Shifts"); } } static class CountingMulPhase extends Phase { @Override protected void run(StructuredGraph graph) { Debug.methodMetrics(graph.method()).addToMetric(graph.getNodes().filter(MulNode.class).count(), "Muls"); } } static class CountingSubPhase extends Phase { @Override protected void run(StructuredGraph graph) { Debug.methodMetrics(graph.method()).addToMetric(graph.getNodes().filter(SubNode.class).count(), "Subs"); } } static class CountingDivPhase extends Phase { @Override protected void run(StructuredGraph graph) { Debug.methodMetrics(graph.method()).addToMetric(graph.getNodes().filter(SignedDivNode.class).count(), "Divs"); } } static class CountingBinOpPhase extends Phase { @Override protected void run(StructuredGraph graph) { Debug.methodMetrics(graph.method()).addToMetric(graph.getNodes().filter(x -> x instanceof BinaryNode || x instanceof FixedBinaryNode).count(), "BinOps"); } } static class ScopeTestPhase extends Phase { // typically those global metrics would be static final, but we need new timers every // invocation if we override the debugvaluefactory private final DebugTimer timer = Debug.timer("GlobalTimer1"); private final DebugTimer scopedTimer = Debug.timer("GlobalTimer2"); private final DebugTimer scopedScopedTimer = Debug.timer("GlobalTimer3"); private final DebugTimer scopedScopedScopeTimer = Debug.timer("GlobalTimer4"); private final DebugTimer timer1 = Debug.timer("GlobalTimer1_WithoutInlineEnhancement"); private final DebugTimer scopedTimer1 = Debug.timer("GlobalTimer2_WithoutInlineEnhancement"); private final DebugTimer scopedScopedTimer1 = Debug.timer("GlobalTimer3_WithoutInlineEnhancement"); private final DebugTimer scopedScopedScopeTimer1 = Debug.timer("GlobalTimer4_WithoutInlineEnhancement"); @Override @SuppressWarnings("try") protected void run(StructuredGraph graph) { // we are in an enhanced debug scope from graal compiler // now we open multiple inlining scopes, record their time try (DebugCloseable c1 = timer.start()) { try (DebugCloseable c2 = scopedTimer.start()) { try (DebugCloseable c3 = scopedScopedTimer.start()) { // do sth unnecessary long allocating many inlinee scopes for (int i = 0; i < 50; i++) { try (Debug.Scope s1 = Debug.methodMetricsScope("InlineEnhancement1", MethodMetricsInlineeScopeInfo.create(graph.method()), false)) { try (DebugCloseable c4 = scopedScopedScopeTimer.start()) { new SchedulePhase(SchedulingStrategy.LATEST_OUT_OF_LOOPS).apply(graph); // double scoped inlinee scopes should not make problems // with the data try (Debug.Scope s2 = Debug.methodMetricsScope("InlineEnhancement2", MethodMetricsInlineeScopeInfo.create(graph.method()), false)) { new SchedulePhase(SchedulingStrategy.LATEST_OUT_OF_LOOPS).apply(graph); } } } } } } } // now lets try different counters without the inline enhancement try (DebugCloseable c1 = timer1.start()) { try (DebugCloseable c2 = scopedTimer1.start()) { try (DebugCloseable c3 = scopedScopedTimer1.start()) { // do sth unnecessary long allocating many inlinee scopes for (int i = 0; i < 50; i++) { try (DebugCloseable c4 = scopedScopedScopeTimer1.start()) { new SchedulePhase(SchedulingStrategy.LATEST_OUT_OF_LOOPS).apply(graph); new SchedulePhase(SchedulingStrategy.LATEST_OUT_OF_LOOPS).apply(graph); } } } } } } } } static DebugConfig overrideGraalDebugConfig(PrintStream log, String methodFilter, String methodMeter) { List<DebugDumpHandler> dumpHandlers = new ArrayList<>(); List<DebugVerifyHandler> verifyHandlers = new ArrayList<>(); OptionValues options = getInitialOptions(); GraalDebugConfig debugConfig = new GraalDebugConfig( options, GraalDebugConfig.Options.Log.getValue(options), GraalDebugConfig.Options.Count.getValue(options), GraalDebugConfig.Options.TrackMemUse.getValue(options), GraalDebugConfig.Options.Time.getValue(options), GraalDebugConfig.Options.Dump.getValue(options), GraalDebugConfig.Options.Verify.getValue(options), methodFilter, methodMeter, log, dumpHandlers, verifyHandlers); return debugConfig; } abstract Phase additionalPhase(); @Override protected Suites createSuites(OptionValues options) { Suites ret = super.createSuites(options); ListIterator<BasePhase<? super HighTierContext>> iter = ret.getHighTier().findPhase(ConvertDeoptimizeToGuardPhase.class, true); PhaseSuite.findNextPhase(iter, CanonicalizerPhase.class); iter.add(additionalPhase()); return ret; } @Test @SuppressWarnings("try") public void test() throws Throwable { try (DebugConfigScope s = Debug.setConfig(getConfig())) { executeMethod(TestApplication.class.getMethod("m01", testSignature), null, testArgs); executeMethod(TestApplication.class.getMethod("m02", testSignature), null, testArgs); executeMethod(TestApplication.class.getMethod("m03", testSignature), null, testArgs); executeMethod(TestApplication.class.getMethod("m04", testSignature), null, testArgs); executeMethod(TestApplication.class.getMethod("m05", testSignature), null, testArgs); executeMethod(TestApplication.class.getMethod("m06", testSignature), null, testArgs); executeMethod(TestApplication.class.getMethod("m07", testSignature), null, testArgs); executeMethod(TestApplication.class.getMethod("m08", testSignature), null, testArgs); executeMethod(TestApplication.class.getMethod("m09", testSignature), null, testArgs); executeMethod(TestApplication.class.getMethod("m10", testSignature), null, testArgs); assertValues(); } } void executeMethod(Method m, Object receiver, Object... args) { OptionValues options = new OptionValues(getInitialOptions(), MethodMetricsPrinter.Options.MethodMeterPrintAscii, true); test(options, asResolvedJavaMethod(m), receiver, args); } @Before public void rememberScopeId() { scopeIdBeforeAccess = DebugScope.getCurrentGlobalScopeId(); } @After public void clearMMCache() { MethodMetricsImpl.clearMM(); } abstract DebugConfig getConfig(); abstract void assertValues() throws Throwable; @SuppressWarnings("unchecked") private static Map<ResolvedJavaMethod, CompilationData> readMethodMetricsImplData() { Map<ResolvedJavaMethod, CompilationData> threadLocalMap = null; for (Field f : MethodMetricsImpl.class.getDeclaredFields()) { if (f.getName().equals("threadEntries")) { Util.setAccessible(f, true); Object map; try { map = ((ThreadLocal<?>) f.get(null)).get(); } catch (Throwable t) { throw new RuntimeException(t); } threadLocalMap = (Map<ResolvedJavaMethod, CompilationData>) map; break; } } return threadLocalMap; } private long scopeIdBeforeAccess; private long scopeIdAfterAccess; protected long readValFromCurrThread(ResolvedJavaMethod method, String metricName) { Map<ResolvedJavaMethod, CompilationData> threadLocalMap = readMethodMetricsImplData(); assert threadLocalMap != null; CompilationData compilationData = threadLocalMap.get(method); assert compilationData != null; Map<Long, Map<String, Long>> compilations = compilationData.getCompilations(); List<Map<String, Long>> compilationEntries = new ArrayList<>(); compilations.forEach((x, y) -> { if (x >= scopeIdBeforeAccess && x <= scopeIdAfterAccess) { compilationEntries.add(y); } }); List<Map<String, Long>> listView = compilationEntries.stream().filter(x -> x.size() > 0).collect(Collectors.toList()); assert listView.size() <= 1 : "There must be at most one none empty compilation data point present:" + listView.size(); /* * NOTE: Using the pre-generation of compilation entries for a method has the disadvantage * that during testing we have different points in time when we request the metric. First, * properly, when we use it and then when we want to know the result, but when we check the * result the debug context no longer holds a correct scope with the unique id, so we return * the first compilation entry that is not empty. */ Map<String, Long> entries = listView.size() > 0 ? listView.get(0) : null; Long res = entries != null ? entries.get(metricName) : null; return res != null ? res : 0; } @SuppressWarnings("try") void assertValues(String metricName, long[] vals) { scopeIdAfterAccess = DebugScope.getCurrentGlobalScopeId(); try (DebugConfigScope s = Debug.setConfig(new DelegatingDebugConfig().enable(Feature.METHOD_METRICS))) { Assert.assertEquals(vals[0], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m01", testSignature)), metricName)); Assert.assertEquals(vals[1], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m02", testSignature)), metricName)); Assert.assertEquals(vals[2], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m03", testSignature)), metricName)); Assert.assertEquals(vals[3], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m04", testSignature)), metricName)); Assert.assertEquals(vals[4], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m05", testSignature)), metricName)); Assert.assertEquals(vals[5], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m06", testSignature)), metricName)); Assert.assertEquals(vals[6], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m07", testSignature)), metricName)); Assert.assertEquals(vals[7], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m08", testSignature)), metricName)); Assert.assertEquals(vals[8], readValFromCurrThread(asResolvedJavaMethod(TestApplication.class.getMethod("m09", testSignature)), metricName)); } catch (Throwable t) { throw new RuntimeException(t); } } }