Deopt loop reported for TruffleStringFactory$EqualNodeGen.execute

Open eregon opened this issue 2 months ago • 5 comments

Describe GraalVM and your environment :

GraalVM version or commit id if built from source: bca835cac2d1fa985dfd21a4ecdbf89fe86315ed
CE or EE: CE
JDK version: labsjdk-ce-latest-25+37-jvmci-b02
OS and OS Version: Linux
Architecture: amd64
The output of java -Xinternalversion:

OpenJDK 64-Bit Server VM (25+37-jvmci-b02) for linux-amd64 JRE (25+37-jvmci-b02), built on 2025-09-17T09:50:12Z with gcc 14.2.0

Have you verified this issue still happens when using the latest snapshot? Yes, I tried with latest master (8ad5cf768bd8f6e661e2e51b197ddc95b9fbfe31) and it still reproduces.

Describe the issue

[engine] opt deopt  engine=1  id=1601  Kernel#require_relative                            |Invalidated  true|                                                                                                            |UTC 2025-10-03T12:01:57.845|Src resource:/truffleruby/core/kernel.rb:282 0xc8a7880e
[engine] opt failed engine=1  id=1601  Kernel#require_relative                            |Tier 2|Time   275( 171+105 )ms|Reason: jdk.graal.compiler.code.SourceStackTraceBailoutException$1: Deopt taken too many times. Deopt Node: 5493|Deopt. This could indicate a deopt cycle, which typically hints at a bug in the language implementation or Truffle.|UTC 2025-10-03T12:01:58.121|Src resource:/truffleruby/core/kernel.rb:282 0xc8a7880e
[[[Graal compilation failure]]]
Thread[#1405,System-1345,5,main]: Compilation of Isolated: Kernel#require_relative failed:
jdk.graal.compiler.code.SourceStackTraceBailoutException$1: Deopt taken too many times. Deopt Node: 5493|Deopt. This could indicate a deopt cycle, which typically hints at a bug in the language implementation or Truffle.
	at com.oracle.truffle.api.strings.TruffleStringFactory$EqualNodeGen.execute(TruffleStringFactory.java:5468)
	at org.truffleruby.core.string.StringHelperNodes$StringEqualInternalNode.equalBytes(StringHelperNodes.java:166)
	at org.truffleruby.core.string.StringHelperNodesFactory$StringEqualInternalNodeGen$Inlined.executeInternal(StringHelperNodesFactory.java:409)
	at org.truffleruby.core.string.StringHelperNodes$EqualNode.equal(StringHelperNodes.java:118)
	at org.truffleruby.core.string.StringHelperNodesFactory$EqualNodeGen.execute(StringHelperNodesFactory.java:208)
	at org.truffleruby.core.string.RubyStringGen$InteropLibraryExports$Cached.asString(RubyStringGen.java:179)
	at org.truffleruby.interop.ToJavaStringNode.interopString(ToJavaStringNode.java:37)
	at org.truffleruby.interop.ToJavaStringNodeGen$Inlined.execute(ToJavaStringNodeGen.java:116)
	at org.truffleruby.core.kernel.KernelNodes$FindFileNode.findFile(KernelNodes.java:254)
	at org.truffleruby.core.kernel.KernelNodesFactory$FindFileNodeFactory$FindFileNodeGen.execute(KernelNodesFactory.java:772)
	at org.truffleruby.language.control.SequenceNode.execute(SequenceNode.java:35)
	at org.truffleruby.language.RubyMethodRootNode.execute(RubyMethodRootNode.java:65)
	at com.oracle.truffle.runtime.OptimizedCallTarget.executeRootNode(OptimizedCallTarget.java:834)
	at com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(OptimizedCallTarget.java:630)
	at com.oracle.truffle.runtime.OptimizedDirectCallNode.call(OptimizedDirectCallNode.java:94)
	at org.truffleruby.language.methods.CallInternalMethodNode.callCached(CallInternalMethodNode.java:66)
	at org.truffleruby.language.methods.CallInternalMethodNodeGen.execute(CallInternalMethodNodeGen.java:104)
	at org.truffleruby.language.dispatch.DispatchNode.dispatch(DispatchNode.java:300)
	at org.truffleruby.language.dispatch.DispatchNodeGen.execute(DispatchNodeGen.java:148)
	at org.truffleruby.language.dispatch.RubyCallNode.doCall(RubyCallNode.java:186)
	at org.truffleruby.language.dispatch.RubyCallNode.execute(RubyCallNode.java:138)
	at org.truffleruby.language.locals.WriteLocalVariableNode.execute(WriteLocalVariableNode.java:28)
	at org.truffleruby.language.RubyContextSourceNode.executeVoid(RubyContextSourceNode.java:23)
	at org.truffleruby.language.control.SequenceNode.execute(SequenceNode.java:32)
	at org.truffleruby.language.RubyMethodRootNode.execute(RubyMethodRootNode.java:65)
	at com.oracle.truffle.runtime.OptimizedCallTarget.executeRootNode(OptimizedCallTarget.java:834)
	at com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(OptimizedCallTarget.java:630)
	at com.oracle.truffle.runtime.OptimizedDirectCallNode.call(OptimizedDirectCallNode.java:94)
	at org.truffleruby.language.methods.CallInternalMethodNode.callCached(CallInternalMethodNode.java:66)
	at org.truffleruby.language.methods.CallInternalMethodNodeGen.execute(CallInternalMethodNodeGen.java:104)
	at org.truffleruby.language.dispatch.DispatchNode.dispatch(DispatchNode.java:300)
	at org.truffleruby.language.dispatch.DispatchNodeGen.execute(DispatchNodeGen.java:148)
	at org.truffleruby.language.dispatch.RubyCallNode.doCall(RubyCallNode.java:186)
	at org.truffleruby.language.dispatch.RubyCallNode.execute(RubyCallNode.java:138)
	at org.truffleruby.core.array.MultipleAssignmentNode.execute(MultipleAssignmentNode.java:67)
	at org.truffleruby.language.RubyContextSourceNode.executeVoid(RubyContextSourceNode.java:23)
	at org.truffleruby.language.control.SequenceNode.execute(SequenceNode.java:32)
	at org.truffleruby.language.RubyMethodRootNode.execute(RubyMethodRootNode.java:65)
	at com.oracle.truffle.runtime.OptimizedCallTarget.executeRootNode(OptimizedCallTarget.java:834)
	at com.oracle.truffle.runtime.OptimizedCallTarget.profiledPERoot(OptimizedCallTarget.java:758)
Options: {AutomaticReferenceHandling=false, CompilationExpirationPeriod=100.0, DoNotMoveAllocationsWithOOMEHandlers=false, DumpPath=/home/eregon/code/trws/truffleruby/graal_dumps/2025.10.03.14.01.29.413, EnableSignalHandling=false, InstallSegfaultHandler=false, UsePerfData=false, compiler.DiagnoseFailure=true, compiler.TreatPerformanceWarningsAsErrors=PerformanceWarnings[kinds=[FRAME_INCOMPATIBLE_MERGE, TRIVIAL_FAIL, VIRTUAL_INSTANCEOF, VIRTUAL_RUNTIME_CALL, VIRTUAL_STORE]]}
If in an environment where setting system properties is possible, the following
properties are available to change compilation failure reporting:
- To disable compilation failure notifications, set CompilationFailureAction to Silent (e.g., -Djdk.graal.CompilationFailureAction=Silent).
- To print a message for a compilation failure without retrying the compilation, set CompilationFailureAction to Print (e.g., -Djdk.graal.CompilationFailureAction=Print).
Retrying compilation of Isolated: Kernel#require_relative
Dumping IGV graphs in /home/eregon/code/trws/truffleruby/graal_dumps/2025.10.03.14.01.29.413/graal_diagnostics_80571@1/Isolated:_Kernel#require_relative
[engine] opt failed engine=1  id=1601  Kernel#require_relative                            |Tier 2|Time 107142(79975+27168)ms|Reason: jdk.graal.compiler.core.common.PermanentBailoutException: Compilation exceeded 100.000 seconds (GC time is 50177 ms of 105939 ms elapsed). 
 Phase timings:
<see below for Phase timings>

Looking at the stacktrace it doesn't seem likely that that identify check can cause a deopt loop. The code generated by the DSL looks OK at first glance.

Code snippet or code repository that reproduces the issue https://github.com/truffleruby/truffleruby

Steps to reproduce the issue

git clone [email protected]:truffleruby/truffleruby.git
cd truffleruby
git checkout 2267c479baf44aab7e823163f61ed7861c33f491
# (or b1fb52eaa7045ac3d69e7b8fb5c78a6d8168f7ec to use latest graal)
bin/jt build --env native --extra-image-builder-argument=-H:+IncludeNodeSourcePositions
bin/jt -u native test compiler compile-immediately

It seems to reproduces fairly reliably, >50% of the time, in GitHub Actions and locally. One to the local build didn't seem to repro with a few tries, so it can be worth to rebuild the image if it doesn't repro. Though on GitHub it has both passed and failed with the same built image.

Looking at https://github.com/truffleruby/truffleruby/commits/master the first time it failed is on https://github.com/truffleruby/truffleruby/commits/master/ and very frequent since then. So maybe there is a bug in that change from 26.0 to 25.1, or some version check somewhere still checking against 26?

Expected behavior No deopt loop.

Additional context

The recompilation fails with a timeout, which seems a separate bug:

Details

Options: {AutomaticReferenceHandling=false, CompilationExpirationPeriod=100.0, DoNotMoveAllocationsWithOOMEHandlers=false, DumpPath=/home/eregon/code/trws/truffleruby/graal_dumps/2025.10.03.14.01.29.413, EnableSignalHandling=false, InstallSegfaultHandler=false, UsePerfData=false, compiler.DiagnoseFailure=true, compiler.TreatPerformanceWarningsAsErrors=PerformanceWarnings[kinds=[FRAME_INCOMPATIBLE_MERGE, TRIVIAL_FAIL, VIRTUAL_INSTANCEOF, VIRTUAL_RUNTIME_CALL, VIRTUAL_STORE]]}
If in an environment where setting system properties is possible, the following
properties are available to change compilation failure reporting:
- To disable compilation failure notifications, set CompilationFailureAction to Silent (e.g., -Djdk.graal.CompilationFailureAction=Silent).
- To print a message for a compilation failure without retrying the compilation, set CompilationFailureAction to Print (e.g., -Djdk.graal.CompilationFailureAction=Print).
Retrying compilation of Isolated: Kernel#require_relative
Dumping IGV graphs in /home/eregon/code/trws/truffleruby/graal_dumps/2025.10.03.14.01.29.413/graal_diagnostics_80571@1/Isolated:_Kernel#require_relative
[engine] opt failed engine=1  id=1601  Kernel#require_relative                            |Tier 2|Time 107142(79975+27168)ms|Reason: jdk.graal.compiler.core.common.PermanentBailoutException: Compilation exceeded 100.000 seconds (GC time is 50177 ms of 105939 ms elapsed). 
 Phase timings:
 Root -> com.oracle.truffle.runtime.OptimizedCallTarget.profiledPERoot(Object[])->105939ms elapsed [startMS=0] graphSizeBefore->After=[0->0]
	TruffleTier->78772ms elapsed [startMS=10967815] graphSizeBefore->After=[1->5429]
		AgnosticInliningPhase->50903ms elapsed [startMS=10967815] graphSizeBefore->After=[1->5430]
			SubstratePostPartialEvaluationSuite->41ms elapsed [startMS=10967859] graphSizeBefore->After=[1152->376]
				InsertProxyPhase->3ms elapsed [startMS=10967859] graphSizeBefore->After=[1152->1152]
				ConvertDeoptimizeToGuardPhase->11ms elapsed [startMS=10967862] graphSizeBefore->After=[1152->973]
					DeadCodeEliminationPhase->2ms elapsed [startMS=10967866] graphSizeBefore->After=[1015->1015]
					IncrementalCanonicalizerPhase->2ms elapsed [startMS=10967868] graphSizeBefore->After=[1015->973]
				PostPartialEvaluationSuite$InlineReplacementsPhase->2ms elapsed [startMS=10967874] graphSizeBefore->After=[973->973]
				CanonicalizerPhase->2ms elapsed [startMS=10967876] graphSizeBefore->After=[973->671]
				ConditionalEliminationPhase->5ms elapsed [startMS=10967879] graphSizeBefore->After=[671->625]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10967881] graphSizeBefore->After=[640->625]
				FrameAccessVerificationPhase->1ms elapsed [startMS=10967885] graphSizeBefore->After=[625->625]
				PartialEscapePhase->9ms elapsed [startMS=10967886] graphSizeBefore->After=[625->376]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10967886] graphSizeBefore->After=[625->625]
					DeadCodeEliminationPhase->1ms elapsed [startMS=10967891] graphSizeBefore->After=[633->405]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10967892] graphSizeBefore->After=[405->405]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10967893] graphSizeBefore->After=[405->376]
				PhiTransformPhase->2ms elapsed [startMS=10967895] graphSizeBefore->After=[376->376]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10967895] graphSizeBefore->After=[376->376]
				DeadStoreRemovalPhase->1ms elapsed [startMS=10967897] graphSizeBefore->After=[376->376]
				TruffleBoundaryPhase->1ms elapsed [startMS=10967898] graphSizeBefore->After=[376->376]
			IntermediateRoot -> com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(Node, Object[])->4ms elapsed [startMS=10967909] graphSizeBefore->After=[0->0]
				SubstratePostPartialEvaluationSuite->4ms elapsed [startMS=10967909] graphSizeBefore->After=[110->31]
					ConvertDeoptimizeToGuardPhase->1ms elapsed [startMS=10967909] graphSizeBefore->After=[110->42]
					PartialEscapePhase->1ms elapsed [startMS=10967911] graphSizeBefore->After=[33->31]
			SubstratePostPartialEvaluationSuite->25ms elapsed [startMS=10968017] graphSizeBefore->After=[718->302]
				InsertProxyPhase->1ms elapsed [startMS=10968017] graphSizeBefore->After=[718->718]
				ConvertDeoptimizeToGuardPhase->5ms elapsed [startMS=10968018] graphSizeBefore->After=[718->540]
					DeadCodeEliminationPhase->1ms elapsed [startMS=10968020] graphSizeBefore->After=[615->615]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968021] graphSizeBefore->After=[615->540]
				PostPartialEvaluationSuite$InlineReplacementsPhase->1ms elapsed [startMS=10968024] graphSizeBefore->After=[540->540]
				CanonicalizerPhase->1ms elapsed [startMS=10968025] graphSizeBefore->After=[540->421]
				ConditionalEliminationPhase->3ms elapsed [startMS=10968027] graphSizeBefore->After=[421->419]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968028] graphSizeBefore->After=[419->419]
				FrameAccessVerificationPhase->1ms elapsed [startMS=10968030] graphSizeBefore->After=[419->419]
				PartialEscapePhase->6ms elapsed [startMS=10968031] graphSizeBefore->After=[419->302]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968031] graphSizeBefore->After=[419->419]
					DeadCodeEliminationPhase->1ms elapsed [startMS=10968034] graphSizeBefore->After=[424->331]
				PhiTransformPhase->1ms elapsed [startMS=10968038] graphSizeBefore->After=[302->302]
			IntermediateRoot -> com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(Node, Object[])->75ms elapsed [startMS=10968120] graphSizeBefore->After=[0->0]
				SubstratePostPartialEvaluationSuite->75ms elapsed [startMS=10968120] graphSizeBefore->After=[1744->545]
					InsertProxyPhase->3ms elapsed [startMS=10968120] graphSizeBefore->After=[1744->1744]
					ConvertDeoptimizeToGuardPhase->14ms elapsed [startMS=10968124] graphSizeBefore->After=[1744->1335]
						DeadCodeEliminationPhase->3ms elapsed [startMS=10968128] graphSizeBefore->After=[1540->1540]
						IncrementalCanonicalizerPhase->3ms elapsed [startMS=10968131] graphSizeBefore->After=[1540->1335]
					PostPartialEvaluationSuite$InlineReplacementsPhase->3ms elapsed [startMS=10968138] graphSizeBefore->After=[1335->1335]
					CanonicalizerPhase->3ms elapsed [startMS=10968141] graphSizeBefore->After=[1335->1020]
					ConditionalEliminationPhase->8ms elapsed [startMS=10968144] graphSizeBefore->After=[1020->1014]
						IncrementalCanonicalizerPhase->2ms elapsed [startMS=10968147] graphSizeBefore->After=[1016->1014]
					FrameAccessVerificationPhase->2ms elapsed [startMS=10968152] graphSizeBefore->After=[1014->1015]
					PartialEscapePhase->17ms elapsed [startMS=10968155] graphSizeBefore->After=[1015->545]
						IncrementalCanonicalizerPhase->2ms elapsed [startMS=10968155] graphSizeBefore->After=[1015->1015]
						DeadCodeEliminationPhase->3ms elapsed [startMS=10968163] graphSizeBefore->After=[973->624]
						IncrementalCanonicalizerPhase->2ms elapsed [startMS=10968166] graphSizeBefore->After=[624->624]
						IncrementalCanonicalizerPhase->2ms elapsed [startMS=10968169] graphSizeBefore->After=[624->545]
					PhiTransformPhase->17ms elapsed [startMS=10968173] graphSizeBefore->After=[545->545]
						IncrementalCanonicalizerPhase->16ms elapsed [startMS=10968173] graphSizeBefore->After=[545->545]
					DeadStoreRemovalPhase->1ms elapsed [startMS=10968191] graphSizeBefore->After=[545->545]
					TruffleBoundaryPhase->1ms elapsed [startMS=10968192] graphSizeBefore->After=[545->545]
			SubstratePostPartialEvaluationSuite->31ms elapsed [startMS=10968242] graphSizeBefore->After=[970->368]
				InsertProxyPhase->1ms elapsed [startMS=10968242] graphSizeBefore->After=[970->970]
				ConvertDeoptimizeToGuardPhase->7ms elapsed [startMS=10968244] graphSizeBefore->After=[970->736]
					DeadCodeEliminationPhase->1ms elapsed [startMS=10968247] graphSizeBefore->After=[851->851]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968248] graphSizeBefore->After=[851->736]
				PostPartialEvaluationSuite$InlineReplacementsPhase->1ms elapsed [startMS=10968252] graphSizeBefore->After=[736->736]
				CanonicalizerPhase->1ms elapsed [startMS=10968253] graphSizeBefore->After=[736->548]
				ConditionalEliminationPhase->4ms elapsed [startMS=10968255] graphSizeBefore->After=[548->545]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968257] graphSizeBefore->After=[545->545]
				FrameAccessVerificationPhase->1ms elapsed [startMS=10968260] graphSizeBefore->After=[545->545]
				PartialEscapePhase->8ms elapsed [startMS=10968261] graphSizeBefore->After=[545->368]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968261] graphSizeBefore->After=[545->545]
					DeadCodeEliminationPhase->1ms elapsed [startMS=10968265] graphSizeBefore->After=[548->408]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968266] graphSizeBefore->After=[408->408]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968267] graphSizeBefore->After=[408->368]
				PhiTransformPhase->2ms elapsed [startMS=10968269] graphSizeBefore->After=[368->368]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968269] graphSizeBefore->After=[368->368]
				DeadStoreRemovalPhase->1ms elapsed [startMS=10968271] graphSizeBefore->After=[368->368]
				TruffleBoundaryPhase->1ms elapsed [startMS=10968272] graphSizeBefore->After=[368->368]
			IntermediateRoot -> com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(Node, Object[])->4ms elapsed [startMS=10968277] graphSizeBefore->After=[0->0]
				SubstratePostPartialEvaluationSuite->4ms elapsed [startMS=10968277] graphSizeBefore->After=[100->30]
					PartialEscapePhase->1ms elapsed [startMS=10968280] graphSizeBefore->After=[32->30]
			SubstratePostPartialEvaluationSuite->48ms elapsed [startMS=10968312] graphSizeBefore->After=[908->228]
				InsertProxyPhase->2ms elapsed [startMS=10968312] graphSizeBefore->After=[908->908]
				ConvertDeoptimizeToGuardPhase->7ms elapsed [startMS=10968314] graphSizeBefore->After=[908->734]
					DeadCodeEliminationPhase->1ms elapsed [startMS=10968316] graphSizeBefore->After=[790->790]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968318] graphSizeBefore->After=[790->734]
				PostPartialEvaluationSuite$InlineReplacementsPhase->1ms elapsed [startMS=10968322] graphSizeBefore->After=[734->734]
				CanonicalizerPhase->1ms elapsed [startMS=10968324] graphSizeBefore->After=[734->581]
				ConditionalEliminationPhase->5ms elapsed [startMS=10968325] graphSizeBefore->After=[581->577]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968327] graphSizeBefore->After=[577->577]
				FrameAccessVerificationPhase->2ms elapsed [startMS=10968331] graphSizeBefore->After=[577->577]
				PartialEscapePhase->23ms elapsed [startMS=10968333] graphSizeBefore->After=[577->228]
					IncrementalCanonicalizerPhase->2ms elapsed [startMS=10968333] graphSizeBefore->After=[577->577]
					DeadCodeEliminationPhase->1ms elapsed [startMS=10968338] graphSizeBefore->After=[576->265]
					IncrementalCanonicalizerPhase->14ms elapsed [startMS=10968340] graphSizeBefore->After=[265->265]
				PhiTransformPhase->1ms elapsed [startMS=10968356] graphSizeBefore->After=[228->228]
			IntermediateRoot -> com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(Node, Object[])->38ms elapsed [startMS=10968403] graphSizeBefore->After=[0->0]
				SubstratePostPartialEvaluationSuite->38ms elapsed [startMS=10968403] graphSizeBefore->After=[1094->462]
					InsertProxyPhase->2ms elapsed [startMS=10968403] graphSizeBefore->After=[1094->1094]
					ConvertDeoptimizeToGuardPhase->8ms elapsed [startMS=10968405] graphSizeBefore->After=[1094->906]
						DeadCodeEliminationPhase->2ms elapsed [startMS=10968408] graphSizeBefore->After=[979->979]
						IncrementalCanonicalizerPhase->2ms elapsed [startMS=10968410] graphSizeBefore->After=[979->906]
					PostPartialEvaluationSuite$InlineReplacementsPhase->2ms elapsed [startMS=10968414] graphSizeBefore->After=[906->906]
					CanonicalizerPhase->2ms elapsed [startMS=10968416] graphSizeBefore->After=[906->686]
					ConditionalEliminationPhase->5ms elapsed [startMS=10968418] graphSizeBefore->After=[686->653]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968420] graphSizeBefore->After=[679->653]
					FrameAccessVerificationPhase->1ms elapsed [startMS=10968423] graphSizeBefore->After=[653->653]
					PartialEscapePhase->10ms elapsed [startMS=10968425] graphSizeBefore->After=[653->462]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968425] graphSizeBefore->After=[653->653]
						DeadCodeEliminationPhase->1ms elapsed [startMS=10968429] graphSizeBefore->After=[654->564]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968431] graphSizeBefore->After=[564->564]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968432] graphSizeBefore->After=[564->462]
					PhiTransformPhase->2ms elapsed [startMS=10968435] graphSizeBefore->After=[462->462]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968435] graphSizeBefore->After=[462->462]
					DeadStoreRemovalPhase->1ms elapsed [startMS=10968437] graphSizeBefore->After=[462->462]
					TruffleBoundaryPhase->1ms elapsed [startMS=10968438] graphSizeBefore->After=[462->462]
			SubstratePostPartialEvaluationSuite->48ms elapsed [startMS=10968484] graphSizeBefore->After=[861->332]
				InsertProxyPhase->2ms elapsed [startMS=10968484] graphSizeBefore->After=[861->861]
				ConvertDeoptimizeToGuardPhase->8ms elapsed [startMS=10968486] graphSizeBefore->After=[861->730]
					DeadCodeEliminationPhase->2ms elapsed [startMS=10968489] graphSizeBefore->After=[778->778]
					IncrementalCanonicalizerPhase->2ms elapsed [startMS=10968491] graphSizeBefore->After=[778->730]
				PostPartialEvaluationSuite$InlineReplacementsPhase->1ms elapsed [startMS=10968495] graphSizeBefore->After=[730->730]
				CanonicalizerPhase->1ms elapsed [startMS=10968497] graphSizeBefore->After=[730->441]
				ConditionalEliminationPhase->3ms elapsed [startMS=10968499] graphSizeBefore->After=[441->422]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968500] graphSizeBefore->After=[438->422]
				FrameAccessVerificationPhase->1ms elapsed [startMS=10968503] graphSizeBefore->After=[422->422]
				PartialEscapePhase->23ms elapsed [startMS=10968504] graphSizeBefore->After=[422->332]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968504] graphSizeBefore->After=[422->422]
					DeadCodeEliminationPhase->1ms elapsed [startMS=10968508] graphSizeBefore->After=[434->351]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968510] graphSizeBefore->After=[351->351]
					IncrementalCanonicalizerPhase->14ms elapsed [startMS=10968512] graphSizeBefore->After=[351->332]
				PhiTransformPhase->1ms elapsed [startMS=10968527] graphSizeBefore->After=[332->332]
			IntermediateRoot -> com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(Node, Object[])->4ms elapsed [startMS=10968535] graphSizeBefore->After=[0->0]
				SubstratePostPartialEvaluationSuite->4ms elapsed [startMS=10968535] graphSizeBefore->After=[90->29]
					ConvertDeoptimizeToGuardPhase->1ms elapsed [startMS=10968535] graphSizeBefore->After=[90->34]
			SubstratePostPartialEvaluationSuite->8ms elapsed [startMS=10968543] graphSizeBefore->After=[141->86]
				ConvertDeoptimizeToGuardPhase->1ms elapsed [startMS=10968543] graphSizeBefore->After=[141->109]
				PartialEscapePhase->2ms elapsed [startMS=10968547] graphSizeBefore->After=[101->86]
			IntermediateRoot -> com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(Node, Object[])->26ms elapsed [startMS=10968573] graphSizeBefore->After=[0->0]
				SubstratePostPartialEvaluationSuite->26ms elapsed [startMS=10968573] graphSizeBefore->After=[647->272]
					InsertProxyPhase->1ms elapsed [startMS=10968573] graphSizeBefore->After=[647->647]
					ConvertDeoptimizeToGuardPhase->6ms elapsed [startMS=10968575] graphSizeBefore->After=[647->495]
						DeadCodeEliminationPhase->1ms elapsed [startMS=10968577] graphSizeBefore->After=[546->546]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968578] graphSizeBefore->After=[546->495]
					PostPartialEvaluationSuite$InlineReplacementsPhase->1ms elapsed [startMS=10968581] graphSizeBefore->After=[495->495]
					CanonicalizerPhase->1ms elapsed [startMS=10968582] graphSizeBefore->After=[495->402]
					ConditionalEliminationPhase->3ms elapsed [startMS=10968584] graphSizeBefore->After=[402->367]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968585] graphSizeBefore->After=[385->367]
					FrameAccessVerificationPhase->1ms elapsed [startMS=10968587] graphSizeBefore->After=[367->367]
					PartialEscapePhase->6ms elapsed [startMS=10968589] graphSizeBefore->After=[367->272]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968589] graphSizeBefore->After=[367->367]
						DeadCodeEliminationPhase->1ms elapsed [startMS=10968591] graphSizeBefore->After=[376->284]
					PhiTransformPhase->1ms elapsed [startMS=10968596] graphSizeBefore->After=[272->272]
			SubstratePostPartialEvaluationSuite->53ms elapsed [startMS=10968641] graphSizeBefore->After=[1085->515]
				InsertProxyPhase->2ms elapsed [startMS=10968641] graphSizeBefore->After=[1085->1085]
				ConvertDeoptimizeToGuardPhase->8ms elapsed [startMS=10968643] graphSizeBefore->After=[1085->892]
					DeadCodeEliminationPhase->2ms elapsed [startMS=10968646] graphSizeBefore->After=[967->967]
					IncrementalCanonicalizerPhase->2ms elapsed [startMS=10968648] graphSizeBefore->After=[967->892]
				PostPartialEvaluationSuite$InlineReplacementsPhase->2ms elapsed [startMS=10968652] graphSizeBefore->After=[892->892]
				CanonicalizerPhase->3ms elapsed [startMS=10968655] graphSizeBefore->After=[892->643]
				ConditionalEliminationPhase->18ms elapsed [startMS=10968658] graphSizeBefore->After=[643->632]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968672] graphSizeBefore->After=[637->632]
				FrameAccessVerificationPhase->1ms elapsed [startMS=10968676] graphSizeBefore->After=[632->632]
				PartialEscapePhase->10ms elapsed [startMS=10968677] graphSizeBefore->After=[632->515]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968677] graphSizeBefore->After=[632->632]
					DeadCodeEliminationPhase->1ms elapsed [startMS=10968681] graphSizeBefore->After=[633->548]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968683] graphSizeBefore->After=[548->548]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968685] graphSizeBefore->After=[548->515]
				PhiTransformPhase->2ms elapsed [startMS=10968687] graphSizeBefore->After=[515->515]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968687] graphSizeBefore->After=[515->515]
				DeadStoreRemovalPhase->1ms elapsed [startMS=10968690] graphSizeBefore->After=[515->515]
				TruffleBoundaryPhase->1ms elapsed [startMS=10968692] graphSizeBefore->After=[515->515]
			IntermediateRoot -> com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(Node, Object[])->5ms elapsed [startMS=10968698] graphSizeBefore->After=[0->0]
				SubstratePostPartialEvaluationSuite->5ms elapsed [startMS=10968698] graphSizeBefore->After=[81->21]
					ConvertDeoptimizeToGuardPhase->1ms elapsed [startMS=10968698] graphSizeBefore->After=[81->27]
			SubstratePostPartialEvaluationSuite->23ms elapsed [startMS=10968732] graphSizeBefore->After=[675->95]
				InsertProxyPhase->1ms elapsed [startMS=10968732] graphSizeBefore->After=[675->675]
				ConvertDeoptimizeToGuardPhase->6ms elapsed [startMS=10968734] graphSizeBefore->After=[675->497]
					DeadCodeEliminationPhase->1ms elapsed [startMS=10968735] graphSizeBefore->After=[559->559]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968737] graphSizeBefore->After=[559->497]
				PostPartialEvaluationSuite$InlineReplacementsPhase->1ms elapsed [startMS=10968740] graphSizeBefore->After=[497->497]
				CanonicalizerPhase->1ms elapsed [startMS=10968741] graphSizeBefore->After=[497->346]
				ConditionalEliminationPhase->3ms elapsed [startMS=10968743] graphSizeBefore->After=[346->340]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968744] graphSizeBefore->After=[340->340]
				FrameAccessVerificationPhase->1ms elapsed [startMS=10968746] graphSizeBefore->After=[340->340]
				PartialEscapePhase->5ms elapsed [startMS=10968748] graphSizeBefore->After=[340->95]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968748] graphSizeBefore->After=[340->340]
				PhiTransformPhase->1ms elapsed [startMS=10968753] graphSizeBefore->After=[95->95]
			IntermediateRoot -> com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(Node, Object[])->30ms elapsed [startMS=10968774] graphSizeBefore->After=[0->0]
				SubstratePostPartialEvaluationSuite->30ms elapsed [startMS=10968774] graphSizeBefore->After=[452->109]
					InsertProxyPhase->1ms elapsed [startMS=10968774] graphSizeBefore->After=[452->452]
					ConvertDeoptimizeToGuardPhase->4ms elapsed [startMS=10968775] graphSizeBefore->After=[452->399]
						DeadCodeEliminationPhase->1ms elapsed [startMS=10968777] graphSizeBefore->After=[407->407]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968778] graphSizeBefore->After=[407->399]
					PostPartialEvaluationSuite$InlineReplacementsPhase->1ms elapsed [startMS=10968780] graphSizeBefore->After=[399->399]
					CanonicalizerPhase->1ms elapsed [startMS=10968781] graphSizeBefore->After=[399->284]
					ConditionalEliminationPhase->3ms elapsed [startMS=10968782] graphSizeBefore->After=[284->279]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968783] graphSizeBefore->After=[280->279]
					PartialEscapePhase->5ms elapsed [startMS=10968786] graphSizeBefore->After=[279->109]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968786] graphSizeBefore->After=[279->279]
					PhiTransformPhase->1ms elapsed [startMS=10968792] graphSizeBefore->After=[109->109]
					TruffleBoundaryPhase->10ms elapsed [startMS=10968794] graphSizeBefore->After=[109->109]
			SubstratePostPartialEvaluationSuite->13ms elapsed [startMS=10968810] graphSizeBefore->After=[226->123]
				ConvertDeoptimizeToGuardPhase->2ms elapsed [startMS=10968811] graphSizeBefore->After=[226->157]
				ConditionalEliminationPhase->1ms elapsed [startMS=10968815] graphSizeBefore->After=[146->140]
				PartialEscapePhase->3ms elapsed [startMS=10968817] graphSizeBefore->After=[140->123]
				PhiTransformPhase->1ms elapsed [startMS=10968821] graphSizeBefore->After=[123->123]
			IntermediateRoot -> com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(Node, Object[])->8ms elapsed [startMS=10968826] graphSizeBefore->After=[0->0]
				SubstratePostPartialEvaluationSuite->8ms elapsed [startMS=10968826] graphSizeBefore->After=[87->46]
					ConvertDeoptimizeToGuardPhase->1ms elapsed [startMS=10968827] graphSizeBefore->After=[87->67]
					PartialEscapePhase->2ms elapsed [startMS=10968831] graphSizeBefore->After=[62->46]
			SubstratePostPartialEvaluationSuite->6ms elapsed [startMS=10968837] graphSizeBefore->After=[81->21]
				ConvertDeoptimizeToGuardPhase->1ms elapsed [startMS=10968838] graphSizeBefore->After=[81->27]
				ConditionalEliminationPhase->1ms elapsed [startMS=10968840] graphSizeBefore->After=[26->21]
			IntermediateRoot -> com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(Node, Object[])->17ms elapsed [startMS=10968855] graphSizeBefore->After=[0->0]
				SubstratePostPartialEvaluationSuite->17ms elapsed [startMS=10968855] graphSizeBefore->After=[320->141]
					ConvertDeoptimizeToGuardPhase->3ms elapsed [startMS=10968856] graphSizeBefore->After=[320->240]
					ConditionalEliminationPhase->2ms elapsed [startMS=10968861] graphSizeBefore->After=[187->185]
					PartialEscapePhase->4ms elapsed [startMS=10968865] graphSizeBefore->After=[185->141]
					PhiTransformPhase->1ms elapsed [startMS=10968869] graphSizeBefore->After=[141->141]
			SubstratePostPartialEvaluationSuite->48ms elapsed [startMS=10968904] graphSizeBefore->After=[923->243]
				InsertProxyPhase->2ms elapsed [startMS=10968904] graphSizeBefore->After=[923->923]
				ConvertDeoptimizeToGuardPhase->19ms elapsed [startMS=10968907] graphSizeBefore->After=[923->767]
					DeadCodeEliminationPhase->2ms elapsed [startMS=10968909] graphSizeBefore->After=[823->823]
					IncrementalCanonicalizerPhase->2ms elapsed [startMS=10968911] graphSizeBefore->After=[823->767]
				PostPartialEvaluationSuite$InlineReplacementsPhase->2ms elapsed [startMS=10968927] graphSizeBefore->After=[767->767]
				CanonicalizerPhase->2ms elapsed [startMS=10968929] graphSizeBefore->After=[767->612]
				ConditionalEliminationPhase->5ms elapsed [startMS=10968931] graphSizeBefore->After=[612->605]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968933] graphSizeBefore->After=[606->605]
				FrameAccessVerificationPhase->1ms elapsed [startMS=10968937] graphSizeBefore->After=[605->605]
				PartialEscapePhase->9ms elapsed [startMS=10968939] graphSizeBefore->After=[605->243]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968939] graphSizeBefore->After=[605->605]
					DeadCodeEliminationPhase->1ms elapsed [startMS=10968943] graphSizeBefore->After=[596->285]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968945] graphSizeBefore->After=[285->285]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968946] graphSizeBefore->After=[285->243]
				PhiTransformPhase->2ms elapsed [startMS=10968948] graphSizeBefore->After=[243->243]
					IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968948] graphSizeBefore->After=[243->243]
				DeadStoreRemovalPhase->1ms elapsed [startMS=10968950] graphSizeBefore->After=[243->243]
				TruffleBoundaryPhase->1ms elapsed [startMS=10968951] graphSizeBefore->After=[243->243]
			IntermediateRoot -> com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(Node, Object[])->35ms elapsed [startMS=10968976] graphSizeBefore->After=[0->0]
				SubstratePostPartialEvaluationSuite->35ms elapsed [startMS=10968976] graphSizeBefore->After=[765->380]
					InsertProxyPhase->2ms elapsed [startMS=10968976] graphSizeBefore->After=[765->765]
					ConvertDeoptimizeToGuardPhase->8ms elapsed [startMS=10968979] graphSizeBefore->After=[765->604]
						DeadCodeEliminationPhase->1ms elapsed [startMS=10968981] graphSizeBefore->After=[653->653]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968983] graphSizeBefore->After=[653->604]
					PostPartialEvaluationSuite$InlineReplacementsPhase->1ms elapsed [startMS=10968987] graphSizeBefore->After=[604->604]
					CanonicalizerPhase->1ms elapsed [startMS=10968989] graphSizeBefore->After=[604->453]
					ConditionalEliminationPhase->4ms elapsed [startMS=10968991] graphSizeBefore->After=[453->430]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968993] graphSizeBefore->After=[447->430]
					FrameAccessVerificationPhase->1ms elapsed [startMS=10968995] graphSizeBefore->After=[430->430]
					PartialEscapePhase->8ms elapsed [startMS=10968997] graphSizeBefore->After=[430->380]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10968997] graphSizeBefore->After=[430->430]
						DeadCodeEliminationPhase->1ms elapsed [startMS=10969000] graphSizeBefore->After=[435->391]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10969001] graphSizeBefore->After=[391->391]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10969003] graphSizeBefore->After=[391->380]
					PhiTransformPhase->2ms elapsed [startMS=10969005] graphSizeBefore->After=[380->380]
						IncrementalCanonicalizerPhase->1ms elapsed [startMS=10969005] graphSizeBefore->After=[380->380]
					DeadStoreRemovalPhase->1ms elapsed [startMS=10969008] graphSizeBefore->After=[380->380]
					TruffleBoundaryPhase->1ms elapsed [startMS=10969009] graphSizeBefore->After=[380->380]
			SubstratePostPartialEvaluationSuite->117ms elapsed [startMS=10969023] graphSizeBefore->After=[259->69]
				ConvertDeoptimizeToGuardPhase->3ms elapsed [startMS=10969024] graphSizeBefore->After=[259->207]
				ConditionalEliminationPhase->2ms elapsed [startMS=10969029] graphSizeBefore->After=[125->123]
				FrameAccessVerificationPhase->1ms elapsed [startMS=10969031] graphSizeBefore->After=[123->123]
				PartialEscapePhase->105ms elapsed [startMS=10969032] graphSizeBefore->After=[123->69]
					IncrementalCanonicalizerPhase->101ms elapsed [startMS=10969032] graphSizeBefore->After=[123->123]
				PhiTransformPhase->1ms elapsed [startMS=10969138] graphSizeBefore->After=[69->69]
			SubstratePostPartialEvaluationSuite->45880ms elapsed [startMS=10971694] graphSizeBefore->After=[10569->5430]
				InsertProxyPhase->1956ms elapsed [startMS=10971694] graphSizeBefore->After=[10569->10552]
				ConvertDeoptimizeToGuardPhase->9350ms elapsed [startMS=10973651] graphSizeBefore->After=[10552->9919]
					DeadCodeEliminationPhase->2279ms elapsed [startMS=10976182] graphSizeBefore->After=[9949->9949]
					IncrementalCanonicalizerPhase->1924ms elapsed [startMS=10978462] graphSizeBefore->After=[9949->9919]
				PostPartialEvaluationSuite$InlineReplacementsPhase->2715ms elapsed [startMS=10983001] graphSizeBefore->After=[9919->9919]
				CanonicalizerPhase->1826ms elapsed [startMS=10985716] graphSizeBefore->After=[9919->8988]
				ConditionalEliminationPhase->7151ms elapsed [startMS=10987543] graphSizeBefore->After=[8988->8870]
					IncrementalCanonicalizerPhase->2864ms elapsed [startMS=10990195] graphSizeBefore->After=[8962->8870]
				FrameAccessVerificationPhase->1826ms elapsed [startMS=10994694] graphSizeBefore->After=[8870->8870]
				PartialEscapePhase->12972ms elapsed [startMS=10996520] graphSizeBefore->After=[8870->5430]
					IncrementalCanonicalizerPhase->3013ms elapsed [startMS=10996521] graphSizeBefore->After=[8870->8870]
					SchedulePhase->1ms elapsed [startMS=10999534] graphSizeBefore->After=[8870->8870]
					DeadCodeEliminationPhase->2947ms elapsed [startMS=11001222] graphSizeBefore->After=[7278->6478]
					IncrementalCanonicalizerPhase->3164ms elapsed [startMS=11004170] graphSizeBefore->After=[6478->6478]
					IncrementalCanonicalizerPhase->1012ms elapsed [startMS=11007334] graphSizeBefore->After=[6478->5430]
				PhiTransformPhase->2456ms elapsed [startMS=11009493] graphSizeBefore->After=[5430->5430]
					IncrementalCanonicalizerPhase->1103ms elapsed [startMS=11009493] graphSizeBefore->After=[5430->5430]
				DeadStoreRemovalPhase->1230ms elapsed [startMS=11011950] graphSizeBefore->After=[5430->5430]
				TruffleBoundaryPhase->3471ms elapsed [startMS=11013180] graphSizeBefore->After=[5430->5430]
		InstrumentationSuite->2505ms elapsed [startMS=11018719] graphSizeBefore->After=[5430->5430]
		ReportPerformanceWarningsPhase->4670ms elapsed [startMS=11021224] graphSizeBefore->After=[5430->5430]
		VerifyFrameDoesNotEscapePhase->2143ms elapsed [startMS=11025894] graphSizeBefore->After=[5430->5430]
		NeverPartOfCompilationPhase->2550ms elapsed [startMS=11028038] graphSizeBefore->After=[5430->5430]
		MaterializeFramesPhase->5304ms elapsed [startMS=11030588] graphSizeBefore->After=[5430->5430]
		SetIdentityForValueTypesPhase->1968ms elapsed [startMS=11035893] graphSizeBefore->After=[5430->5430]
		ReplaceAnyExtendNodePhase->2519ms elapsed [startMS=11037862] graphSizeBefore->After=[5430->5429]
		InliningAcrossTruffleBoundaryPhase->5218ms elapsed [startMS=11040381] graphSizeBefore->After=[5429->5429]
	HighTier->20923ms elapsed [startMS=11052831] graphSizeBefore->After=[5429->0]
		CanonicalizerPhase->2078ms elapsed [startMS=11053770] graphSizeBefore->After=[5429->5429]
		InliningPhase->2563ms elapsed [startMS=11055849] graphSizeBefore->After=[5429->5429]
		DeadStoreRemovalPhase->2514ms elapsed [startMS=11058413] graphSizeBefore->After=[5429->5429]
		RemoveUnwindPhase->6003ms elapsed [startMS=11060927] graphSizeBefore->After=[5429->5429]
		DeadCodeEliminationPhase->2087ms elapsed [startMS=11066931] graphSizeBefore->After=[5429->5429]
		DisableOverflownCountedLoopsPhase->2160ms elapsed [startMS=11069019] graphSizeBefore->After=[5429->5429]
		ConvertDeoptimizeToGuardPhase->2574ms elapsed [startMS=11071180] graphSizeBefore->After=[5429->0] <===== TIMEOUT HERE|UTC 2025-10-03T12:03:45.264|Src resource:/truffleruby/core/kernel.rb:282 0xc8a7880e
