-
Bug
-
Resolution: Fixed
-
P4
-
20, 21, 22, 23
-
b05
Issue | Fix Version | Assignee | Priority | Status | Resolution | Resolved In Build |
---|---|---|---|---|---|---|
JDK-8324378 | 22.0.1 | Thomas Schatzl | P4 | Resolved | Fixed | b02 |
JDK-8323649 | 22 | Thomas Schatzl | P4 | Resolved | Fixed | b32 |
The following test failed in the JDK23 CI:
gc/g1/TestSkipRebuildRemsetPhase.java
Here's a snippet from the log file:
#section:driver
----------messages:(7/258)----------
command: driver gc.g1.TestSkipRebuildRemsetPhase
reason: User specified action: run driver gc.g1.TestSkipRebuildRemsetPhase
started: Fri Jan 05 11:16:56 UTC 2024
Mode: agentvm
Agent id: 9
finished: Fri Jan 05 11:16:57 UTC 2024
elapsed time (seconds): 0.418
----------configuration:(14/1870)----------
<snip>
----------System.out:(5/2017)----------
Command line: [/opt/mach5/mesos/work_dir/jib-master/install/jdk-23+5-209/linux-aarch64-debug.jdk/jdk-23/fastdebug/bin/java -cp /opt/mach5/mesos/work_dir/slaves/6a6709c5-8dd0-4c1a-8549-7a448290c389-S4087/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/46963134-5f49-451d-96b4-0af17157be99/runs/922e5e36-c5c6-45f6-9603-3f333cd4a70c/testoutput/test-support/jtreg_open_test_hotspot_jtreg_tier1_gc_1/classes/1/gc/g1/TestSkipRebuildRemsetPhase.d:/opt/mach5/mesos/work_dir/jib-master/install/jdk-23+5-209/src.full/open/test/hotspot/jtreg/gc/g1:/opt/mach5/mesos/work_dir/slaves/6a6709c5-8dd0-4c1a-8549-7a448290c389-S4087/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/46963134-5f49-451d-96b4-0af17157be99/runs/922e5e36-c5c6-45f6-9603-3f333cd4a70c/testoutput/test-support/jtreg_open_test_hotspot_jtreg_tier1_gc_1/classes/1/test/lib:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/7.3.1/1/bundles/jtreg-7.3.1+1.zip/jtreg/lib/jtreg.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/7.3.1/1/bundles/jtreg-7.3.1+1.zip/jtreg/lib/junit-platform-console-standalone-1.9.2.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/7.3.1/1/bundles/jtreg-7.3.1+1.zip/jtreg/lib/testng-7.3.0.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/7.3.1/1/bundles/jtreg-7.3.1+1.zip/jtreg/lib/jcommander-1.82.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/7.3.1/1/bundles/jtreg-7.3.1+1.zip/jtreg/lib/guice-5.1.0.jar -Xbootclasspath/a:. -XX:+UseG1GC -XX:+UnlockExperimentalVMOptions -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -XX:G1MixedGCLiveThresholdPercent=20 -Xlog:gc+marking=debug,gc+phases=debug,gc+remset+tracking=trace -Xms10M -Xmx10M gc.g1.TestSkipRebuildRemsetPhase$GCTest ]
[2024-01-05T11:16:57.014543358Z] Gathering output for process 11606
[2024-01-05T11:16:57.027737409Z] Waiting for completion for process 11606
[2024-01-05T11:16:57.303702851Z] Waiting for completion finished for process 11606
Output and diagnostic info for process 11606 was saved into 'pid-11606-output.log'
----------System.err:(227/23651)----------
stdout: [[0.232s][debug][gc,phases] GC(0) Phase 1: Reference Processing 0.153ms
[0.232s][debug][gc,phases] GC(0) VM Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 4, Avg: 4.0, Max: 4, Diff: 0, Sum: 4, Workers: 1
[0.232s][debug][gc,phases] GC(0) ObjectSynchronizer Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 1, Workers: 1
[0.232s][debug][gc,phases] GC(0) JVMTI Tag Weak OopStorage Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) StringTable Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 1, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 45, Avg: 45.0, Max: 45, Diff: 0, Sum: 45, Workers: 1
[0.232s][debug][gc,phases] GC(0) ResolvedMethodTable Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 2, Avg: 2.0, Max: 2, Diff: 0, Sum: 2, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 50, Avg: 50.0, Max: 50, Diff: 0, Sum: 50, Workers: 1
[0.232s][debug][gc,phases] GC(0) JNI Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) StringDedup Table Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) StringDedup Requests0 Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) StringDedup Requests1 Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Weak JFR Old Object Samples Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Phase 1: Weak Processing 0.648ms
[0.232s][debug][gc,phases] GC(0) ClassLoaderData 0.002ms
[0.232s][debug][gc,phases] GC(0) Trigger cleanups 0.000ms
[0.233s][debug][gc,phases] GC(0) G1 Complete Cleaning 0.367ms
[0.233s][debug][gc,phases] GC(0) Purge Unlinked NMethods 0.001ms
[0.233s][debug][gc,phases] GC(0) Unregister NMethods 0.045ms
[0.233s][debug][gc,phases] GC(0) Free Code Blobs 0.003ms
[0.233s][debug][gc,phases] GC(0) Purge Class Loader Data 0.013ms
[0.233s][debug][gc,phases] GC(0) Phase 1: Class Unloading and Cleanup 0.483ms
[0.233s][debug][gc,phases] GC(0) Report Object Count 0.001ms
[0.233s][info ][gc,phases] GC(0) Phase 1: Mark live objects 8.252ms
[0.233s][debug][gc,phases] GC(0) Phase 2: Determine work lists 0.007ms
[0.233s][debug][gc,phases] GC(0) Phase 2: Prepare parallel compaction 0.332ms
[0.233s][info ][gc,phases] GC(0) Phase 2: Prepare compaction 0.368ms
[0.238s][info ][gc,phases] GC(0) Phase 3: Adjust pointers 4.893ms
[0.240s][info ][gc,phases] GC(0) Phase 4: Compact heap 2.030ms
[0.241s][info ][gc,phases] GC(0) Phase 5: Reset Metadata 1.094ms
[0.243s][info ][gc,phases] GC(1) Pre Evacuate Collection Set: 0.07ms
[0.243s][debug][gc,phases] GC(1) Reset Marking State (ms): Min: 0.02, Avg: 0.02, Max: 0.02, Diff: 0.00, Sum: 0.02, Workers: 1
[0.243s][debug][gc,phases] GC(1) Note Start Of Mark (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Pre Evacuate Prepare: 0.02ms
[0.243s][debug][gc,phases] GC(1) JT Retire TLABs And Flush Logs (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Non-JT Flush Logs (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Choose Collection Set: 0.00ms
[0.243s][debug][gc,phases] GC(1) Region Register: 0.02ms
[0.243s][debug][gc,phases] GC(1) Prepare Heap Roots: 0.00ms
[0.243s][info ][gc,phases] GC(1) Merge Heap Roots: 0.04ms
[0.243s][debug][gc,phases] GC(1) Prepare Merge Heap Roots: 0.00ms
[0.243s][debug][gc,phases] GC(1) Remembered Sets (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Eager Reclaim (ms): skipped
[0.243s][debug][gc,phases] GC(1) Merged Inline Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Merged ArrayOfCards Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Merged Howl Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Merged Full Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Merged Howl Inline Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Merged Howl ArrayOfCards Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Merged Howl BitMap Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Merged Howl Full Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Merged Cards Min: 16, Avg: 16.0, Max: 16, Diff: 0, Sum: 32, Workers: 2
[0.243s][debug][gc,phases] GC(1) Log Buffers (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Dirty Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Skipped Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][info ][gc,phases] GC(1) Evacuate Collection Set: 0.44ms
[0.243s][debug][gc,phases] GC(1) Ext Root Scanning (ms): Min: 0.13, Avg: 0.25, Max: 0.37, Diff: 0.25, Sum: 0.50, Workers: 2
[0.243s][debug][gc,phases] GC(1) Scan Heap Roots (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Scanned Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Scanned Blocks: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Claimed Chunks: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Found Roots: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Code Root Scan (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Scanned Nmethods Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Object Copy (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Termination (ms): Min: 0.00, Avg: 0.14, Max: 0.27, Diff: 0.27, Sum: 0.27, Workers: 2
[0.243s][debug][gc,phases] GC(1) Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2, Workers: 2
[0.243s][debug][gc,phases] GC(1) GC Worker Other (ms): Min: 0.00, Avg: 0.01, Max: 0.01, Diff: 0.00, Sum: 0.01, Workers: 2
[0.243s][debug][gc,phases] GC(1) GC Worker Total (ms): Min: 0.38, Avg: 0.39, Max: 0.40, Diff: 0.02, Sum: 0.79, Workers: 2
[0.243s][info ][gc,phases] GC(1) Post Evacuate Collection Set: 0.13ms
[0.243s][debug][gc,phases] GC(1) NMethod List Cleanup: 0.01ms
[0.243s][debug][gc,phases] GC(1) Reference Processing: 0.00ms
[0.243s][debug][gc,phases] GC(1) Weak Processing: 0.03ms
[0.243s][debug][gc,phases] GC(1) VM Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 4, Avg: 4.0, Max: 4, Diff: 0, Sum: 4, Workers: 1
[0.243s][debug][gc,phases] GC(1) ObjectSynchronizer Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 1, Workers: 1
[0.243s][debug][gc,phases] GC(1) JVMTI Tag Weak OopStorage Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) StringTable Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 45, Avg: 45.0, Max: 45, Diff: 0, Sum: 45, Workers: 1
[0.243s][debug][gc,phases] GC(1) ResolvedMethodTable Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 50, Avg: 50.0, Max: 50, Diff: 0, Sum: 50, Workers: 1
[0.243s][debug][gc,phases] GC(1) JNI Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) StringDedup Table Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) StringDedup Requests0 Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) StringDedup Requests1 Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Weak JFR Old Object Samples Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Post Evacuate Cleanup 1: 0.03ms
[0.243s][debug][gc,phases] GC(1) Merge Per-Thread State (ms): Min: 0.01, Avg: 0.01, Max: 0.01, Diff: 0.00, Sum: 0.01, Workers: 1
[0.243s][debug][gc,phases] GC(1) Copied Bytes Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) LAB Waste Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) LAB Undo Waste Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Evac Fail Extra Cards Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Clear Logged Cards (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Recalculate Used Memory (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Post Evacuate Cleanup 2: 0.03ms
[0.243s][debug][gc,phases] GC(1) Update Derived Pointers (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Eagerly Reclaim Humongous Objects (ms): skipped
[0.243s][debug][gc,phases] GC(1) Humongous Total skipped
[0.243s][debug][gc,phases] GC(1) Humongous Candidates skipped
[0.243s][debug][gc,phases] GC(1) Humongous Reclaimed skipped
[0.243s][debug][gc,phases] GC(1) Redirty Logged Cards (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Redirtied Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Resize TLABs (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Free Collection Set (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Rebuild Free List: 0.03ms
[0.243s][debug][gc,phases] GC(1) Prepare For Mutator: 0.00ms
[0.243s][debug][gc,phases] GC(1) Expand Heap After Collection: 0.00ms
[0.243s][info ][gc,phases] GC(1) Other: 0.08ms
[0.243s][info ][gc,marking] GC(2) Concurrent Scan Root Regions
[0.243s][info ][gc,marking] GC(2) Concurrent Scan Root Regions 0.034ms
[0.243s][info ][gc,marking] GC(2) Concurrent Mark
[0.244s][info ][gc,marking] GC(2) Concurrent Mark From Roots
[0.254s][info ][gc,marking] GC(2) Concurrent Mark From Roots 10.043ms
[0.254s][info ][gc,marking] GC(2) Concurrent Preclean
[0.254s][info ][gc,marking] GC(2) Concurrent Preclean 0.027ms
[0.254s][debug][gc,phases ] GC(2) Finalize Marking 0.308ms
[0.254s][debug][gc,phases ] GC(2) Reference Processing 0.013ms
[0.254s][debug][gc,phases ] GC(2) VM Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 4, Avg: 4.0, Max: 4, Diff: 0, Sum: 4, Workers: 1
[0.254s][debug][gc,phases ] GC(2) ObjectSynchronizer Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 1, Workers: 1
[0.254s][debug][gc,phases ] GC(2) JVMTI Tag Weak OopStorage Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) StringTable Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 45, Avg: 45.0, Max: 45, Diff: 0, Sum: 45, Workers: 1
[0.254s][debug][gc,phases ] GC(2) ResolvedMethodTable Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 50, Avg: 50.0, Max: 50, Diff: 0, Sum: 50, Workers: 1
[0.254s][debug][gc,phases ] GC(2) JNI Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) StringDedup Table Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) StringDedup Requests0 Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) StringDedup Requests1 Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Weak JFR Old Object Samples Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Weak Processing 0.217ms
[0.254s][debug][gc,phases ] GC(2) ClassLoaderData 0.002ms
[0.254s][debug][gc,phases ] GC(2) Trigger cleanups 0.002ms
[0.255s][debug][gc,phases ] GC(2) G1 Complete Cleaning 0.348ms
[0.255s][debug][gc,phases ] GC(2) Purge Unlinked NMethods 0.027ms
[0.255s][debug][gc,phases ] GC(2) Unregister NMethods 0.035ms
[0.255s][debug][gc,phases ] GC(2) Free Code Blobs 0.005ms
[0.255s][debug][gc,phases ] GC(2) Purge Class Loader Data 0.013ms
[0.255s][debug][gc,phases ] GC(2) Class Unloading 0.484ms
[0.255s][debug][gc,phases ] GC(2) Flush Task Caches 0.015ms
[0.255s][trace][gc,remset,tracking] GC(2) Before rebuild region 0 (tams: 0x00000000fe0602b8) total_live_bytes 393912 selected false (live_bytes 393912 type OLD)
[0.255s][trace][gc,remset,tracking] GC(2) Before rebuild region 1 (tams: 0x00000000fe120510) total_live_bytes 132368 selected true (live_bytes 132368 type OLD)
[0.255s][trace][gc,remset,tracking] GC(2) Before rebuild region 30 (tams: 0x00000000fff00000) total_live_bytes 1040456 selected false (live_bytes 1040456 type OLD)
[0.255s][debug][gc,remset,tracking] GC(2) Remembered Set Tracking update regions total 32, selected 1
[0.255s][debug][gc,phases ] GC(2) Update Remembered Set Tracking Before Rebuild 0.044ms
[0.255s][debug][gc,phases ] GC(2) Reclaim Empty Regions 0.031ms
[0.255s][debug][gc,phases ] GC(2) Report Object Count 0.001ms
[0.255s][info ][gc,marking ] GC(2) Concurrent Mark 11.631ms
[0.255s][info ][gc,marking ] GC(2) Concurrent Rebuild Remembered Sets and Scrub Regions
[0.259s][info ][gc,marking ] GC(2) Concurrent Rebuild Remembered Sets and Scrub Regions 4.239ms
[0.259s][trace][gc,remset,tracking] GC(2) After rebuild region 0 (tams 0x00000000fe0602b8 liveness 393912 remset occ 0 size 688)
[0.259s][trace][gc,remset,tracking] GC(2) After rebuild region 1 (tams 0x00000000fe120510 liveness 132368 remset occ 111 size 1536)
[0.259s][trace][gc,remset,tracking] GC(2) After rebuild region 30 (tams 0x00000000fff00000 liveness 1040456 remset occ 0 size 688)
[0.259s][debug][gc,phases ] GC(2) Update Remembered Set Tracking After Rebuild 0.049ms
[0.260s][debug][gc,phases ] GC(2) Finalize Concurrent Mark Cleanup 0.062ms
[0.260s][info ][gc,marking ] GC(2) Concurrent Clear Claimed Marks
[0.260s][info ][gc,marking ] GC(2) Concurrent Clear Claimed Marks 0.016ms
[0.260s][info ][gc,marking ] GC(2) Concurrent Cleanup for Next Mark
[0.260s][info ][gc,marking ] GC(2) Concurrent Cleanup for Next Mark 0.071ms
[B@15db9742
];
stderr: []
exitValue = 0
java.lang.RuntimeException: 'Skipping Remembered Set Rebuild.' missing from stdout/stderr
at jdk.test.lib.process.OutputAnalyzer.shouldContain(OutputAnalyzer.java:252)
at gc.g1.TestSkipRebuildRemsetPhase.main(TestSkipRebuildRemsetPhase.java:53)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
at java.base/java.lang.reflect.Method.invoke(Method.java:580)
at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:333)
at java.base/java.lang.Thread.run(Thread.java:1570)
JavaTest Message: Test threw exception: java.lang.RuntimeException
JavaTest Message: shutting down test
result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: 'Skipping Remembered Set Rebuild.' missing from stdout/stderr
gc/g1/TestSkipRebuildRemsetPhase.java
Here's a snippet from the log file:
#section:driver
----------messages:(7/258)----------
command: driver gc.g1.TestSkipRebuildRemsetPhase
reason: User specified action: run driver gc.g1.TestSkipRebuildRemsetPhase
started: Fri Jan 05 11:16:56 UTC 2024
Mode: agentvm
Agent id: 9
finished: Fri Jan 05 11:16:57 UTC 2024
elapsed time (seconds): 0.418
----------configuration:(14/1870)----------
<snip>
----------System.out:(5/2017)----------
Command line: [/opt/mach5/mesos/work_dir/jib-master/install/jdk-23+5-209/linux-aarch64-debug.jdk/jdk-23/fastdebug/bin/java -cp /opt/mach5/mesos/work_dir/slaves/6a6709c5-8dd0-4c1a-8549-7a448290c389-S4087/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/46963134-5f49-451d-96b4-0af17157be99/runs/922e5e36-c5c6-45f6-9603-3f333cd4a70c/testoutput/test-support/jtreg_open_test_hotspot_jtreg_tier1_gc_1/classes/1/gc/g1/TestSkipRebuildRemsetPhase.d:/opt/mach5/mesos/work_dir/jib-master/install/jdk-23+5-209/src.full/open/test/hotspot/jtreg/gc/g1:/opt/mach5/mesos/work_dir/slaves/6a6709c5-8dd0-4c1a-8549-7a448290c389-S4087/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/46963134-5f49-451d-96b4-0af17157be99/runs/922e5e36-c5c6-45f6-9603-3f333cd4a70c/testoutput/test-support/jtreg_open_test_hotspot_jtreg_tier1_gc_1/classes/1/test/lib:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/7.3.1/1/bundles/jtreg-7.3.1+1.zip/jtreg/lib/jtreg.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/7.3.1/1/bundles/jtreg-7.3.1+1.zip/jtreg/lib/junit-platform-console-standalone-1.9.2.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/7.3.1/1/bundles/jtreg-7.3.1+1.zip/jtreg/lib/testng-7.3.0.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/7.3.1/1/bundles/jtreg-7.3.1+1.zip/jtreg/lib/jcommander-1.82.jar:/opt/mach5/mesos/work_dir/jib-master/install/jtreg/7.3.1/1/bundles/jtreg-7.3.1+1.zip/jtreg/lib/guice-5.1.0.jar -Xbootclasspath/a:. -XX:+UseG1GC -XX:+UnlockExperimentalVMOptions -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -XX:G1MixedGCLiveThresholdPercent=20 -Xlog:gc+marking=debug,gc+phases=debug,gc+remset+tracking=trace -Xms10M -Xmx10M gc.g1.TestSkipRebuildRemsetPhase$GCTest ]
[2024-01-05T11:16:57.014543358Z] Gathering output for process 11606
[2024-01-05T11:16:57.027737409Z] Waiting for completion for process 11606
[2024-01-05T11:16:57.303702851Z] Waiting for completion finished for process 11606
Output and diagnostic info for process 11606 was saved into 'pid-11606-output.log'
----------System.err:(227/23651)----------
stdout: [[0.232s][debug][gc,phases] GC(0) Phase 1: Reference Processing 0.153ms
[0.232s][debug][gc,phases] GC(0) VM Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 4, Avg: 4.0, Max: 4, Diff: 0, Sum: 4, Workers: 1
[0.232s][debug][gc,phases] GC(0) ObjectSynchronizer Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 1, Workers: 1
[0.232s][debug][gc,phases] GC(0) JVMTI Tag Weak OopStorage Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) StringTable Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 1, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 45, Avg: 45.0, Max: 45, Diff: 0, Sum: 45, Workers: 1
[0.232s][debug][gc,phases] GC(0) ResolvedMethodTable Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 2, Avg: 2.0, Max: 2, Diff: 0, Sum: 2, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 50, Avg: 50.0, Max: 50, Diff: 0, Sum: 50, Workers: 1
[0.232s][debug][gc,phases] GC(0) JNI Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) StringDedup Table Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) StringDedup Requests0 Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) StringDedup Requests1 Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Weak JFR Old Object Samples Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.232s][debug][gc,phases] GC(0) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.232s][debug][gc,phases] GC(0) Phase 1: Weak Processing 0.648ms
[0.232s][debug][gc,phases] GC(0) ClassLoaderData 0.002ms
[0.232s][debug][gc,phases] GC(0) Trigger cleanups 0.000ms
[0.233s][debug][gc,phases] GC(0) G1 Complete Cleaning 0.367ms
[0.233s][debug][gc,phases] GC(0) Purge Unlinked NMethods 0.001ms
[0.233s][debug][gc,phases] GC(0) Unregister NMethods 0.045ms
[0.233s][debug][gc,phases] GC(0) Free Code Blobs 0.003ms
[0.233s][debug][gc,phases] GC(0) Purge Class Loader Data 0.013ms
[0.233s][debug][gc,phases] GC(0) Phase 1: Class Unloading and Cleanup 0.483ms
[0.233s][debug][gc,phases] GC(0) Report Object Count 0.001ms
[0.233s][info ][gc,phases] GC(0) Phase 1: Mark live objects 8.252ms
[0.233s][debug][gc,phases] GC(0) Phase 2: Determine work lists 0.007ms
[0.233s][debug][gc,phases] GC(0) Phase 2: Prepare parallel compaction 0.332ms
[0.233s][info ][gc,phases] GC(0) Phase 2: Prepare compaction 0.368ms
[0.238s][info ][gc,phases] GC(0) Phase 3: Adjust pointers 4.893ms
[0.240s][info ][gc,phases] GC(0) Phase 4: Compact heap 2.030ms
[0.241s][info ][gc,phases] GC(0) Phase 5: Reset Metadata 1.094ms
[0.243s][info ][gc,phases] GC(1) Pre Evacuate Collection Set: 0.07ms
[0.243s][debug][gc,phases] GC(1) Reset Marking State (ms): Min: 0.02, Avg: 0.02, Max: 0.02, Diff: 0.00, Sum: 0.02, Workers: 1
[0.243s][debug][gc,phases] GC(1) Note Start Of Mark (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Pre Evacuate Prepare: 0.02ms
[0.243s][debug][gc,phases] GC(1) JT Retire TLABs And Flush Logs (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Non-JT Flush Logs (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Choose Collection Set: 0.00ms
[0.243s][debug][gc,phases] GC(1) Region Register: 0.02ms
[0.243s][debug][gc,phases] GC(1) Prepare Heap Roots: 0.00ms
[0.243s][info ][gc,phases] GC(1) Merge Heap Roots: 0.04ms
[0.243s][debug][gc,phases] GC(1) Prepare Merge Heap Roots: 0.00ms
[0.243s][debug][gc,phases] GC(1) Remembered Sets (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Eager Reclaim (ms): skipped
[0.243s][debug][gc,phases] GC(1) Merged Inline Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Merged ArrayOfCards Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Merged Howl Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Merged Full Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Merged Howl Inline Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Merged Howl ArrayOfCards Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Merged Howl BitMap Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Merged Howl Full Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Merged Cards Min: 16, Avg: 16.0, Max: 16, Diff: 0, Sum: 32, Workers: 2
[0.243s][debug][gc,phases] GC(1) Log Buffers (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Dirty Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Skipped Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][info ][gc,phases] GC(1) Evacuate Collection Set: 0.44ms
[0.243s][debug][gc,phases] GC(1) Ext Root Scanning (ms): Min: 0.13, Avg: 0.25, Max: 0.37, Diff: 0.25, Sum: 0.50, Workers: 2
[0.243s][debug][gc,phases] GC(1) Scan Heap Roots (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Scanned Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Scanned Blocks: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Claimed Chunks: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Found Roots: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Code Root Scan (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Scanned Nmethods Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Object Copy (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Termination (ms): Min: 0.00, Avg: 0.14, Max: 0.27, Diff: 0.27, Sum: 0.27, Workers: 2
[0.243s][debug][gc,phases] GC(1) Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2, Workers: 2
[0.243s][debug][gc,phases] GC(1) GC Worker Other (ms): Min: 0.00, Avg: 0.01, Max: 0.01, Diff: 0.00, Sum: 0.01, Workers: 2
[0.243s][debug][gc,phases] GC(1) GC Worker Total (ms): Min: 0.38, Avg: 0.39, Max: 0.40, Diff: 0.02, Sum: 0.79, Workers: 2
[0.243s][info ][gc,phases] GC(1) Post Evacuate Collection Set: 0.13ms
[0.243s][debug][gc,phases] GC(1) NMethod List Cleanup: 0.01ms
[0.243s][debug][gc,phases] GC(1) Reference Processing: 0.00ms
[0.243s][debug][gc,phases] GC(1) Weak Processing: 0.03ms
[0.243s][debug][gc,phases] GC(1) VM Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 4, Avg: 4.0, Max: 4, Diff: 0, Sum: 4, Workers: 1
[0.243s][debug][gc,phases] GC(1) ObjectSynchronizer Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 1, Workers: 1
[0.243s][debug][gc,phases] GC(1) JVMTI Tag Weak OopStorage Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) StringTable Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 45, Avg: 45.0, Max: 45, Diff: 0, Sum: 45, Workers: 1
[0.243s][debug][gc,phases] GC(1) ResolvedMethodTable Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 50, Avg: 50.0, Max: 50, Diff: 0, Sum: 50, Workers: 1
[0.243s][debug][gc,phases] GC(1) JNI Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) StringDedup Table Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) StringDedup Requests0 Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) StringDedup Requests1 Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Weak JFR Old Object Samples Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.243s][debug][gc,phases] GC(1) Post Evacuate Cleanup 1: 0.03ms
[0.243s][debug][gc,phases] GC(1) Merge Per-Thread State (ms): Min: 0.01, Avg: 0.01, Max: 0.01, Diff: 0.00, Sum: 0.01, Workers: 1
[0.243s][debug][gc,phases] GC(1) Copied Bytes Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) LAB Waste Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) LAB Undo Waste Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Evac Fail Extra Cards Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Clear Logged Cards (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Recalculate Used Memory (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Post Evacuate Cleanup 2: 0.03ms
[0.243s][debug][gc,phases] GC(1) Update Derived Pointers (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.243s][debug][gc,phases] GC(1) Eagerly Reclaim Humongous Objects (ms): skipped
[0.243s][debug][gc,phases] GC(1) Humongous Total skipped
[0.243s][debug][gc,phases] GC(1) Humongous Candidates skipped
[0.243s][debug][gc,phases] GC(1) Humongous Reclaimed skipped
[0.243s][debug][gc,phases] GC(1) Redirty Logged Cards (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Redirtied Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[0.243s][debug][gc,phases] GC(1) Resize TLABs (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Free Collection Set (ms): Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 2
[0.243s][debug][gc,phases] GC(1) Rebuild Free List: 0.03ms
[0.243s][debug][gc,phases] GC(1) Prepare For Mutator: 0.00ms
[0.243s][debug][gc,phases] GC(1) Expand Heap After Collection: 0.00ms
[0.243s][info ][gc,phases] GC(1) Other: 0.08ms
[0.243s][info ][gc,marking] GC(2) Concurrent Scan Root Regions
[0.243s][info ][gc,marking] GC(2) Concurrent Scan Root Regions 0.034ms
[0.243s][info ][gc,marking] GC(2) Concurrent Mark
[0.244s][info ][gc,marking] GC(2) Concurrent Mark From Roots
[0.254s][info ][gc,marking] GC(2) Concurrent Mark From Roots 10.043ms
[0.254s][info ][gc,marking] GC(2) Concurrent Preclean
[0.254s][info ][gc,marking] GC(2) Concurrent Preclean 0.027ms
[0.254s][debug][gc,phases ] GC(2) Finalize Marking 0.308ms
[0.254s][debug][gc,phases ] GC(2) Reference Processing 0.013ms
[0.254s][debug][gc,phases ] GC(2) VM Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 4, Avg: 4.0, Max: 4, Diff: 0, Sum: 4, Workers: 1
[0.254s][debug][gc,phases ] GC(2) ObjectSynchronizer Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 1, Workers: 1
[0.254s][debug][gc,phases ] GC(2) JVMTI Tag Weak OopStorage Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) StringTable Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 45, Avg: 45.0, Max: 45, Diff: 0, Sum: 45, Workers: 1
[0.254s][debug][gc,phases ] GC(2) ResolvedMethodTable Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 50, Avg: 50.0, Max: 50, Diff: 0, Sum: 50, Workers: 1
[0.254s][debug][gc,phases ] GC(2) JNI Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) StringDedup Table Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) StringDedup Requests0 Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) StringDedup Requests1 Weak Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Weak JFR Old Object Samples Min: 0.00, Avg: 0.00, Max: 0.00, Diff: 0.00, Sum: 0.00, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Dead Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Total Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 1
[0.254s][debug][gc,phases ] GC(2) Weak Processing 0.217ms
[0.254s][debug][gc,phases ] GC(2) ClassLoaderData 0.002ms
[0.254s][debug][gc,phases ] GC(2) Trigger cleanups 0.002ms
[0.255s][debug][gc,phases ] GC(2) G1 Complete Cleaning 0.348ms
[0.255s][debug][gc,phases ] GC(2) Purge Unlinked NMethods 0.027ms
[0.255s][debug][gc,phases ] GC(2) Unregister NMethods 0.035ms
[0.255s][debug][gc,phases ] GC(2) Free Code Blobs 0.005ms
[0.255s][debug][gc,phases ] GC(2) Purge Class Loader Data 0.013ms
[0.255s][debug][gc,phases ] GC(2) Class Unloading 0.484ms
[0.255s][debug][gc,phases ] GC(2) Flush Task Caches 0.015ms
[0.255s][trace][gc,remset,tracking] GC(2) Before rebuild region 0 (tams: 0x00000000fe0602b8) total_live_bytes 393912 selected false (live_bytes 393912 type OLD)
[0.255s][trace][gc,remset,tracking] GC(2) Before rebuild region 1 (tams: 0x00000000fe120510) total_live_bytes 132368 selected true (live_bytes 132368 type OLD)
[0.255s][trace][gc,remset,tracking] GC(2) Before rebuild region 30 (tams: 0x00000000fff00000) total_live_bytes 1040456 selected false (live_bytes 1040456 type OLD)
[0.255s][debug][gc,remset,tracking] GC(2) Remembered Set Tracking update regions total 32, selected 1
[0.255s][debug][gc,phases ] GC(2) Update Remembered Set Tracking Before Rebuild 0.044ms
[0.255s][debug][gc,phases ] GC(2) Reclaim Empty Regions 0.031ms
[0.255s][debug][gc,phases ] GC(2) Report Object Count 0.001ms
[0.255s][info ][gc,marking ] GC(2) Concurrent Mark 11.631ms
[0.255s][info ][gc,marking ] GC(2) Concurrent Rebuild Remembered Sets and Scrub Regions
[0.259s][info ][gc,marking ] GC(2) Concurrent Rebuild Remembered Sets and Scrub Regions 4.239ms
[0.259s][trace][gc,remset,tracking] GC(2) After rebuild region 0 (tams 0x00000000fe0602b8 liveness 393912 remset occ 0 size 688)
[0.259s][trace][gc,remset,tracking] GC(2) After rebuild region 1 (tams 0x00000000fe120510 liveness 132368 remset occ 111 size 1536)
[0.259s][trace][gc,remset,tracking] GC(2) After rebuild region 30 (tams 0x00000000fff00000 liveness 1040456 remset occ 0 size 688)
[0.259s][debug][gc,phases ] GC(2) Update Remembered Set Tracking After Rebuild 0.049ms
[0.260s][debug][gc,phases ] GC(2) Finalize Concurrent Mark Cleanup 0.062ms
[0.260s][info ][gc,marking ] GC(2) Concurrent Clear Claimed Marks
[0.260s][info ][gc,marking ] GC(2) Concurrent Clear Claimed Marks 0.016ms
[0.260s][info ][gc,marking ] GC(2) Concurrent Cleanup for Next Mark
[0.260s][info ][gc,marking ] GC(2) Concurrent Cleanup for Next Mark 0.071ms
[B@15db9742
];
stderr: []
exitValue = 0
java.lang.RuntimeException: 'Skipping Remembered Set Rebuild.' missing from stdout/stderr
at jdk.test.lib.process.OutputAnalyzer.shouldContain(OutputAnalyzer.java:252)
at gc.g1.TestSkipRebuildRemsetPhase.main(TestSkipRebuildRemsetPhase.java:53)
at java.base/jdk.internal.reflect.DirectMethodHandleAccessor.invoke(DirectMethodHandleAccessor.java:103)
at java.base/java.lang.reflect.Method.invoke(Method.java:580)
at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:333)
at java.base/java.lang.Thread.run(Thread.java:1570)
JavaTest Message: Test threw exception: java.lang.RuntimeException
JavaTest Message: shutting down test
result: Failed. Execution failed: `main' threw exception: java.lang.RuntimeException: 'Skipping Remembered Set Rebuild.' missing from stdout/stderr
- backported by
-
JDK-8323649 gc/g1/TestSkipRebuildRemsetPhase.java fails with 'Skipping Remembered Set Rebuild.' missing
-
- Resolved
-
-
JDK-8324378 gc/g1/TestSkipRebuildRemsetPhase.java fails with 'Skipping Remembered Set Rebuild.' missing
-
- Resolved
-
- links to
-
Commit openjdk/jdk22/749f749f
-
Commit openjdk/jdk/ee98d262
-
Review openjdk/jdk22/51
-
Review openjdk/jdk/17309
(1 links to)