Uncommon trap in OptimizedCallTarget::executeHelper

Tom Rodriguez tom.rodriguez at oracle.com
Thu Jan 16 10:27:02 PST 2014 

On Jan 16, 2014, at 8:15 AM, Stefan Marr <java at stefan-marr.de> wrote:

> Hi:
> 
> [First one of the main issues, will later send a more complete status update.]
> 
> I am currently encountering issues with invalidation of methods in a couple of scenarios, that I can’t track down.
> 
> One of them looks like this:
> 
> [truffle] optimized Method Vector>>#at::../som/Smalltalk//Vector.som:33 at 687080dc 726302d8 |Nodes      19 |Time     8(   6+3   )ms |Nodes   102/   83 |CodeSize 336
> Uncommon trap   bci=11 pc=301889326, relative_pc=270, method=executeGeneric, speculation=0
> Uncommon trap occurred in com.oracle.graal.truffle.OptimizedCallTarget::executeHelper (Graal: installedCodeName=HotSpotMethod<OptimizedCallTarget.executeHelper(PackedFrame, Arguments)>)  (@0x0000000111fe772e) thread=6403 reason=null_assert|unreached0 action=reinterpret unloaded_class_index=-1 speculation=0
> [truffle] invalidated Method Vector>>#at::../som/Smalltalk//Vector.som:33 at 687080dc |Inv# 3161                                     |Replace# 8
> 
> The first odd thing is that the method name is executeGeneric, but then the line after refers to executeHelper in OptimizedCallTarget.

The first message is the method and bci of an inlined method which is the actual trap point.  executeHelper is the root of the compilation.  The first message probably should be printing the class name in addition the method name.  You can get more detail from the VM itself using -XX:+UnlockDiagnosticVMOptions -XX:+LogCompilation.  This caused hotspot to dump an xml log of compiler related events.  For an uncommon trap you’ll get output that shows the full inline path of the trap point, like this:

<uncommon_trap thread='6403' reason='bimorphic|optimized_type_check' action='make_not_entrant' speculation='0' compile_id='793' compiler='Graal' stamp='40.499'>
<jvms bci='27' method='com/oracle/graal/graph/NodeClass$NodeClassIterator nextElement ()Lcom/oracle/graal/graph/Node;' bytes='74' count='4430' backedge_count='1' iicount='2066146'/>
<jvms bci='1' method='com/oracle/graal/graph/NodeClass$NodeClassIterator next ()Lcom/oracle/graal/graph/Node;' bytes='18' count='3721' backedge_count='1' iicount='2089650'/>
<jvms bci='1' method='com/oracle/graal/graph/NodeClass$NodeClassSuccessorsWithModCountIterator next ()Lcom/oracle/graal/graph/Node;' bytes='70' count='7404' backedge_count='1' iicount='645736'/>
<jvms bci='1' method='com/oracle/graal/graph/NodeClass$NodeClassIterator next ()Ljava/lang/Object;' bytes='5' count='3926' backedge_count='1' iicount='2314754'/>
<jvms bci='102' method='com/oracle/graal/phases/graph/PostOrderNodeIterator queueSuccessors (Lcom/oracle/graal/nodes/FixedNode;Ljava/util/Set;)V' bytes='139' count='5000' backedge_count='5002' iicount='326580'/>
</uncommon_trap>

The log ends up in hotspot_pid%p.log where %p is the pid of the hotspot process.  Hopefully this will provide enough crumbs to at least figure out where the trap is occurring.

tom

