Bug ID: JDK-8211366 gc/g1/TestLargePageUseForAuxMemory.java intermittently times out on Windows

JDK-8211366 : gc/g1/TestLargePageUseForAuxMemory.java intermittently times out on Windows

Type: Bug
Component: core-libs
Sub-Component: java.lang
Affected Version: 12

Priority: P4
Status: Resolved
Resolution: Cannot Reproduce

Submitted: 2018-10-02
Updated: 2020-11-09
Resolved: 2020-11-09

Versions (Unresolved/Resolved/Fixed)

The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.

Other
tbdResolved

Related Reports

Relates :

JDK-8217170 - gc/arguments/TestUseCompressedOopsErgo.java timed out

Description

Test gc/g1/TestLargePageUseForAuxMemory.java times out on Windows. It happens 1 time in about 1000 runs.

Failure has been seen in jdk 12-12 and jdk12-13.

Test is hanging by waiting results with child process. I haven't to find any info about child process in logs/artifacts for test run.

The java stack for test is:
----------------------------------------
[2018-09-29 21:14:45] [C:\ade\mesos\work_dir\jib-master\install\jdk\12\13\windows-x64-debug.jdk\jdk-12\fastdebug\bin\jstack.exe, 16176] timeout=20000
----------------------------------------
2018-09-29 21:14:47
Full thread dump Java HotSpot(TM) 64-Bit Server VM (12-ea+13 mixed mode):

Threads class SMR info:
_java_thread_list=0x00000051f9355f80, length=13, elements={
0x00000051d368f000, 0x00000051f7ba3800, 0x00000051f7bad800, 0x00000051f7c0b000,
0x00000051f7c0c000, 0x00000051f7c0e800, 0x00000051f7c13000, 0x00000051f7c1d000,
0x00000051f7eb9000, 0x00000051f802b000, 0x00000051f818a800, 0x00000051f8fc6800,
0x00000051f92bc000
}
_java_thread_list_alloc_cnt=42, _java_thread_list_free_cnt=41, _java_thread_list_max=13, _nested_thread_list_max=1
_tlh_cnt=3836, _tlh_times=126, avg_tlh_time=0.03, _tlh_time_max=122
_deleted_thread_cnt=14, _deleted_thread_times=0, avg_deleted_thread_time=0.00, _deleted_thread_time_max=0
_delete_lock_wait_cnt=0, _delete_lock_wait_max=0
_to_delete_list_cnt=0, _to_delete_list_max=1

