--- old/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp 2015-02-18 13:24:50.792824195 +0100 +++ new/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp 2015-02-18 13:24:50.719822029 +0100 @@ -351,6 +351,23 @@ gclog_or_tty->cr(); } +static const char* g1_ext_root_task_strings[G1CollectedHeap::G1H_PS_NumElements] = { + "Filter SATB Roots (ms)", + "CM RefProcessor Roots (ms)", + "Wait For Strong CLD (ms)", + "Weak CLD Roots (ms)" +}; + +const char* G1CollectedHeap::ext_roots_task_string(uint i) { + vmassert(i < num_ext_root_tasks(), "must be"); + if (i < SH_PS_NumElements) { + return SharedHeap::ext_roots_task_str(i); + } else { + return g1_ext_root_task_strings[i - SharedHeap::SH_PS_NumElements]; + } +} + + void G1RegionMappingChangedListener::reset_from_card_cache(uint start_idx, size_t num_regions) { HeapRegionRemSet::invalidate_from_card_cache(start_idx, num_regions); } @@ -4552,6 +4569,9 @@ G1ParPushHeapRSClosure push_heap_rs_cl(_g1h, &pss); + G1GCPhaseTimes* pt = _g1h->g1_policy()->phase_times(); + GCPhaseTimeData phase_tracker(pt->get_ext_root_scan_phase_times(), pt->num_ext_root_scan_phases(), worker_id); + pss.start_strong_roots(); _g1h->g1_process_roots(strong_root_cl, weak_root_cl, @@ -4559,7 +4579,8 @@ strong_cld_cl, weak_cld_cl, strong_code_cl, - worker_id); + worker_id, + &phase_tracker); pss.end_strong_roots(); @@ -4604,7 +4625,8 @@ CLDClosure* scan_strong_clds, CLDClosure* scan_weak_clds, CodeBlobClosure* scan_strong_code, - uint worker_i) { + uint worker_i, + PhaseTimeData* phase_tracker) { // First scan the shared roots. double ext_roots_start = os::elapsedTime(); @@ -4623,24 +4645,36 @@ scan_strong_clds, // Unloading Initial Marks handle the weak CLDs separately. (trace_metadata ? NULL : scan_weak_clds), - scan_strong_code); + scan_strong_code, + phase_tracker); // Now the CM ref_processor roots. - if (!_process_strong_tasks->is_task_claimed(G1H_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. - ref_processor_cm()->weak_oops_do(&buf_scan_non_heap_roots); + { + TrackPhaseTime x(phase_tracker, SharedHeap::SH_PS_NumElements + G1H_PS_refProcessor_oops_do); + if (!_process_strong_tasks->is_task_claimed(G1H_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. + 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. - active_strong_roots_scope()->wait_until_all_workers_done_with_threads(n_par_threads()); + { + TrackPhaseTime x(phase_tracker, SharedHeap::SH_PS_NumElements + G1H_PS_wait_strong_cld_nmethods); + if (trace_metadata) { + // Barrier to make sure all workers passed + // the strong CLD and strong nmethods phases. + active_strong_roots_scope()->wait_until_all_workers_done_with_threads(n_par_threads()); + } + } - // Now take the complement of the strong CLDs. - ClassLoaderDataGraph::roots_cld_do(NULL, scan_weak_clds); + { + TrackPhaseTime x(phase_tracker, SharedHeap::SH_PS_NumElements + G1H_PS_weak_clds_oops_do); + if (trace_metadata) { + // Now take the complement of the strong CLDs. + ClassLoaderDataGraph::roots_cld_do(NULL, scan_weak_clds); + } } // Finish up any enqueued closure apps (attributed as object copy time). @@ -4661,13 +4695,16 @@ // to make sure we remove any oops into the CSet (which will show up // as implicitly live). double satb_filtering_ms = 0.0; - if (!_process_strong_tasks->is_task_claimed(G1H_PS_filter_satb_buffers)) { - if (mark_in_progress()) { - double satb_filter_start = os::elapsedTime(); + { + TrackPhaseTime x(phase_tracker, SharedHeap::SH_PS_NumElements + G1H_PS_filter_satb_buffers); + if (!_process_strong_tasks->is_task_claimed(G1H_PS_filter_satb_buffers)) { + if (mark_in_progress()) { + double satb_filter_start = os::elapsedTime(); - JavaThread::satb_mark_queue_set().filter_thread_buffers(); + JavaThread::satb_mark_queue_set().filter_thread_buffers(); - satb_filtering_ms = (os::elapsedTime() - satb_filter_start) * 1000.0; + satb_filtering_ms = (os::elapsedTime() - satb_filter_start) * 1000.0; + } } } g1_policy()->phase_times()->record_satb_filtering_time(worker_i, satb_filtering_ms); --- old/src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp 2015-02-18 13:24:51.277838588 +0100 +++ new/src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp 2015-02-18 13:24:51.204836421 +0100 @@ -795,7 +795,8 @@ CLDClosure* scan_strong_clds, CLDClosure* scan_weak_clds, CodeBlobClosure* scan_strong_code, - uint worker_i); + uint worker_i, + PhaseTimeData* phase_times); // The concurrent marker (and the thread it runs in.) ConcurrentMark* _cm; @@ -983,21 +984,29 @@ // of G1CollectedHeap::_gc_time_stamp. uint* _worker_cset_start_region_time_stamp; + SubTasksDone* _process_strong_tasks; + + volatile bool _free_regions_coming; + + +public: enum G1H_process_roots_tasks { - G1H_PS_filter_satb_buffers, + G1H_PS_First, + G1H_PS_filter_satb_buffers = G1H_PS_First, G1H_PS_refProcessor_oops_do, + G1H_PS_wait_strong_cld_nmethods, + G1H_PS_weak_clds_oops_do, // Leave this one last. G1H_PS_NumElements }; - SubTasksDone* _process_strong_tasks; - - volatile bool _free_regions_coming; - -public: + // Returns the number of external root tasks. + static uint num_ext_root_tasks() { return G1H_PS_NumElements + SharedHeap::SH_PS_NumElements; } + // Returns a human readable description of the given external root task. + static const char* ext_roots_task_string(uint i); SubTasksDone* process_strong_tasks() { return _process_strong_tasks; } - + void set_refine_cte_cl_concurrency(bool concurrent); RefToScanQueue *task_queue(int i) const; --- old/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp 2015-02-18 13:24:51.697851050 +0100 +++ new/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp 2015-02-18 13:24:51.628849003 +0100 @@ -86,6 +86,8 @@ G1CollectorPolicy::G1CollectorPolicy() : _parallel_gc_threads(ParallelGCThreads), + _phase_times(NULL), + _recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), _stop_world_start(0.0), @@ -208,8 +210,6 @@ _recent_prev_end_times_for_all_gcs_sec->add(os::elapsedTime()); _prev_collection_pause_end_ms = os::elapsedTime() * 1000.0; - _phase_times = new G1GCPhaseTimes(_parallel_gc_threads); - int index = MIN2(_parallel_gc_threads - 1, 7); _rs_length_diff_seq->add(rs_length_diff_defaults[index]); @@ -435,6 +435,7 @@ } void G1CollectorPolicy::init() { + _phase_times = new G1GCPhaseTimes(_parallel_gc_threads, G1Log::finest() ? G1CollectedHeap::num_ext_root_tasks() : 0); // Set aside an initial future to_space. _g1 = G1CollectedHeap::heap(); --- old/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp 2015-02-18 13:24:52.117863513 +0100 +++ new/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp 2015-02-18 13:24:52.048861466 +0100 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2013, 2014 Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2013, 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 @@ -158,10 +158,12 @@ #endif -G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) : +G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads, uint num_ext_root_scan_phases) : _max_gc_threads(max_gc_threads), + _num_ext_root_scan_phases(num_ext_root_scan_phases), _last_gc_worker_start_times_ms(_max_gc_threads, "%.1lf", false), _last_ext_root_scan_times_ms(_max_gc_threads, "%.1lf"), + _last_ext_root_scan_phase_times_ms(NULL), _last_satb_filtering_times_ms(_max_gc_threads, "%.1lf"), _last_update_rs_times_ms(_max_gc_threads, "%.1lf"), _last_update_rs_processed_buffers(_max_gc_threads, "%d"), @@ -179,6 +181,21 @@ _cur_string_dedup_table_fixup_worker_times_ms(_max_gc_threads, "%.1lf") { assert(max_gc_threads > 0, "Must have some GC threads"); + if (track_ext_root_scan_phases()) { + _last_ext_root_scan_phase_times_ms = NEW_C_HEAP_ARRAY(WorkerDataArray*, num_ext_root_scan_phases, mtGC); + for (uint i = 0; i < num_ext_root_scan_phases; i++) { + _last_ext_root_scan_phase_times_ms[i] = new WorkerDataArray(_max_gc_threads, "%.1lf"); + } + } +} + +G1GCPhaseTimes::~G1GCPhaseTimes() { + if (track_ext_root_scan_phases()) { + for (uint i = 0; i < _num_ext_root_scan_phases; i++) { + delete _last_ext_root_scan_phase_times_ms[i]; + } + FREE_C_HEAP_ARRAY(WorkerDataArray*, _last_ext_root_scan_phase_times_ms); + } } void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) { @@ -203,6 +220,9 @@ _last_redirty_logged_cards_time_ms.reset(); _last_redirty_logged_cards_processed_cards.reset(); + for (uint i = 0; i < _num_ext_root_scan_phases; i++) { + _last_ext_root_scan_phase_times_ms[i]->reset(); + } } void G1GCPhaseTimes::note_gc_end() { @@ -295,6 +315,12 @@ print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads); _last_gc_worker_start_times_ms.print(2, "GC Worker Start (ms)"); _last_ext_root_scan_times_ms.print(2, "Ext Root Scanning (ms)"); + if (track_ext_root_scan_phases()) { + for (uint i = 0; i < _num_ext_root_scan_phases; i++) { + WorkerDataArray* data = _last_ext_root_scan_phase_times_ms[i]; + data->print(3, G1CollectedHeap::ext_roots_task_string(i)); + } + } if (_last_satb_filtering_times_ms.sum() > 0.0) { _last_satb_filtering_times_ms.print(2, "SATB Filtering (ms)"); } --- old/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp 2015-02-18 13:24:52.522875530 +0100 +++ new/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp 2015-02-18 13:24:52.450873393 +0100 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2013, 2014 Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2013, 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 @@ -107,14 +107,35 @@ } }; +class GCPhaseTimeData : public PhaseTimeData { +private: + WorkerDataArray** _data; + uint _num_phases; + uint _worker_id; +public: + GCPhaseTimeData(WorkerDataArray** data, uint num_phases, uint worker_id) : + _data(data), _num_phases(num_phases), _worker_id(worker_id) { } + + virtual bool active() const { return _num_phases > 0; } + + virtual void set_value(uint phase, double value) { + assert(_data != NULL, "just checking"); + _data[phase]->set(_worker_id, value); + } +}; + class G1GCPhaseTimes : public CHeapObj { private: uint _active_gc_threads; uint _max_gc_threads; + uint _num_ext_root_scan_phases; + + bool track_ext_root_scan_phases() const { return _num_ext_root_scan_phases > 0; } WorkerDataArray _last_gc_worker_start_times_ms; WorkerDataArray _last_ext_root_scan_times_ms; + WorkerDataArray** _last_ext_root_scan_phase_times_ms; WorkerDataArray _last_satb_filtering_times_ms; WorkerDataArray _last_update_rs_times_ms; WorkerDataArray _last_update_rs_processed_buffers; @@ -171,7 +192,12 @@ void print_stats(int level, const char* str, double value, uint workers); public: - G1GCPhaseTimes(uint max_gc_threads); + G1GCPhaseTimes(uint max_gc_threads, uint num_ext_root_scan_phases); + virtual ~G1GCPhaseTimes(); + + WorkerDataArray** get_ext_root_scan_phase_times() const { return _last_ext_root_scan_phase_times_ms; } + uint num_ext_root_scan_phases() const { return _num_ext_root_scan_phases; } + void note_gc_start(uint active_gc_threads); void note_gc_end(); void print(double pause_time_sec); --- old/src/share/vm/memory/sharedHeap.cpp 2015-02-18 13:24:52.916887220 +0100 +++ new/src/share/vm/memory/sharedHeap.cpp 2015-02-18 13:24:52.848885203 +0100 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2000, 2014, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2000, 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 @@ -38,23 +38,27 @@ PRAGMA_FORMAT_MUTE_WARNINGS_FOR_GCC -SharedHeap* SharedHeap::_sh; - -// The set of potentially parallel tasks in root scanning. -enum SH_process_roots_tasks { - SH_PS_Universe_oops_do, - SH_PS_JNIHandles_oops_do, - SH_PS_ObjectSynchronizer_oops_do, - SH_PS_FlatProfiler_oops_do, - SH_PS_Management_oops_do, - SH_PS_SystemDictionary_oops_do, - SH_PS_ClassLoaderDataGraph_oops_do, - SH_PS_jvmti_oops_do, - SH_PS_CodeCache_oops_do, - // Leave this one last. - SH_PS_NumElements +static const char* ext_roots_task_strings[SharedHeap::SH_PS_NumElements] = { + "Thread Roots (ms)", + "StringTable Roots (ms)", + "Universe Roots (ms)", + "JNI Handles Roots (ms)", + "ObjectSynchronizer Roots (ms)", + "FlatProfiler Roots (ms)", + "Management Roots (ms)", + "SystemDictionary Roots (ms)", + "CLDG Roots (ms)", + "JVMTI Roots (ms)", + "CodeCache Roots (ms)" }; +const char* SharedHeap::ext_roots_task_str(uint task) { + vmassert(task < ARRAY_SIZE(ext_roots_task_strings), "must be"); + return ext_roots_task_strings[task]; +} + +SharedHeap* SharedHeap::_sh; + SharedHeap::SharedHeap(CollectorPolicy* policy_) : CollectedHeap(), _collector_policy(policy_), @@ -185,7 +189,8 @@ OopClosure* weak_roots, CLDClosure* strong_cld_closure, CLDClosure* weak_cld_closure, - CodeBlobClosure* code_roots) { + CodeBlobClosure* code_roots, + PhaseTimeData* phase_durations) { StrongRootsScope srs(this, activate_scope); // General roots. @@ -200,8 +205,11 @@ // 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(SH_PS_ClassLoaderDataGraph_oops_do)) { - ClassLoaderDataGraph::roots_cld_do(strong_cld_closure, weak_cld_closure); + { + TrackPhaseTime x(phase_durations, SH_PS_ClassLoaderDataGraph_oops_do); + if (!_process_strong_tasks->is_task_claimed(SH_PS_ClassLoaderDataGraph_oops_do)) { + ClassLoaderDataGraph::roots_cld_do(strong_cld_closure, weak_cld_closure); + } } // Some CLDs contained in the thread frames should be considered strong. @@ -210,60 +218,89 @@ // Only process code roots from thread stacks if we aren't visiting the entire CodeCache anyway CodeBlobClosure* roots_from_code_p = (so & SO_AllCodeCache) ? NULL : code_roots; - Threads::possibly_parallel_oops_do(strong_roots, roots_from_clds_p, roots_from_code_p); + { + TrackPhaseTime x(phase_durations, SH_PS_Threads_oops_do); + Threads::possibly_parallel_oops_do(strong_roots, roots_from_clds_p, roots_from_code_p); + } // 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. active_strong_roots_scope()->mark_worker_done_with_threads(n_par_threads()); - if (!_process_strong_tasks->is_task_claimed(SH_PS_Universe_oops_do)) { - Universe::oops_do(strong_roots); + { + TrackPhaseTime x(phase_durations, SH_PS_Universe_oops_do); + if (!_process_strong_tasks->is_task_claimed(SH_PS_Universe_oops_do)) { + Universe::oops_do(strong_roots); + } } - // Global (strong) JNI handles - if (!_process_strong_tasks->is_task_claimed(SH_PS_JNIHandles_oops_do)) - JNIHandles::oops_do(strong_roots); - - if (!_process_strong_tasks-> is_task_claimed(SH_PS_ObjectSynchronizer_oops_do)) - ObjectSynchronizer::oops_do(strong_roots); - if (!_process_strong_tasks->is_task_claimed(SH_PS_FlatProfiler_oops_do)) - FlatProfiler::oops_do(strong_roots); - if (!_process_strong_tasks->is_task_claimed(SH_PS_Management_oops_do)) - Management::oops_do(strong_roots); - if (!_process_strong_tasks->is_task_claimed(SH_PS_jvmti_oops_do)) - JvmtiExport::oops_do(strong_roots); - - if (!_process_strong_tasks->is_task_claimed(SH_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) { - if (CollectedHeap::use_parallel_gc_threads()) { - StringTable::possibly_parallel_oops_do(weak_roots); - } else { - StringTable::oops_do(weak_roots); + { + TrackPhaseTime x(phase_durations, SH_PS_JNIHandles_oops_do); + // Global (strong) JNI handles + if (!_process_strong_tasks->is_task_claimed(SH_PS_JNIHandles_oops_do)) + JNIHandles::oops_do(strong_roots); + } + + { + TrackPhaseTime x(phase_durations, SH_PS_ObjectSynchronizer_oops_do); + if (!_process_strong_tasks-> is_task_claimed(SH_PS_ObjectSynchronizer_oops_do)) + ObjectSynchronizer::oops_do(strong_roots); + } + { + TrackPhaseTime x(phase_durations, SH_PS_FlatProfiler_oops_do); + if (!_process_strong_tasks->is_task_claimed(SH_PS_FlatProfiler_oops_do)) + FlatProfiler::oops_do(strong_roots); + } + { + TrackPhaseTime x(phase_durations, SH_PS_Management_oops_do); + if (!_process_strong_tasks->is_task_claimed(SH_PS_Management_oops_do)) + Management::oops_do(strong_roots); + } + { + TrackPhaseTime x(phase_durations, SH_PS_jvmti_oops_do); + if (!_process_strong_tasks->is_task_claimed(SH_PS_jvmti_oops_do)) + JvmtiExport::oops_do(strong_roots); + } + { + TrackPhaseTime x(phase_durations, SH_PS_SystemDictionary_oops_do); + if (!_process_strong_tasks->is_task_claimed(SH_PS_SystemDictionary_oops_do)) { + SystemDictionary::roots_oops_do(strong_roots, weak_roots); } } - if (!_process_strong_tasks->is_task_claimed(SH_PS_CodeCache_oops_do)) { - if (so & SO_ScavengeCodeCache) { - assert(code_roots != NULL, "must supply closure for code cache"); - - // We only visit parts of the CodeCache when scavenging. - CodeCache::scavenge_root_nmethods_do(code_roots); + { + TrackPhaseTime x(phase_durations, SH_PS_StringTable_oops_do); + // All threads execute the following. A specific chunk of buckets + // from the StringTable are the individual tasks. + if (weak_roots != NULL) { + if (CollectedHeap::use_parallel_gc_threads()) { + StringTable::possibly_parallel_oops_do(weak_roots); + } else { + StringTable::oops_do(weak_roots); + } } - if (so & SO_AllCodeCache) { - assert(code_roots != NULL, "must supply closure for code cache"); + } - // CMSCollector uses this to do intermediate-strength collections. - // We scan the entire code cache, since CodeCache::do_unloading is not called. - CodeCache::blobs_do(code_roots); + { + TrackPhaseTime x(phase_durations, SH_PS_CodeCache_oops_do); + if (!_process_strong_tasks->is_task_claimed(SH_PS_CodeCache_oops_do)) { + if (so & SO_ScavengeCodeCache) { + assert(code_roots != NULL, "must supply closure for code cache"); + + // We only visit parts of the CodeCache when scavenging. + CodeCache::scavenge_root_nmethods_do(code_roots); + } + if (so & SO_AllCodeCache) { + assert(code_roots != NULL, "must supply closure for code cache"); + + // CMSCollector uses this to do intermediate-strength collections. + // We scan the entire code cache, since CodeCache::do_unloading is not called. + CodeCache::blobs_do(code_roots); + } + // Verify that the code cache contents are not subject to + // movement by a scavenging collection. + DEBUG_ONLY(CodeBlobToOopClosure assert_code_is_non_scavengable(&assert_is_non_scavengable_closure, !CodeBlobToOopClosure::FixRelocations)); + DEBUG_ONLY(CodeCache::asserted_non_scavengable_nmethods_do(&assert_code_is_non_scavengable)); } - // Verify that the code cache contents are not subject to - // movement by a scavenging collection. - DEBUG_ONLY(CodeBlobToOopClosure assert_code_is_non_scavengable(&assert_is_non_scavengable_closure, !CodeBlobToOopClosure::FixRelocations)); - DEBUG_ONLY(CodeCache::asserted_non_scavengable_nmethods_do(&assert_code_is_non_scavengable)); } _process_strong_tasks->all_tasks_completed(); @@ -273,22 +310,26 @@ ScanningOption so, OopClosure* roots, CLDClosure* cld_closure, - CodeBlobClosure* code_closure) { + CodeBlobClosure* code_closure, + PhaseTimeData* phase_durations) { process_roots(activate_scope, so, roots, roots, cld_closure, cld_closure, - code_closure); + code_closure, + phase_durations); } void SharedHeap::process_strong_roots(bool activate_scope, ScanningOption so, OopClosure* roots, CLDClosure* cld_closure, - CodeBlobClosure* code_closure) { + CodeBlobClosure* code_closure, + PhaseTimeData* phase_durations) { process_roots(activate_scope, so, roots, NULL, cld_closure, NULL, - code_closure); + code_closure, + phase_durations); } --- old/src/share/vm/memory/sharedHeap.hpp 2015-02-18 13:24:53.315899058 +0100 +++ new/src/share/vm/memory/sharedHeap.hpp 2015-02-18 13:24:53.251897159 +0100 @@ -1,5 +1,5 @@ /* - * Copyright (c) 2000, 2014, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 2000, 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 @@ -103,7 +103,25 @@ friend class VM_GC_Operation; friend class VM_CGC_Operation; +public: + // The set of potentially parallel tasks in root scanning. + enum SH_process_roots_tasks { + SH_PS_Threads_oops_do, + SH_PS_StringTable_oops_do, + SH_PS_Universe_oops_do, + SH_PS_JNIHandles_oops_do, + SH_PS_ObjectSynchronizer_oops_do, + SH_PS_FlatProfiler_oops_do, + SH_PS_Management_oops_do, + SH_PS_SystemDictionary_oops_do, + SH_PS_ClassLoaderDataGraph_oops_do, + SH_PS_jvmti_oops_do, + SH_PS_CodeCache_oops_do, + // Leave this one last. + SH_PS_NumElements + }; + static const char* ext_roots_task_str(uint task); private: // For claiming strong_roots tasks. SubTasksDone* _process_strong_tasks; @@ -240,17 +258,20 @@ OopClosure* weak_roots, CLDClosure* strong_cld_closure, CLDClosure* weak_cld_closure, - CodeBlobClosure* code_roots); + CodeBlobClosure* code_roots, + PhaseTimeData* phase_durations = NULL); void process_all_roots(bool activate_scope, ScanningOption so, OopClosure* roots, CLDClosure* cld_closure, - CodeBlobClosure* code_roots); + CodeBlobClosure* code_roots, + PhaseTimeData* phase_durations = NULL); void process_strong_roots(bool activate_scope, ScanningOption so, OopClosure* roots, CLDClosure* cld_closure, - CodeBlobClosure* code_roots); + CodeBlobClosure* code_roots, + PhaseTimeData* phase_durations = NULL); // Apply "root_closure" to the JNI weak roots.. --- old/src/share/vm/runtime/timer.cpp 2015-02-18 13:24:53.727911282 +0100 +++ new/src/share/vm/runtime/timer.cpp 2015-02-18 13:24:53.659909264 +0100 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1997, 2014, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1997, 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 @@ -140,6 +140,20 @@ } } +TrackPhaseTime::TrackPhaseTime(PhaseTimeData *data, uint phase) : + _data(data), _phase(phase) { + if (_data != NULL && _data->active()) { + _last = os::elapsed_counter(); + } +} + +TrackPhaseTime::~TrackPhaseTime() { + if (_data != NULL && _data->active()) { + double time = (double)(os::elapsed_counter() - _last) * 1000.0 / os::elapsed_frequency(); + _data->set_value(_phase, time); + } +} + TraceCPUTime::TraceCPUTime(bool doit, bool print_cr, outputStream *logfile) : --- old/src/share/vm/runtime/timer.hpp 2015-02-18 13:24:54.125923090 +0100 +++ new/src/share/vm/runtime/timer.hpp 2015-02-18 13:24:54.061921191 +0100 @@ -1,5 +1,5 @@ /* - * Copyright (c) 1997, 2013, Oracle and/or its affiliates. All rights reserved. + * Copyright (c) 1997, 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 @@ -103,6 +103,23 @@ void resume() { if (_active) _t.start(); } }; +class PhaseTimeData : public StackObj { +public: + virtual bool active() const = 0; + virtual void set_value(uint phase, double value) = 0; +}; + +class TrackPhaseTime : public StackObj { + private: + PhaseTimeData* _data; + uint _phase; + jlong _last; + public: + // Constructors + TrackPhaseTime(PhaseTimeData *data, uint phase); + ~TrackPhaseTime(); +}; + class TraceCPUTime: public StackObj { private: bool _active; // true if times will be measured and printed --- old/test/gc/g1/TestGCLogMessages.java 2015-02-18 13:24:54.503934304 +0100 +++ new/test/gc/g1/TestGCLogMessages.java 2015-02-18 13:24:54.439932405 +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("Filter SATB Roots", 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"); + } } - } } +