--- old/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp 2015-03-18 12:29:04.150318208 +0100 +++ new/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp 2015-03-18 12:29:04.038318213 +0100 @@ -249,7 +249,24 @@ _gc_par_phases[GCWorkerStart] = new WorkerDataArray(max_gc_threads, "GC Worker Start (ms)", false, G1Log::LevelFiner, 2); _gc_par_phases[ExtRootScan] = new WorkerDataArray(max_gc_threads, "Ext Root Scanning (ms)", true, G1Log::LevelFiner, 2); - _gc_par_phases[SATBFiltering] = new WorkerDataArray(max_gc_threads, "SATB Filtering (ms)", true, G1Log::LevelFiner, 2); + + // Root scanning phases + _gc_par_phases[ThreadRoots] = new WorkerDataArray(max_gc_threads, "Thread Roots (ms)", true, G1Log::LevelFinest, 3); + _gc_par_phases[StringTableRoots] = new WorkerDataArray(max_gc_threads, "StringTable Roots (ms)", true, G1Log::LevelFinest, 3); + _gc_par_phases[UniverseRoots] = new WorkerDataArray(max_gc_threads, "Universe Roots (ms)", true, G1Log::LevelFinest, 3); + _gc_par_phases[JNIRoots] = new WorkerDataArray(max_gc_threads, "JNI Handles Roots (ms)", true, G1Log::LevelFinest, 3); + _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray(max_gc_threads, "ObjectSynchronizer Roots (ms)", true, G1Log::LevelFinest, 3); + _gc_par_phases[FlatProfilerRoots] = new WorkerDataArray(max_gc_threads, "FlatProfiler Roots (ms)", true, G1Log::LevelFinest, 3); + _gc_par_phases[ManagementRoots] = new WorkerDataArray(max_gc_threads, "Management Roots (ms)", true, G1Log::LevelFinest, 3); + _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray(max_gc_threads, "SystemDictionary Roots (ms)", true, G1Log::LevelFinest, 3); + _gc_par_phases[CLDGRoots] = new WorkerDataArray(max_gc_threads, "CLDG Roots (ms)", true, G1Log::LevelFinest, 3); + _gc_par_phases[JVMTIRoots] = new WorkerDataArray(max_gc_threads, "JVMTI Roots (ms)", true, G1Log::LevelFinest, 3); + _gc_par_phases[CodeCacheRoots] = new WorkerDataArray(max_gc_threads, "CodeCache Roots (ms)", true, G1Log::LevelFinest, 3); + _gc_par_phases[CMRefRoots] = new WorkerDataArray(max_gc_threads, "CM RefProcessor Roots (ms)", true, G1Log::LevelFinest, 3); + _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray(max_gc_threads, "Wait For Strong CLD (ms)", true, G1Log::LevelFinest, 3); + _gc_par_phases[WeakCLDRoots] = new WorkerDataArray(max_gc_threads, "Weak CLD Roots (ms)", true, G1Log::LevelFinest, 3); + _gc_par_phases[SATBFiltering] = new WorkerDataArray(max_gc_threads, "SATB Filtering (ms)", true, G1Log::LevelFinest, 3); + _gc_par_phases[UpdateRS] = new WorkerDataArray(max_gc_threads, "Update RS (ms)", true, G1Log::LevelFiner, 2); _gc_par_phases[ScanRS] = new WorkerDataArray(max_gc_threads, "Scan RS (ms)", true, G1Log::LevelFiner, 2); _gc_par_phases[CodeRoots] = new WorkerDataArray(max_gc_threads, "Code Root Scanning (ms)", true, G1Log::LevelFiner, 2); @@ -282,8 +299,6 @@ _gc_par_phases[i]->reset(); } - _gc_par_phases[SATBFiltering]->set_enabled(mark_in_progress); - _gc_par_phases[StringDedupQueueFixup]->set_enabled(G1StringDedup::is_enabled()); _gc_par_phases[StringDedupTableFixup]->set_enabled(G1StringDedup::is_enabled()); } --- old/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp 2015-03-18 12:29:04.354318200 +0100 +++ new/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp 2015-03-18 12:29:04.242318205 +0100 @@ -41,6 +41,20 @@ enum GCParPhases { GCWorkerStart, ExtRootScan, + ThreadRoots, + StringTableRoots, + UniverseRoots, + JNIRoots, + ObjectSynchronizerRoots, + FlatProfilerRoots, + ManagementRoots, + SystemDictionaryRoots, + CLDGRoots, + JVMTIRoots, + CodeCacheRoots, + CMRefRoots, + WaitForStrongCLD, + WeakCLDRoots, SATBFiltering, UpdateRS, ScanRS, --- old/src/share/vm/gc_implementation/g1/g1RootProcessor.cpp 2015-03-18 12:29:04.550318192 +0100 +++ new/src/share/vm/gc_implementation/g1/g1RootProcessor.cpp 2015-03-18 12:29:04.438318196 +0100 @@ -128,6 +128,7 @@ uint worker_i) { // First scan the shared roots. double ext_roots_start = os::elapsedTime(); + G1GCPhaseTimes* phase_times = _g1h->g1_policy()->phase_times(); BufferingOopClosure buf_scan_non_heap_roots(scan_non_heap_roots); BufferingOopClosure buf_scan_non_heap_weak_roots(scan_non_heap_weak_roots); @@ -142,7 +143,9 @@ _trace_metadata ? scan_strong_clds : NULL, scan_strong_clds, _trace_metadata ? NULL : scan_weak_clds, - &root_code_blobs); + &root_code_blobs, + phase_times, + worker_i); // This is the point where this worker thread will not find more strong CLDs/nmethods. // Report this so G1 can synchronize the strong and weak CLDs/nmethods processing. @@ -150,24 +153,36 @@ worker_has_discovered_all_strong_classes(); } - process_vm_roots(strong_roots, weak_roots); + process_vm_roots(strong_roots, weak_roots, phase_times, worker_i); - // Now the CM ref_processor roots. - if (!_process_strong_tasks->is_task_claimed(G1RP_PS_refProcessor_oops_do)) { - // We need to treat the discovered reference lists of the - // concurrent mark ref processor as roots and keep entries - // (which are added by the marking threads) on them live - // until they can be processed at the end of marking. - _g1h->ref_processor_cm()->weak_oops_do(&buf_scan_non_heap_roots); + { + // Now the CM ref_processor roots. + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::CMRefRoots, worker_i); + if (!_process_strong_tasks->is_task_claimed(G1RP_PS_refProcessor_oops_do)) { + // We need to treat the discovered reference lists of the + // concurrent mark ref processor as roots and keep entries + // (which are added by the marking threads) on them live + // until they can be processed at the end of marking. + _g1h->ref_processor_cm()->weak_oops_do(&buf_scan_non_heap_roots); + } } if (_trace_metadata) { - // Barrier to make sure all workers passed - // the strong CLD and strong nmethods phases. - wait_until_all_strong_classes_discovered(); + { + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::WaitForStrongCLD, worker_i); + // Barrier to make sure all workers passed + // the strong CLD and strong nmethods phases. + wait_until_all_strong_classes_discovered(); + } - // Now take the complement of the strong CLDs. - ClassLoaderDataGraph::roots_cld_do(NULL, scan_weak_clds); + { + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::WeakCLDRoots, worker_i); + // Now take the complement of the strong CLDs. + ClassLoaderDataGraph::roots_cld_do(NULL, scan_weak_clds); + } + } else { + phase_times->record_time_secs(G1GCPhaseTimes::WaitForStrongCLD, worker_i, 0.0); + phase_times->record_time_secs(G1GCPhaseTimes::WeakCLDRoots, worker_i, 0.0); } // Finish up any enqueued closure apps (attributed as object copy time). @@ -177,7 +192,6 @@ double obj_copy_time_sec = buf_scan_non_heap_roots.closure_app_seconds() + buf_scan_non_heap_weak_roots.closure_app_seconds(); - G1GCPhaseTimes* phase_times = _g1h->g1_policy()->phase_times(); phase_times->record_time_secs(G1GCPhaseTimes::ObjCopy, worker_i, obj_copy_time_sec); double ext_root_time_sec = os::elapsedTime() - ext_roots_start - obj_copy_time_sec; @@ -201,8 +215,8 @@ CLDClosure* clds, CodeBlobClosure* blobs) { - process_java_roots(oops, clds, clds, NULL, blobs); - process_vm_roots(oops, NULL); + process_java_roots(oops, clds, clds, NULL, blobs, NULL, 0); + process_vm_roots(oops, NULL, NULL, 0); _process_strong_tasks->all_tasks_completed(); } @@ -211,8 +225,8 @@ CLDClosure* clds, CodeBlobClosure* blobs) { - process_java_roots(oops, NULL, clds, clds, NULL); - process_vm_roots(oops, oops); + process_java_roots(oops, NULL, clds, clds, NULL, NULL, 0); + process_vm_roots(oops, oops, NULL, 0); if (!_process_strong_tasks->is_task_claimed(G1RP_PS_CodeCache_oops_do)) { CodeCache::blobs_do(blobs); @@ -225,60 +239,95 @@ CLDClosure* thread_stack_clds, CLDClosure* strong_clds, CLDClosure* weak_clds, - CodeBlobClosure* strong_code) { + CodeBlobClosure* strong_code, + G1GCPhaseTimes* phase_times, + uint worker_i) { assert(thread_stack_clds == NULL || weak_clds == NULL, "There is overlap between those, only one may be set"); // Iterating over the CLDG and the Threads are done early to allow us to // first process the strong CLDs and nmethods and then, after a barrier, // let the thread process the weak CLDs and nmethods. - - if (!_process_strong_tasks->is_task_claimed(G1RP_PS_ClassLoaderDataGraph_oops_do)) { - ClassLoaderDataGraph::roots_cld_do(strong_clds, weak_clds); + { + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::CLDGRoots, worker_i); + if (!_process_strong_tasks->is_task_claimed(G1RP_PS_ClassLoaderDataGraph_oops_do)) { + ClassLoaderDataGraph::roots_cld_do(strong_clds, weak_clds); + } } - Threads::possibly_parallel_oops_do(strong_roots, thread_stack_clds, strong_code); + { + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::ThreadRoots, worker_i); + Threads::possibly_parallel_oops_do(strong_roots, thread_stack_clds, strong_code); + } } void G1RootProcessor::process_vm_roots(OopClosure* strong_roots, - OopClosure* weak_roots) { - - if (!_process_strong_tasks->is_task_claimed(G1RP_PS_Universe_oops_do)) { - Universe::oops_do(strong_roots); + OopClosure* weak_roots, + G1GCPhaseTimes* phase_times, + uint worker_i) { + { + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::UniverseRoots, worker_i); + if (!_process_strong_tasks->is_task_claimed(G1RP_PS_Universe_oops_do)) { + Universe::oops_do(strong_roots); + } } - if (!_process_strong_tasks->is_task_claimed(G1RP_PS_JNIHandles_oops_do)) { - JNIHandles::oops_do(strong_roots); + { + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::JNIRoots, worker_i); + if (!_process_strong_tasks->is_task_claimed(G1RP_PS_JNIHandles_oops_do)) { + JNIHandles::oops_do(strong_roots); + } } - if (!_process_strong_tasks-> is_task_claimed(G1RP_PS_ObjectSynchronizer_oops_do)) { - ObjectSynchronizer::oops_do(strong_roots); + { + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::ObjectSynchronizerRoots, worker_i); + if (!_process_strong_tasks-> is_task_claimed(G1RP_PS_ObjectSynchronizer_oops_do)) { + ObjectSynchronizer::oops_do(strong_roots); + } } - if (!_process_strong_tasks->is_task_claimed(G1RP_PS_FlatProfiler_oops_do)) { - FlatProfiler::oops_do(strong_roots); + { + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::FlatProfilerRoots, worker_i); + if (!_process_strong_tasks->is_task_claimed(G1RP_PS_FlatProfiler_oops_do)) { + FlatProfiler::oops_do(strong_roots); + } } - if (!_process_strong_tasks->is_task_claimed(G1RP_PS_Management_oops_do)) { - Management::oops_do(strong_roots); + { + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::ManagementRoots, worker_i); + if (!_process_strong_tasks->is_task_claimed(G1RP_PS_Management_oops_do)) { + Management::oops_do(strong_roots); + } } - if (!_process_strong_tasks->is_task_claimed(G1RP_PS_jvmti_oops_do)) { - JvmtiExport::oops_do(strong_roots); + { + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::JVMTIRoots, worker_i); + if (!_process_strong_tasks->is_task_claimed(G1RP_PS_jvmti_oops_do)) { + JvmtiExport::oops_do(strong_roots); + } } - if (!_process_strong_tasks->is_task_claimed(G1RP_PS_SystemDictionary_oops_do)) { - SystemDictionary::roots_oops_do(strong_roots, weak_roots); + { + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::SystemDictionaryRoots, worker_i); + if (!_process_strong_tasks->is_task_claimed(G1RP_PS_SystemDictionary_oops_do)) { + SystemDictionary::roots_oops_do(strong_roots, weak_roots); + } } - // All threads execute the following. A specific chunk of buckets - // from the StringTable are the individual tasks. - if (weak_roots != NULL) { - StringTable::possibly_parallel_oops_do(weak_roots); + { + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::StringTableRoots, worker_i); + // All threads execute the following. A specific chunk of buckets + // from the StringTable are the individual tasks. + if (weak_roots != NULL) { + StringTable::possibly_parallel_oops_do(weak_roots); + } } } void G1RootProcessor::scan_remembered_sets(G1ParPushHeapRSClosure* scan_rs, OopClosure* scan_non_heap_weak_roots, uint worker_i) { + G1GCPhaseTimes* phase_times = _g1h->g1_policy()->phase_times(); + G1GCParPhaseTimesTracker x(phase_times, G1GCPhaseTimes::CodeCacheRoots, worker_i); + // Now scan the complement of the collection set. G1CodeBlobClosure scavenge_cs_nmethods(scan_non_heap_weak_roots); --- old/src/share/vm/gc_implementation/g1/g1RootProcessor.hpp 2015-03-18 12:29:04.754318183 +0100 +++ new/src/share/vm/gc_implementation/g1/g1RootProcessor.hpp 2015-03-18 12:29:04.646318188 +0100 @@ -32,6 +32,7 @@ class CLDClosure; class CodeBlobClosure; class G1CollectedHeap; +class G1GCPhaseTimes; class G1ParPushHeapRSClosure; class Monitor; class OopClosure; @@ -75,10 +76,14 @@ CLDClosure* thread_stack_clds, CLDClosure* scan_strong_clds, CLDClosure* scan_weak_clds, - CodeBlobClosure* scan_strong_code); + CodeBlobClosure* scan_strong_code, + G1GCPhaseTimes* phase_times, + uint worker_i); void process_vm_roots(OopClosure* scan_non_heap_roots, - OopClosure* scan_non_heap_weak_roots); + OopClosure* scan_non_heap_weak_roots, + G1GCPhaseTimes* phase_times, + uint worker_i); public: G1RootProcessor(G1CollectedHeap* g1h, bool trace_metadata); --- old/test/gc/g1/TestGCLogMessages.java 2015-03-18 12:29:04.930318176 +0100 +++ new/test/gc/g1/TestGCLogMessages.java 2015-03-18 12:29:04.826318180 +0100 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2014, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2014, 2015 Oracle and/or its affiliates. All rights reserved. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. * * This code is free software; you can redistribute it and/or modify it @@ -23,7 +23,7 @@ /* * @test TestGCLogMessages - * @bug 8035406 8027295 8035398 8019342 8027959 8048179 + * @bug 8035406 8027295 8035398 8019342 8027959 8048179 8027962 * @summary Ensure that the PrintGCDetails output for a minor GC with G1 * includes the expected necessary messages. * @key gc @@ -34,131 +34,159 @@ import com.oracle.java.testlibrary.OutputAnalyzer; public class TestGCLogMessages { - public static void main(String[] args) throws Exception { - testNormalLogs(); - testWithToSpaceExhaustionLogs(); - } - - private static void testNormalLogs() throws Exception { - - ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", - "-Xmx10M", - GCTest.class.getName()); - - OutputAnalyzer output = new OutputAnalyzer(pb.start()); - - output.shouldNotContain("[Redirty Cards"); - output.shouldNotContain("[Parallel Redirty"); - output.shouldNotContain("[Redirtied Cards"); - output.shouldNotContain("[Code Root Purge"); - output.shouldNotContain("[String Dedup Fixup"); - output.shouldNotContain("[Young Free CSet"); - output.shouldNotContain("[Non-Young Free CSet"); - output.shouldNotContain("[Humongous Register"); - output.shouldNotContain("[Humongous Reclaim"); - output.shouldHaveExitValue(0); - - pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", - "-XX:+UseStringDeduplication", - "-Xmx10M", - "-XX:+PrintGCDetails", - GCTest.class.getName()); - - output = new OutputAnalyzer(pb.start()); - - output.shouldContain("[Redirty Cards"); - output.shouldNotContain("[Parallel Redirty"); - output.shouldNotContain("[Redirtied Cards"); - output.shouldContain("[Code Root Purge"); - output.shouldContain("[String Dedup Fixup"); - output.shouldNotContain("[Young Free CSet"); - output.shouldNotContain("[Non-Young Free CSet"); - output.shouldContain("[Humongous Register"); - output.shouldNotContain("[Humongous Total"); - output.shouldNotContain("[Humongous Candidate"); - output.shouldContain("[Humongous Reclaim"); - output.shouldNotContain("[Humongous Reclaimed"); - output.shouldHaveExitValue(0); - - pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", - "-XX:+UseStringDeduplication", - "-Xmx10M", - "-XX:+PrintGCDetails", - "-XX:+UnlockExperimentalVMOptions", - "-XX:G1LogLevel=finest", - GCTest.class.getName()); - - output = new OutputAnalyzer(pb.start()); - - output.shouldContain("[Redirty Cards"); - output.shouldContain("[Parallel Redirty"); - output.shouldContain("[Redirtied Cards"); - output.shouldContain("[Code Root Purge"); - output.shouldContain("[String Dedup Fixup"); - output.shouldContain("[Young Free CSet"); - output.shouldContain("[Non-Young Free CSet"); - output.shouldContain("[Humongous Register"); - output.shouldContain("[Humongous Total"); - output.shouldContain("[Humongous Candidate"); - output.shouldContain("[Humongous Reclaim"); - output.shouldContain("[Humongous Reclaimed"); - output.shouldHaveExitValue(0); - } - - private static void testWithToSpaceExhaustionLogs() throws Exception { - ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", - "-Xmx32M", - "-Xmn16M", - "-XX:+PrintGCDetails", - GCTestWithToSpaceExhaustion.class.getName()); - - OutputAnalyzer output = new OutputAnalyzer(pb.start()); - output.shouldContain("[Evacuation Failure"); - output.shouldNotContain("[Recalculate Used"); - output.shouldNotContain("[Remove Self Forwards"); - output.shouldNotContain("[Restore RemSet"); - output.shouldHaveExitValue(0); - - pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", - "-Xmx32M", - "-Xmn16M", - "-XX:+PrintGCDetails", - "-XX:+UnlockExperimentalVMOptions", - "-XX:G1LogLevel=finest", - GCTestWithToSpaceExhaustion.class.getName()); - - output = new OutputAnalyzer(pb.start()); - output.shouldContain("[Evacuation Failure"); - output.shouldContain("[Recalculate Used"); - output.shouldContain("[Remove Self Forwards"); - output.shouldContain("[Restore RemSet"); - output.shouldHaveExitValue(0); - } - - static class GCTest { - private static byte[] garbage; - public static void main(String [] args) { - System.out.println("Creating garbage"); - // create 128MB of garbage. This should result in at least one GC - for (int i = 0; i < 1024; i++) { - garbage = new byte[128 * 1024]; - } - System.out.println("Done"); - } - } - - static class GCTestWithToSpaceExhaustion { - private static byte[] garbage; - private static byte[] largeObject; - public static void main(String [] args) { - largeObject = new byte[16*1024*1024]; - System.out.println("Creating garbage"); - // create 128MB of garbage. This should result in at least one GC, - // some of them with to-space exhaustion. - for (int i = 0; i < 1024; i++) { - garbage = new byte[128 * 1024]; - } - System.out.println("Done"); + + private enum Level { + OFF, FINER, FINEST; + public boolean lessOrEqualTo(Level other) { + return this.compareTo(other) < 0; + } + } + + private class LogMessageWithLevel { + String message; + Level level; + + public LogMessageWithLevel(String message, Level level) { + this.message = message; + this.level = level; + } + }; + + private LogMessageWithLevel allLogMessages[] = new LogMessageWithLevel[] { + // Ext Root Scan + new LogMessageWithLevel("Thread Roots (ms)", Level.FINEST), + new LogMessageWithLevel("StringTable Roots (ms)", Level.FINEST), + new LogMessageWithLevel("Universe Roots (ms)", Level.FINEST), + new LogMessageWithLevel("JNI Handles Roots (ms)", Level.FINEST), + new LogMessageWithLevel("ObjectSynchronizer Roots (ms)", Level.FINEST), + new LogMessageWithLevel("FlatProfiler Roots", Level.FINEST), + new LogMessageWithLevel("Management Roots", Level.FINEST), + new LogMessageWithLevel("SystemDictionary Roots", Level.FINEST), + new LogMessageWithLevel("CLDG Roots", Level.FINEST), + new LogMessageWithLevel("JVMTI Roots", Level.FINEST), + new LogMessageWithLevel("CodeCache Roots", Level.FINEST), + new LogMessageWithLevel("SATB Filtering", Level.FINEST), + new LogMessageWithLevel("CM RefProcessor Roots", Level.FINEST), + new LogMessageWithLevel("Wait For Strong CLD", Level.FINEST), + new LogMessageWithLevel("Weak CLD Roots", Level.FINEST), + // Redirty Cards + new LogMessageWithLevel("Redirty Cards", Level.FINER), + new LogMessageWithLevel("Parallel Redirty", Level.FINEST), + new LogMessageWithLevel("Redirtied Cards", Level.FINEST), + // Misc Top-level + new LogMessageWithLevel("Code Root Purge", Level.FINER), + new LogMessageWithLevel("String Dedup Fixup", Level.FINER), + // Free CSet + new LogMessageWithLevel("Young Free CSet", Level.FINEST), + new LogMessageWithLevel("Non-Young Free CSet", Level.FINEST), + // Humongous Eager Reclaim + new LogMessageWithLevel("Humongous Reclaim", Level.FINER), + new LogMessageWithLevel("Humongous Register", Level.FINER), + }; + + void checkMessagesAtLevel(OutputAnalyzer output, LogMessageWithLevel messages[], Level level) throws Exception { + for (LogMessageWithLevel l : messages) { + if (level.lessOrEqualTo(l.level)) { + output.shouldNotContain(l.message); + } else { + output.shouldContain(l.message); + } + } + } + + public static void main(String[] args) throws Exception { + new TestGCLogMessages().testNormalLogs(); + new TestGCLogMessages().testWithToSpaceExhaustionLogs(); + } + + private void testNormalLogs() throws Exception { + + ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", + "-Xmx10M", + GCTest.class.getName()); + + OutputAnalyzer output = new OutputAnalyzer(pb.start()); + checkMessagesAtLevel(output, allLogMessages, Level.OFF); + output.shouldHaveExitValue(0); + + pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", + "-XX:+UseStringDeduplication", + "-Xmx10M", + "-XX:+PrintGCDetails", + GCTest.class.getName()); + + output = new OutputAnalyzer(pb.start()); + checkMessagesAtLevel(output, allLogMessages, Level.FINER); + + pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", + "-XX:+UseStringDeduplication", + "-Xmx10M", + "-XX:+PrintGCDetails", + "-XX:+UnlockExperimentalVMOptions", + "-XX:G1LogLevel=finest", + GCTest.class.getName()); + + output = new OutputAnalyzer(pb.start()); + checkMessagesAtLevel(output, allLogMessages, Level.FINEST); + output.shouldHaveExitValue(0); + } + + LogMessageWithLevel exhFailureMessages[] = new LogMessageWithLevel[] { + new LogMessageWithLevel("Evacuation Failure", Level.FINER), + new LogMessageWithLevel("Recalculate Used", Level.FINEST), + new LogMessageWithLevel("Remove Self Forwards", Level.FINEST), + new LogMessageWithLevel("Restore RemSet", Level.FINEST), + }; + + private void testWithToSpaceExhaustionLogs() throws Exception { + ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", + "-Xmx32M", + "-Xmn16M", + "-XX:+PrintGCDetails", + GCTestWithToSpaceExhaustion.class.getName()); + + OutputAnalyzer output = new OutputAnalyzer(pb.start()); + checkMessagesAtLevel(output, exhFailureMessages, Level.FINER); + output.shouldHaveExitValue(0); + + pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC", + "-Xmx32M", + "-Xmn16M", + "-XX:+PrintGCDetails", + "-XX:+UnlockExperimentalVMOptions", + "-XX:G1LogLevel=finest", + GCTestWithToSpaceExhaustion.class.getName()); + + output = new OutputAnalyzer(pb.start()); + checkMessagesAtLevel(output, exhFailureMessages, Level.FINEST); + output.shouldHaveExitValue(0); + } + + static class GCTest { + private static byte[] garbage; + public static void main(String [] args) { + System.out.println("Creating garbage"); + // create 128MB of garbage. This should result in at least one GC + for (int i = 0; i < 1024; i++) { + garbage = new byte[128 * 1024]; + } + System.out.println("Done"); + } + } + + static class GCTestWithToSpaceExhaustion { + private static byte[] garbage; + private static byte[] largeObject; + public static void main(String [] args) { + largeObject = new byte[16*1024*1024]; + System.out.println("Creating garbage"); + // create 128MB of garbage. This should result in at least one GC, + // some of them with to-space exhaustion. + for (int i = 0; i < 1024; i++) { + garbage = new byte[128 * 1024]; + } + System.out.println("Done"); + } } - } } +