This looks like a Graal bug, related to escape analysis, or maybe a bug in JRuby+Truffle.
Could we reproduce this ourselves? Is it from latest https://github.com/PragTob/rubykon?
I think that would help a lot.

Hey, most definitely! Yep this is rubykon master, should all be easily reproducible I hope :)

This seems a spurious bug. I could reproduce it a couple times in many tries.
I could not reproduce it with latest Graal, but maybe it's just harder to reproduce with it.
I'll file a bug upstream.

Note that you are using the --graal option of tool/jt.rb.
Using Graal with the tool is like this (as in your README):

jruby-truffle-tool --graal-path ../graalvm-0.18-re/bin/java run --graal -- benchmark/mcts_avg.rb

I would think this bug is fairly independent of which launcher is used, but one thing that the tool changes is it enables assertions.

--no-asserts can be used to disable them for benchmarking

@eregon thanks, didn't update the README yet for the newest addition as I was sitll figuring stuff out but thought it had all changed, glad it hasn't :D I'll try again and if it clear will close out here. Thanks for the support! :)

So, the benchmark runs now with --no-asserts ... but it spouts out errors like an avalanche. Seems to always be that "FrameWithoutBoxing" error but it comes from EVERYWHERE. Class.new, my won #won method, Integer#times etc.... it also still happens after warmup completed (although just one time and with a method that had already seen the error).

No sure how confident I'm with publishing those benchmarks results then. they're also worse than what they should be/what they were when running with jt.rb :|

for reference, I ran

tobi@speedy ~/github/rubykon $ ../jruby/bin/jruby-truffle-tool --graal-path ~/dev/graalvm-0.18-re/bin/java run --graal --no-asserts -- benchmark/mcts_avg.rb
jtt: detected gem/app: rubykon
jtt: executing "run" command
jtt: $ JAVACMD="/home/tobi/dev/graalvm-0.18-re/bin/java" /home/tobi/github/jruby/tool/jt.rb ruby -X\+T -J-Xmx2G -Xtruffle.core.load_path\=/home/tobi/github/jruby/truffle/src/main/ruby -r /home/tobi/github/rubykon/.jruby-truffle-tool_bundle/bundler/setup.rb -I /home/tobi/github/jruby/lib/ruby/truffle/jruby-truffle-tool/lib benchmark/mcts_avg.rb
$ /home/tobi/github/jruby/bin/jruby -X+T -Xtruffle.core.load_path=/home/tobi/github/jruby/truffle/src/main/ruby -Xtruffle.graal.warn_unless=false -X+T -J-Xmx2G -Xtruffle.core.load_path=/home/tobi/github/jruby/truffle/src/main/ruby -r /home/tobi/github/rubykon/.jruby-truffle-tool_bundle/bundler/setup.rb -I /home/tobi/github/jruby/lib/ruby/truffle/jruby-truffle-tool/lib benchmark/mcts_avg.rb

so I guess what I'm also saying is, I can reproduce this VERY reliably. Not sure if it does you any good, but I created a gist with all the errors - it's over 12 000 lines.

Thanks for all the details!
Yes, this error is a general problem, not related to a particular method. From what I saw today, it looks like for some reason the node doing block calls can be not inlined properly, making Graal believe the frame escapes.
A wild guess could be that the inlining limit we set somehow interacts badly.
If compilation fails like this, performance is not going to look good.

Running benchmarks with jt.rb is perfectly fine BTW.
It would be quite interesting (and surprising) if these errors never happen with it.
After all, jruby-truffle-tool calls out to jt.rb with a few extra arguments.

I'll try to reproduce tomorrow.
Before that command, you only did ../jruby/bin/jruby-truffle-tool setup and built jruby with ./mvnw or tool/jt.rb build?
Maybe we can discuss tomorrow on IRC Freenode on #jruby for faster feedback?

@eregon ah I setup my machine anew again and haven't setup IRC yet, I'll try to restore my settings and roll. Has been too long since I hang out in #jruby :) Will try to, I have a guest and possibly something else that might keep me but I'll try :)

Regarding jt.rb, yes it'll do but then only for my home rolled benchmarking library (that I wrote specifically to play nice with truffle/graal btw.) as it's in the repo and hence I don't need the rubygems/bundler functionality the tool gives me. It didn't show up so far, but I'll keep my eyes open when I rerun them :)

Thanks for all the nice help!