"main" #1 prio=5 os_prio=0 cpu=414015.63ms elapsed=1265.27s tid=0x00000051d368f000 nid=0x5200 in Object.wait()  [0x00000051d2e2f000]
   java.lang.Thread.State: WAITING (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00000051d368f000  [0x5200] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Object.wait(java.base@12-ea/Native Method)
	- waiting on <0x00000007178a7490> (a java.lang.Thread)
	at java.lang.Thread.join(java.base@12-ea/Thread.java:1308)
	- waiting to re-lock in wait() <0x00000007178a7490> (a java.lang.Thread)
	at java.lang.Thread.join(java.base@12-ea/Thread.java:1375)
	at com.sun.javatest.regtest.agent.MainWrapper.main(MainWrapper.java:74)

"Reference Handler" #2 daemon prio=10 os_prio=2 cpu=0.00ms elapsed=677.22s tid=0x00000051f7ba3800 nid=0x7728 waiting on condition  [0x00000051f848f000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00000051f7ba3800  [0x7728] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.ref.Reference.waitForReferencePendingList(java.base@12-ea/Native Method)
	at java.lang.ref.Reference.processPendingReferences(java.base@12-ea/Reference.java:241)
	at java.lang.ref.Reference$ReferenceHandler.run(java.base@12-ea/Reference.java:213)

"Finalizer" #3 daemon prio=8 os_prio=1 cpu=0.00ms elapsed=677.21s tid=0x00000051f7bad800 nid=0x91a0 in Object.wait()  [0x00000051f858e000]
   java.lang.Thread.State: WAITING (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00000051f7bad800  [0x91a0] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Object.wait(java.base@12-ea/Native Method)
	- waiting on <0x00000007178e1cc8> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@12-ea/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x00000007178e1cc8> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@12-ea/ReferenceQueue.java:176)
	at java.lang.ref.Finalizer$FinalizerThread.run(java.base@12-ea/Finalizer.java:170)

"Signal Dispatcher" #4 daemon prio=9 os_prio=2 cpu=0.00ms elapsed=677.11s tid=0x00000051f7c0b000 nid=0x80b8 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00000051f7c0b000  [0x80b8] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Attach Listener" #5 daemon prio=5 os_prio=2 cpu=281.25ms elapsed=677.11s tid=0x00000051f7c0c000 nid=0x54f0 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00000051f7c0c000  [0x54f0] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"C2 CompilerThread0" #6 daemon prio=9 os_prio=2 cpu=546.88ms elapsed=677.11s tid=0x00000051f7c0e800 nid=0x76c0 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00000051f7c0e800  [0x76c0] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
   No compile task

"C1 CompilerThread0" #9 daemon prio=9 os_prio=2 cpu=1093.75ms elapsed=677.11s tid=0x00000051f7c13000 nid=0x4d38 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00000051f7c13000  [0x4d38] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
   No compile task

"Sweeper thread" #10 daemon prio=9 os_prio=2 cpu=0.00ms elapsed=677.11s tid=0x00000051f7c1d000 nid=0x2928 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00000051f7c1d000  [0x2928] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"Common-Cleaner" #11 daemon prio=8 os_prio=1 cpu=0.00ms elapsed=676.86s tid=0x00000051f7eb9000 nid=0xe50 in Object.wait()  [0x00000051f8b8e000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
   JavaThread state: _thread_blocked
Thread: 0x00000051f7eb9000  [0xe50] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at java.lang.Object.wait(java.base@12-ea/Native Method)
	- waiting on <0x00000007178cc190> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(java.base@12-ea/ReferenceQueue.java:155)
	- waiting to re-lock in wait() <0x00000007178cc190> (a java.lang.ref.ReferenceQueue$Lock)
	at jdk.internal.ref.CleanerImpl.run(java.base@12-ea/CleanerImpl.java:148)
	at java.lang.Thread.run(java.base@12-ea/Thread.java:835)
	at jdk.internal.misc.InnocuousThread.run(java.base@12-ea/InnocuousThread.java:134)

"Service Thread" #12 daemon prio=9 os_prio=0 cpu=0.00ms elapsed=676.72s tid=0x00000051f802b000 nid=0x3f98 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_blocked
Thread: 0x00000051f802b000  [0x3f98] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked

"MainThread" #14 prio=5 os_prio=0 cpu=546.88ms elapsed=676.54s tid=0x00000051f818a800 nid=0x92e4 waiting on condition  [0x00000051f9e5e000]
   java.lang.Thread.State: WAITING (parking)
   JavaThread state: _thread_blocked
Thread: 0x00000051f818a800  [0x92e4] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_blocked
	at jdk.internal.misc.Unsafe.park(java.base@12-ea/Native Method)
	- parking to wait for  <0x000000071817c1e8> (a java.util.concurrent.FutureTask)
	at java.util.concurrent.locks.LockSupport.park(java.base@12-ea/LockSupport.java:194)
	at java.util.concurrent.FutureTask.awaitDone(java.base@12-ea/FutureTask.java:447)
	at java.util.concurrent.FutureTask.get(java.base@12-ea/FutureTask.java:190)
	at jdk.test.lib.process.OutputBuffer$LazyOutputBuffer$StreamTask.get(OutputBuffer.java:79)
	at jdk.test.lib.process.OutputBuffer$LazyOutputBuffer.getStderr(OutputBuffer.java:107)
	at jdk.test.lib.process.OutputAnalyzer.getStderr(OutputAnalyzer.java:502)
	at jdk.test.lib.process.OutputAnalyzer.firstMatch(OutputAnalyzer.java:386)
	at TestLargePageUseForAuxMemory.checkSize(TestLargePageUseForAuxMemory.java:56)
	at TestLargePageUseForAuxMemory.checkSmallTables(TestLargePageUseForAuxMemory.java:71)
	at TestLargePageUseForAuxMemory.testVM(TestLargePageUseForAuxMemory.java:110)
	at TestLargePageUseForAuxMemory.main(TestLargePageUseForAuxMemory.java:169)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@12-ea/Native Method)
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@12-ea/NativeMethodAccessorImpl.java:62)
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@12-ea/DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(java.base@12-ea/Method.java:566)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127)
	at java.lang.Thread.run(java.base@12-ea/Thread.java:835)

