java.lang.RuntimeException: 'Deflating object ' missing from stdout/stderr
Likely a regression due to JDK-8145153
Comments
The same issue also happened on Solaris
04-01-2016
According to Marcus Larsson:
I don't think it's a flushing problem, because all messages are flushed immediately after being written (see LogFileStreamOutput.cpp:60).
18-12-2015
When the VM is exiting it will go to a safepoint and not return, so I don't think the flush at the end of the VMThread::run loop would get hit in the termination case. The flush (as part of logging shutdown?) should happen right at the very end of the VM termination sequence.
If this can't be fixed "immediately" the test should be @ignored or excluded on Windows, if that is the only place it fails.
17-12-2015
It is a simple test failure for one feature not something that anyone will encounter. We could @ignore the test.
17-12-2015
Coleen, I think we can write a simple multi-thread program that's more predictable than relying on internal JDK implementation. Anyway, I changed that bug (JDK-8145606) to P4.
For this bug, I think the missing fflush should be added, so that we don't get surprises in future tests that may check on other log messages coming during VM thread shut down.
16-12-2015
The test also has problems. I have filed a separate bug for it: JDK-8145606
16-12-2015
The fix in JDK-8139801 is not complete. The flush is done here:
Breakpoint 4, JNI_CreateJavaVM_inner (vm=0x7ffff7fbbea0, penv=0x7ffff7fbbeb0, args=0x7ffff7fbbec0) at /home/iklam/jdk/jdk9_rt/hotspot/src/share/vm/prims/jni.cpp:4092
4092 fflush(stdout);
(gdb) where
#0 JNI_CreateJavaVM_inner (vm=0x7ffff7fbbea0, penv=0x7ffff7fbbeb0, args=0x7ffff7fbbec0) at /home/iklam/jdk/jdk9_rt/hotspot/src/share/vm/prims/jni.cpp:4092
#1 0x00007ffff66e6e77 in JNI_CreateJavaVM (vm=0x7ffff7fbbea0, penv=0x7ffff7fbbeb0, args=0x7ffff7fbbec0) at /home/iklam/jdk/jdk9_rt/hotspot/src/share/vm/prims/jni.cpp:4105
#2 0x00007ffff7fe80fc in JavaMain () from /jdk/bld/jdk9_rt/images/jdk/bin/../lib/amd64/jli/libjli.so
#3 0x00007ffff75fa182 in start_thread (arg=0x7ffff7fbc700) at pthread_create.c:312
#4 0x00007ffff7b0f30d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
But more print out is done afterwards:
(gdb) c
Continuing.
[Switching to Thread 0x7ffecfd83700 (LWP 31635)]
Breakpoint 2, ObjectSynchronizer::deflate_monitor (mid=0x7ffec0002b80, obj=0x411006db0, freeHeadp=0x7ffecfd828c8, freeTailp=0x7ffecfd828d0)
at /home/iklam/jdk/jdk9_rt/hotspot/src/share/vm/runtime/synchronizer.cpp:1515
1515 ObjectMonitor** freeTailp) {
(gdb) where
#0 ObjectSynchronizer::deflate_monitor (mid=0x7ffec0002b80, obj=0x411006db0, freeHeadp=0x7ffecfd828c8, freeTailp=0x7ffecfd828d0) at /home/iklam/jdk/jdk9_rt/hotspot/src/share/vm/runtime/synchronizer.cpp:1515
#1 0x00007ffff6bac2e8 in ObjectSynchronizer::deflate_idle_monitors () at /home/iklam/jdk/jdk9_rt/hotspot/src/share/vm/runtime/synchronizer.cpp:1649
#2 0x00007ffff6afe42c in SafepointSynchronize::do_cleanup_tasks () at /home/iklam/jdk/jdk9_rt/hotspot/src/share/vm/runtime/safepoint.cpp:491
#3 0x00007ffff6afdfed in SafepointSynchronize::begin () at /home/iklam/jdk/jdk9_rt/hotspot/src/share/vm/runtime/safepoint.cpp:380
#4 0x00007ffff6ca1036 in VMThread::loop (this=0x7ffff03f7000) at /home/iklam/jdk/jdk9_rt/hotspot/src/share/vm/runtime/vmThread.cpp:471
#5 0x00007ffff6ca0789 in VMThread::run (this=0x7ffff03f7000) at /home/iklam/jdk/jdk9_rt/hotspot/src/share/vm/runtime/vmThread.cpp:265
#6 0x00007ffff69fd1b9 in java_start (thread=0x7ffff03f7000) at /home/iklam/jdk/jdk9_rt/hotspot/src/os/linux/vm/os_linux.cpp:683
#7 0x00007ffff75fa182 in start_thread (arg=0x7ffecfd83700) at pthread_create.c:312
#8 0x00007ffff7b0f30d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
So we should add
fflush(stdout);
fflush(stderr);
to the end of VMThread::loop().
16-12-2015
The purpose of the test is to check as many logging messages come out as practical. I believe if we check just the inflation that would satisfy the requirements of testing this code change. Would the ReferenceQueue locks always be inflated? It seems so.
16-12-2015
This may be related to JDK-8139801 -- maybe the "Deflating" message, which would appear after the "-version" output (see Linux sample output below), was somehow cut off by Windows??
$ java -Xlog:monitorinflation=debug -version
[0.129s][debug ][monitorinflation] Inflating object 0x0000000411006db0 , mark 0x00007f6760002c02 , type java.lang.ref.Reference$Lock
[0.129s][debug ][monitorinflation] Inflating object 0x00000004110078b0 , mark 0x00007f6760004c02 , type java.lang.Object
[0.144s][debug ][monitorinflation] Inflating object 0x000000041100b1a0 , mark 0x00007f6760004b02 , type java.lang.ref.ReferenceQueue$Lock
java version "9-internal"
Java(TM) SE Runtime Environment (build 9-internal+0-2015-12-15-132951.iklam.jdk9rt)
Java HotSpot(TM) 64-Bit Server VM (build 9-internal+0-2015-12-15-132951.iklam.jdk9rt, mixed mode)
[0.226s][debug ][monitorinflation] Deflating object 0x00000004110078b0 , mark 0x00007f6760004c02 , type java.lang.Object
16-12-2015
ILW (m=reduced test coverage, h=regression, h=none) = P2