[engine] opt fail     Kernel#require_relative                                     |AST    129
jdk.graal.compiler.code.SourceStackTraceBailoutException$1:jdk.graal.compiler.code.SourceStackTraceBailoutException:jdk.graal.compiler.core.common.PermanentBailoutException:jdk.graal.compiler.core.common.GraalBailoutException:jdk.vm.ci.code.BailoutException:java.lang.RuntimeException:java.lang.Exception:
jdk.graal.compiler.code.SourceStackTraceBailoutException$1: Deopt taken too many times. Deopt Node: 5493|Deopt. This could indicate a deopt cycle, which typically hints at a bug in the language implementation or Truffle.
	at com.oracle.truffle.api.strings.TruffleStringFactory$EqualNodeGen.execute(TruffleStringFactory.java:5468)
	at org.truffleruby.core.string.StringHelperNodes$StringEqualInternalNode.equalBytes(StringHelperNodes.java:166)
	at org.truffleruby.core.string.StringHelperNodesFactory$StringEqualInternalNodeGen$Inlined.executeInternal(StringHelperNodesFactory.java:409)
	at org.truffleruby.core.string.StringHelperNodes$EqualNode.equal(StringHelperNodes.java:118)
	at org.truffleruby.core.string.StringHelperNodesFactory$EqualNodeGen.execute(StringHelperNodesFactory.java:208)
	at org.truffleruby.core.string.RubyStringGen$InteropLibraryExports$Cached.asString(RubyStringGen.java:179)
	at org.truffleruby.interop.ToJavaStringNode.interopString(ToJavaStringNode.java:37)
	at org.truffleruby.interop.ToJavaStringNodeGen$Inlined.execute(ToJavaStringNodeGen.java:116)
	at org.truffleruby.core.kernel.KernelNodes$FindFileNode.findFile(KernelNodes.java:254)
	at org.truffleruby.core.kernel.KernelNodesFactory$FindFileNodeFactory$FindFileNodeGen.execute(KernelNodesFactory.java:772)
	at org.truffleruby.language.control.SequenceNode.execute(SequenceNode.java:35)
	at org.truffleruby.language.RubyMethodRootNode.execute(RubyMethodRootNode.java:65)
	at com.oracle.truffle.runtime.OptimizedCallTarget.executeRootNode(OptimizedCallTarget.java:834)
	at com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(OptimizedCallTarget.java:630)
	at com.oracle.truffle.runtime.OptimizedDirectCallNode.call(OptimizedDirectCallNode.java:94)
	at org.truffleruby.language.methods.CallInternalMethodNode.callCached(CallInternalMethodNode.java:66)
	at org.truffleruby.language.methods.CallInternalMethodNodeGen.execute(CallInternalMethodNodeGen.java:104)
	at org.truffleruby.language.dispatch.DispatchNode.dispatch(DispatchNode.java:300)
	at org.truffleruby.language.dispatch.DispatchNodeGen.execute(DispatchNodeGen.java:148)
	at org.truffleruby.language.dispatch.RubyCallNode.doCall(RubyCallNode.java:186)
	at org.truffleruby.language.dispatch.RubyCallNode.execute(RubyCallNode.java:138)
	at org.truffleruby.language.locals.WriteLocalVariableNode.execute(WriteLocalVariableNode.java:28)
	at org.truffleruby.language.RubyContextSourceNode.executeVoid(RubyContextSourceNode.java:23)
	at org.truffleruby.language.control.SequenceNode.execute(SequenceNode.java:32)
	at org.truffleruby.language.RubyMethodRootNode.execute(RubyMethodRootNode.java:65)
	at com.oracle.truffle.runtime.OptimizedCallTarget.executeRootNode(OptimizedCallTarget.java:834)
	at com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(OptimizedCallTarget.java:630)
	at com.oracle.truffle.runtime.OptimizedDirectCallNode.call(OptimizedDirectCallNode.java:94)
	at org.truffleruby.language.methods.CallInternalMethodNode.callCached(CallInternalMethodNode.java:66)
	at org.truffleruby.language.methods.CallInternalMethodNodeGen.execute(CallInternalMethodNodeGen.java:104)
	at org.truffleruby.language.dispatch.DispatchNode.dispatch(DispatchNode.java:300)
	at org.truffleruby.language.dispatch.DispatchNodeGen.execute(DispatchNodeGen.java:148)
	at org.truffleruby.language.dispatch.RubyCallNode.doCall(RubyCallNode.java:186)
	at org.truffleruby.language.dispatch.RubyCallNode.execute(RubyCallNode.java:138)
	at org.truffleruby.core.array.MultipleAssignmentNode.execute(MultipleAssignmentNode.java:67)
	at org.truffleruby.language.RubyContextSourceNode.executeVoid(RubyContextSourceNode.java:23)
	at org.truffleruby.language.control.SequenceNode.execute(SequenceNode.java:32)
	at org.truffleruby.language.RubyMethodRootNode.execute(RubyMethodRootNode.java:65)
	at com.oracle.truffle.runtime.OptimizedCallTarget.executeRootNode(OptimizedCallTarget.java:834)
	at com.oracle.truffle.runtime.OptimizedCallTarget.profiledPERoot(OptimizedCallTarget.java:758)