"Thread-15" #29 daemon prio=5 os_prio=0 cpu=15.63ms elapsed=0.12s tid=0x00000051f8fc6800 nid=0x7718 runnable  [0x00000051f9f5e000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_in_native
Thread: 0x00000051f8fc6800  [0x7718] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_in_native
	at java.io.FileInputStream.readBytes(java.base@12-ea/Native Method)
	at java.io.FileInputStream.read(java.base@12-ea/FileInputStream.java:279)
	at java.io.BufferedInputStream.read1(java.base@12-ea/BufferedInputStream.java:290)
	at java.io.BufferedInputStream.read(java.base@12-ea/BufferedInputStream.java:351)
	- locked <0x0000000718179b58> (a java.io.BufferedInputStream)
	at java.io.BufferedInputStream.fill(java.base@12-ea/BufferedInputStream.java:252)
	at java.io.BufferedInputStream.read1(java.base@12-ea/BufferedInputStream.java:292)
	at java.io.BufferedInputStream.read(java.base@12-ea/BufferedInputStream.java:351)
	- locked <0x000000071817f1a8> (a java.io.BufferedInputStream)
	at java.io.FilterInputStream.read(java.base@12-ea/FilterInputStream.java:107)
	at jdk.test.lib.process.StreamPumper.run(StreamPumper.java:109)
	at java.util.concurrent.Executors$RunnableAdapter.call(java.base@12-ea/Executors.java:515)
	at java.util.concurrent.FutureTask.run(java.base@12-ea/FutureTask.java:264)
	at java.lang.Thread.run(java.base@12-ea/Thread.java:835)

"Thread-16" #30 daemon prio=5 os_prio=0 cpu=15.63ms elapsed=0.12s tid=0x00000051f92bc000 nid=0x8fec runnable  [0x00000051fa05e000]
   java.lang.Thread.State: RUNNABLE
   JavaThread state: _thread_in_native
Thread: 0x00000051f92bc000  [0x8fec] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
   JavaThread state: _thread_in_native
	at java.io.FileInputStream.readBytes(java.base@12-ea/Native Method)
	at java.io.FileInputStream.read(java.base@12-ea/FileInputStream.java:279)
	at java.io.BufferedInputStream.fill(java.base@12-ea/BufferedInputStream.java:252)
	at java.io.BufferedInputStream.read1(java.base@12-ea/BufferedInputStream.java:292)
	at java.io.BufferedInputStream.read(java.base@12-ea/BufferedInputStream.java:351)
	- locked <0x0000000718182f40> (a java.io.BufferedInputStream)
	at java.io.FilterInputStream.read(java.base@12-ea/FilterInputStream.java:107)
	at jdk.test.lib.process.StreamPumper.run(StreamPumper.java:109)
	at java.util.concurrent.Executors$RunnableAdapter.call(java.base@12-ea/Executors.java:515)
	at java.util.concurrent.FutureTask.run(java.base@12-ea/FutureTask.java:264)
	at java.lang.Thread.run(java.base@12-ea/Thread.java:835)

"VM Thread" os_prio=2 cpu=703.13ms elapsed=677.26s tid=0x00000051f7b79800 nid=0x5738 runnable  

"GC Thread#0" os_prio=2 cpu=140.63ms elapsed=1265.22s tid=0x00000051d36af800 nid=0xb184 runnable  

"GC Thread#1" os_prio=2 cpu=140.63ms elapsed=11.51s tid=0x00000051f7c2c000 nid=0x9fdc runnable  

"GC Thread#2" os_prio=2 cpu=140.63ms elapsed=11.51s tid=0x00000051f7c2e800 nid=0xe58 runnable  

"GC Thread#3" os_prio=2 cpu=15.63ms elapsed=11.51s tid=0x00000051f7c2f800 nid=0xa4b4 runnable  

"GC Thread#4" os_prio=2 cpu=15.63ms elapsed=11.51s tid=0x00000051f7c30000 nid=0x7bc0 runnable  

"GC Thread#5" os_prio=2 cpu=109.38ms elapsed=11.51s tid=0x00000051f93f2800 nid=0x52dc runnable  

"GC Thread#6" os_prio=2 cpu=156.25ms elapsed=11.51s tid=0x00000051f93f3000 nid=0xbaa8 runnable  

"GC Thread#7" os_prio=2 cpu=125.00ms elapsed=11.51s tid=0x00000051f93f5800 nid=0x31b0 runnable  