When assertions are enabled, it seems an opt fail aborts the process.
Instead, when assertions are disabled, the process keeps going and it seems it keeps running into this bug.

The current benchmark takes a while to run, is there a smaller benchmark I could execute? Or some parameters I could tune?

I can reproduce fairly frequently with GraalVM 0.18, but not with latest Graal.
One interesting thing to try would be to use the latest Graal, as documented in https://github.com/jruby/jruby/wiki/Building-Graal
It's quite easy to build Graal nowadays, in a nutshell you just need to download a JVMCI-enabled JDK8 on OTN, get mx and mx build (see the detailed instructions in the above link).

I'll take a look as well today or tomorrow.

I'll see what I can do, was surprisingly out of home almost the whole day today :) There's a lot of micro benchmarks in playout_micros (Chris actually wrote those last year) - even running all of them on Graal VM 0.18 doesn't trigger the error for me :|

You can of course try to tune warmup/time parameters (warmup is very generous precisely for truffle/graal) of benchmark.ips and benchmark.avg as well as the number of iterations in mcts_avg.rb (1_000 atm) so that it finishes earlier or that individual iterations take less time. You could also try smaller board sizes (currently commented out)

All that said, I just ran full_playout.rb without getting any error... twice! mcts_avg.rb still errors out though.

I'll have to set this up as a benchmark in our CI system. Then we can run it reliably on all configurations and versions of Graal. Is benchmark/mcts_avg.rb the key benchmark where you see the failures? It may take me a few days to set up the benchmark around other stuff.

Yes I see it in benchmark/mcts_avg.rb - I might try to run a benchmark just for the mcts stuff, because the only thing that mcts_avg.rb benchmarks that full_playout.rb does not benchmark is the actual monte carlo tree search tree. :) Might also be because mcts_avg.rb uses my home rolled benchmarking framework (after your feedback from last year, that really runs warmup and real benchmarking together, not statistics output inbetween etc.). It's not available as a separate gem yet, but I might do it some time :)

I have identified an issue triggered by this benchmark.
I looked at it by running:

GRAAL_BIN=... jt ruby -J-Xmx2G --graal --fg --trace -J-Dgraal.TraceTruffleAssumptions=true
-r.../rubykon/.jruby-truffle-tool_bundle/bundler/setup.rb
-I.../jruby/lib/ruby/truffle/jruby-truffle-tool/lib
benchmark/mcts_avg.rb

That is, what jruby-truffle-tool runs, and the additional options
--fg --trace -J-Dgraal.TraceTruffleAssumptions=true.
Respectively, they disable background compilation so compilation is reproducible, show which methods get optimized and deoptimized, and show what code invalidates assumptions.

It turns out there was a repeated deoptimization, caused by a bad transition when storing fields in a KeyValue pair object (used in Hash). Specifically, the storage of the value was going back and forth between int and DynamicObject. 0d50664 fixes the issue by generalizing to Object in that case. After that, the code does not deoptimize repeatedly anymore.

@PragTob Could you try running with the latest commit on truffle-head and latest Graal?
Hopefully that should fix your problems and performance.

Hey I tried the IRC thing but no response so far, so posting here as I'll turn off IRC soon :)

sadly the fix does not seem to work for me (I did git pull, then jt.rb build and then tried to execute the benchmark again) - still errors out for me
haven't built Graal myself yet though, which is what might be next on the list
or is there some step I forgot?

@PragTob No indeed, you need latest Graal to avoid the opt fail issue.
My fix only improves performance.
GraalVM 0.18 is quite old, we should have 0.19 soon, but in the meantime please try latest Graal.

Hey there! I got back on this and noticed that 0.19 was out and tried it out... sad to say it's still broken for me :( Well, some times.

