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.HashMap;
30 import java.util.List;
31 import java.util.ListIterator;
32 import java.util.Map;
33 import java.util.stream.Collectors;
34
35 import org.junit.After;
36 import org.junit.Assert;
37 import org.junit.Before;
38 import org.junit.Test;
39
40 import org.graalvm.compiler.core.test.GraalCompilerTest;
41 import org.graalvm.compiler.debug.Debug;
42 import org.graalvm.compiler.debug.DebugCloseable;
43 import org.graalvm.compiler.debug.DebugConfig;
44 import org.graalvm.compiler.debug.DebugConfigScope;
45 import org.graalvm.compiler.debug.DebugCounter;
46 import org.graalvm.compiler.debug.DebugDumpHandler;
47 import org.graalvm.compiler.debug.DebugMethodMetrics;
48 import org.graalvm.compiler.debug.DebugTimer;
49 import org.graalvm.compiler.debug.DebugVerifyHandler;
50 import org.graalvm.compiler.debug.DelegatingDebugConfig;
51 import org.graalvm.compiler.debug.DelegatingDebugConfig.Feature;
52 import org.graalvm.compiler.debug.GraalDebugConfig;
53 import org.graalvm.compiler.debug.internal.DebugScope;
54 import org.graalvm.compiler.debug.internal.method.MethodMetricsImpl;
55 import org.graalvm.compiler.debug.internal.method.MethodMetricsImpl.CompilationData;
56 import org.graalvm.compiler.debug.internal.method.MethodMetricsInlineeScopeInfo;
57 import org.graalvm.compiler.debug.internal.method.MethodMetricsPrinter;
58 import org.graalvm.compiler.nodes.InvokeNode;
59 import org.graalvm.compiler.nodes.StructuredGraph;
60 import org.graalvm.compiler.nodes.calc.BinaryNode;
61 import org.graalvm.compiler.nodes.calc.FixedBinaryNode;
62 import org.graalvm.compiler.nodes.calc.MulNode;
63 import org.graalvm.compiler.nodes.calc.ShiftNode;
64 import org.graalvm.compiler.nodes.calc.SignedDivNode;
65 import org.graalvm.compiler.nodes.calc.SubNode;
66 import org.graalvm.compiler.options.OptionValue;
67 import org.graalvm.compiler.options.OptionValue.OverrideScope;
68 import org.graalvm.compiler.phases.BasePhase;
69 import org.graalvm.compiler.phases.Phase;
70 import org.graalvm.compiler.phases.PhaseSuite;
71 import org.graalvm.compiler.phases.common.CanonicalizerPhase;
72 import org.graalvm.compiler.phases.common.ConvertDeoptimizeToGuardPhase;
73 import org.graalvm.compiler.phases.schedule.SchedulePhase;
74 import org.graalvm.compiler.phases.schedule.SchedulePhase.SchedulingStrategy;
75 import org.graalvm.compiler.phases.tiers.HighTierContext;
76 import org.graalvm.compiler.phases.tiers.Suites;
77
78 import jdk.vm.ci.meta.ResolvedJavaMethod;
79
80 public 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 }