Bug ID: JDK-8139801 Error message from validation check has wrong order on Windows

Type: Bug
Component: hotspot
Sub-Component: runtime
Affected Version: 9

Priority: P3
Status: Resolved
Resolution: Fixed

Submitted: 2015-10-16
Updated: 2023-08-21
Resolved: 2015-10-26

JDK 9
9 b94Fixed

Windows prints validation fail error message out of order.

eg) 
Expected behavior (except Windows)
bin/java -XX:MinTLABSize=1 -version
MinTLABSize (1) must be greater than or equal to reserved area in TLAB (16)
Error: Could not create the Java Virtual Machine.
Error: A fatal exception has occurred. Program will exit.

On Windows:
Error: Could not create the Java Virtual Machine.
Error: A fatal exception has occurred. Program will exit.
MinTLABSize (1) must be greater than or equal to reserved area in TLAB (16)

URL: http://hg.openjdk.java.net/jdk9/jdk9/hotspot/rev/0aa8adafb982 User: lana Date: 2015-11-18 23:53:22 +0000
18-11-2015
URL: http://hg.openjdk.java.net/jdk9/hs-rt/hotspot/rev/0aa8adafb982 User: coleenp Date: 2015-10-26 18:52:14 +0000
26-10-2015
David, interesting read, and I had come across something similar when we first started tracking this problem down last week. What we care about most is that everything is flushed before exit, so I think the originally proposed fflush() approach is the right solution, although it looks like it is needed in more than one place. The other choice is setvbuf(), but that one makes me a bit nervous. For one, it hurts performance when sending to a file. We actually want buffering in that case.
20-10-2015
Ioi, I wasn't concerned about the order, but it partial evidence of the problem. It points to stderr being buffered, and we believe that the buffering and lack of an fflush before exit is why sometimes stderr is missing from the output. It's possible that sometimes stdout is missing from the output on occasion too, but we don't have any tests that would fail because of that.
20-10-2015
Chris, I did your experiment on Windows and 'stderr' is appeared first. (ie, both 'stderr' and 'stdout' are buffered) $ java -showversion -Xshare:on -XX:SharedArchiveFile=/rootfile.jsa Error occurred during initialization of VM Unable to use shared archive. An error has occurred while processing the shared archive file. Specified shared archive not found. Test stderr 1 Test stdout 2 And if the test doesn't check the error messages order(as Ioi said), we can fflush when we abort (vm_abort) as a general fix.
20-10-2015
David, using 'setvbuf' is also considered for 'stderr' but still needs fflush(stdout) at the end (as changing unbuffered for 'stdout' seems not appropriate). So instead of touching differently for stdout and stderr, I was thinking to call fflush for both.
20-10-2015
The only guarantees we need are that we flush when we write a newline. As long as there is no buffering then the output will appear in chronological order. I don't see how buffering or not of stdout explains what we see on windows - the problem is we don't see the output of stderr when we expect, which means it is buffered and not flushed. Interesting reading here: http://stackoverflow.com/questions/1716296/why-does-printf-not-flush-after-the-call-unless-a-newline-is-in-the-format-strin Within our test framework we may be seeing full buffering rather than line buffering.
20-10-2015
I am not sure if Windows has any guarantee on the ordering of stdout vs stderr, regardless of whether you call fflush or not. Also, the order of the stdout vs stderr is not specified by Java. So why are we explicitly testing for it? It's better to fix the test to not assume a certain order of the error messages.
20-10-2015
Sangheon, I think you are right about not being able to guarantee the order for my CDS example. I think it would be necessary to fflush(stderr) after sending output there. So that would mean putting the fix in the filemap.cpp fail() function, although that would not help other users of vm_abort(). It might be worth trying an experiment on Windows: fprintf(stderr, "Test stderr 1"\n" fprintf(stdout, "Test stdout 2\n"); fflush(stderr); fflush(stdout); If stdout appears first, then that means stdout is unbuffered while stderr is buffered.
20-10-2015
Apparently not on Windows. There are a few modes, and Windows seems to be using the most lax flushing mode for stderr. I get the feeling stdout is actually more aggressively flushed. We've seen two different but likely relate symptoms: For CDS, some tests are failing because the stderr message is not there even though the stdout message is (and the printf of the stderr message is actually the first one to execute). For this MinTLABSize test (and another I showed with illegal arguments), the stderr message done by the JVM is printed after the stderr message printed by JavaMain(), even though the execution order is the reverse of this. Both message are to stderr, but the second one comes first. I suspected the stderr in JavaMain was different on Windows than the one in the jvm dll, and Sangheon check and this is true (they are the same on linux so probably imported from a .so). Also, the same issue appears here as with the lost CDS error message. The message printed by the jvm dll sometimes does not appear, but the one done by JavaMain will appear.
20-10-2015
Aren't streams automatically flushed when passed a newline?
20-10-2015
I checked that CDS failure has the order as below on Windows. $ java -showversion -Xshare:on -XX:SharedArchiveFile=/rootfile.jsa Error occurred during initialization of VM Unable to use shared archive. An error has occurred while processing the shared archive file. Specified shared archive not found. And I think calling fflush(NULL) will not make sure the order of their strings when they are added but just to be flushed. So the wrong order can't be fixed.
20-10-2015
Here's a CDS failure that goes through the vm_abort path: bash-4.1$ ./java -showversion -Xshare:on -XX:SharedArchiveFile=/rootfile.jsa An error has occurred while processing the shared archive file. Specified shared archive not found. Error occurred during initialization of VM Unable to use shared archive. Make sure /rootfile.jsa is not writable (use any file name, just make sure the directory is not writable). Try to confirm that the error messages are not in the above order. Hopefully they are NOT. That way after the fix is in, if they appear in the right order it will help to prove your fix is working. BTW, the first two lines are to stderr and the last two are to stdout. See the fail() function in filemap.cpp.
19-10-2015
After discussion with Chris Plummer, we agreed that we need to add fflush more general place. If VM creates an error message, there are 2 ways at the end. 1. Return to its caller: if we add 'fflush()' at JNI_CreateJavaVM_inner() when the result of Threads::create_vm() is not JNI_OK, a message from jvm.dll will be printed out correctly. 2. Call vm_abort(): I'm not sure how this case can be tested.
19-10-2015
Unlike other platforms, 'stderr' is buffered on Windows. And we are using two different 'stderr'. (JavaMain() is calling 'jvm.dll') JavaMain() is printing out 2 strings of "Error: Could not create the Java Virtual Machine.\nError: A fatal exception has occurred. Program will exit." and "\n" to stderr A. And constraint function(CommandLineError::print() from MinTLABSizeConstraintFunc()) is also printing "MinTLABSize (1) must be greater than or equal to reserved area in TLAB (16)\n" to stderr B. When VM exits stderr A from JavaMain() is flushed first and then stderr B from CommandLineError::print() (jvm.dll) is flushed later. Both functions are called on the same thread.
16-10-2015