It takes a lot longer (before it'd trigger after seconds for me, this time more ~ 2minutes) to get the FrameWithoutBoxingError but I do get it after quite some time. jruby/truffle-head is b9fe9f0 and the graalvm is the 0.19-dk now.

It also doesn't happen consistently anymore. I ran it 5 times (with the settings on master). It failed 3 times. The 2 times that it didn't fail I used --no-asserts but it didn't spew out messages for the opt fails like it used to, but that might just be 0.19 not printing them out... I don't know 🤷‍♂️

Error is:

tobi@speedy ~/github/rubykon $ benchmark/benchmark.sh benchmark/mcts_avg.rb 
Using /home/tobi/.rvm/gems/ruby-2.3.3
Running new truffle head
jtt: detected gem/app: rubykon
jtt: executing "run" command
jtt: $ JAVACMD="/home/tobi/dev/graalvm-0.19-dk/bin/java" /home/tobi/github/jruby/tool/jt.rb ruby -X\+T -J-Xmx2G -J-ea -J-esa -Xtruffle.core.load_path\=/home/tobi/github/jruby/truffle/src/main/ruby -r /home/tobi/github/rubykon/.jruby-truffle-tool_bundle/bundler/setup.rb -I /home/tobi/github/jruby/lib/ruby/truffle/jruby-truffle-tool/lib -J-Xmx1500m benchmark/mcts_avg.rb
$ /home/tobi/github/jruby/bin/jruby -X+T -Xtruffle.core.load_path=/home/tobi/github/jruby/truffle/src/main/ruby -Xtruffle.graal.warn_unless=false -X+T -J-Xmx2G -J-ea -J-esa -Xtruffle.core.load_path=/home/tobi/github/jruby/truffle/src/main/ruby -r /home/tobi/github/rubykon/.jruby-truffle-tool_bundle/bundler/setup.rb -I /home/tobi/github/jruby/lib/ruby/truffle/jruby-truffle-tool/lib -J-Xmx1500m benchmark/mcts_avg.rb
warning: -J-Xmx1500m argument ignored (launched in same VM?)
Running your benchmark...
--------------------------------------------------------------------------------
[truffle] opt fail         #take_liberties_of_enemies /home/tobi/github/rubykon/lib/rubykon/group_tracker.rb:54|Reason com.oracle.graal.code.SourceStackTraceBailoutException$1: Object of type Lcom/oracle/graal/truffle/FrameWithoutBoxing; should not be materialized (must not let virtual object escape at node 1055|EndNode): 
com.oracle.graal.code.SourceStackTraceBailoutException$1: Object of type Lcom/oracle/graal/truffle/FrameWithoutBoxing; should not be materialized (must not let virtual object escape at node 1055|EndNode):
	at org.jruby.truffle.core.hash.HashNodesFactory$GetIndexNodeFactory$GetIndexNodeGen$PolymorphicNode_.execute_(HashNodesFactory.java:599)
	at org.jruby.truffle.core.hash.HashNodesFactory$GetIndexNodeFactory$GetIndexNodeGen$BaseNode_.execute0(HashNodesFactory.java:513)
	at org.jruby.truffle.core.hash.HashNodesFactory$GetIndexNodeFactory$GetIndexNodeGen.execute(HashNodesFactory.java:460)
	at org.jruby.truffle.language.control.SequenceNode.execute(SequenceNode.java:34)
	at org.jruby.truffle.language.methods.ExceptionTranslatingNode.execute(ExceptionTranslatingNode.java:45)
# and so on...

here is another one on another:

tobi@speedy ~/github/rubykon $ ../jruby/bin/jruby-truffle-tool --graal-path ~/dev/graalvm-0.19-dk/bin/java run --graal -- -J-Xmx1500m benchmark/mcts_avg.rb 
jtt: detected gem/app: rubykon
jtt: executing "run" command
jtt: $ JAVACMD="/home/tobi/dev/graalvm-0.19-dk/bin/java" /home/tobi/github/jruby/tool/jt.rb ruby -X\+T -J-Xmx2G -J-ea -J-esa -Xtruffle.core.load_path\=/home/tobi/github/jruby/truffle/src/main/ruby -r /home/tobi/github/rubykon/.jruby-truffle-tool_bundle/bundler/setup.rb -I /home/tobi/github/jruby/lib/ruby/truffle/jruby-truffle-tool/lib -J-Xmx1500m benchmark/mcts_avg.rb
$ /home/tobi/github/jruby/bin/jruby -X+T -Xtruffle.core.load_path=/home/tobi/github/jruby/truffle/src/main/ruby -Xtruffle.graal.warn_unless=false -X+T -J-Xmx2G -J-ea -J-esa -Xtruffle.core.load_path=/home/tobi/github/jruby/truffle/src/main/ruby -r /home/tobi/github/rubykon/.jruby-truffle-tool_bundle/bundler/setup.rb -I /home/tobi/github/jruby/lib/ruby/truffle/jruby-truffle-tool/lib -J-Xmx1500m benchmark/mcts_avg.rb
warning: -J-Xmx1500m argument ignored (launched in same VM?)
Running your benchmark...
--------------------------------------------------------------------------------
[truffle] opt fail         #assign /home/tobi/github/rubykon/lib/rubykon/group_tracker.rb:11|Reason com.oracle.graal.code.SourceStackTraceBailoutException$1: Object of type Lcom/oracle/graal/truffle/FrameWithoutBoxing; should not be materialized (must not pass virtual object into an invoke that cannot be inlined): 
com.oracle.graal.code.SourceStackTraceBailoutException$1: Object of type Lcom/oracle/graal/truffle/FrameWithoutBoxing; should not be materialized (must not pass virtual object into an invoke that cannot be inlined):
	at org.jruby.truffle.language.yield.CallBlockNodeGen$CallBlockCachedNode_.execute1(CallBlockNodeGen.java:223)
	at org.jruby.truffle.language.yield.CallBlockNodeGen.executeCallBlock(CallBlockNodeGen.java:47)
	at org.jruby.truffle.language.yield.YieldNode.dispatch(YieldNode.java:38)
	at org.jruby.truffle.builtins.YieldingCoreMethodNode.yield(YieldingCoreMethodNode.java:29)

@PragTob Hello!
I wanted to try as well if 0.19 would fix it but apparently not 😞
Note that the GraalVM 0.19 release is a bit old (it uses a graal-core from December 5, it took a while to get it on OTN).
I would be curious if latest Graal works for you, as I didn't manage to reproduce the error with it IIRC.

If it does not spew messages it should work correctly. How was the performance in that case?

Performance was good but also the standard deviation was a bit high even after the generous warmup time... so not too sure. I guess I'll try to compile graalvm, but only when I got a bit more time :)

Sounds good :)
FWIW, by "building Graal" I mean building graal-core which takes less than 10 min, it got a lot faster with precompiled JVMCI-enabled JDKs.