[engine] Exiting VM due to engine.CompilationFailureAction=ExitVM
Graal diagnostic output saved in '/home/eregon/code/trws/truffleruby/graal_dumps/2025.10.03.14.01.29.413/[email protected]'

Oct 03 '25 12:10 eregon

I attach [email protected] here.

Oct 03 '25 12:10 eregon

Adding --vm.XX:+TraceDeoptimization --engine.NodeSourcePositions in test/truffle/compiler/compile-immediately.sh I get:

[engine] opt deopt  engine=1  id=1601  Kernel#require_relative                            |Invalidated false|                                                                                                            |UTC 2025-10-03T12:26:15.869|Src resource:/truffleruby/core/kernel.rb:282 0x8e9eb153
[Deoptimization initiated
    name: Kernel#require_relative (SubstrateCompilation-3154)
    sp: 0x7ffe81b6ff00  ip: 0x7f20745cf6f4
    reason: TransferToInterpreter  action: InvalidateReprofile
    debugId: 228  speculation: com.oracle.svm.graal.isolated.EncodedSpeculationReason@f9f01ea8
    stack trace that triggered deoptimization:
        at com.oracle.truffle.api.strings.TruffleStringFactory$EqualNodeGen.execute(TruffleStringFactory.java:5468)
        at org.truffleruby.core.string.StringHelperNodes$StringEqualInternalNode.equalBytes(StringHelperNodes.java:166)
        at org.truffleruby.core.string.StringHelperNodesFactory$StringEqualInternalNodeGen$Inlined.executeInternal(StringHelperNodesFactory.java:409)
        at org.truffleruby.core.string.StringHelperNodes$EqualNode.equal(StringHelperNodes.java:118)
        at org.truffleruby.core.string.StringHelperNodesFactory$EqualNodeGen.execute(StringHelperNodesFactory.java:208)
        at org.truffleruby.core.string.RubyStringGen$InteropLibraryExports$Cached.asString(RubyStringGen.java:179)
        at org.truffleruby.interop.ToJavaStringNode.interopString(ToJavaStringNode.java:37)
        at org.truffleruby.interop.ToJavaStringNodeGen$Inlined.execute(ToJavaStringNodeGen.java:116)
        at org.truffleruby.core.kernel.KernelNodes$FindFileNode.findFile(KernelNodes.java:254)
        at org.truffleruby.core.kernel.KernelNodesFactory$FindFileNodeFactory$FindFileNodeGen.execute(KernelNodesFactory.java:772)
        at org.truffleruby.language.control.SequenceNode.execute(SequenceNode.java:35)
        at org.truffleruby.language.RubyMethodRootNode.execute(RubyMethodRootNode.java:65)
        at com.oracle.truffle.runtime.OptimizedCallTarget.executeRootNode(OptimizedCallTarget.java:834)
        at com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(OptimizedCallTarget.java:630)
        at com.oracle.truffle.runtime.OptimizedDirectCallNode.call(OptimizedDirectCallNode.java:94)
        at org.truffleruby.language.methods.CallInternalMethodNode.callCached(CallInternalMethodNode.java:66)
        at org.truffleruby.language.methods.CallInternalMethodNodeGen.execute(CallInternalMethodNodeGen.java:104)
        at org.truffleruby.language.dispatch.DispatchNode.dispatch(DispatchNode.java:300)
        at org.truffleruby.language.dispatch.DispatchNodeGen.execute(DispatchNodeGen.java:148)
        at org.truffleruby.language.dispatch.RubyCallNode.doCall(RubyCallNode.java:186)
        at org.truffleruby.language.dispatch.RubyCallNode.execute(RubyCallNode.java:138)
        at org.truffleruby.language.locals.WriteLocalVariableNode.execute(WriteLocalVariableNode.java:28)
        at org.truffleruby.language.RubyContextSourceNode.executeVoid(RubyContextSourceNode.java:23)
        at org.truffleruby.language.control.SequenceNode.execute(SequenceNode.java:32)
        at org.truffleruby.language.RubyMethodRootNode.execute(RubyMethodRootNode.java:65)
        at com.oracle.truffle.runtime.OptimizedCallTarget.executeRootNode(OptimizedCallTarget.java:834)
        at com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(OptimizedCallTarget.java:630)
        at com.oracle.truffle.runtime.OptimizedDirectCallNode.call(OptimizedDirectCallNode.java:94)
        at org.truffleruby.language.methods.CallInternalMethodNode.callCached(CallInternalMethodNode.java:66)
        at org.truffleruby.language.methods.CallInternalMethodNodeGen.execute(CallInternalMethodNodeGen.java:104)
        at org.truffleruby.language.dispatch.DispatchNode.dispatch(DispatchNode.java:300)
        at org.truffleruby.language.dispatch.DispatchNodeGen.execute(DispatchNodeGen.java:148)
        at org.truffleruby.language.dispatch.RubyCallNode.doCall(RubyCallNode.java:186)
        at org.truffleruby.language.dispatch.RubyCallNode.execute(RubyCallNode.java:138)
        at org.truffleruby.core.array.MultipleAssignmentNode.execute(MultipleAssignmentNode.java:67)
        at org.truffleruby.language.RubyContextSourceNode.executeVoid(RubyContextSourceNode.java:23)
        at org.truffleruby.language.control.SequenceNode.execute(SequenceNode.java:32)
        at org.truffleruby.language.RubyMethodRootNode.execute(RubyMethodRootNode.java:65)
        at com.oracle.truffle.runtime.OptimizedCallTarget.executeRootNode(OptimizedCallTarget.java:834)
        at com.oracle.truffle.runtime.OptimizedCallTarget.profiledPERoot(OptimizedCallTarget.java:758)
[engine] opt inval. engine=1  id=1601  Kernel#require_relative                                                                                                                                                           |UTC 2025-10-03T12:26:15.869|Src resource:/truffleruby/core/kernel.rb:282 0x8e9eb153|Reason null
]
[Deoptimization of frame (32.784s)
    name: Kernel#require_relative (SubstrateCompilation-3154)
    sp: 0x00007ffe81b6ff00  ip: 0x00007f20745cf6f4
    stack trace where execution continues:
        at org.truffleruby.core.string.StringPrimitiveNodesFactory$StartWithNodeFactory$StartWithNodeGen.execute(StringPrimitiveNodesFactory.java:1042) bci 83  return address 0x00007f2087be0997
        at org.truffleruby.language.control.SequenceNode.execute(SequenceNode.java:35) bci 43 duringCall  return address 0x00007f20882de7f0
        at org.truffleruby.language.control.IfElseNode.doIfElse(IfElseNode.java:39) bci 30 duringCall  return address 0x00007f20882d1d74
        at org.truffleruby.language.control.IfElseNodeGen.execute(IfElseNodeGen.java:82) bci 8 duringCall  return address 0x00007f20882d2b8f
        at org.truffleruby.language.control.SequenceNode.execute(SequenceNode.java:35) bci 43 duringCall  return address 0x00007f20882de7f0
        at org.truffleruby.language.RubyMethodRootNode.execute(RubyMethodRootNode.java:65) bci 69 duringCall  return address 0x00007f20882482bf
        at com.oracle.truffle.runtime.OptimizedCallTarget.executeRootNode(OptimizedCallTarget.java:834) bci 5 duringCall  return address 0x00007f2084b22653
        at com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(OptimizedCallTarget.java:630) bci 23 duringCall  return address 0x00007f2084b1f4a9
        at com.oracle.truffle.runtime.OptimizedDirectCallNode.call(OptimizedDirectCallNode.java:94) bci 30 duringCall  return address 0x00007f2084b2b97c
        at org.truffleruby.language.methods.CallInternalMethodNode.callCached(CallInternalMethodNode.java:66) bci 6 duringCall  return address 0x00007f2088411125
        at org.truffleruby.language.methods.CallInternalMethodNodeGen.execute(CallInternalMethodNodeGen.java:104) bci 151 duringCall  return address 0x00007f20884128ea
        at org.truffleruby.language.dispatch.DispatchNode.dispatch(DispatchNode.java:300) bci 153 duringCall  return address 0x00007f208830c4b2
        at org.truffleruby.language.dispatch.DispatchNodeGen.execute(DispatchNodeGen.java:148) bci 72 duringCall  return address 0x00007f208830cdba
        at org.truffleruby.language.dispatch.RubyCallNode.doCall(RubyCallNode.java:186) bci 73 duringCall  return address 0x00007f2088324889
        at org.truffleruby.language.dispatch.RubyCallNode.execute(RubyCallNode.java:138) bci 111 duringCall  return address 0x00007f2088327211
        at org.truffleruby.language.control.IfNode.doIf(IfNode.java:35) bci 7 duringCall  return address 0x00007f20882d389c
        at org.truffleruby.language.control.IfNodeGen.execute(IfNodeGen.java:82) bci 8 duringCall  return address 0x00007f20882d46ef
        at org.truffleruby.language.RubyContextSourceNode.executeVoid(RubyContextSourceNode.java:23) bci 2 duringCall  return address 0x00007f208814a8c2
        at org.truffleruby.language.control.SequenceNode.execute(SequenceNode.java:32) bci 20 duringCall  return address 0x00007f20882de77e
        at org.truffleruby.language.RubyMethodRootNode.execute(RubyMethodRootNode.java:65) bci 69 duringCall  return address 0x00007f20882482bf
        at com.oracle.truffle.runtime.OptimizedCallTarget.executeRootNode(OptimizedCallTarget.java:834) bci 5 duringCall  return address 0x00007f2084b22653
        at com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(OptimizedCallTarget.java:630) bci 23 duringCall  return address 0x00007f2084b1f4a9
        at com.oracle.truffle.runtime.OptimizedDirectCallNode.call(OptimizedDirectCallNode.java:94) bci 30 duringCall  return address 0x00007f2084b2b97c
        at org.truffleruby.language.methods.CallInternalMethodNode.callCached(CallInternalMethodNode.java:66) bci 6 duringCall  return address 0x00007f2088411125
        at org.truffleruby.language.methods.CallInternalMethodNodeGen.execute(CallInternalMethodNodeGen.java:104) bci 151 duringCall  return address 0x00007f20884128ea
        at org.truffleruby.language.dispatch.DispatchNode.dispatch(DispatchNode.java:300) bci 153 duringCall  return address 0x00007f208830c4b2
        at org.truffleruby.language.dispatch.DispatchNodeGen.execute(DispatchNodeGen.java:148) bci 72 duringCall  return address 0x00007f208830cdba
        at org.truffleruby.language.dispatch.RubyCallNode.doCall(RubyCallNode.java:186) bci 73 duringCall  return address 0x00007f2088324889
        at org.truffleruby.language.dispatch.RubyCallNode.execute(RubyCallNode.java:138) bci 111 duringCall  return address 0x00007f2088327211
        at org.truffleruby.language.locals.WriteLocalVariableNode.execute(WriteLocalVariableNode.java:28) bci 5 duringCall  return address 0x00007f20883ec4ee
        at org.truffleruby.language.RubyContextSourceNode.executeVoid(RubyContextSourceNode.java:23) bci 2 duringCall  return address 0x00007f208814a8c2
        at org.truffleruby.language.control.SequenceNode.execute(SequenceNode.java:32) bci 20 duringCall  return address 0x00007f20882de77e
        at org.truffleruby.language.RubyMethodRootNode.execute(RubyMethodRootNode.java:65) bci 69 duringCall  return address 0x00007f20882482bf
        at com.oracle.truffle.runtime.OptimizedCallTarget.executeRootNode(OptimizedCallTarget.java:834) bci 5 duringCall  return address 0x00007f2084b22653
        at com.oracle.truffle.runtime.OptimizedCallTarget.callInlined(OptimizedCallTarget.java:630) bci 23 duringCall  return address 0x00007f2084b1f4a9
        at com.oracle.truffle.runtime.OptimizedDirectCallNode.call(OptimizedDirectCallNode.java:94) bci 30 duringCall  return address 0x00007f2084b2b97c
        at org.truffleruby.language.methods.CallInternalMethodNode.callCached(CallInternalMethodNode.java:66) bci 6 duringCall  return address 0x00007f2088411125
        at org.truffleruby.language.methods.CallInternalMethodNodeGen.execute(CallInternalMethodNodeGen.java:104) bci 151 duringCall  return address 0x00007f20884128ea
        at org.truffleruby.language.dispatch.DispatchNode.dispatch(DispatchNode.java:300) bci 153 duringCall  return address 0x00007f208830c4b2
        at org.truffleruby.language.dispatch.DispatchNodeGen.execute(DispatchNodeGen.java:148) bci 72 duringCall  return address 0x00007f208830cdba
        at org.truffleruby.language.dispatch.RubyCallNode.doCall(RubyCallNode.java:186) bci 73 duringCall  return address 0x00007f2088324889
        at org.truffleruby.language.dispatch.RubyCallNode.execute(RubyCallNode.java:138) bci 111 duringCall  return address 0x00007f2088327211
        at org.truffleruby.core.array.MultipleAssignmentNode.execute(MultipleAssignmentNode.java:67) bci 48 duringCall  return address 0x00007f2086cc1c67
        at org.truffleruby.language.RubyContextSourceNode.executeVoid(RubyContextSourceNode.java:23) bci 2 duringCall  return address 0x00007f208814a8c2
        at org.truffleruby.language.control.SequenceNode.execute(SequenceNode.java:32) bci 20 duringCall  return address 0x00007f20882de77e
        at org.truffleruby.language.RubyMethodRootNode.execute(RubyMethodRootNode.java:65) bci 69 duringCall  return address 0x00007f20882482bf
        at com.oracle.truffle.runtime.OptimizedCallTarget.executeRootNode(OptimizedCallTarget.java:834) bci 5 duringCall  return address 0x00007f2084b22653
        at com.oracle.truffle.runtime.OptimizedCallTarget.profiledPERoot(OptimizedCallTarget.java:758) bci 40 duringCall  return address 0x00007f2084b2990f
]

