# HG changeset patch # User Lukas Stadler # Date 1380719104 -7200 # Node ID 8a201c64cd18dc2d8d2828af5d0a88b66ac34fd0 # Parent 5501a34d43bb81f8d2f7283e35ac2ccb173ae555 in-depth profiling of allocations and monitors diff -r 5501a34d43bb -r 8a201c64cd18 graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/replacements/MonitorSnippets.java --- a/graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/replacements/MonitorSnippets.java Wed Oct 02 15:04:04 2013 +0200 +++ b/graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/replacements/MonitorSnippets.java Wed Oct 02 15:05:04 2013 +0200 @@ -40,14 +40,17 @@ import com.oracle.graal.graph.iterators.*; import com.oracle.graal.hotspot.nodes.*; import com.oracle.graal.nodes.*; +import com.oracle.graal.nodes.debug.*; import com.oracle.graal.nodes.extended.*; import com.oracle.graal.nodes.java.*; import com.oracle.graal.nodes.java.MethodCallTargetNode.InvokeKind; import com.oracle.graal.nodes.spi.*; import com.oracle.graal.nodes.type.*; +import com.oracle.graal.options.*; import com.oracle.graal.phases.common.*; import com.oracle.graal.replacements.*; import com.oracle.graal.replacements.Snippet.ConstantParameter; +import com.oracle.graal.replacements.Snippet.Fold; import com.oracle.graal.replacements.SnippetTemplate.AbstractTemplates; import com.oracle.graal.replacements.SnippetTemplate.Arguments; import com.oracle.graal.replacements.SnippetTemplate.SnippetInfo; @@ -63,6 +66,22 @@ */ public class MonitorSnippets implements Snippets { + public static class Options { + + //@formatter:off + @Option(help = "") + private static final OptionValue ProfileMonitors = new OptionValue<>(false); + //@formatter:on + } + + private static final boolean PROFILE_CONTEXT = false; + + @Fold + @SuppressWarnings("unused") + private static boolean doProfile(String path) { + return Options.ProfileMonitors.getValue(); + } + /** * Monitor operations on objects whose type contains this substring will be traced. */ @@ -118,7 +137,7 @@ trace(trace, " tmp: 0x%016lx\n", tmp); if (probability(FREQUENT_PROBABILITY, tmp.equal(0))) { // Object is already biased to current thread -> done - traceObject(trace, "+lock{bias:existing}", object); + traceObject(trace, "+lock{bias:existing}", object, true); return; } @@ -154,13 +173,13 @@ trace(trace, " biasedMark: 0x%016lx\n", biasedMark); if (probability(VERY_FAST_PATH_PROBABILITY, compareAndSwap(object, markOffset(), unbiasedMark, biasedMark, MARK_WORD_LOCATION).equal(unbiasedMark))) { // Object is now biased to current thread -> done - traceObject(trace, "+lock{bias:acquired}", object); + traceObject(trace, "+lock{bias:acquired}", object, true); return; } // If the biasing toward our thread failed, this means that another thread // owns the bias and we need to revoke that bias. The revocation will occur // in the interpreter runtime. - traceObject(trace, "+lock{stub:revoke}", object); + traceObject(trace, "+lock{stub:revoke}", object, true); monitorenterStub(MONITORENTER, object, lock); return; } else { @@ -174,13 +193,13 @@ trace(trace, " biasedMark: 0x%016lx\n", biasedMark); if (probability(VERY_FAST_PATH_PROBABILITY, compareAndSwap(object, markOffset(), mark, biasedMark, MARK_WORD_LOCATION).equal(mark))) { // Object is now biased to current thread -> done - traceObject(trace, "+lock{bias:transfer}", object); + traceObject(trace, "+lock{bias:transfer}", object, true); return; } // If the biasing toward our thread failed, then another thread // succeeded in biasing it toward itself and we need to revoke that // bias. The revocation will occur in the runtime in the slow case. - traceObject(trace, "+lock{stub:epoch-expired}", object); + traceObject(trace, "+lock{stub:epoch-expired}", object, true); monitorenterStub(MONITORENTER, object, lock); return; } @@ -237,16 +256,16 @@ final Word stackPointer = stackPointer(); if (probability(VERY_SLOW_PATH_PROBABILITY, currentMark.subtract(stackPointer).and(alignedMask.subtract(pageSize())).notEqual(0))) { // Most likely not a recursive lock, go into a slow runtime call - traceObject(trace, "+lock{stub:failed-cas}", object); + traceObject(trace, "+lock{stub:failed-cas}", object, true); monitorenterStub(MONITORENTER, object, lock); return; } else { // Recursively locked => write 0 to the lock slot lock.writeWord(lockDisplacedMarkOffset(), Word.zero(), DISPLACED_MARK_WORD_LOCATION); - traceObject(trace, "+lock{recursive}", object); + traceObject(trace, "+lock{recursive}", object, true); } } else { - traceObject(trace, "+lock{cas}", object); + traceObject(trace, "+lock{cas}", object, true); } } @@ -263,7 +282,7 @@ // BeginLockScope nodes do not read from object so a use of object // cannot float about the null check above final Word lock = beginLockScope(lockDepth); - traceObject(trace, "+lock{stub}", object); + traceObject(trace, "+lock{stub}", object, true); monitorenterStub(MONITORENTER, object, lock); } @@ -282,7 +301,7 @@ if (probability(FREQUENT_PROBABILITY, mark.and(biasedLockMaskInPlace()).equal(Word.unsigned(biasedLockPattern())))) { endLockScope(); decCounter(); - traceObject(trace, "-lock{bias}", object); + traceObject(trace, "-lock{bias}", object, false); return; } } @@ -295,7 +314,7 @@ if (displacedMark.equal(0)) { // Recursive locking => done - traceObject(trace, "-lock{recursive}", object); + traceObject(trace, "-lock{recursive}", object, false); } else { verifyOop(object); // Test if object's mark word is pointing to the displaced mark word, and if so, restore @@ -304,10 +323,10 @@ if (probability(VERY_SLOW_PATH_PROBABILITY, DirectCompareAndSwapNode.compareAndSwap(object, markOffset(), lock, displacedMark, MARK_WORD_LOCATION).notEqual(lock))) { // The object's mark word was not pointing to the displaced header, // we do unlocking via runtime call. - traceObject(trace, "-lock{stub}", object); + traceObject(trace, "-lock{stub}", object, false); MonitorExitStubCall.call(object, lockDepth); } else { - traceObject(trace, "-lock{cas}", object); + traceObject(trace, "-lock{cas}", object, false); } } endLockScope(); @@ -320,13 +339,16 @@ @Snippet public static void monitorexitStub(Object object, @ConstantParameter int lockDepth, @ConstantParameter boolean trace) { verifyOop(object); - traceObject(trace, "-lock{stub}", object); + traceObject(trace, "-lock{stub}", object, false); MonitorExitStubCall.call(object, lockDepth); endLockScope(); decCounter(); } - private static void traceObject(boolean enabled, String action, Object object) { + private static void traceObject(boolean enabled, String action, Object object, boolean enter) { + if (doProfile(action)) { + DynamicCounterNode.counter(action, enter ? "~monitorenter" : "~monitorexit", 1, PROFILE_CONTEXT); + } if (enabled) { Log.print(action); Log.print(' '); diff -r 5501a34d43bb -r 8a201c64cd18 graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/replacements/NewObjectSnippets.java --- a/graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/replacements/NewObjectSnippets.java Wed Oct 02 15:04:04 2013 +0200 +++ b/graal/com.oracle.graal.hotspot/src/com/oracle/graal/hotspot/replacements/NewObjectSnippets.java Wed Oct 02 15:05:04 2013 +0200 @@ -34,17 +34,21 @@ import com.oracle.graal.api.code.*; import com.oracle.graal.api.meta.*; import com.oracle.graal.debug.*; +import com.oracle.graal.graph.*; import com.oracle.graal.graph.Node.ConstantNodeParameter; import com.oracle.graal.graph.Node.NodeIntrinsic; import com.oracle.graal.hotspot.meta.*; import com.oracle.graal.hotspot.nodes.*; import com.oracle.graal.nodes.*; +import com.oracle.graal.nodes.debug.*; import com.oracle.graal.nodes.extended.*; import com.oracle.graal.nodes.java.*; import com.oracle.graal.nodes.spi.*; import com.oracle.graal.nodes.type.*; +import com.oracle.graal.options.*; import com.oracle.graal.replacements.*; import com.oracle.graal.replacements.Snippet.ConstantParameter; +import com.oracle.graal.replacements.Snippet.Fold; import com.oracle.graal.replacements.Snippet.VarargsParameter; import com.oracle.graal.replacements.SnippetTemplate.AbstractTemplates; import com.oracle.graal.replacements.SnippetTemplate.Arguments; @@ -59,6 +63,20 @@ public static final LocationIdentity INIT_LOCATION = new NamedLocationIdentity("Initialization"); + public static class Options { + + //@formatter:off + @Option(help = "") + private static final OptionValue ProfileAllocations = new OptionValue<>(false); + //@formatter:on + } + + static enum ProfileMode { + AllocatingMethods, InstanceOrArray, AllocatedTypes, AllocatedTypesInMethods, Total + } + + public static final ProfileMode PROFILE_MODE = ProfileMode.Total; + @Snippet public static Word allocate(int size) { Word thread = thread(); @@ -76,8 +94,41 @@ return Word.zero(); } + @Fold + private static String createName(String path, String typeContext) { + switch (PROFILE_MODE) { + case AllocatingMethods: + return ""; + case InstanceOrArray: + return path; + case AllocatedTypes: + case AllocatedTypesInMethods: + return typeContext; + case Total: + return "bytes"; + default: + throw GraalInternalError.shouldNotReachHere(); + } + } + + @Fold + @SuppressWarnings("unused") + private static boolean doProfile(String path, String typeContext) { + return Options.ProfileAllocations.getValue(); + } + + private static void profileAllocation(String path, long size, String typeContext) { + if (doProfile(path, typeContext)) { + String name = createName(path, typeContext); + + boolean context = PROFILE_MODE == ProfileMode.AllocatingMethods || PROFILE_MODE == ProfileMode.AllocatedTypesInMethods; + DynamicCounterNode.counter(name, "~bytes", size, context); + DynamicCounterNode.counter(name, "~sites", 1, context); + } + } + @Snippet - public static Object allocateInstance(@ConstantParameter int size, Word hub, Word prototypeMarkWord, @ConstantParameter boolean fillContents) { + public static Object allocateInstance(@ConstantParameter int size, Word hub, Word prototypeMarkWord, @ConstantParameter boolean fillContents, @ConstantParameter String typeContext) { Object result; Word thread = thread(); Word top = readTlabTop(thread); @@ -90,6 +141,7 @@ new_stub.inc(); result = NewInstanceStubCall.call(hub); } + profileAllocation("instance", size, typeContext); return piCast(verifyOop(result), StampFactory.forNodeIntrinsic()); } @@ -99,15 +151,16 @@ public static final int MAX_ARRAY_FAST_PATH_ALLOCATION_LENGTH = 0x00FFFFFF; @Snippet - public static Object allocateArray(Word hub, int length, Word prototypeMarkWord, @ConstantParameter int headerSize, @ConstantParameter int log2ElementSize, @ConstantParameter boolean fillContents) { + public static Object allocateArray(Word hub, int length, Word prototypeMarkWord, @ConstantParameter int headerSize, @ConstantParameter int log2ElementSize, + @ConstantParameter boolean fillContents, @ConstantParameter String typeContext) { if (!belowThan(length, MAX_ARRAY_FAST_PATH_ALLOCATION_LENGTH)) { // This handles both negative array sizes and very large array sizes DeoptimizeNode.deopt(DeoptimizationAction.None, DeoptimizationReason.RuntimeConstraint); } - return allocateArrayImpl(hub, length, prototypeMarkWord, headerSize, log2ElementSize, fillContents); + return allocateArrayImpl(hub, length, prototypeMarkWord, headerSize, log2ElementSize, fillContents, typeContext); } - private static Object allocateArrayImpl(Word hub, int length, Word prototypeMarkWord, int headerSize, int log2ElementSize, boolean fillContents) { + private static Object allocateArrayImpl(Word hub, int length, Word prototypeMarkWord, int headerSize, int log2ElementSize, boolean fillContents, String typeContext) { Object result; int alignment = wordSize(); int allocationSize = computeArrayAllocationSize(length, alignment, headerSize, log2ElementSize); @@ -123,6 +176,7 @@ newarray_stub.inc(); result = NewArrayStubCall.call(hub, length); } + profileAllocation("array", allocationSize, typeContext); return piArrayCast(verifyOop(result), length, StampFactory.forNodeIntrinsic()); } @@ -156,7 +210,7 @@ int log2ElementSize = (layoutHelper >> layoutHelperLog2ElementSizeShift()) & layoutHelperLog2ElementSizeMask(); Word prototypeMarkWord = hub.readWord(prototypeMarkWordOffset(), PROTOTYPE_MARK_WORD_LOCATION); - return allocateArrayImpl(hub, length, prototypeMarkWord, headerSize, log2ElementSize, fillContents); + return allocateArrayImpl(hub, length, prototypeMarkWord, headerSize, log2ElementSize, fillContents, "dynamic type"); } /** @@ -261,6 +315,7 @@ args.add("hub", hub); args.add("prototypeMarkWord", type.prototypeMarkWord()); args.addConst("fillContents", newInstanceNode.fillContents()); + args.addConst("typeContext", MetaUtil.toJavaName(type, false)); SnippetTemplate template = template(args); Debug.log("Lowering allocateInstance in %s: node=%s, template=%s, arguments=%s", graph, newInstanceNode, template, args); @@ -286,6 +341,7 @@ args.addConst("headerSize", headerSize); args.addConst("log2ElementSize", log2ElementSize); args.addConst("fillContents", newArrayNode.fillContents()); + args.addConst("typeContext", MetaUtil.toJavaName(arrayType, false)); SnippetTemplate template = template(args); Debug.log("Lowering allocateArray in %s: node=%s, template=%s, arguments=%s", graph, newArrayNode, template, args);