# HG changeset patch # User Doug Simon # Date 1359126311 -3600 # Node ID 223f645acb9b753a7a022c8eac668c5e172289b4 # Parent db90c8b5a861a89ae27d038084502131e6def6df added compilation rate measurements on top of existing metric/timer facility - enabled with -Dgraal.benchmark.compilation=true diff -r db90c8b5a861 -r 223f645acb9b graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/CompilationTask.java --- a/graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/CompilationTask.java Fri Jan 25 15:31:54 2013 +0100 +++ b/graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/CompilationTask.java Fri Jan 25 16:05:11 2013 +0100 @@ -23,12 +23,14 @@ package com.oracle.graal.hotspot; import static com.oracle.graal.nodes.StructuredGraph.*; +import static com.oracle.graal.phases.common.InliningUtil.*; import java.util.concurrent.*; import com.oracle.graal.api.code.*; import com.oracle.graal.api.meta.*; import com.oracle.graal.debug.*; +import com.oracle.graal.debug.internal.*; import com.oracle.graal.graph.*; import com.oracle.graal.hotspot.meta.*; import com.oracle.graal.nodes.*; @@ -112,9 +114,14 @@ } } + /** + * Time spent in compilation. + */ + public static final DebugTimer CompilationTime = Debug.timer("CompilationTime"); + public void runCompilation() { CompilationStatistics stats = CompilationStatistics.create(method, entryBCI != StructuredGraph.INVOCATION_ENTRY_BCI); - try { + try (TimerCloseable a = CompilationTime.start()) { final boolean printCompilation = GraalOptions.PrintCompilation && !TTY.isSuppressed(); if (printCompilation) { TTY.println(String.format("%-6d Graal %-70s %-45s %-50s %s...", id, method.getDeclaringClass().getName(), method.getName(), method.getSignature(), @@ -138,6 +145,7 @@ graph = graph.copy(); // System.out.println("compiling intrinsic " + method); } + InlinedBytecodes.add(method.getCodeSize()); return graalRuntime.getCompiler().compileMethod(method, graph, graalRuntime.getCache(), plan, optimisticOpts); } }); diff -r db90c8b5a861 -r 223f645acb9b graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/bridge/MetricRateInPhase.java --- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/bridge/MetricRateInPhase.java Fri Jan 25 16:05:11 2013 +0100 @@ -0,0 +1,75 @@ +/* + * Copyright (c) 2013, 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 com.oracle.graal.hotspot.bridge; + +import java.util.concurrent.*; + +import com.oracle.graal.debug.*; +import com.oracle.graal.debug.internal.*; + +/** + * The rate of accumulation for a metric within an execution phase. + */ +final class MetricRateInPhase { + + private final String phase; + private final MetricRateInPhase previous; + private final long time; + private final long value; + private final TimeUnit timeUnit; + + public static MetricRateInPhase snapshot(String phase, MetricRateInPhase previous, DebugMetric metric, DebugTimer timer, TimeUnit timeUnit) { + return new MetricRateInPhase(phase, previous, metric, timer, timeUnit); + } + + private MetricRateInPhase(String phase, MetricRateInPhase previous, DebugMetric metric, DebugTimer timer, TimeUnit timeUnit) { + this.phase = phase; + this.previous = previous; + this.time = VMToCompilerImpl.collectTotal((DebugValue) timer); + this.value = VMToCompilerImpl.collectTotal((DebugValue) metric); + this.timeUnit = timeUnit; + } + + public int rate() { + long t = time; + long v = value; + if (previous != null) { + t -= previous.time; + v -= previous.value; + } + + t = timeUnit.convert(t, TimeUnit.NANOSECONDS); + if (t == 0) { + t = 1; + } + return (int) (v / t); + } + + public void printAll(String label) { + MetricRateInPhase rs = this; + while (rs != null) { + System.out.println(label + "@" + rs.phase + ": " + rs.rate()); + rs = rs.previous; + } + } +} diff -r db90c8b5a861 -r 223f645acb9b graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/bridge/VMToCompilerImpl.java --- a/graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/bridge/VMToCompilerImpl.java Fri Jan 25 15:31:54 2013 +0100 +++ b/graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/bridge/VMToCompilerImpl.java Fri Jan 25 16:05:11 2013 +0100 @@ -24,6 +24,9 @@ package com.oracle.graal.hotspot.bridge; import static com.oracle.graal.graph.UnsafeAccess.*; +import static com.oracle.graal.hotspot.CompilationTask.*; +import static com.oracle.graal.java.GraphBuilderPhase.*; +import static com.oracle.graal.phases.common.InliningUtil.*; import java.io.*; import java.lang.reflect.*; @@ -53,6 +56,8 @@ private final HotSpotGraalRuntime graalRuntime; + private static final boolean BenchmarkCompilation = Boolean.getBoolean("graal.benchmark.compilation"); + public final HotSpotResolvedPrimitiveType typeBoolean; public final HotSpotResolvedPrimitiveType typeChar; public final HotSpotResolvedPrimitiveType typeFloat; @@ -121,6 +126,13 @@ } } + if (BenchmarkCompilation) { + GraalOptions.Debug = true; + GraalOptions.Meter = ""; + GraalOptions.Time = ""; + GraalOptions.SummarizeDebugValues = true; + } + if (GraalOptions.Debug) { Debug.enable(); if (GraalOptions.DebugSnippets) { @@ -147,6 +159,10 @@ } + if (GraalOptions.DebugSnippets) { + phaseTransition("snippets"); + } + // Create compilation queue. BlockingQueue queue = GraalOptions.PriorityCompileQueue ? new PriorityBlockingQueue() : new LinkedBlockingQueue(); compileQueue = new ThreadPoolExecutor(GraalOptions.Threads, GraalOptions.Threads, 0L, TimeUnit.MILLISECONDS, queue, CompilerThread.FACTORY); @@ -181,6 +197,19 @@ } /** + * Take action related to entering a new execution phase. + * + * @param phase the execution phase being entered + */ + protected void phaseTransition(String phase) { + CompilationStatistics.clear(phase); + if (BenchmarkCompilation) { + parsedBytecodesPerSecond = MetricRateInPhase.snapshot(phase, parsedBytecodesPerSecond, BytecodesParsed, CompilationTime, TimeUnit.SECONDS); + inlinedBytecodesPerSecond = MetricRateInPhase.snapshot(phase, inlinedBytecodesPerSecond, InlinedBytecodes, CompilationTime, TimeUnit.SECONDS); + } + } + + /** * This method is the first method compiled during bootstrapping. Put any code in there that * warms up compiler paths that are otherwise not exercised during bootstrapping and lead to * later deoptimization when application code is compiled. @@ -239,7 +268,9 @@ } } } while ((System.currentTimeMillis() - startTime) <= GraalOptions.TimedBootstrap); - CompilationStatistics.clear("bootstrap"); + + phaseTransition("bootstrap"); + bootstrapRunning = false; TTY.println(" in %d ms", System.currentTimeMillis() - startTime); @@ -247,9 +278,12 @@ graalRuntime.getCache().clear(); } System.gc(); - CompilationStatistics.clear("bootstrap2"); + phaseTransition("bootstrap2"); } + private MetricRateInPhase parsedBytecodesPerSecond; + private MetricRateInPhase inlinedBytecodesPerSecond; + private void enqueue(Method m) throws Throwable { JavaMethod javaMethod = graalRuntime.getRuntime().lookupJavaMethod(m); assert !Modifier.isAbstract(((HotSpotResolvedJavaMethod) javaMethod).getModifiers()) && !Modifier.isNative(((HotSpotResolvedJavaMethod) javaMethod).getModifiers()) : javaMethod; @@ -298,9 +332,7 @@ if (GraalOptions.SummarizePerPhase) { flattenChildren(map, globalMap); } else { - for (DebugValueMap child : map.getChildren()) { - globalMap.addChild(child); - } + globalMap.addChild(map); } } if (!GraalOptions.SummarizePerPhase) { @@ -311,7 +343,11 @@ } } } - CompilationStatistics.clear("final"); + phaseTransition("final"); + + parsedBytecodesPerSecond.printAll("ParsedBytecodesPerSecond"); + inlinedBytecodesPerSecond.printAll("InlinedBytecodesPerSecond"); + SnippetCounter.printGroups(TTY.out().out()); } @@ -334,6 +370,18 @@ printMap(result, debugValues, 0); } + static long collectTotal(DebugValue value) { + List maps = DebugValueMap.getTopLevelMaps(); + long total = 0; + for (int i = 0; i < maps.size(); i++) { + DebugValueMap map = maps.get(i); + int index = value.getIndex(); + total += map.getCurrentValue(index); + total += collectTotal(map.getChildren(), index); + } + return total; + } + private static long collectTotal(List maps, int index) { long total = 0; for (int i = 0; i < maps.size(); i++) { diff -r db90c8b5a861 -r 223f645acb9b graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/meta/HotSpotRuntime.java --- a/graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/meta/HotSpotRuntime.java Fri Jan 25 15:31:54 2013 +0100 +++ b/graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/meta/HotSpotRuntime.java Fri Jan 25 16:05:11 2013 +0100 @@ -22,6 +22,7 @@ */ package com.oracle.graal.hotspot.meta; +import static com.oracle.graal.api.code.CallingConvention.Type.*; import static com.oracle.graal.api.code.DeoptimizationAction.*; import static com.oracle.graal.api.code.MemoryBarriers.*; import static com.oracle.graal.api.code.Register.RegisterFlag.*; @@ -29,12 +30,11 @@ import static com.oracle.graal.api.meta.Value.*; import static com.oracle.graal.hotspot.HotSpotGraalRuntime.*; import static com.oracle.graal.hotspot.snippets.SystemSubstitutions.*; -import static com.oracle.graal.java.GraphBuilderPhase.*; +import static com.oracle.graal.java.GraphBuilderPhase.RuntimeCalls.*; import static com.oracle.graal.nodes.UnwindNode.*; import static com.oracle.graal.nodes.java.RegisterFinalizerNode.*; import static com.oracle.graal.snippets.Log.*; import static com.oracle.graal.snippets.MathSubstitutionsX86.*; -import static com.oracle.graal.api.code.CallingConvention.Type.*; import java.lang.reflect.*; import java.util.*; diff -r db90c8b5a861 -r 223f645acb9b graal/com.oracle.graal.java/src/com/oracle/graal/java/GraphBuilderPhase.java --- a/graal/com.oracle.graal.java/src/com/oracle/graal/java/GraphBuilderPhase.java Fri Jan 25 15:31:54 2013 +0100 +++ b/graal/com.oracle.graal.java/src/com/oracle/graal/java/GraphBuilderPhase.java Fri Jan 25 16:05:11 2013 +0100 @@ -54,8 +54,11 @@ */ public final class GraphBuilderPhase extends Phase { - public static final Descriptor CREATE_NULL_POINTER_EXCEPTION = new Descriptor("createNullPointerException", true, Object.class); - public static final Descriptor CREATE_OUT_OF_BOUNDS_EXCEPTION = new Descriptor("createOutOfBoundsException", true, Object.class, int.class); + public static final class RuntimeCalls { + + public static final Descriptor CREATE_NULL_POINTER_EXCEPTION = new Descriptor("createNullPointerException", true, Object.class); + public static final Descriptor CREATE_OUT_OF_BOUNDS_EXCEPTION = new Descriptor("createOutOfBoundsException", true, Object.class, int.class); + } /** * The minimum value to which {@link GraalOptions#TraceBytecodeParserLevel} must be set to trace @@ -94,6 +97,11 @@ private long graphId; /** + * Meters the number of actual bytecodes parsed. + */ + public static final DebugMetric BytecodesParsed = Debug.metric("BytecodesParsed"); + + /** * Node that marks the begin of block during bytecode parsing. When a block is identified the * first time as a jump target, the placeholder is created and used as the successor for the * jump. When the block is seen the second time, a MergeNode is created to correctly merge the @@ -833,7 +841,7 @@ ValueNode exception = ConstantNode.forObject(cachedNullPointerException, runtime, currentGraph); trueSucc.setNext(handleException(exception, bci())); } else { - RuntimeCallNode call = currentGraph.add(new RuntimeCallNode(CREATE_NULL_POINTER_EXCEPTION)); + RuntimeCallNode call = currentGraph.add(new RuntimeCallNode(RuntimeCalls.CREATE_NULL_POINTER_EXCEPTION)); call.setStateAfter(frameState.create(bci())); trueSucc.setNext(call); call.setNext(handleException(call, bci())); @@ -859,7 +867,7 @@ ValueNode exception = ConstantNode.forObject(cachedArrayIndexOutOfBoundsException, runtime, currentGraph); falseSucc.setNext(handleException(exception, bci())); } else { - RuntimeCallNode call = currentGraph.add(new RuntimeCallNode(CREATE_OUT_OF_BOUNDS_EXCEPTION, index)); + RuntimeCallNode call = currentGraph.add(new RuntimeCallNode(RuntimeCalls.CREATE_OUT_OF_BOUNDS_EXCEPTION, index)); call.setStateAfter(frameState.create(bci())); falseSucc.setNext(call); call.setNext(handleException(call, bci())); @@ -1587,6 +1595,8 @@ stream.setBCI(block.startBci); int bci = block.startBci; + BytecodesParsed.add(block.endBci - bci); + while (bci < endBCI) { // read the opcode int opcode = stream.currentBC(); diff -r db90c8b5a861 -r 223f645acb9b graal/com.oracle.graal.phases.common/src/com/oracle/graal/phases/common/InliningUtil.java --- a/graal/com.oracle.graal.phases.common/src/com/oracle/graal/phases/common/InliningUtil.java Fri Jan 25 15:31:54 2013 +0100 +++ b/graal/com.oracle.graal.phases.common/src/com/oracle/graal/phases/common/InliningUtil.java Fri Jan 25 16:05:11 2013 +0100 @@ -48,6 +48,13 @@ private static final DebugMetric metricInliningTailDuplication = Debug.metric("InliningTailDuplication"); private static final String inliningDecisionsScopeString = "InliningDecisions"; + /** + * Meters the size (in bytecodes) of all methods processed during compilation (i.e., top level and all + * inlined methods), irrespective of how many bytecodes in each method are actually parsed + * (which may be none for methods whose IR is retrieved from a cache). + */ + public static final DebugMetric InlinedBytecodes = Debug.metric("InlinedBytecodes"); + public interface InliningCallback { StructuredGraph buildGraph(final ResolvedJavaMethod method); @@ -243,6 +250,7 @@ if (calleeGraph == null) { calleeGraph = getGraph(concrete, callback); } + InlinedBytecodes.add(concrete.getCodeSize()); assumptions.recordMethodContents(concrete); InliningUtil.inline(invoke, calleeGraph, receiverNullCheck); }