Oct 03 '25 12:10 eregon

From that it seems clear that the deopt resumes execution in a different call target, notably because the first stacktrace has 3 RubyMethodRootNode.execute and the second stacktrace has 4 RubyMethodRootNode.execute.

So then it seems likely it probably invalidates "the wrong CallTarget", and as a result keeps running into that deopt without ever removing the problematic JITed-compiled native code.

Although, we do see

[engine] opt inval. engine=1  id=1601  Kernel#require_relative

so it does seem to remove the correct CallTarget. But probably, after deopting to another CallTarget the execution probably runs into another Tier2 or maybe a Tier1 compilation which has already learned from that deopt and so runs fine without deopting. But then when require_relative is called again, with --engine.CompileImmediately it recompiles without having learned from the deopt.

This is my guess, but the bottom line is the VM doesn't seem to learn from that deopt, and therefore deopts repeatedly.

I think a solution could be when detecting a deopt loop to recompile with some extra nodes which guarantee to always deopt in the same CallTarget (i.e., "precise deoptimization").

Or potentially to invalidate all compilations which include the CallTarget in which the deopt triggers (i.e. the first CallTarget in stack trace that triggered deoptimization).

Oct 03 '25 12:10 eregon

Discussed in https://graalvm.slack.com/archives/CNQSB2DHD/p1759493884063259

Oct 03 '25 20:10 eregon

Hi @eregon,

Thank you for looking into this issue. I noticed that you referenced it in truffleruby/truffleruby#3960

Thanks a lot!

Oct 06 '25 09:10 selhagani