This can be reliably reproduced (or not reproduced, depending on what you want) with openjdk version "1.8.0_222" (used in my analysis), OpenJDK 12.0.1 (according to Oleksandr Pyrohov) and OpenJDK 13 (according to Carlos Heuberger).
I ran the code with -XX:+PrintCompilation enough times to get both behaviours and here are the differences.
Buggy implementation (displays output):
--- Previous lines are identical in both
54 17 3 java.lang.AbstractStringBuilder::<init> (12 bytes)
54 23 3 LoopOutPut::test (57 bytes)
54 18 3 java.lang.String::<init> (82 bytes)
55 21 3 java.lang.AbstractStringBuilder::append (62 bytes)
55 26 4 java.lang.AbstractStringBuilder::ensureCapacityInternal (27 bytes)
55 20 3 java.lang.StringBuilder::<init> (7 bytes)
56 19 3 java.lang.StringBuilder::toString (17 bytes)
56 25 3 java.lang.Integer::getChars (131 bytes)
56 22 3 java.lang.StringBuilder::append (8 bytes)
56 27 4 java.lang.String::equals (81 bytes)
56 10 3 java.lang.AbstractStringBuilder::ensureCapacityInternal (27 bytes) made not entrant
56 28 4 java.lang.AbstractStringBuilder::append (50 bytes)
56 29 4 java.lang.String::getChars (62 bytes)
56 24 3 java.lang.Integer::stringSize (21 bytes)
58 14 3 java.lang.String::getChars (62 bytes) made not entrant
58 33 4 LoopOutPut::test (57 bytes)
59 13 3 java.lang.AbstractStringBuilder::append (50 bytes) made not entrant
59 34 4 java.lang.Integer::getChars (131 bytes)
60 3 3 java.lang.String::equals (81 bytes) made not entrant
60 30 4 java.util.Arrays::copyOfRange (63 bytes)
61 25 3 java.lang.Integer::getChars (131 bytes) made not entrant
61 32 4 java.lang.String::<init> (82 bytes)
61 16 3 java.util.Arrays::copyOfRange (63 bytes) made not entrant
61 31 4 java.lang.AbstractStringBuilder::append (62 bytes)
61 23 3 LoopOutPut::test (57 bytes) made not entrant
61 33 4 LoopOutPut::test (57 bytes) made not entrant
62 35 3 LoopOutPut::test (57 bytes)
63 36 4 java.lang.StringBuilder::append (8 bytes)
63 18 3 java.lang.String::<init> (82 bytes) made not entrant
63 38 4 java.lang.StringBuilder::append (8 bytes)
64 21 3 java.lang.AbstractStringBuilder::append (62 bytes) made not entrant
Correct run (no display):
--- Previous lines identical in both
55 23 3 LoopOutPut::test (57 bytes)
55 17 3 java.lang.AbstractStringBuilder::<init> (12 bytes)
56 18 3 java.lang.String::<init> (82 bytes)
56 20 3 java.lang.StringBuilder::<init> (7 bytes)
56 21 3 java.lang.AbstractStringBuilder::append (62 bytes)
56 26 4 java.lang.AbstractStringBuilder::ensureCapacityInternal (27 bytes)
56 19 3 java.lang.StringBuilder::toString (17 bytes)
57 22 3 java.lang.StringBuilder::append (8 bytes)
57 24 3 java.lang.Integer::stringSize (21 bytes)
57 25 3 java.lang.Integer::getChars (131 bytes)
57 27 4 java.lang.String::equals (81 bytes)
57 28 4 java.lang.AbstractStringBuilder::append (50 bytes)
57 10 3 java.lang.AbstractStringBuilder::ensureCapacityInternal (27 bytes) made not entrant
57 29 4 java.util.Arrays::copyOfRange (63 bytes)
60 16 3 java.util.Arrays::copyOfRange (63 bytes) made not entrant
60 13 3 java.lang.AbstractStringBuilder::append (50 bytes) made not entrant
60 33 4 LoopOutPut::test (57 bytes)
60 34 4 java.lang.Integer::getChars (131 bytes)
61 3 3 java.lang.String::equals (81 bytes) made not entrant
61 32 4 java.lang.String::<init> (82 bytes)
62 25 3 java.lang.Integer::getChars (131 bytes) made not entrant
62 30 4 java.lang.AbstractStringBuilder::append (62 bytes)
63 18 3 java.lang.String::<init> (82 bytes) made not entrant
63 31 4 java.lang.String::getChars (62 bytes)
We can notice one significant difference. With the correct execution we compile test() twice. Once in the beginning, and once again afterwards (presumably because the JIT notices how hot the method is). In the buggy execution test() is compiled (or decompiled) 5 times.
Additionally, running with -XX:-TieredCompilation (which either interprets, or uses C2) or with -Xbatch (which forces the compilation to run in the main thread, instead of parallelly), the output is guaranteed and with 30000 iterations prints out a lot of stuff, so the C2 compiler seems to be the culprit. This is confirmed by running with -XX:TieredStopAtLevel=1, which disables C2 and doesn’t produce output (stopping at level 4 shows the bug again).
In the correct execution, the method is first compiled with Level 3 compilation, then afterwards with Level 4.
In the buggy execution, the previous compilations are discared (made non entrant) and it’s again compiled on Level 3 (which is C1, see previous link).
So it definitely is a bug in C2, although I’m not absolutely sure whether the fact that it’s going back to Level 3 compilation affects it (and why is it going back to level 3, so many uncertainties still).
You can generate the assembly code with the following line to go even deeper into the rabbit hole (also see this to enable assembly printing).
java -XX:+PrintCompilation -Xbatch -XX:+UnlockDiagnosticVMOptions -XX:+PrintAssembly LoopOutPut > broken.asm
At this point I’m starting to run out of skills, the buggy behaviour starts to exhibit when the previous compiled versions are discarded, but what little assembly skills I have are from the 90’s, so I’ll let someone smarter than me take it from here.
It’s likely that there is already a bug report about this, since the code was presented to the OP by someone else, and as all code C2 isn’t without bugs. I hope this analysis has been as informative to others as it has been to me.
As the venerable apangin pointed out in the comments, this is a recent bug. Much obliged to all the interested and helpful people 🙂