I'm not afraid of the actual compile times, but more of dependency shenanigans :D I've been in this a good amount of time, still manually compiling still gives me a shiver and flashbacks from hour long dependency sessions like when I tried to compile gedit :D

Compiling graal-core only requires the right JDK and the mx tool (depending on Python 2), and then it's just compiling Java, no native stuff. I will add a script inside jruby to install graal-core automatically.

I guess I'm not clever enough for this, so I got an Oracle JDK 9, mx and stuff... now when I run mx build I can't seem to find where it puts the output aka the VM or whatever :D There is mxbuild sure enough but it has a bunch of jars and .src zips - nothing like the graalvm i know :)

Also the README says to just run mx vm then which just complains about missing java options for me...

tobi@speedy ~/github/graal-core $ mx vm
Usage: java [options] class [args...]

But it's probably just something stupid that I forget :)

@PragTob Just try GRAAL_HOME=$HOME/github/graal-core tool/jt.rb ruby ... in your jruby checkout.

Note that it's a bit simpler to build with a JVMCI-enabled JDK if that doesn't work.
From memory, expanding on #4400 (comment):

• Download a JVMCI-enabled JDK 8 from OTN.
• Clone graal-core and mx in some directory.
• cd graal-core
• unset JAVA_HOME
• .../path/to/mx/mx build choose the JVMCI-enabled JDK 8 when asked for JAVA_HOME
• cd .../jruby
• GRAAL_HOME=$HOME/github/graal-core tool/jt.rb ruby ...

Yes mx vm is just like running java, so it needs more arguments.

If you've managed to build then you should brea really to just do GRAAL_HOME=$HOME/github/graal-core tool/jt.rb ruby as @eregon says.

I usually have most trouble telling mx where to get the JVMCI-enabled JDK from. It seems to forget JAVA_HOME or it's not right for some other reason.

Closing to be replaced by oracle/truffleruby#1

FYI/to close this out with a new graal-core and head of truffleruby as of a couple of hours ago performance is amazing:

old truffle from ~ a year ago:

Runtime results:
--------------------------------------------------------------------------------
19x19 1_000 iterations        16.93 i/min  3.54 s (avg)  (± 10.70%)
--------------------------------------------------------------------------------

New truffle:

Runtime results:
--------------------------------------------------------------------------------
19x19 1_000 iterations        36.65 i/min  1.64 s (avg)  (± 1.25%)
--------------------------------------------------------------------------------

Thanks for all the help along the way!

Bingo!

Awesome!