"G1 Main Marker" os_prio=2 cpu=15.63ms elapsed=677.48s tid=0x00000051d36e4800 nid=0x4034 runnable  

"G1 Conc#0" os_prio=2 cpu=0.00ms elapsed=677.47s tid=0x00000051d36e6000 nid=0x2b58 runnable  

"G1 Refine#0" os_prio=2 cpu=0.00ms elapsed=677.38s tid=0x00000051f6c84000 nid=0x1e24 runnable  

"G1 Young RemSet Sampling" os_prio=2 cpu=62.50ms elapsed=677.38s tid=0x00000051f6c86800 nid=0x20a0 runnable  
"VM Periodic Task Thread" os_prio=2 cpu=421.88ms elapsed=676.71s tid=0x00000051f805d800 nid=0xb2f4 waiting on condition  

JNI global refs: 8, weak refs: 0

----------------------------------------
[2018-09-29 21:14:47] exit code: 0 time: 1854 ms
----------------------------------------

Comments

There have been no reports of this test failing recently.
09-11-2020
I'm wondering if it can be an OS bug, and Windows just don't close the handles.
01-02-2019
so far, the issue happened tree times on different windows hosts, all these hosts have os_description:Windows_Server_2012_R2_Standard and os_version:6.3 .
01-02-2019
I don't see any obvious problems w/ OutputAnalyzer, OutputBuffer, and StreamPumper classes. what is strange is that `wmic process where ParentProcessId=9564 get ProcessId` reported two children for 9564, while there are, as Roger mentioned, 'process reaper' threads and test threads waiting for these processes to finish.
01-02-2019
The thread dump does not include any thread waiting on the process or any "process reaper" threads. So its not explicitly waiting on a Process event. The StreamPumpers are still waiting for EOF or an exception. Windows should have closed the in/out/err handles when the process terminates.
01-02-2019
although JDK-8217170 and JDK-8176214 can be explained by JDK-8218197, this bug can't as we don't kill processes on windows.
01-02-2019
moved to core-libs/java.lang due to the same reason as JDK-8217170 -- java.lang.Process::waitFor appears to be waiting for an already dead sub-process.
23-01-2019
Kindly asking the maintainers of the test library to look into this issue that apart from the test does not seem to have any connection to GC, but at least related to the use of the test library (where I hope I got the correct component/subcomponent for the CR for). There is also JDK-8217170 that is very similar to this one.
23-01-2019
JDK-8217170 seems to be quite similar to this one, waiting endlessly for an exit value from an already dead sub-process, although it seemingly only occurred once and on Linux.
23-01-2019
All of these seem to be stuck retrieving stderr output from a subprocess that is already dead: at jdk.internal.misc.Unsafe.park(java.base@12-internal/Native Method) - parking to wait for <0x000000008ff52100> (a java.util.concurrent.FutureTask) at java.util.concurrent.locks.LockSupport.park(java.base@12-internal/LockSupport.java:194) at java.util.concurrent.FutureTask.awaitDone(java.base@12-internal/FutureTask.java:447) at java.util.concurrent.FutureTask.get(java.base@12-internal/FutureTask.java:190) at jdk.test.lib.process.OutputBuffer$LazyOutputBuffer$StreamTask.get(OutputBuffer.java:79) at jdk.test.lib.process.OutputBuffer$LazyOutputBuffer.getStderr(OutputBuffer.java:107) at jdk.test.lib.process.OutputAnalyzer.getStderr(OutputAnalyzer.java:502) at jdk.test.lib.process.OutputAnalyzer.firstMatch(OutputAnalyzer.java:386) at TestLargePageUseForAuxMemory.checkSize(TestLargePageUseForAuxMemory.java:56) at TestLargePageUseForAuxMemory.checkSmallTables(TestLargePageUseForAuxMemory.java:71) at TestLargePageUseForAuxMemory.testVM(TestLargePageUseForAuxMemory.java:95) at TestLargePageUseForAuxMemory.main(TestLargePageUseForAuxMemory.java:155) at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(java.base@12-internal/Native Method) at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(java.base@12-internal/NativeMethodAccessorImpl.java:62) at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(java.base@12-internal/DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(java.base@12-internal/Method.java:567) at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:127) at java.lang.Thread.run(java.base@12-internal/Thread.java:835) and two other Java threads looking for data in stdout/stderr.
23-01-2019