Search code examples
javastringwhile-loopjvmjit

The output -1 becomes a slash in the loop


Surprisingly, the following code outputs:

/
-1

The code:

public class LoopOutPut {

    public static void main(String[] args) {
        LoopOutPut loopOutPut = new LoopOutPut();
        for (int i = 0; i < 30000; i++) {
            loopOutPut.test();
        }

    }

    public void test() {
        int i = 8;
        while ((i -= 3) > 0) ;
        String value = i + "";
        if (!value.equals("-1")) {
            System.out.println(value);
            System.out.println(i);
        }
    }

}

I tried many times to determine how many times this would occur, but, unfortunately, it was ultimately uncertain, and I found that the output of -2 sometimes turned into a period. In addition, I also tried to remove the while loop and output -1 without any problems. Who can tell me why?


JDK version information:

HopSpot 64-Bit 1.8.0.171
IDEA 2019.1.1

Solution

  • 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 :)