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