Mercurial > jdk8-mips64-public > hotspot / changeset
changeset
8027962: Per-phase timing measurements for strong roots processing
Thu, 19 Mar 2015 15:25:54 +0100
- author
- brutisso
- date
- Thu, 19 Mar 2015 15:25:54 +0100
- changeset 7660
- 3ca53859c3c7
- parent 7659
- 38d6febe66af
- child 7665
- dfa9eac41999
- child 7666
- 6b65121b3258
- child 7673
- c04f46b4abe4
8027962: Per-phase timing measurements for strong roots processing
Reviewed-by: tschatzl, ecaspole
1.1 --- a/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp Mon Dec 01 15:24:56 2014 +0100 1.2 +++ b/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp Thu Mar 19 15:25:54 2015 +0100 1.3 @@ -249,7 +249,24 @@ 1.4 1.5 _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms)", false, G1Log::LevelFiner, 2); 1.6 _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms)", true, G1Log::LevelFiner, 2); 1.7 - _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms)", true, G1Log::LevelFiner, 2); 1.8 + 1.9 + // Root scanning phases 1.10 + _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms)", true, G1Log::LevelFinest, 3); 1.11 + _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms)", true, G1Log::LevelFinest, 3); 1.12 + _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms)", true, G1Log::LevelFinest, 3); 1.13 + _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms)", true, G1Log::LevelFinest, 3); 1.14 + _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms)", true, G1Log::LevelFinest, 3); 1.15 + _gc_par_phases[FlatProfilerRoots] = new WorkerDataArray<double>(max_gc_threads, "FlatProfiler Roots (ms)", true, G1Log::LevelFinest, 3); 1.16 + _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms)", true, G1Log::LevelFinest, 3); 1.17 + _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms)", true, G1Log::LevelFinest, 3); 1.18 + _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms)", true, G1Log::LevelFinest, 3); 1.19 + _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms)", true, G1Log::LevelFinest, 3); 1.20 + _gc_par_phases[CodeCacheRoots] = new WorkerDataArray<double>(max_gc_threads, "CodeCache Roots (ms)", true, G1Log::LevelFinest, 3); 1.21 + _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms)", true, G1Log::LevelFinest, 3); 1.22 + _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms)", true, G1Log::LevelFinest, 3); 1.23 + _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms)", true, G1Log::LevelFinest, 3); 1.24 + _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms)", true, G1Log::LevelFinest, 3); 1.25 + 1.26 _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms)", true, G1Log::LevelFiner, 2); 1.27 _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms)", true, G1Log::LevelFiner, 2); 1.28 _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms)", true, G1Log::LevelFiner, 2); 1.29 @@ -282,8 +299,6 @@ 1.30 _gc_par_phases[i]->reset(); 1.31 } 1.32 1.33 - _gc_par_phases[SATBFiltering]->set_enabled(mark_in_progress); 1.34 - 1.35 _gc_par_phases[StringDedupQueueFixup]->set_enabled(G1StringDedup::is_enabled()); 1.36 _gc_par_phases[StringDedupTableFixup]->set_enabled(G1StringDedup::is_enabled()); 1.37 }
2.1 --- a/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp Mon Dec 01 15:24:56 2014 +0100 2.2 +++ b/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp Thu Mar 19 15:25:54 2015 +0100 2.3 @@ -41,6 +41,20 @@ 2.4 enum GCParPhases { 2.5 GCWorkerStart, 2.6 ExtRootScan, 2.7 + ThreadRoots, 2.8 + StringTableRoots, 2.9 + UniverseRoots, 2.10 + JNIRoots, 2.11 + ObjectSynchronizerRoots, 2.12 + FlatProfilerRoots, 2.13 + ManagementRoots, 2.14 + SystemDictionaryRoots, 2.15 + CLDGRoots, 2.16 + JVMTIRoots, 2.17 + CodeCacheRoots, 2.18 + CMRefRoots, 2.19 + WaitForStrongCLD, 2.20 + WeakCLDRoots, 2.21 SATBFiltering, 2.22 UpdateRS, 2.23 ScanRS,
3.1 --- a/src/share/vm/gc_implementation/g1/g1RootProcessor.cpp Mon Dec 01 15:24:56 2014 +0100 3.2 +++ b/src/share/vm/gc_implementation/g1/g1RootProcessor.cpp Thu Mar 19 15:25:54 2015 +0100 3.3 @@ -128,6 +128,7 @@ 3.4 uint worker_i) { 3.5 // First scan the shared roots. 3.6 double ext_roots_start = os::elapsedTime(); 3.7 + G1GCPhaseTimes* phase_times = _g1h->g1_policy()->phase_times(); 3.8 3.9 BufferingOopClosure buf_scan_non_heap_roots(scan_non_heap_roots); 3.10 BufferingOopClosure buf_scan_non_heap_weak_roots(scan_non_heap_weak_roots); 3.11 @@ -142,7 +143,9 @@ 3.12 trace_metadata ? scan_strong_clds : NULL, 3.13 scan_strong_clds, 3.14 trace_metadata ? NULL : scan_weak_clds, 3.15 - &root_code_blobs); 3.16 + &root_code_blobs, 3.17 + phase_times, 3.18 + worker_i); 3.19 3.20 // This is the point where this worker thread will not find more strong CLDs/nmethods. 3.21 // Report this so G1 can synchronize the strong and weak CLDs/nmethods processing. 3.22 @@ -150,24 +153,34 @@ 3.23 worker_has_discovered_all_strong_classes(); 3.24 } 3.25 3.26 - process_vm_roots(strong_roots, weak_roots); 3.27 + process_vm_roots(strong_roots, weak_roots, phase_times, worker_i); 3.28 3.29 - // Now the CM ref_processor roots. 3.30 - if (!_process_strong_tasks->is_task_claimed(G1RP_PS_refProcessor_oops_do)) { 3.31 - // We need to treat the discovered reference lists of the 3.32 - // concurrent mark ref processor as roots and keep entries 3.33 - // (which are added by the marking threads) on them live 3.34 - // until they can be processed at the end of marking. 3.35 - _g1h->ref_processor_cm()->weak_oops_do(&buf_scan_non_heap_roots); 3.36 + { 3.37 + // Now the CM ref_processor roots. 3.38 + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::CMRefRoots, worker_i); 3.39 + if (!_process_strong_tasks->is_task_claimed(G1RP_PS_refProcessor_oops_do)) { 3.40 + // We need to treat the discovered reference lists of the 3.41 + // concurrent mark ref processor as roots and keep entries 3.42 + // (which are added by the marking threads) on them live 3.43 + // until they can be processed at the end of marking. 3.44 + _g1h->ref_processor_cm()->weak_oops_do(&buf_scan_non_heap_roots); 3.45 + } 3.46 } 3.47 3.48 if (trace_metadata) { 3.49 - // Barrier to make sure all workers passed 3.50 - // the strong CLD and strong nmethods phases. 3.51 - wait_until_all_strong_classes_discovered(); 3.52 + { 3.53 + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::WaitForStrongCLD, worker_i); 3.54 + // Barrier to make sure all workers passed 3.55 + // the strong CLD and strong nmethods phases. 3.56 + wait_until_all_strong_classes_discovered(); 3.57 + } 3.58 3.59 // Now take the complement of the strong CLDs. 3.60 + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::WeakCLDRoots, worker_i); 3.61 ClassLoaderDataGraph::roots_cld_do(NULL, scan_weak_clds); 3.62 + } else { 3.63 + phase_times->record_time_secs(G1GCPhaseTimes::WaitForStrongCLD, worker_i, 0.0); 3.64 + phase_times->record_time_secs(G1GCPhaseTimes::WeakCLDRoots, worker_i, 0.0); 3.65 } 3.66 3.67 // Finish up any enqueued closure apps (attributed as object copy time). 3.68 @@ -177,7 +190,6 @@ 3.69 double obj_copy_time_sec = buf_scan_non_heap_roots.closure_app_seconds() 3.70 + buf_scan_non_heap_weak_roots.closure_app_seconds(); 3.71 3.72 - G1GCPhaseTimes* phase_times = _g1h->g1_policy()->phase_times(); 3.73 phase_times->record_time_secs(G1GCPhaseTimes::ObjCopy, worker_i, obj_copy_time_sec); 3.74 3.75 double ext_root_time_sec = os::elapsedTime() - ext_roots_start - obj_copy_time_sec; 3.76 @@ -201,8 +213,8 @@ 3.77 CLDClosure* clds, 3.78 CodeBlobClosure* blobs) { 3.79 3.80 - process_java_roots(oops, clds, clds, NULL, blobs); 3.81 - process_vm_roots(oops, NULL); 3.82 + process_java_roots(oops, clds, clds, NULL, blobs, NULL, 0); 3.83 + process_vm_roots(oops, NULL, NULL, 0); 3.84 3.85 _process_strong_tasks->all_tasks_completed(); 3.86 } 3.87 @@ -211,8 +223,8 @@ 3.88 CLDClosure* clds, 3.89 CodeBlobClosure* blobs) { 3.90 3.91 - process_java_roots(oops, NULL, clds, clds, NULL); 3.92 - process_vm_roots(oops, oops); 3.93 + process_java_roots(oops, NULL, clds, clds, NULL, NULL, 0); 3.94 + process_vm_roots(oops, oops, NULL, 0); 3.95 3.96 if (!_process_strong_tasks->is_task_claimed(G1RP_PS_CodeCache_oops_do)) { 3.97 CodeCache::blobs_do(blobs); 3.98 @@ -225,60 +237,95 @@ 3.99 CLDClosure* thread_stack_clds, 3.100 CLDClosure* strong_clds, 3.101 CLDClosure* weak_clds, 3.102 - CodeBlobClosure* strong_code) { 3.103 + CodeBlobClosure* strong_code, 3.104 + G1GCPhaseTimes* phase_times, 3.105 + uint worker_i) { 3.106 assert(thread_stack_clds == NULL || weak_clds == NULL, "There is overlap between those, only one may be set"); 3.107 // Iterating over the CLDG and the Threads are done early to allow us to 3.108 // first process the strong CLDs and nmethods and then, after a barrier, 3.109 // let the thread process the weak CLDs and nmethods. 3.110 - 3.111 - if (!_process_strong_tasks->is_task_claimed(G1RP_PS_ClassLoaderDataGraph_oops_do)) { 3.112 - ClassLoaderDataGraph::roots_cld_do(strong_clds, weak_clds); 3.113 + { 3.114 + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::CLDGRoots, worker_i); 3.115 + if (!_process_strong_tasks->is_task_claimed(G1RP_PS_ClassLoaderDataGraph_oops_do)) { 3.116 + ClassLoaderDataGraph::roots_cld_do(strong_clds, weak_clds); 3.117 + } 3.118 } 3.119 3.120 - Threads::possibly_parallel_oops_do(strong_roots, thread_stack_clds, strong_code); 3.121 + { 3.122 + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::ThreadRoots, worker_i); 3.123 + Threads::possibly_parallel_oops_do(strong_roots, thread_stack_clds, strong_code); 3.124 + } 3.125 } 3.126 3.127 void G1RootProcessor::process_vm_roots(OopClosure* strong_roots, 3.128 - OopClosure* weak_roots) { 3.129 - 3.130 - if (!_process_strong_tasks->is_task_claimed(G1RP_PS_Universe_oops_do)) { 3.131 - Universe::oops_do(strong_roots); 3.132 + OopClosure* weak_roots, 3.133 + G1GCPhaseTimes* phase_times, 3.134 + uint worker_i) { 3.135 + { 3.136 + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::UniverseRoots, worker_i); 3.137 + if (!_process_strong_tasks->is_task_claimed(G1RP_PS_Universe_oops_do)) { 3.138 + Universe::oops_do(strong_roots); 3.139 + } 3.140 } 3.141 3.142 - if (!_process_strong_tasks->is_task_claimed(G1RP_PS_JNIHandles_oops_do)) { 3.143 - JNIHandles::oops_do(strong_roots); 3.144 + { 3.145 + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::JNIRoots, worker_i); 3.146 + if (!_process_strong_tasks->is_task_claimed(G1RP_PS_JNIHandles_oops_do)) { 3.147 + JNIHandles::oops_do(strong_roots); 3.148 + } 3.149 } 3.150 3.151 - if (!_process_strong_tasks-> is_task_claimed(G1RP_PS_ObjectSynchronizer_oops_do)) { 3.152 - ObjectSynchronizer::oops_do(strong_roots); 3.153 + { 3.154 + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::ObjectSynchronizerRoots, worker_i); 3.155 + if (!_process_strong_tasks-> is_task_claimed(G1RP_PS_ObjectSynchronizer_oops_do)) { 3.156 + ObjectSynchronizer::oops_do(strong_roots); 3.157 + } 3.158 } 3.159 3.160 - if (!_process_strong_tasks->is_task_claimed(G1RP_PS_FlatProfiler_oops_do)) { 3.161 - FlatProfiler::oops_do(strong_roots); 3.162 + { 3.163 + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::FlatProfilerRoots, worker_i); 3.164 + if (!_process_strong_tasks->is_task_claimed(G1RP_PS_FlatProfiler_oops_do)) { 3.165 + FlatProfiler::oops_do(strong_roots); 3.166 + } 3.167 } 3.168 3.169 - if (!_process_strong_tasks->is_task_claimed(G1RP_PS_Management_oops_do)) { 3.170 - Management::oops_do(strong_roots); 3.171 + { 3.172 + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::ManagementRoots, worker_i); 3.173 + if (!_process_strong_tasks->is_task_claimed(G1RP_PS_Management_oops_do)) { 3.174 + Management::oops_do(strong_roots); 3.175 + } 3.176 } 3.177 3.178 - if (!_process_strong_tasks->is_task_claimed(G1RP_PS_jvmti_oops_do)) { 3.179 - JvmtiExport::oops_do(strong_roots); 3.180 + { 3.181 + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::JVMTIRoots, worker_i); 3.182 + if (!_process_strong_tasks->is_task_claimed(G1RP_PS_jvmti_oops_do)) { 3.183 + JvmtiExport::oops_do(strong_roots); 3.184 + } 3.185 } 3.186 3.187 - if (!_process_strong_tasks->is_task_claimed(G1RP_PS_SystemDictionary_oops_do)) { 3.188 - SystemDictionary::roots_oops_do(strong_roots, weak_roots); 3.189 + { 3.190 + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::SystemDictionaryRoots, worker_i); 3.191 + if (!_process_strong_tasks->is_task_claimed(G1RP_PS_SystemDictionary_oops_do)) { 3.192 + SystemDictionary::roots_oops_do(strong_roots, weak_roots); 3.193 + } 3.194 } 3.195 3.196 - // All threads execute the following. A specific chunk of buckets 3.197 - // from the StringTable are the individual tasks. 3.198 - if (weak_roots != NULL) { 3.199 - StringTable::possibly_parallel_oops_do(weak_roots); 3.200 + { 3.201 + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::StringTableRoots, worker_i); 3.202 + // All threads execute the following. A specific chunk of buckets 3.203 + // from the StringTable are the individual tasks. 3.204 + if (weak_roots != NULL) { 3.205 + StringTable::possibly_parallel_oops_do(weak_roots); 3.206 + } 3.207 } 3.208 } 3.209 3.210 void G1RootProcessor::scan_remembered_sets(G1ParPushHeapRSClosure* scan_rs, 3.211 OopClosure* scan_non_heap_weak_roots, 3.212 uint worker_i) { 3.213 + G1GCPhaseTimes* phase_times = _g1h->g1_policy()->phase_times(); 3.214 + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::CodeCacheRoots, worker_i); 3.215 + 3.216 // Now scan the complement of the collection set. 3.217 G1CodeBlobClosure scavenge_cs_nmethods(scan_non_heap_weak_roots); 3.218
4.1 --- a/src/share/vm/gc_implementation/g1/g1RootProcessor.hpp Mon Dec 01 15:24:56 2014 +0100 4.2 +++ b/src/share/vm/gc_implementation/g1/g1RootProcessor.hpp Thu Mar 19 15:25:54 2015 +0100 4.3 @@ -32,6 +32,7 @@ 4.4 class CLDClosure; 4.5 class CodeBlobClosure; 4.6 class G1CollectedHeap; 4.7 +class G1GCPhaseTimes; 4.8 class G1ParPushHeapRSClosure; 4.9 class Monitor; 4.10 class OopClosure; 4.11 @@ -74,10 +75,14 @@ 4.12 CLDClosure* thread_stack_clds, 4.13 CLDClosure* scan_strong_clds, 4.14 CLDClosure* scan_weak_clds, 4.15 - CodeBlobClosure* scan_strong_code); 4.16 + CodeBlobClosure* scan_strong_code, 4.17 + G1GCPhaseTimes* phase_times, 4.18 + uint worker_i); 4.19 4.20 void process_vm_roots(OopClosure* scan_non_heap_roots, 4.21 - OopClosure* scan_non_heap_weak_roots); 4.22 + OopClosure* scan_non_heap_weak_roots, 4.23 + G1GCPhaseTimes* phase_times, 4.24 + uint worker_i); 4.25 4.26 public: 4.27 G1RootProcessor(G1CollectedHeap* g1h);
5.1 --- a/test/gc/g1/TestGCLogMessages.java Mon Dec 01 15:24:56 2014 +0100 5.2 +++ b/test/gc/g1/TestGCLogMessages.java Thu Mar 19 15:25:54 2015 +0100 5.3 @@ -1,5 +1,5 @@ 5.4 /* 5.5 - * Copyright (c) 2014, Oracle and/or its affiliates. All rights reserved. 5.6 + * Copyright (c) 2014, 2015 Oracle and/or its affiliates. All rights reserved. 5.7 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. 5.8 * 5.9 * This code is free software; you can redistribute it and/or modify it 5.10 @@ -23,7 +23,7 @@ 5.11 5.12 /* 5.13 * @test TestGCLogMessages 5.14 - * @bug 8035406 8027295 8035398 8019342 8027959 5.15 + * @bug 8035406 8027295 8035398 8019342 8027959 8027962 5.16 * @summary Ensure that the PrintGCDetails output for a minor GC with G1 5.17 * includes the expected necessary messages. 5.18 * @key gc 5.19 @@ -34,128 +34,158 @@ 5.20 import com.oracle.java.testlibrary.OutputAnalyzer; 5.21 5.22 public class TestGCLogMessages { 5.23 - public static void main(String[] args) throws Exception { 5.24 - testNormalLogs(); 5.25 - testWithToSpaceExhaustionLogs(); 5.26 - } 5.27 5.28 - private static void testNormalLogs() throws Exception { 5.29 + private enum Level { 5.30 + OFF, FINER, FINEST; 5.31 + public boolean lessOrEqualTo(Level other) { 5.32 + return this.compareTo(other) < 0; 5.33 + } 5.34 + } 5.35 5.36 - ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", 5.37 - "-Xmx10M", 5.38 - GCTest.class.getName()); 5.39 + private class LogMessageWithLevel { 5.40 + String message; 5.41 + Level level; 5.42 5.43 - OutputAnalyzer output = new OutputAnalyzer(pb.start()); 5.44 + public LogMessageWithLevel(String message, Level level) { 5.45 + this.message = message; 5.46 + this.level = level; 5.47 + } 5.48 + }; 5.49 5.50 - output.shouldNotContain("[Redirty Cards"); 5.51 - output.shouldNotContain("[Parallel Redirty"); 5.52 - output.shouldNotContain("[Redirtied Cards"); 5.53 - output.shouldNotContain("[Code Root Purge"); 5.54 - output.shouldNotContain("[String Dedup Fixup"); 5.55 - output.shouldNotContain("[Young Free CSet"); 5.56 - output.shouldNotContain("[Non-Young Free CSet"); 5.57 - output.shouldNotContain("[Humongous Reclaim"); 5.58 - output.shouldHaveExitValue(0); 5.59 + private LogMessageWithLevel allLogMessages[] = new LogMessageWithLevel[] { 5.60 + // Ext Root Scan 5.61 + new LogMessageWithLevel("Thread Roots (ms)", Level.FINEST), 5.62 + new LogMessageWithLevel("StringTable Roots (ms)", Level.FINEST), 5.63 + new LogMessageWithLevel("Universe Roots (ms)", Level.FINEST), 5.64 + new LogMessageWithLevel("JNI Handles Roots (ms)", Level.FINEST), 5.65 + new LogMessageWithLevel("ObjectSynchronizer Roots (ms)", Level.FINEST), 5.66 + new LogMessageWithLevel("FlatProfiler Roots", Level.FINEST), 5.67 + new LogMessageWithLevel("Management Roots", Level.FINEST), 5.68 + new LogMessageWithLevel("SystemDictionary Roots", Level.FINEST), 5.69 + new LogMessageWithLevel("CLDG Roots", Level.FINEST), 5.70 + new LogMessageWithLevel("JVMTI Roots", Level.FINEST), 5.71 + new LogMessageWithLevel("CodeCache Roots", Level.FINEST), 5.72 + new LogMessageWithLevel("SATB Filtering", Level.FINEST), 5.73 + new LogMessageWithLevel("CM RefProcessor Roots", Level.FINEST), 5.74 + new LogMessageWithLevel("Wait For Strong CLD", Level.FINEST), 5.75 + new LogMessageWithLevel("Weak CLD Roots", Level.FINEST), 5.76 + // Redirty Cards 5.77 + new LogMessageWithLevel("Redirty Cards", Level.FINER), 5.78 + new LogMessageWithLevel("Parallel Redirty", Level.FINEST), 5.79 + new LogMessageWithLevel("Redirtied Cards", Level.FINEST), 5.80 + // Misc Top-level 5.81 + new LogMessageWithLevel("Code Root Purge", Level.FINER), 5.82 + new LogMessageWithLevel("String Dedup Fixup", Level.FINER), 5.83 + // Free CSet 5.84 + new LogMessageWithLevel("Young Free CSet", Level.FINEST), 5.85 + new LogMessageWithLevel("Non-Young Free CSet", Level.FINEST), 5.86 + // Humongous Eager Reclaim 5.87 + new LogMessageWithLevel("Humongous Reclaim", Level.FINER), 5.88 + }; 5.89 5.90 - pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", 5.91 - "-XX:+UseStringDeduplication", 5.92 - "-Xmx10M", 5.93 - "-XX:+PrintGCDetails", 5.94 - GCTest.class.getName()); 5.95 + void checkMessagesAtLevel(OutputAnalyzer output, LogMessageWithLevel messages[], Level level) throws Exception { 5.96 + for (LogMessageWithLevel l : messages) { 5.97 + if (level.lessOrEqualTo(l.level)) { 5.98 + output.shouldNotContain(l.message); 5.99 + } else { 5.100 + output.shouldContain(l.message); 5.101 + } 5.102 + } 5.103 + } 5.104 5.105 - output = new OutputAnalyzer(pb.start()); 5.106 + public static void main(String[] args) throws Exception { 5.107 + new TestGCLogMessages().testNormalLogs(); 5.108 + new TestGCLogMessages().testWithToSpaceExhaustionLogs(); 5.109 + } 5.110 5.111 - output.shouldContain("[Redirty Cards"); 5.112 - output.shouldNotContain("[Parallel Redirty"); 5.113 - output.shouldNotContain("[Redirtied Cards"); 5.114 - output.shouldContain("[Code Root Purge"); 5.115 - output.shouldContain("[String Dedup Fixup"); 5.116 - output.shouldNotContain("[Young Free CSet"); 5.117 - output.shouldNotContain("[Non-Young Free CSet"); 5.118 - output.shouldContain("[Humongous Reclaim"); 5.119 - output.shouldNotContain("[Humongous Total"); 5.120 - output.shouldNotContain("[Humongous Candidate"); 5.121 - output.shouldNotContain("[Humongous Reclaimed"); 5.122 - output.shouldHaveExitValue(0); 5.123 + private void testNormalLogs() throws Exception { 5.124 5.125 - pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", 5.126 - "-XX:+UseStringDeduplication", 5.127 - "-Xmx10M", 5.128 - "-XX:+PrintGCDetails", 5.129 - "-XX:+UnlockExperimentalVMOptions", 5.130 - "-XX:G1LogLevel=finest", 5.131 - GCTest.class.getName()); 5.132 + ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", 5.133 + "-Xmx10M", 5.134 + GCTest.class.getName()); 5.135 5.136 - output = new OutputAnalyzer(pb.start()); 5.137 + OutputAnalyzer output = new OutputAnalyzer(pb.start()); 5.138 + checkMessagesAtLevel(output, allLogMessages, Level.OFF); 5.139 + output.shouldHaveExitValue(0); 5.140 5.141 - output.shouldContain("[Redirty Cards"); 5.142 - output.shouldContain("[Parallel Redirty"); 5.143 - output.shouldContain("[Redirtied Cards"); 5.144 - output.shouldContain("[Code Root Purge"); 5.145 - output.shouldContain("[String Dedup Fixup"); 5.146 - output.shouldContain("[Young Free CSet"); 5.147 - output.shouldContain("[Non-Young Free CSet"); 5.148 - output.shouldContain("[Humongous Reclaim"); 5.149 - output.shouldContain("[Humongous Total"); 5.150 - output.shouldContain("[Humongous Candidate"); 5.151 - output.shouldContain("[Humongous Reclaimed"); 5.152 - output.shouldHaveExitValue(0); 5.153 - } 5.154 + pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", 5.155 + "-XX:+UseStringDeduplication", 5.156 + "-Xmx10M", 5.157 + "-XX:+PrintGCDetails", 5.158 + GCTest.class.getName()); 5.159 5.160 - private static void testWithToSpaceExhaustionLogs() throws Exception { 5.161 - ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", 5.162 - "-Xmx10M", 5.163 - "-Xmn5M", 5.164 - "-XX:+PrintGCDetails", 5.165 - GCTestWithToSpaceExhaustion.class.getName()); 5.166 + output = new OutputAnalyzer(pb.start()); 5.167 + checkMessagesAtLevel(output, allLogMessages, Level.FINER); 5.168 5.169 - OutputAnalyzer output = new OutputAnalyzer(pb.start()); 5.170 - output.shouldContain("[Evacuation Failure"); 5.171 - output.shouldNotContain("[Recalculate Used"); 5.172 - output.shouldNotContain("[Remove Self Forwards"); 5.173 - output.shouldNotContain("[Restore RemSet"); 5.174 - output.shouldHaveExitValue(0); 5.175 + pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", 5.176 + "-XX:+UseStringDeduplication", 5.177 + "-Xmx10M", 5.178 + "-XX:+PrintGCDetails", 5.179 + "-XX:+UnlockExperimentalVMOptions", 5.180 + "-XX:G1LogLevel=finest", 5.181 + GCTest.class.getName()); 5.182 5.183 - pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", 5.184 - "-Xmx10M", 5.185 - "-Xmn5M", 5.186 - "-XX:+PrintGCDetails", 5.187 - "-XX:+UnlockExperimentalVMOptions", 5.188 - "-XX:G1LogLevel=finest", 5.189 - GCTestWithToSpaceExhaustion.class.getName()); 5.190 + output = new OutputAnalyzer(pb.start()); 5.191 + checkMessagesAtLevel(output, allLogMessages, Level.FINEST); 5.192 + output.shouldHaveExitValue(0); 5.193 + } 5.194 5.195 - output = new OutputAnalyzer(pb.start()); 5.196 - output.shouldContain("[Evacuation Failure"); 5.197 - output.shouldContain("[Recalculate Used"); 5.198 - output.shouldContain("[Remove Self Forwards"); 5.199 - output.shouldContain("[Restore RemSet"); 5.200 - output.shouldHaveExitValue(0); 5.201 - } 5.202 + LogMessageWithLevel exhFailureMessages[] = new LogMessageWithLevel[] { 5.203 + new LogMessageWithLevel("Evacuation Failure", Level.FINER), 5.204 + new LogMessageWithLevel("Recalculate Used", Level.FINEST), 5.205 + new LogMessageWithLevel("Remove Self Forwards", Level.FINEST), 5.206 + new LogMessageWithLevel("Restore RemSet", Level.FINEST), 5.207 + }; 5.208 5.209 - static class GCTest { 5.210 - private static byte[] garbage; 5.211 - public static void main(String [] args) { 5.212 - System.out.println("Creating garbage"); 5.213 - // create 128MB of garbage. This should result in at least one GC 5.214 - for (int i = 0; i < 1024; i++) { 5.215 - garbage = new byte[128 * 1024]; 5.216 - } 5.217 - System.out.println("Done"); 5.218 + private void testWithToSpaceExhaustionLogs() throws Exception { 5.219 + ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", 5.220 + "-Xmx32M", 5.221 + "-Xmn16M", 5.222 + "-XX:+PrintGCDetails", 5.223 + GCTestWithToSpaceExhaustion.class.getName()); 5.224 + 5.225 + OutputAnalyzer output = new OutputAnalyzer(pb.start()); 5.226 + checkMessagesAtLevel(output, exhFailureMessages, Level.FINER); 5.227 + output.shouldHaveExitValue(0); 5.228 + 5.229 + pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", 5.230 + "-Xmx32M", 5.231 + "-Xmn16M", 5.232 + "-XX:+PrintGCDetails", 5.233 + "-XX:+UnlockExperimentalVMOptions", 5.234 + "-XX:G1LogLevel=finest", 5.235 + GCTestWithToSpaceExhaustion.class.getName()); 5.236 + 5.237 + output = new OutputAnalyzer(pb.start()); 5.238 + checkMessagesAtLevel(output, exhFailureMessages, Level.FINEST); 5.239 + output.shouldHaveExitValue(0); 5.240 } 5.241 - } 5.242 5.243 - static class GCTestWithToSpaceExhaustion { 5.244 - private static byte[] garbage; 5.245 - private static byte[] largeObject; 5.246 - public static void main(String [] args) { 5.247 - largeObject = new byte[5*1024*1024]; 5.248 - System.out.println("Creating garbage"); 5.249 - // create 128MB of garbage. This should result in at least one GC, 5.250 - // some of them with to-space exhaustion. 5.251 - for (int i = 0; i < 1024; i++) { 5.252 - garbage = new byte[128 * 1024]; 5.253 - } 5.254 - System.out.println("Done"); 5.255 + static class GCTest { 5.256 + private static byte[] garbage; 5.257 + public static void main(String [] args) { 5.258 + System.out.println("Creating garbage"); 5.259 + // create 128MB of garbage. This should result in at least one GC 5.260 + for (int i = 0; i < 1024; i++) { 5.261 + garbage = new byte[128 * 1024]; 5.262 + } 5.263 + System.out.println("Done"); 5.264 + } 5.265 } 5.266 - } 5.267 + 5.268 + static class GCTestWithToSpaceExhaustion { 5.269 + private static byte[] garbage; 5.270 + private static byte[] largeObject; 5.271 + public static void main(String [] args) { 5.272 + largeObject = new byte[16*1024*1024]; 5.273 + System.out.println("Creating garbage"); 5.274 + // create 128MB of garbage. This should result in at least one GC, 5.275 + // some of them with to-space exhaustion. 5.276 + for (int i = 0; i < 1024; i++) { 5.277 + garbage = new byte[128 * 1024]; 5.278 + } 5.279 + System.out.println("Done"); 5.280 + } 5.281 + } 5.282 } 5.283 +
