54

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
Laurel
  • 5,965
  • 14
  • 31
  • 57
okali
  • 513
  • 3
  • 8
  • 2
    Comments are not for extended discussion; this conversation has been [moved to chat](https://chat.stackoverflow.com/rooms/201644/discussion-on-question-by-okali-the-output-1-becomes-a-slash-in-the-loop). – Samuel Liew Oct 31 '19 at 08:26

3 Answers3

38

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

Kayaman
  • 72,141
  • 5
  • 83
  • 121
  • I also think it is `C2` - have looked at generated assembler code (and tried to understand it) using JitWatch - `C1` generated code still resembles bytecode, `C2` is totally different (I couldn't even find initialization of `i` with 8) – user85421 Oct 31 '19 at 08:16
  • your answer is very good, I tried, disable c2, the result is correct. However, in general, most of these parameters are default in the project, although the actual project will not have the above code, but it is likely to have similar code, if the project uses similar code, it is really terrible – okali Oct 31 '19 at 09:13
  • @okali this is a very specific edge case. If you modify the code even slightly it won't exhibit the bug, it also requires a very hot loop, so it's very unlikely that you would encounter this in real code. It is still a bug though. – Kayaman Oct 31 '19 at 10:01
  • @Eugene OpenJDK 12.0.1 - I can reproduce. – Oleksandr Pyrohov Oct 31 '19 at 13:16
  • @OleksandrPyrohov spoke too early! ran a script for that - yup, reproducible! my bad, folks. we need to summon Pangin in here – Eugene Oct 31 '19 at 13:17
  • 1
    @Eugene this has been quite a tricky one, I was sure it was going to be something like eclipse compiler bug or similar...and I couldn't reproduce it at first either.. – Kayaman Oct 31 '19 at 13:25
  • 1
    @Kayaman agreed. The analysis you made is very good, it should be more that enough for apangin to explain and fix this. What a fabulous morning on the train! – Eugene Oct 31 '19 at 13:27
  • 7
    I noticed this topic only accidentally. To make sure I see the question, use @mentions or add a #jvm tag. Good analysis, BTW. This is indeed a C2 compiler bug, fixed only a few days ago - [JDK-8231988](https://bugs.openjdk.java.net/browse/JDK-8231988). – apangin Oct 31 '19 at 16:38
  • @apangin ah, thank you very much. I thought mentions don't work for people not involved in the question already(?), but the jvm tag of course should've been put here. – Kayaman Oct 31 '19 at 16:54
  • how did the OP had the _same_ example as in the bug description though? :| – Eugene Oct 31 '19 at 17:24
  • @Eugene according to the comments/chat, it was presented in some technical group or something (it was a bit unclear). But it originated from fuzz testing (which makes sense, since nobody would come up with that kind of code). – Kayaman Oct 31 '19 at 17:47
4

This is honestly pretty odd, as that code should technically never output because ...

int i = 8;
while ((i -= 3) > 0);

... should always result in i being -1 (8 - 3 = 5; 5 - 3 = 2; 2 - 3 = -1). What is even weirder is that it never outputs in the debug mode of my IDE.

Interestingly, the moment I add a check before the conversion to a String, then no issue...

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

Just two points of good coding practice ...

  1. Rather use String.valueOf()
  2. Some coding standards specify that String literals should be the target of .equals(), rather than argument, thus minimizing NullPointerExceptions.

The only way I got this not to occur was by using String.format()

public void test() {
  int i = 8;
  while ((i -= 3) > 0);
  String value = String.format("%d", i);
  if (!"-1".equalsIgnoreCase(value)) {
    System.out.println(value);
    System.out.println(i);
  }
}

... essentially it just looks like Java needs a little bit of time to catch its breath :)

EDIT: This may be completely coincidental, but there does seem to be some correspondence between the value that is printing out and the ASCII Table.

  • i = -1, character displayed is / (ASCII decimal value of 47)
  • i = -2, character displayed is . (ASCII decimal value of 46)
  • i = -3, character displayed is - (ASCII decimal value of 45)
  • i = -4, character displayed is , (ASCII decimal value of 44)
  • i = -5, character displayed is + (ASCII decimal value of 43)
  • i = -6, character displayed is * (ASCII decimal value of 42)
  • i = -7, character displayed is ) (ASCII decimal value of 41)
  • i = -8, character displayed is ( (ASCII decimal value of 40)
  • i = -9, character displayed is ' (ASCII decimal value of 39)

What is really interesting is that the character at ASCII decimal 48 is the value 0 and 48 - 1 = 47 (character /), etc...

Laurel
  • 5,965
  • 14
  • 31
  • 57
Ambro-r
  • 919
  • 1
  • 4
  • 14
  • 1
    he numerical value of the character "/" is "-1" ??? where does this come from? (`(int)'/' == 47`; `(char)-1` is undefined `0xFFFF` is in Unicode) – user85421 Oct 31 '19 at 08:23
  • 1
    char c = '/'; int a = Character.getNumericValue(c); System.out.println(a); – Ambro-r Oct 31 '19 at 09:04
  • how does `getNumericValue()` relate to given code??? and how does it convert `-1` to `'/'` ??? Why not to `'-'`, `getNumericValue('-')` is also `-1`??? (BTW a lot of methods return `-1`) – user85421 Oct 31 '19 at 09:52
  • @CarlosHeuberger, I was running `getNumericValue()` on `value` (`/`) to get the character value. You are 100% correct that the ASCII decimal value of `/` should be 47 (it was what I was also expecting), but `getNumericValue()` was returning -1 at that point as I had added `System.out.println(Character.getNumericValue(value.toCharArray()[0]));`. I can see the confusion you are referring to and have updated the post. – Ambro-r Oct 31 '19 at 12:35
1

Don't know why Java is giving such random output but the issue is in your concatenation that fails for larger values of i inside the for loop.

If you replace String value = i + ""; line with String value = String.valueOf(i) ; your code works as expected.

Concatenation using + to convert the int to string is native and might be buggy (Oddly we are founding it now probably) and causing such issue.

Note: I reduced the value of i inside for loop to 10000 and I didn't face issue with + concatenation.

This issue must be reported to Java stakeholders & they can give their opinion on same.

Edit I updated the value of i in for loop to 3 million and saw a new set of errors as below:

Exception in thread "main" java.lang.ArrayIndexOutOfBoundsException: -1
    at java.lang.Integer.getChars(Integer.java:463)
    at java.lang.Integer.toString(Integer.java:402)
    at java.lang.String.valueOf(String.java:3099)
    at solving.LoopOutPut.test(LoopOutPut.java:16)
    at solving.LoopOutPut.main(LoopOutPut.java:8)

My Java version is 8.

Laurel
  • 5,965
  • 14
  • 31
  • 57
Vinay Prajapati
  • 7,199
  • 9
  • 45
  • 86
  • 1
    I don't think that string concatenation is native - it just uses `StringConcatFactory` (OpenJDK 13) or `StringBuilder` (Java 8) – user85421 Oct 31 '19 at 07:49
  • @CarlosHeuberger Possible too. I think it's from java 9 if it has to be `StringConcatFactory ` class. but as far as I know java till java 8 java don;t support operator overloading – Vinay Prajapati Oct 31 '19 at 07:54
  • @Vinay, tried this as well and yes it works, but the moment you increase the loop from 30000 to say 3000000 you start having the same issue. – Ambro-r Oct 31 '19 at 07:56
  • @Ambro-r I tried with your suggested value and I get `Exception in thread "main" java.lang.ArrayIndexOutOfBoundsException: -1` error. Strange. – Vinay Prajapati Oct 31 '19 at 07:58
  • 3
    `i + ""` is compiled exactly as `new StringBuilder().append(i).append("").toString()` in Java 8, and using that eventually also produces the output – user85421 Oct 31 '19 at 07:59
  • Thanks @CarlosHeuberger that adds to my knowledge. but String.valueOf is altogether different implementation. – Vinay Prajapati Oct 31 '19 at 08:01
  • @VinayPrajapati Debug mode shows this exception, but running it directly does not – okali Oct 31 '19 at 08:06
  • but it is not directly related to `String.valueOf()` it must be the optimization(JIT compiler, code inline) – user85421 Oct 31 '19 at 08:12