runtime/Thread/TestAlwaysPreTouchStacks.java failed with "Did not find expected NMT output"

The following test failed in the JDK21 CI:

runtime/Thread/TestAlwaysPreTouchStacks.java

Here's a snippet from the log file:

#section:driver
----------messages:(8/332)----------
command: driver TestAlwaysPreTouchStacks
reason: User specified action: run driver TestAlwaysPreTouchStacks
started: Sun Apr 02 09:50:31 UTC 2023
Mode: agentvm
Agent id: 20
Additional exports to unnamed modules from @modules: java.base/jdk.internal.misc
finished: Sun Apr 02 09:50:33 UTC 2023
elapsed time (seconds): 1.804
----------configuration:(15/1478)*----------

<snip>

----------System.out:(6/1719)*----------
Command line: [c:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-21+17-1363\\windows-x64-debug.jdk\\jdk-21\\fastdebug\\bin\\java.exe -cp C:\\sb\\prod\\1680428811\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_runtime\\classes\\0\\runtime\\Thread\\TestAlwaysPreTouchStacks.d;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jdk-21+17-1363\\src.full\\open\\test\\hotspot\\jtreg\\runtime\\Thread;C:\\sb\\prod\\1680428811\\testoutput\\test-support\\jtreg_open_test_hotspot_jtreg_tier1_runtime\\classes\\0\\test\\lib;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.1.1\\1\\bundles\\jtreg-7.1.1+1.zip\\jtreg\\lib\\jtreg.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.1.1\\1\\bundles\\jtreg-7.1.1+1.zip\\jtreg\\lib\\junit-platform-console-standalone-1.8.2.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.1.1\\1\\bundles\\jtreg-7.1.1+1.zip\\jtreg\\lib\\testng-7.3.0.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.1.1\\1\\bundles\\jtreg-7.1.1+1.zip\\jtreg\\lib\\jcommander-1.78.jar;C:\\ade\\mesos\\work_dir\\jib-master\\install\\jtreg\\7.1.1\\1\\bundles\\jtreg-7.1.1+1.zip\\jtreg\\lib\\guice-4.2.3.jar -XX:+UnlockDiagnosticVMOptions -Xmx100M -XX:+AlwaysPreTouchStacks -Xlog:os+thread=trace -XX:NativeMemoryTracking=summary -XX:+PrintNMTStatistics TestAlwaysPreTouchStacks test ]
[2023-04-02T09:50:32.882076200Z] Gathering output for process 17860
[2023-04-02T09:50:33.171528200Z] Waiting for completion for process 17860
[2023-04-02T09:50:33.187089800Z] Waiting for completion finished for process 17860
[2023-04-02T09:50:33.202767800Z] Waiting for completion for process 17860
[2023-04-02T09:50:33.202767800Z] Waiting for completion finished for process 17860
----------System.err:(243/18341)----------
 stdout: [[0.003s][info][os,thread] The SetThreadDescription API is available.
[0.005s][debug][os,thread] Thread 66880 stack guard pages activated: 0x00000092fbb00000-0x00000092fbb04000.
[0.024s][info ][os,thread] Thread "GC Thread#0" started (tid: 33636, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.025s][info ][os,thread] Thread "G1 Main Marker" started (tid: 80644, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.025s][info ][os,thread] Thread is alive (tid: 33636, stacksize: 1024k).
[0.025s][info ][os,thread] Thread "G1 Conc#0" started (tid: 90844, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.025s][debug][os,thread] Thread 33636 stack dimensions: 0x00000092fbc00000-0x00000092fbd00000 (1024k).
[0.025s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: GC Thread#0
[0.025s][info ][os,thread] Thread is alive (tid: 80644, stacksize: 1024k).
[0.025s][debug][os,thread] Thread 80644 stack dimensions: 0x00000092fbd00000-0x00000092fbe00000 (1024k).
[0.025s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: G1 Main Marker
[0.025s][info ][os,thread] Thread is alive (tid: 90844, stacksize: 1024k).
[0.025s][debug][os,thread] Thread 90844 stack dimensions: 0x00000092fbe00000-0x00000092fbf00000 (1024k).
[0.025s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: G1 Conc#0
[0.031s][info ][os,thread] Thread "G1 Refine#0" started (tid: 22980, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.031s][info ][os,thread] Thread "G1 Service" started (tid: 3448, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.031s][info ][os,thread] Thread is alive (tid: 22980, stacksize: 1024k).
[0.031s][debug][os,thread] Thread 22980 stack dimensions: 0x00000092fbf00000-0x00000092fc000000 (1024k).
[0.031s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: G1 Refine#0
[0.031s][info ][os,thread] Thread is alive (tid: 3448, stacksize: 1024k).
[0.031s][debug][os,thread] Thread 3448 stack dimensions: 0x00000092fc000000-0x00000092fc100000 (1024k).
[0.031s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: G1 Service
[0.064s][info ][os,thread] Thread "VM Thread" started (tid: 58272, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.064s][info ][os,thread] Thread is alive (tid: 58272, stacksize: 1024k).
[0.064s][debug][os,thread] Thread 58272 stack dimensions: 0x00000092fc100000-0x00000092fc200000 (1024k).
[0.064s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: VM Thread
[0.097s][info ][os,thread] Thread "Unknown thread" started (tid: 75432, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.098s][info ][os,thread] Thread is alive (tid: 75432, stacksize: 1024k).
[0.098s][debug][os,thread] Thread 75432 stack dimensions: 0x00000092fc200000-0x00000092fc300000 (1024k).
[0.098s][info ][os,thread] Thread "Unknown thread" started (tid: 7668, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.098s][debug][os,thread] Thread 75432 stack guard pages activated: 0x00000092fc200000-0x00000092fc204000.
[0.098s][info ][os,thread] Thread is alive (tid: 7668, stacksize: 1024k).
[0.098s][debug][os,thread] Thread 7668 stack dimensions: 0x00000092fc300000-0x00000092fc400000 (1024k).
[0.098s][debug][os,thread] Thread 7668 stack guard pages activated: 0x00000092fc300000-0x00000092fc304000.
[0.099s][info ][os,thread] Thread "Unknown thread" started (tid: 59544, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.099s][trace][os,thread] Pretouching thread stack from 0x00000092fc20fff0 to 0x00000092fc210000.
[0.099s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: Reference Handler
[0.099s][info ][os,thread] Thread "Unknown thread" started (tid: 55976, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.099s][info ][os,thread] Thread is alive (tid: 59544, stacksize: 1024k).
[0.099s][trace][os,thread] Pretouching thread stack from 0x00000092fc30fff0 to 0x00000092fc310000.
[0.123s][debug][os,thread] Thread 59544 stack dimensions: 0x00000092fc400000-0x00000092fc500000 (1024k).
[0.123s][debug][os,thread] Thread 59544 stack guard pages activated: 0x00000092fc400000-0x00000092fc404000.
[0.123s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: Finalizer
[0.123s][info ][os,thread] Thread "Unknown thread" started (tid: 61584, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.123s][info ][os,thread] Thread is alive (tid: 55976, stacksize: 1024k).
[0.123s][debug][os,thread] Thread 55976 stack dimensions: 0x00000092fc500000-0x00000092fc600000 (1024k).
[0.123s][debug][os,thread] Thread 55976 stack guard pages activated: 0x00000092fc500000-0x00000092fc504000.
[0.123s][info ][os,thread] Thread "Unknown thread" started (tid: 40444, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.123s][info ][os,thread] Thread "Unknown thread" started (tid: 13808, attributes: stacksize: 1024k, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS_A)
[0.123s][info ][os,thread] Thread is alive (tid: 40444, stacksize: 1024k).
[0.123s][debug][os,thread] Thread 40444 stack dimensions: 0x00000092fc700000-0x00000092fc800000 (1024k).
[0.123s][info ][os,thread] Thread is alive (tid: 61584, stacksize: 1024k).
[0.123s][debug][os,thread] Thread 40444 stack guard pages activated: 0x00000092fc700000-0x00000092fc704000.
[0.123s][debug][os,thread] Thread 61584 stack dimensions: 0x00000092fc600000-0x00000092fc700000 (1024k).
[0.123s][info ][os,thread] Thread is alive (tid: 13808, stacksize: 1024k).
[0.123s][debug][os,thread] Thread 61584 stack guard pages activated: 0x00000092fc600000-0x00000092fc604000.
[0.123s][debug][os,thread] Thread 13808 stack dimensions: 0x00000092fc800000-0x00000092fc900000 (1024k).
[0.124s][info ][os,thread] Thread "Unknown thread" started (tid: 18744, attributes: stacksize: 1024k, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS_A)
[0.124s][debug][os,thread] Thread 13808 stack guard pages activated: 0x00000092fc800000-0x00000092fc804000.
[0.124s][info ][os,thread] Thread is alive (tid: 18744, stacksize: 1024k).
[0.124s][debug][os,thread] Thread 18744 stack dimensions: 0x00000092fc900000-0x00000092fca00000 (1024k).
[0.124s][debug][os,thread] Thread 18744 stack guard pages activated: 0x00000092fc900000-0x00000092fc904000.
[0.125s][trace][os,thread] Pretouching thread stack from 0x00000092fc40fff0 to 0x00000092fc410000.
[0.125s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: Signal Dispatcher
[0.126s][trace][os,thread] Pretouching thread stack from 0x00000092fc50fff0 to 0x00000092fc510000.
[0.126s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: Attach Listener
[0.126s][trace][os,thread] Pretouching thread stack from 0x00000092fc80fff0 to 0x00000092fc810000.
[0.126s][trace][os,thread] Pretouching thread stack from 0x00000092fc70fff0 to 0x00000092fc710000.
[0.126s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: C2 CompilerThread0
[0.126s][trace][os,thread] Pretouching thread stack from 0x00000092fc90fff0 to 0x00000092fc910000.
[0.126s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: Monitor Deflation Thread
[0.126s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: C1 CompilerThread0
[0.127s][trace][os,thread] Pretouching thread stack from 0x00000092fc60fff0 to 0x00000092fc610000.
[0.127s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: Service Thread
[0.186s][info ][os,thread] Thread "Unknown thread" started (tid: 23748, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.186s][info ][os,thread] Thread is alive (tid: 23748, stacksize: 1024k).
[0.186s][debug][os,thread] Thread 23748 stack dimensions: 0x00000092fca00000-0x00000092fcb00000 (1024k).
[0.186s][debug][os,thread] Thread 23748 stack guard pages activated: 0x00000092fca00000-0x00000092fca04000.
[0.187s][trace][os,thread] Pretouching thread stack from 0x00000092fca0fff0 to 0x00000092fca10000.
[0.187s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: Notification Thread
[0.188s][info ][os,thread] Thread "VM Periodic Task Thread" started (tid: 4996, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.188s][info ][os,thread] Thread is alive (tid: 4996, stacksize: 1024k).
[0.188s][debug][os,thread] Thread 4996 stack dimensions: 0x00000092fcb00000-0x00000092fcc00000 (1024k).
[0.188s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: VM Periodic Task Thread
[0.196s][info ][os,thread] Thread "Unknown thread" started (tid: 73368, attributes: stacksize: default, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS)
[0.197s][info ][os,thread] Thread is alive (tid: 73368, stacksize: 1024k).
[0.197s][debug][os,thread] Thread 73368 stack dimensions: 0x00000092fcc00000-0x00000092fcd00000 (1024k).
[0.197s][debug][os,thread] Thread 73368 stack guard pages activated: 0x00000092fcc00000-0x00000092fcc04000.
[0.197s][trace][os,thread] Pretouching thread stack from 0x00000092fcc0fff0 to 0x00000092fcc10000.
[0.197s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: Common-Cleaner
[0.266s][info ][os,thread] Thread "Unknown thread" started (tid: 4636, attributes: stacksize: 256k, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS_A_)
[0.266s][info ][os,thread] Thread "Unknown thread" started (tid: 97680, attributes: stacksize: 512k, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS_A_)
[0.266s][info ][os,thread] Thread is alive (tid: 4636, stacksize: 256k).
[0.266s][info ][os,thread] Thread "Unknown thread" started (tid: 26540, attributes: stacksize: 3072k, flags: CREATE_SUSPENDED STACK_SIZE_PARAM_IS_A)
[0.266s][debug][os,thread] Thread 4636 stack dimensions: 0x00000092fb5a0000-0x00000092fb5e0000 (256k).
[0.266s][debug][os,thread] Thread 4636 stack guard pages activated: 0x00000092fb5a0000-0x00000092fb5a4000.
[0.266s][info ][os,thread] Thread is alive (tid: 97680, stacksize: 512k).
[0.266s][debug][os,thread] Thread 97680 stack dimensions: 0x00000092fcd00000-0x00000092fcd80000 (512k).
[0.266s][debug][os,thread] Thread 97680 stack guard pages activated: 0x00000092fcd00000-0x00000092fcd04000.
[0.267s][info ][os,thread] Thread is alive (tid: 26540, stacksize: 3072k).
[0.267s][trace][os,thread] Pretouching thread stack from 0x00000092fb5afff0 to 0x00000092fb5b0000.
[0.267s][debug][os,thread] Thread 26540 stack dimensions: 0x00000092fcd80000-0x00000092fd080000 (3072k).
[0.267s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: Thread-262144
[0.267s][debug][os,thread] Thread 26540 stack guard pages activated: 0x00000092fcd80000-0x00000092fcd84000.
[0.267s][trace][os,thread] Pretouching thread stack from 0x00000092fcd0fff0 to 0x00000092fcd10000.
[0.267s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: Thread-524288
Alive: 262144
[0.269s][debug][os,thread] Thread 4636 stack guard pages removed: 0x00000092fb5a0000-0x00000092fb5a4000.
Alive: 524288
[0.269s][info ][os,thread] JavaThread exiting (tid: 4636).
[0.269s][debug][os,thread] Thread 97680 stack guard pages removed: 0x00000092fcd00000-0x00000092fcd04000.
[0.269s][info ][os,thread] Thread finished (tid: 4636).
[0.269s][info ][os,thread] JavaThread exiting (tid: 97680).
[0.269s][info ][os,thread] Thread finished (tid: 97680).
[0.269s][trace][os,thread] Pretouching thread stack from 0x00000092fcd8fff0 to 0x00000092fcd90000.
[0.269s][trace][os,thread] set_native_thread_name: SetThreadDescription succeeded - new name: Thread-3145728
Alive: 3145728
[0.270s][debug][os,thread] Thread 26540 stack guard pages removed: 0x00000092fcd80000-0x00000092fcd84000.
[0.270s][debug][os,thread] Thread 66880 stack guard pages removed: 0x00000092fbb00000-0x00000092fbb04000.
[0.270s][info ][os,thread] JavaThread exiting (tid: 26540).
[0.270s][info ][os,thread] JavaThread detaching (tid: 66880).
[0.270s][info ][os,thread] Thread finished (tid: 26540).
[0.270s][info ][os,thread] Thread attached (tid: 66880, stack: 0x00000092fbc00000 - 0x00000092fbb00000 (1048576k) ).
[0.270s][debug][os,thread] Thread 66880 stack guard pages activated: 0x00000092fbb00000-0x00000092fbb04000.
[0.271s][info ][os,thread] Thread finished (tid: 4996).
[0.271s][info ][os,thread] Thread finished (tid: 22980).
[0.271s][info ][os,thread] Thread finished (tid: 3448).
[0.271s][info ][os,thread] Thread finished (tid: 80644).

Native Memory Tracking:

Total: reserved=1589829842, committed=199098578
       malloc: 26263762 #34962
       mmap: reserved=1563566080, committed=172834816

- Java Heap (reserved=104857600, committed=104857600)
[0.272s][debug][os,thread] Thread 59544 stack guard pages removed: 0x00000092fc400000-0x00000092fc404000.
                            (mmap: reserved=104857600, committed=104857600)
 
- Class (reserved=1073821395, committed=210643[0.272s][info ][os,thread] JavaThread exiting (tid: 59544).
)
                            (classes #715)
                            ( instance classes #609, array classes #106)
                            (malloc=79571 #1612) (peak=80507 #1610)
                            (mmap: reserved=1073741824, committed=131072)
                            ( Metadata: )
                            ( reserved=67108864, committed=327680)
                            ( used=254704)
                            ( waste=72976 =22.27%)
                            ( Class space:)
                            ( reserved=1073741824, committed=131072)
                            ( used=12240)
                            ( waste=118832 =90.66%)
 
- Thread (reserved=14727016, committed=10463080)
                            (thread #14)
                            (stack: [0.272s][info ][os,thread] Thread finished (tid: 59544).
reserved=14680064, committed=10416128)
                            (malloc=27320 #112) (peak=40888 #134)
                            (arena=19632 #34) (peak=173336 #34)
 
- Code (reserved=254159544, committed=8198840)
                            (malloc=469688 #14867) (peak=469752 #14870)
                            (mmap: reserved=253689856, committed=7729152)
                            (arena=0 #0) (peak=33712 #1)
 
- GC (reserved=57264062, committed=57149374)
                            (malloc=21481406 #508) (peak=21481526 #511)
                            (mmap: reserved=35782656, committed=35667968)
 
- GCCardSet (reserved=23432, committed=23432)
                            (malloc=23432 #303) (at peak)
 
- Compiler (reserved=206904, committed=206904)
                            (malloc=5616 #44) (peak=5752 #45)
                            (arena=201288 #5) (peak=1478664 #6)
 
- Internal (reserved=538564, committed=538564)
                            (malloc=473028 #11302) (peak=476840 #11308)
                            (mmap: reserved=65536, committed=65536)
 
- Symbol (reserved=1275632, committed=1275632)
                            (malloc=906992 #3148) (at peak)
                            (arena=368640 #1) (at peak)
 
- Native Memory Tracking (reserved=565712, committed=565712)
                            (malloc=6320 #61) (peak=7456 #71)
                            (tracking overhead=559392)
 
- Shared class space (reserved=13631488, committed=13631488, readonly=0)
                            (mmap: reserved=13631488, committed=13631488)
 
- Arena Chunk (reserved=1328408, committed=1328408)
                            (malloc=1328408 #96) (peak=2006232 #98)
 
- Tracing (reserved=321, committed=321)
                            (malloc=321 #9) (at peak)
 
- Statistics (reserved=128, committed=128)
                            (malloc=128 #2) (at peak)
 
- Arguments (reserved=212, committed=212)
                            (malloc=212 #5) (at peak)
 
- Module (reserved=204264, committed=204264)
                            (malloc=204264 #2075) (at peak)
 
- Safepoint (reserved=8192, committed=8192)
                            (mmap: reserved=8192, committed=8192)
 
- Synchronization (reserved=76976, committed=76976)
                            (malloc=76976 #788) (at peak)
 
- Serviceability (reserved=17104, committed=17104)
                            (malloc=17104 #9) (at peak)
 
- Metaspace (reserved=67121424, committed=340240)
                            (malloc=12560 #9) (at peak)
                            (mmap: reserved=67108864, committed=327680)
 
- String Deduplication (reserved=632, committed=632)
                            (malloc=632 #8) (at peak)
 
- Object Monitors (reserved=832, committed=832)
                            (malloc=832 #4) (at peak)
 
[0.272s][debug][os,thread] Thread 66880 stack guard pages removed: 0x00000092fbb00000-0x00000092fbb04000.
[0.272s][info ][os,thread] JavaThread exiting (tid: 66880).
[0.299s][info ][os,thread] Thread finished (tid: 58272).
];
 stderr: []
 exitValue = 0

java.lang.RuntimeException: Did not find expected NMT output
at TestAlwaysPreTouchStacks.main(TestAlwaysPreTouchStacks.java:119)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
at java.base/java.lang.reflect.Method.invoke(Method.java:578)
at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:312)
at java.base/java.lang.Thread.run(Thread.java:1623)

JavaTest Message: Test threw exception: java.lang.RuntimeException
JavaTest Message: shutting down test

result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: Did not find expected NMT output


This is a newly added test with the fix for:

JDK-8294266 Add a way to pre-touch java thread stacks