> 
> Based on the output [1], I was trying to find an executeGeneric method, were the bytecode index 11 could give any clues, but I didn’t see anything useful, i.e., depending on a null_assert (which, I interpreted as being anything accessing an object).
> 
> Are there any ways to get more information about such invalidations?
> I also got other cases, the trees are stable, but something still causes invalidations. And, I am mostly guessing around to figure out what the case could be.
> 
> In the particular case, a non-local return is involved, which is implemented using a control flow exception that’s fought in the CatchNonLocalReturnNode.
> When I change the SOM code to avoid a non-local return, but keeping the rest the same, I don’t run into this particular issue.
> So, I assume, it is somehow related to this node, or the exception throwing. 
> The TruffleSOM repository contains a corresponding micro benchmark. [2]
> 
> 
> 
> 
> 
> Another, more academic issue for the moment, is a problem with the classic SlopStone Smalltalk benchmarks.
> The program never finishes, and profiling/debugging indicates that at least one of the reasons is the node count visitor.
> 
> Imagine a method like this:
> 
>    1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+
>    1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+
>    1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+
>    1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+
>    1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+
>    1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1+1
> 
> That’s a pretty pathological case, causing hundreds of nodes being visited quite a number of times.
> Would it make sense to cache the AST tree size. I know, that’ll require not very trivial update logic, but perhaps, it’s worth it?
> 
> 
> Thanks
> Stefan
> 
> [1] OptimizedCallTarget.executeHelper(OptimizedCallTarget.java:213)
>  (OptimizedCallTarget.java:214) Method.execute(Method.java:67)
>    (Method.java:67) ArgumentInitializationNode.executeGeneric(ArgumentInitializationNode.java:24)
>      (ArgumentInitializationNode.java:25) LocalVariableWriteObjectNode.executeGeneric(LocalVariableNodeFactory.java:504)
>        (LocalVariableNodeFactory.java:504) ArgumentReadNode.executeGeneric(ArgumentReadNode.java:20)
>      (ArgumentInitializationNode.java:25) LocalVariableWriteObjectNode.executeGeneric(LocalVariableNodeFactory.java:504)
>        (LocalVariableNodeFactory.java:504) ArgumentReadNode.executeGeneric(ArgumentReadNode.java:20)
>      (ArgumentInitializationNode.java:27) CatchNonLocalReturnNode.executeGeneric(ReturnNonLocalNode.java:120)
>        (ReturnNonLocalNode.java:128) SequenceNode.executeGeneric(SequenceNode.java:37)
>          (SequenceNode.java:37) TernarySendNode<CachedSendNode>.executeGeneric(TernarySendNode.java:67)
>            (TernarySendNode.java:67) LocalVariableReadObjectNode.executeGeneric(LocalVariableNodeFactory.java:193)
>            (TernarySendNode.java:67) SObjectCheckNode.execute(ClassCheckNode.java:161)
>            (TernarySendNode.java:68) LocalVariableReadObjectNode.executeGeneric(LocalVariableNodeFactory.java:193)
>            (TernarySendNode.java:69) InlinableSendNode.executeEvaluated(TernarySendNode.java:250)
>            (TernarySendNode.java:69) BlockNode<BlockNodeWithContext>.executeGeneric(BlockNode.java:29)
>              (BlockNode.java) Universe.newBlock(Universe.java:413)
>            (TernarySendNode.java:70) UninitializedSendNode.executeEvaluated(TernarySendNode.java:129)
>          (SequenceNode.java:40) UninitializedVariableReadNode.executeGeneric(UninitializedVariableNode.java:50)
> 
> 
> [2]
> 
> git clone --recursive https://github.com/smarr/TruffleSOM.git som
> cd som
> ant jar
> cd ../graal
> ./mx.sh --vm server vm -G:+TraceTruffleExpansion -G:+TraceTruffleExpansionSource -XX:+TraceDeoptimization -G:-TruffleBackgroundCompilation -G:+TraceTruffleCompilationDetails -Xbootclasspath/a:../som/build/classes:../som/libs/truffle.jar som.vm.Universe -cp ../som/Smalltalk ../som/Examples/Benchmarks/BenchmarkHarness.som WhileLoopVAt 10 10 6000
> 
> -- 
> Stefan Marr
> INRIA Lille - Nord Europe
> http://stefan-marr.de/research/
> 
> 
>

More information about the graal-dev mailing list