Skip to content

D
dragonwell8_hotspot

openanolis / dragonwell8_hotspot

通知 2
Star 2
Fork 0
D
dragonwell8_hotspot

体验新版 GitCode，发现更多精彩内容 >>

提交 b7f37497 编写于 作者: J jmasa
浏览文件
操作

Merge

上级 85d771bd b0453758
展开全部 隐藏空白更改
内联 并排
Showing with 732 addition and 663 deletion
src/share/vm/gc_implementation/g1/concurrentG1Refine.cpp
浏览文件 @ b7f37497
/*
* Copyright (c) 2001, 2011, Oracle and/or its affiliates. All rights reserved.
* Copyright (c) 2001, 2012, 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
......@@ -27,6 +27,7 @@
#include "gc_implementation/g1/concurrentG1RefineThread.hpp"
#include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
#include "gc_implementation/g1/g1CollectorPolicy.hpp"
#include "gc_implementation/g1/g1GCPhaseTimes.hpp"
#include "gc_implementation/g1/g1RemSet.hpp"
#include "gc_implementation/g1/heapRegionSeq.inline.hpp"
#include "memory/space.inline.hpp"
......@@ -500,11 +501,11 @@ bool ConcurrentG1Refine::expand_card_count_cache(int cache_size_idx) {
}
void ConcurrentG1Refine::clear_and_record_card_counts() {
if (G1ConcRSLogCacheSize == 0) return;
if (G1ConcRSLogCacheSize == 0) {
return;
}
#ifndef PRODUCT
double start = os::elapsedTime();
#endif
if (_expand_card_counts) {
int new_idx = _cache_size_index + 1;
......@@ -523,11 +524,8 @@ void ConcurrentG1Refine::clear_and_record_card_counts() {
assert((this_epoch+1) <= max_jint, "to many periods");
// Update epoch
_n_periods++;
#ifndef PRODUCT
double elapsed = os::elapsedTime() - start;
_g1h->g1_policy()->record_cc_clear_time(elapsed * 1000.0);
#endif
double cc_clear_time_ms = (os::elapsedTime() - start) * 1000;
_g1h->g1_policy()->phase_times()->record_cc_clear_time_ms(cc_clear_time_ms);
}
void ConcurrentG1Refine::print_worker_threads_on(outputStream* st) const {
......
src/share/vm/gc_implementation/g1/concurrentMark.cpp
浏览文件 @ b7f37497
......@@ -3156,9 +3156,6 @@ bool ConcurrentMark::do_yield_check(uint worker_id) {
_g1h->g1_policy()->record_concurrent_pause();
}
cmThread()->yield();
if (worker_id == 0) {
_g1h->g1_policy()->record_concurrent_pause_end();
}
return true;
} else {
return false;
......
src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp
浏览文件 @ b7f37497
......@@ -33,6 +33,7 @@
#include "gc_implementation/g1/g1CollectorPolicy.hpp"
#include "gc_implementation/g1/g1ErgoVerbose.hpp"
#include "gc_implementation/g1/g1EvacFailure.hpp"
#include "gc_implementation/g1/g1GCPhaseTimes.hpp"
#include "gc_implementation/g1/g1Log.hpp"
#include "gc_implementation/g1/g1MarkSweep.hpp"
#include "gc_implementation/g1/g1OopClosures.inline.hpp"
......@@ -2274,7 +2275,7 @@ void G1CollectedHeap::iterate_dirty_card_closure(CardTableEntryClosure* cl,
while (dcqs.apply_closure_to_completed_buffer(cl, worker_i, 0, true)) {
n_completed_buffers++;
}
g1_policy()->record_update_rs_processed_buffers(worker_i,
g1_policy()->phase_times()->record_update_rs_processed_buffers(worker_i,
(double) n_completed_buffers);
dcqs.clear_n_completed_buffers();
assert(!dcqs.completed_buffers_exist_dirty(), "Completed buffers exist!");
......@@ -3633,10 +3634,10 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps);
TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty);
GCCauseString gc_cause_str = GCCauseString("GC pause", gc_cause())
.append(g1_policy()->gcs_are_young() ? " (young)" : " (mixed)")
.append(g1_policy()->during_initial_mark_pause() ? " (initial-mark)" : "");
TraceTime t(gc_cause_str, G1Log::fine() && !G1Log::finer(), true, gclog_or_tty);
int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ?
workers()->active_workers() : 1);
g1_policy()->phase_times()->note_gc_start(os::elapsedTime(), active_workers,
g1_policy()->gcs_are_young(), g1_policy()->during_initial_mark_pause(), gc_cause());
TraceCollectorStats tcs(g1mm()->incremental_collection_counters());
TraceMemoryManagerStats tms(false /* fullGC */, gc_cause());
......@@ -3699,9 +3700,15 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
// before the start GC event.
_hr_printer.start_gc(false /* full */, (size_t) total_collections());
// This timing is only used by the ergonomics to handle our pause target.
// It is unclear why this should not include the full pause. We will
// investigate this in CR 7178365.
//
// Preserving the old comment here if that helps the investigation:
//
// The elapsed time induced by the start time below deliberately elides
// the possible verification above.
double start_time_sec = os::elapsedTime();
double sample_start_time_sec = os::elapsedTime();
size_t start_used_bytes = used();
#if YOUNG_LIST_VERBOSE
......@@ -3710,7 +3717,7 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
g1_policy()->print_collection_set(g1_policy()->inc_cset_head(), gclog_or_tty);
#endif // YOUNG_LIST_VERBOSE
g1_policy()->record_collection_pause_start(start_time_sec,
g1_policy()->record_collection_pause_start(sample_start_time_sec,
start_used_bytes);
double scan_wait_start = os::elapsedTime();
......@@ -3719,11 +3726,12 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
// objects on them have been correctly scanned before we start
// moving them during the GC.
bool waited = _cm->root_regions()->wait_until_scan_finished();
double wait_time_ms = 0.0;
if (waited) {
double scan_wait_end = os::elapsedTime();
double wait_time_ms = (scan_wait_end - scan_wait_start) * 1000.0;
g1_policy()->record_root_region_scan_wait_time(wait_time_ms);
wait_time_ms = (scan_wait_end - scan_wait_start) * 1000.0;
}
g1_policy()->phase_times()->record_root_region_scan_wait_time(wait_time_ms);
#if YOUNG_LIST_VERBOSE
gclog_or_tty->print_cr("\nAfter recording pause start.\nYoung_list:");
......@@ -3877,12 +3885,16 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
true /* verify_fingers */);
_cm->note_end_of_gc();
double end_time_sec = os::elapsedTime();
double pause_time_ms = (end_time_sec - start_time_sec) * MILLIUNITS;
g1_policy()->record_pause_time_ms(pause_time_ms);
int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ?
workers()->active_workers() : 1);
g1_policy()->record_collection_pause_end(active_workers);
// Collect thread local data to allow the ergonomics to use
// the collected information
g1_policy()->phase_times()->collapse_par_times();
// This timing is only used by the ergonomics to handle our pause target.
// It is unclear why this should not include the full pause. We will
// investigate this in CR 7178365.
double sample_end_time_sec = os::elapsedTime();
double pause_time_ms = (sample_end_time_sec - sample_start_time_sec) * MILLIUNITS;
g1_policy()->record_collection_pause_end(pause_time_ms);
MemoryService::track_memory_usage();
......@@ -3929,9 +3941,6 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
// RETIRE events are generated before the end GC event.
_hr_printer.end_gc(false /* full */, (size_t) total_collections());
// We have to do this after we decide whether to expand the heap or not.
g1_policy()->print_heap_transition();
if (mark_in_progress()) {
concurrent_mark()->update_g1_committed();
}
......@@ -3941,13 +3950,14 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
#endif
gc_epilogue(false);
g1_policy()->phase_times()->note_gc_end(os::elapsedTime());
// We have to do this after we decide whether to expand the heap or not.
g1_policy()->print_heap_transition();
}
// The closing of the inner scope, immediately above, will complete
// logging at the "fine" level. The record_collection_pause_end() call
// above will complete logging at the "finer" level.
//
// It is not yet to safe, however, to tell the concurrent mark to
// It is not yet to safe to tell the concurrent mark to
// start as we have some optional output below. We don't want the
// output from the concurrent mark thread interfering with this
// logging output either.
......@@ -4695,7 +4705,7 @@ public:
if (worker_id >= _n_workers) return; // no work needed this round
double start_time_ms = os::elapsedTime() * 1000.0;
_g1h->g1_policy()->record_gc_worker_start_time(worker_id, start_time_ms);
_g1h->g1_policy()->phase_times()->record_gc_worker_start_time(worker_id, start_time_ms);
{
ResourceMark rm;
......@@ -4744,8 +4754,8 @@ public:
evac.do_void();
double elapsed_ms = (os::elapsedTime()-start)*1000.0;
double term_ms = pss.term_time()*1000.0;
_g1h->g1_policy()->record_obj_copy_time(worker_id, elapsed_ms-term_ms);
_g1h->g1_policy()->record_termination(worker_id, term_ms, pss.term_attempts());
_g1h->g1_policy()->phase_times()->record_obj_copy_time(worker_id, elapsed_ms-term_ms);
_g1h->g1_policy()->phase_times()->record_termination(worker_id, term_ms, pss.term_attempts());
}
_g1h->g1_policy()->record_thread_age_table(pss.age_table());
_g1h->update_surviving_young_words(pss.surviving_young_words()+1);
......@@ -4763,7 +4773,7 @@ public:
}
double end_time_ms = os::elapsedTime() * 1000.0;
_g1h->g1_policy()->record_gc_worker_end_time(worker_id, end_time_ms);
_g1h->g1_policy()->phase_times()->record_gc_worker_end_time(worker_id, end_time_ms);
}
};
......@@ -4874,15 +4884,15 @@ g1_process_strong_roots(bool collecting_perm_gen,
double ext_roots_end = os::elapsedTime();
g1_policy()->reset_obj_copy_time(worker_i);
g1_policy()->phase_times()->reset_obj_copy_time(worker_i);
double obj_copy_time_sec = buf_scan_perm.closure_app_seconds() +
buf_scan_non_heap_roots.closure_app_seconds();
g1_policy()->record_obj_copy_time(worker_i, obj_copy_time_sec * 1000.0);
g1_policy()->phase_times()->record_obj_copy_time(worker_i, obj_copy_time_sec * 1000.0);
double ext_root_time_ms =
((ext_roots_end - ext_roots_start) - obj_copy_time_sec) * 1000.0;
g1_policy()->record_ext_root_scan_time(worker_i, ext_root_time_ms);
g1_policy()->phase_times()->record_ext_root_scan_time(worker_i, ext_root_time_ms);
// During conc marking we have to filter the per-thread SATB buffers
// to make sure we remove any oops into the CSet (which will show up
......@@ -4893,7 +4903,7 @@ g1_process_strong_roots(bool collecting_perm_gen,
}
}
double satb_filtering_ms = (os::elapsedTime() - ext_roots_end) * 1000.0;
g1_policy()->record_satb_filtering_time(worker_i, satb_filtering_ms);
g1_policy()->phase_times()->record_satb_filtering_time(worker_i, satb_filtering_ms);
// Now scan the complement of the collection set.
if (scan_rs != NULL) {
......@@ -5393,7 +5403,7 @@ void G1CollectedHeap::process_discovered_references() {
assert(pss.refs()->is_empty(), "both queue and overflow should be empty");
double ref_proc_time = os::elapsedTime() - ref_proc_start;
g1_policy()->record_ref_proc_time(ref_proc_time * 1000.0);
g1_policy()->phase_times()->record_ref_proc_time(ref_proc_time * 1000.0);
}
// Weak Reference processing during an evacuation pause (part 2).
......@@ -5430,7 +5440,7 @@ void G1CollectedHeap::enqueue_discovered_references() {
// and could signicantly increase the pause time.
double ref_enq_time = os::elapsedTime() - ref_enq_start;
g1_policy()->record_ref_enq_time(ref_enq_time * 1000.0);
g1_policy()->phase_times()->record_ref_enq_time(ref_enq_time * 1000.0);
}
void G1CollectedHeap::evacuate_collection_set() {
......@@ -5493,11 +5503,11 @@ void G1CollectedHeap::evacuate_collection_set() {
}
double par_time_ms = (end_par_time_sec - start_par_time_sec) * 1000.0;
g1_policy()->record_par_time(par_time_ms);
g1_policy()->phase_times()->record_par_time(par_time_ms);
double code_root_fixup_time_ms =
(os::elapsedTime() - end_par_time_sec) * 1000.0;
g1_policy()->record_code_root_fixup_time(code_root_fixup_time_ms);
g1_policy()->phase_times()->record_code_root_fixup_time(code_root_fixup_time_ms);
set_par_threads(0);
......@@ -5759,7 +5769,7 @@ void G1CollectedHeap::cleanUpCardTable() {
}
double elapsed = os::elapsedTime() - start;
g1_policy()->record_clear_ct_time(elapsed * 1000.0);
g1_policy()->phase_times()->record_clear_ct_time(elapsed * 1000.0);
}
void G1CollectedHeap::free_collection_set(HeapRegion* cs_head) {
......@@ -5868,8 +5878,8 @@ void G1CollectedHeap::free_collection_set(HeapRegion* cs_head) {
NULL /* old_proxy_set */,
NULL /* humongous_proxy_set */,
false /* par */);
policy->record_young_free_cset_time_ms(young_time_ms);
policy->record_non_young_free_cset_time_ms(non_young_time_ms);
policy->phase_times()->record_young_free_cset_time_ms(young_time_ms);
policy->phase_times()->record_non_young_free_cset_time_ms(non_young_time_ms);
}
// This routine is similar to the above but does not record
......
src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp
浏览文件 @ b7f37497
......@@ -36,6 +36,7 @@
class HeapRegion;
class CollectionSetChooser;
class G1GCPhaseTimes;
// TraceGen0Time collects data on _both_ young and mixed evacuation pauses
// (the latter may contain non-young regions - i.e. regions that are
......@@ -61,26 +62,14 @@ class TraceGen0TimeData : public CHeapObj<mtGC> {
NumberSeq _parallel_other;
NumberSeq _clear_ct;
void print_summary (int level, const char* str, const NumberSeq* seq) const;
void print_summary_sd (int level, const char* str, const NumberSeq* seq) const;
void print_summary(const char* str, const NumberSeq* seq) const;
void print_summary_sd(const char* str, const NumberSeq* seq) const;
public:
TraceGen0TimeData() : _young_pause_num(0), _mixed_pause_num(0) {};
void record_start_collection(double time_to_stop_the_world_ms);
void record_yield_time(double yield_time_ms);
void record_end_collection(
double total_ms,
double other_ms,
double root_region_scan_wait_ms,
double parallel_ms,
double ext_root_scan_ms,
double satb_filtering_ms,
double update_rs_ms,
double scan_rs_ms,
double obj_copy_ms,
double termination_ms,
double parallel_other_ms,
double clear_ct_ms);
void record_end_collection(double pause_time_ms, G1GCPhaseTimes* phase_times);
void increment_young_collection_count();
void increment_mixed_collection_count();
void print() const;
......@@ -186,25 +175,9 @@ private:
CollectionSetChooser* _collectionSetChooser;
double _cur_collection_start_sec;
double _full_collection_start_sec;
size_t _cur_collection_pause_used_at_start_bytes;
uint _cur_collection_pause_used_regions_at_start;
double _cur_collection_par_time_ms;
double _cur_collection_code_root_fixup_time_ms;
double _cur_clear_ct_time_ms;
double _cur_ref_proc_time_ms;
double _cur_ref_enq_time_ms;
#ifndef PRODUCT
// Card Table Count Cache stats
double _min_clear_cc_time_ms; // min
double _max_clear_cc_time_ms; // max
double _cur_clear_cc_time_ms; // clearing time during current pause
double _cum_clear_cc_time_ms; // cummulative clearing time
jlong _num_cc_clears; // number of times the card count cache has been cleared
#endif
// These exclude marking times.
TruncatedSeq* _recent_gc_times_ms;
......@@ -217,23 +190,6 @@ private:
double _stop_world_start;
double* _par_last_gc_worker_start_times_ms;
double* _par_last_ext_root_scan_times_ms;
double* _par_last_satb_filtering_times_ms;
double* _par_last_update_rs_times_ms;
double* _par_last_update_rs_processed_buffers;
double* _par_last_scan_rs_times_ms;
double* _par_last_obj_copy_times_ms;
double* _par_last_termination_times_ms;
double* _par_last_termination_attempts;
double* _par_last_gc_worker_end_times_ms;
double* _par_last_gc_worker_times_ms;
// Each workers 'other' time i.e. the elapsed time of the parallel
// code executed by a worker minus the sum of the individual sub-phase
// times for that worker thread.
double* _par_last_gc_worker_other_times_ms;
// indicates whether we are in young or mixed GC mode
bool _gcs_are_young;
......@@ -306,10 +262,6 @@ private:
size_t _recorded_rs_lengths;
size_t _max_rs_lengths;
double _recorded_young_free_cset_time_ms;
double _recorded_non_young_free_cset_time_ms;
double _sigma;
size_t _rs_lengths_prediction;
......@@ -341,8 +293,7 @@ private:
void set_no_of_gc_threads(uintx v) { _no_of_gc_threads = v; }
double _pause_time_target_ms;
double _recorded_young_cset_choice_time_ms;
double _recorded_non_young_cset_choice_time_ms;
size_t _pending_cards;
size_t _max_pending_cards;
......@@ -497,14 +448,6 @@ public:
uint young_cset_region_length() { return eden_cset_region_length() +
survivor_cset_region_length(); }
void record_young_free_cset_time_ms(double time_ms) {
_recorded_young_free_cset_time_ms = time_ms;
}
void record_non_young_free_cset_time_ms(double time_ms) {
_recorded_non_young_free_cset_time_ms = time_ms;
}
double predict_survivor_regions_evac_time();
void cset_regions_freed() {
......@@ -552,19 +495,6 @@ public:
}
private:
void print_stats(int level, const char* str, double value);
void print_stats(int level, const char* str, double value, int workers);
void print_stats(int level, const char* str, int value);
void print_par_stats(int level, const char* str, double* data, bool showDecimals = true);
double avg_value (double* data);
double max_value (double* data);
double sum_of_values (double* data);
double max_sum (double* data1, double* data2);
double _last_pause_time_ms;
size_t _bytes_in_collection_set_before_gc;
size_t _bytes_copied_during_gc;
......@@ -638,6 +568,8 @@ private:
// Stash a pointer to the g1 heap.
G1CollectedHeap* _g1;
G1GCPhaseTimes* _phase_times;
// The ratio of gc time to elapsed time, computed over recent pauses.
double _recent_avg_pause_time_ratio;
......@@ -677,7 +609,6 @@ private:
double _cur_mark_stop_world_time_ms;
double _mark_remark_start_sec;
double _mark_cleanup_start_sec;
double _root_region_scan_wait_time_ms;
// Update the young list target length either by setting it to the
// desired fixed value or by calculating it using G1's pause
......@@ -728,6 +659,8 @@ public:
return CollectorPolicy::G1CollectorPolicyKind;
}
G1GCPhaseTimes* phase_times() const { return _phase_times; }
// Check the current value of the young list RSet lengths and
// compare it against the last prediction. If the current value is
// higher, recalculate the young list target length prediction.
......@@ -772,10 +705,6 @@ public:
void record_concurrent_mark_init_end(double
mark_init_elapsed_time_ms);
void record_root_region_scan_wait_time(double time_ms) {
_root_region_scan_wait_time_ms = time_ms;
}
void record_concurrent_mark_remark_start();
void record_concurrent_mark_remark_end();
......@@ -784,97 +713,14 @@ public:
void record_concurrent_mark_cleanup_completed();
void record_concurrent_pause();
void record_concurrent_pause_end();
void record_collection_pause_end(int no_of_gc_threads);
void record_collection_pause_end(double pause_time);
void print_heap_transition();
// Record the fact that a full collection occurred.
void record_full_collection_start();
void record_full_collection_end();
void record_gc_worker_start_time(int worker_i, double ms) {
_par_last_gc_worker_start_times_ms[worker_i] = ms;
}
void record_ext_root_scan_time(int worker_i, double ms) {
_par_last_ext_root_scan_times_ms[worker_i] = ms;
}
void record_satb_filtering_time(int worker_i, double ms) {
_par_last_satb_filtering_times_ms[worker_i] = ms;
}
void record_update_rs_time(int thread, double ms) {
_par_last_update_rs_times_ms[thread] = ms;
}
void record_update_rs_processed_buffers (int thread,
double processed_buffers) {
_par_last_update_rs_processed_buffers[thread] = processed_buffers;
}
void record_scan_rs_time(int thread, double ms) {
_par_last_scan_rs_times_ms[thread] = ms;
}
void reset_obj_copy_time(int thread) {
_par_last_obj_copy_times_ms[thread] = 0.0;
}
void reset_obj_copy_time() {
reset_obj_copy_time(0);
}
void record_obj_copy_time(int thread, double ms) {
_par_last_obj_copy_times_ms[thread] += ms;
}
void record_termination(int thread, double ms, size_t attempts) {
_par_last_termination_times_ms[thread] = ms;
_par_last_termination_attempts[thread] = (double) attempts;
}
void record_gc_worker_end_time(int worker_i, double ms) {
_par_last_gc_worker_end_times_ms[worker_i] = ms;
}
void record_pause_time_ms(double ms) {
_last_pause_time_ms = ms;
}
void record_clear_ct_time(double ms) {
_cur_clear_ct_time_ms = ms;
}
void record_par_time(double ms) {
_cur_collection_par_time_ms = ms;
}
void record_code_root_fixup_time(double ms) {
_cur_collection_code_root_fixup_time_ms = ms;
}
void record_ref_proc_time(double ms) {
_cur_ref_proc_time_ms = ms;
}
void record_ref_enq_time(double ms) {
_cur_ref_enq_time_ms = ms;
}
#ifndef PRODUCT
void record_cc_clear_time(double ms) {
if (_min_clear_cc_time_ms < 0.0 || ms <= _min_clear_cc_time_ms)
_min_clear_cc_time_ms = ms;
if (_max_clear_cc_time_ms < 0.0 || ms >= _max_clear_cc_time_ms)
_max_clear_cc_time_ms = ms;
_cur_clear_cc_time_ms = ms;
_cum_clear_cc_time_ms += ms;
_num_cc_clears++;
}
#endif
// Record how much space we copied during a GC. This is typically
// called when a GC alloc region is being retired.
void record_bytes_copied_during_gc(size_t bytes) {
......
src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp 0 → 100644
浏览文件 @ b7f37497
/*
* Copyright (c) 2012, 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
* under the terms of the GNU General Public License version 2 only, as
* published by the Free Software Foundation.
*
* This code is distributed in the hope that it will be useful, but WITHOUT
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
* version 2 for more details (a copy is included in the LICENSE file that
* accompanied this code).
*
* You should have received a copy of the GNU General Public License version
* 2 along with this work; if not, write to the Free Software Foundation,
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
*
* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
* or visit www.oracle.com if you need additional information or have any
* questions.
*
*/
#include "precompiled.hpp"
#include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
#include "gc_implementation/g1/g1GCPhaseTimes.hpp"
#include "gc_implementation/g1/g1Log.hpp"
// Helper class for avoiding interleaved logging
class LineBuffer: public StackObj {
private:
static const int BUFFER_LEN = 1024;
static const int INDENT_CHARS = 3;
char _buffer[BUFFER_LEN];
int _indent_level;
int _cur;
void vappend(const char* format, va_list ap) {
int res = vsnprintf(&_buffer[_cur], BUFFER_LEN - _cur, format, ap);
if (res != -1) {
_cur += res;
} else {
DEBUG_ONLY(warning("buffer too small in LineBuffer");)
_buffer[BUFFER_LEN -1] = 0;
_cur = BUFFER_LEN; // vsnprintf above should not add to _buffer if we are called again
}
}
public:
explicit LineBuffer(int indent_level): _indent_level(indent_level), _cur(0) {
for (; (_cur < BUFFER_LEN && _cur < (_indent_level * INDENT_CHARS)); _cur++) {
_buffer[_cur] = ' ';
}
}
#ifndef PRODUCT
~LineBuffer() {
assert(_cur == _indent_level * INDENT_CHARS, "pending data in buffer - append_and_print_cr() not called?");
}
#endif
void append(const char* format, ...) {
va_list ap;
va_start(ap, format);
vappend(format, ap);
va_end(ap);
}
void append_and_print_cr(const char* format, ...) {
va_list ap;
va_start(ap, format);
vappend(format, ap);
va_end(ap);
gclog_or_tty->print_cr("%s", _buffer);
_cur = _indent_level * INDENT_CHARS;
}
};
G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
_max_gc_threads(max_gc_threads),
_min_clear_cc_time_ms(-1.0),
_max_clear_cc_time_ms(-1.0),
_cur_clear_cc_time_ms(0.0),
_cum_clear_cc_time_ms(0.0),
_num_cc_clears(0L)
{
assert(max_gc_threads > 0, "Must have some GC threads");
_par_last_gc_worker_start_times_ms = new double[_max_gc_threads];
_par_last_ext_root_scan_times_ms = new double[_max_gc_threads];
_par_last_satb_filtering_times_ms = new double[_max_gc_threads];
_par_last_update_rs_times_ms = new double[_max_gc_threads];
_par_last_update_rs_processed_buffers = new double[_max_gc_threads];
_par_last_scan_rs_times_ms = new double[_max_gc_threads];
_par_last_obj_copy_times_ms = new double[_max_gc_threads];
_par_last_termination_times_ms = new double[_max_gc_threads];
_par_last_termination_attempts = new double[_max_gc_threads];
_par_last_gc_worker_end_times_ms = new double[_max_gc_threads];
_par_last_gc_worker_times_ms = new double[_max_gc_threads];
_par_last_gc_worker_other_times_ms = new double[_max_gc_threads];
}
void G1GCPhaseTimes::note_gc_start(double pause_start_time_sec, uint active_gc_threads,
bool is_young_gc, bool is_initial_mark_gc, GCCause::Cause gc_cause) {
assert(active_gc_threads > 0, "The number of threads must be > 0");
assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max nubmer of threads");
_active_gc_threads = active_gc_threads;
_pause_start_time_sec = pause_start_time_sec;
_is_young_gc = is_young_gc;
_is_initial_mark_gc = is_initial_mark_gc;
_gc_cause = gc_cause;
#ifdef ASSERT
// initialise the timing data to something well known so that we can spot
// if something is not set properly
for (uint i = 0; i < _max_gc_threads; ++i) {
_par_last_gc_worker_start_times_ms[i] = -1234.0;
_par_last_ext_root_scan_times_ms[i] = -1234.0;
_par_last_satb_filtering_times_ms[i] = -1234.0;
_par_last_update_rs_times_ms[i] = -1234.0;
_par_last_update_rs_processed_buffers[i] = -1234.0;
_par_last_scan_rs_times_ms[i] = -1234.0;
_par_last_obj_copy_times_ms[i] = -1234.0;
_par_last_termination_times_ms[i] = -1234.0;
_par_last_termination_attempts[i] = -1234.0;
_par_last_gc_worker_end_times_ms[i] = -1234.0;
_par_last_gc_worker_times_ms[i] = -1234.0;
_par_last_gc_worker_other_times_ms[i] = -1234.0;
}
#endif
}
void G1GCPhaseTimes::note_gc_end(double pause_end_time_sec) {
if (G1Log::fine()) {
double pause_time_ms = (pause_end_time_sec - _pause_start_time_sec) * MILLIUNITS;
for (uint i = 0; i < _active_gc_threads; i++) {
_par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] -
_par_last_gc_worker_start_times_ms[i];
double worker_known_time = _par_last_ext_root_scan_times_ms[i] +
_par_last_satb_filtering_times_ms[i] +
_par_last_update_rs_times_ms[i] +
_par_last_scan_rs_times_ms[i] +
_par_last_obj_copy_times_ms[i] +
_par_last_termination_times_ms[i];
_par_last_gc_worker_other_times_ms[i] = _par_last_gc_worker_times_ms[i] -
worker_known_time;
}
print(pause_time_ms);
}
}
void G1GCPhaseTimes::print_par_stats(int level,
const char* str,
double* data,
bool showDecimals) {
double min = data[0], max = data[0];
double total = 0.0;
LineBuffer buf(level);
buf.append("[%s (ms):", str);
for (uint i = 0; i < _active_gc_threads; ++i) {
double val = data[i];
if (val < min)
min = val;
if (val > max)
max = val;
total += val;
if (G1Log::finest()) {
if (showDecimals) {
buf.append(" %.1lf", val);
} else {
buf.append(" %d", (int)val);
}
}
}
if (G1Log::finest()) {
buf.append_and_print_cr("");
}
double avg = total / (double) _active_gc_threads;
if (showDecimals) {
buf.append_and_print_cr(" Min: %.1lf, Avg: %.1lf, Max: %.1lf, Diff: %.1lf, Sum: %.1lf]",
min, avg, max, max - min, total);
} else {
buf.append_and_print_cr(" Min: %d, Avg: %d, Max: %d, Diff: %d, Sum: %d]",
(int)min, (int)avg, (int)max, (int)max - (int)min, (int)total);
}
}
void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
}
void G1GCPhaseTimes::print_stats(int level, const char* str, double value, int workers) {
LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %d]", str, value, workers);
}
void G1GCPhaseTimes::print_stats(int level, const char* str, int value) {
LineBuffer(level).append_and_print_cr("[%s: %d]", str, value);
}
double G1GCPhaseTimes::avg_value(double* data) {
if (G1CollectedHeap::use_parallel_gc_threads()) {
double ret = 0.0;
for (uint i = 0; i < _active_gc_threads; ++i) {
ret += data[i];
}
return ret / (double) _active_gc_threads;
} else {
return data[0];
}
}
double G1GCPhaseTimes::max_value(double* data) {
if (G1CollectedHeap::use_parallel_gc_threads()) {
double ret = data[0];
for (uint i = 1; i < _active_gc_threads; ++i) {
if (data[i] > ret) {
ret = data[i];
}
}
return ret;
} else {
return data[0];
}
}
double G1GCPhaseTimes::sum_of_values(double* data) {
if (G1CollectedHeap::use_parallel_gc_threads()) {
double sum = 0.0;
for (uint i = 0; i < _active_gc_threads; i++) {
sum += data[i];
}
return sum;
} else {
return data[0];
}
}
double G1GCPhaseTimes::max_sum(double* data1, double* data2) {
double ret = data1[0] + data2[0];
if (G1CollectedHeap::use_parallel_gc_threads()) {
for (uint i = 1; i < _active_gc_threads; ++i) {
double data = data1[i] + data2[i];
if (data > ret) {
ret = data;
}
}
}
return ret;
}
void G1GCPhaseTimes::collapse_par_times() {
_ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms);
_satb_filtering_time = avg_value(_par_last_satb_filtering_times_ms);
_update_rs_time = avg_value(_par_last_update_rs_times_ms);
_update_rs_processed_buffers =
sum_of_values(_par_last_update_rs_processed_buffers);
_scan_rs_time = avg_value(_par_last_scan_rs_times_ms);
_obj_copy_time = avg_value(_par_last_obj_copy_times_ms);
_termination_time = avg_value(_par_last_termination_times_ms);
}
double G1GCPhaseTimes::accounted_time_ms() {
// Subtract the root region scanning wait time. It's initialized to
// zero at the start of the pause.
double misc_time_ms = _root_region_scan_wait_time_ms;
misc_time_ms += _cur_collection_par_time_ms;
// Now subtract the time taken to fix up roots in generated code
misc_time_ms += _cur_collection_code_root_fixup_time_ms;
// Subtract the time taken to clean the card table from the
// current value of "other time"
misc_time_ms += _cur_clear_ct_time_ms;
return misc_time_ms;
}
void G1GCPhaseTimes::print(double pause_time_ms) {
if (PrintGCTimeStamps) {
gclog_or_tty->stamp();
gclog_or_tty->print(": ");
}
GCCauseString gc_cause_str = GCCauseString("GC pause", _gc_cause)
.append(_is_young_gc ? " (young)" : " (mixed)")
.append(_is_initial_mark_gc ? " (initial-mark)" : "");
gclog_or_tty->print_cr("[%s, %3.7f secs]", (const char*)gc_cause_str, pause_time_ms / 1000.0);
if (!G1Log::finer()) {
return;
}
if (_root_region_scan_wait_time_ms > 0.0) {
print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
}
if (G1CollectedHeap::use_parallel_gc_threads()) {
print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads);
print_par_stats(2, "GC Worker Start", _par_last_gc_worker_start_times_ms);
print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms);
if (_satb_filtering_time > 0.0) {
print_par_stats(2, "SATB Filtering", _par_last_satb_filtering_times_ms);
}
print_par_stats(2, "Update RS", _par_last_update_rs_times_ms);
if (G1Log::finest()) {
print_par_stats(3, "Processed Buffers", _par_last_update_rs_processed_buffers,
false /* showDecimals */);
}
print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms);
print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms);
print_par_stats(2, "Termination", _par_last_termination_times_ms);
if (G1Log::finest()) {
print_par_stats(3, "Termination Attempts", _par_last_termination_attempts,
false /* showDecimals */);
}
print_par_stats(2, "GC Worker Other", _par_last_gc_worker_other_times_ms);
print_par_stats(2, "GC Worker Total", _par_last_gc_worker_times_ms);
print_par_stats(2, "GC Worker End", _par_last_gc_worker_end_times_ms);
} else {
print_stats(1, "Ext Root Scanning", _ext_root_scan_time);
if (_satb_filtering_time > 0.0) {
print_stats(1, "SATB Filtering", _satb_filtering_time);
}
print_stats(1, "Update RS", _update_rs_time);
if (G1Log::finest()) {
print_stats(2, "Processed Buffers", (int)_update_rs_processed_buffers);
}
print_stats(1, "Scan RS", _scan_rs_time);
print_stats(1, "Object Copying", _obj_copy_time);
}
print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
if (Verbose && G1Log::finest()) {
print_stats(1, "Cur Clear CC", _cur_clear_cc_time_ms);
print_stats(1, "Cum Clear CC", _cum_clear_cc_time_ms);
print_stats(1, "Min Clear CC", _min_clear_cc_time_ms);
print_stats(1, "Max Clear CC", _max_clear_cc_time_ms);
if (_num_cc_clears > 0) {
print_stats(1, "Avg Clear CC", _cum_clear_cc_time_ms / ((double)_num_cc_clears));
}
}
double misc_time_ms = pause_time_ms - accounted_time_ms();
print_stats(1, "Other", misc_time_ms);
print_stats(2, "Choose CSet",
(_recorded_young_cset_choice_time_ms +
_recorded_non_young_cset_choice_time_ms));
print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
print_stats(2, "Free CSet",
(_recorded_young_free_cset_time_ms +
_recorded_non_young_free_cset_time_ms));
}
void G1GCPhaseTimes::record_cc_clear_time_ms(double ms) {
if (!(Verbose && G1Log::finest())) {
return;
}
if (_min_clear_cc_time_ms < 0.0 || ms <= _min_clear_cc_time_ms) {
_min_clear_cc_time_ms = ms;
}
if (_max_clear_cc_time_ms < 0.0 || ms >= _max_clear_cc_time_ms) {
_max_clear_cc_time_ms = ms;
}
_cur_clear_cc_time_ms = ms;
_cum_clear_cc_time_ms += ms;
_num_cc_clears++;
}
src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp 0 → 100644
浏览文件 @ b7f37497
/*
* Copyright (c) 2012, 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
* under the terms of the GNU General Public License version 2 only, as
* published by the Free Software Foundation.
*
* This code is distributed in the hope that it will be useful, but WITHOUT
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
* version 2 for more details (a copy is included in the LICENSE file that
* accompanied this code).
*
* You should have received a copy of the GNU General Public License version
* 2 along with this work; if not, write to the Free Software Foundation,
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
*
* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
* or visit www.oracle.com if you need additional information or have any
* questions.
*
*/
#ifndef SHARE_VM_GC_IMPLEMENTATION_G1_G1GCPHASETIMESLOG_HPP
#define SHARE_VM_GC_IMPLEMENTATION_G1_G1GCPHASETIMESLOG_HPP
#include "memory/allocation.hpp"
#include "gc_interface/gcCause.hpp"
class G1GCPhaseTimes : public CHeapObj<mtGC> {
friend class G1CollectorPolicy;
friend class TraceGen0TimeData;
private:
uint _active_gc_threads;
uint _max_gc_threads;
GCCause::Cause _gc_cause;
bool _is_young_gc;
bool _is_initial_mark_gc;
double _pause_start_time_sec;
double* _par_last_gc_worker_start_times_ms;
double* _par_last_ext_root_scan_times_ms;
double* _par_last_satb_filtering_times_ms;
double* _par_last_update_rs_times_ms;
double* _par_last_update_rs_processed_buffers;
double* _par_last_scan_rs_times_ms;
double* _par_last_obj_copy_times_ms;
double* _par_last_termination_times_ms;
double* _par_last_termination_attempts;
double* _par_last_gc_worker_end_times_ms;
double* _par_last_gc_worker_times_ms;
double* _par_last_gc_worker_other_times_ms;
double _cur_collection_par_time_ms;
double _cur_collection_code_root_fixup_time_ms;
double _cur_clear_ct_time_ms;
double _cur_ref_proc_time_ms;
double _cur_ref_enq_time_ms;
// Helper methods for detailed logging
void print_par_stats(int level, const char* str, double* data, bool showDecimals = true);
void print_stats(int level, const char* str, double value);
void print_stats(int level, const char* str, double value, int workers);
void print_stats(int level, const char* str, int value);
double avg_value(double* data);
double max_value(double* data);
double sum_of_values(double* data);
double max_sum(double* data1, double* data2);
double accounted_time_ms();
// Card Table Count Cache stats
double _min_clear_cc_time_ms; // min
double _max_clear_cc_time_ms; // max
double _cur_clear_cc_time_ms; // clearing time during current pause
double _cum_clear_cc_time_ms; // cummulative clearing time
jlong _num_cc_clears; // number of times the card count cache has been cleared
// The following insance variables are directly accessed by G1CollectorPolicy
// and TraceGen0TimeData. This is why those classes are declared friends.
// An alternative is to add getters and setters for all of these fields.
// It might also be possible to restructure the code to reduce these
// dependencies.
double _ext_root_scan_time;
double _satb_filtering_time;
double _update_rs_time;
double _update_rs_processed_buffers;
double _scan_rs_time;
double _obj_copy_time;
double _termination_time;
double _cur_collection_start_sec;
double _root_region_scan_wait_time_ms;
double _recorded_young_cset_choice_time_ms;
double _recorded_non_young_cset_choice_time_ms;
double _recorded_young_free_cset_time_ms;
double _recorded_non_young_free_cset_time_ms;
void print(double pause_time_ms);
public:
G1GCPhaseTimes(uint max_gc_threads);
void note_gc_start(double pause_start_time_sec, uint active_gc_threads,
bool is_young_gc, bool is_initial_mark_gc, GCCause::Cause gc_cause);
void note_gc_end(double pause_end_time_sec);
void collapse_par_times();
void record_gc_worker_start_time(uint worker_i, double ms) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_gc_worker_start_times_ms[worker_i] = ms;
}
void record_ext_root_scan_time(uint worker_i, double ms) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_ext_root_scan_times_ms[worker_i] = ms;
}
void record_satb_filtering_time(uint worker_i, double ms) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_satb_filtering_times_ms[worker_i] = ms;
}
void record_update_rs_time(uint worker_i, double ms) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_update_rs_times_ms[worker_i] = ms;
}
void record_update_rs_processed_buffers (uint worker_i,
double processed_buffers) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_update_rs_processed_buffers[worker_i] = processed_buffers;
}
void record_scan_rs_time(uint worker_i, double ms) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_scan_rs_times_ms[worker_i] = ms;
}
void reset_obj_copy_time(uint worker_i) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_obj_copy_times_ms[worker_i] = 0.0;
}
void reset_obj_copy_time() {
reset_obj_copy_time(0);
}
void record_obj_copy_time(uint worker_i, double ms) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_obj_copy_times_ms[worker_i] += ms;
}
void record_termination(uint worker_i, double ms, size_t attempts) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_termination_times_ms[worker_i] = ms;
_par_last_termination_attempts[worker_i] = (double) attempts;
}
void record_gc_worker_end_time(uint worker_i, double ms) {
assert(worker_i >= 0, "worker index must be > 0");
assert(worker_i < _active_gc_threads, "worker index out of bounds");
_par_last_gc_worker_end_times_ms[worker_i] = ms;
}
void record_clear_ct_time(double ms) {
_cur_clear_ct_time_ms = ms;
}
void record_par_time(double ms) {
_cur_collection_par_time_ms = ms;
}
void record_code_root_fixup_time(double ms) {
_cur_collection_code_root_fixup_time_ms = ms;
}
void record_ref_proc_time(double ms) {
_cur_ref_proc_time_ms = ms;
}
void record_ref_enq_time(double ms) {
_cur_ref_enq_time_ms = ms;
}
void record_root_region_scan_wait_time(double time_ms) {
_root_region_scan_wait_time_ms = time_ms;
}
void record_cc_clear_time_ms(double ms);
void record_young_free_cset_time_ms(double time_ms) {
_recorded_young_free_cset_time_ms = time_ms;
}
void record_non_young_free_cset_time_ms(double time_ms) {
_recorded_non_young_free_cset_time_ms = time_ms;
}
};
#endif // SHARE_VM_GC_IMPLEMENTATION_G1_G1GCPHASETIMESLOG_HPP
src/share/vm/gc_implementation/g1/g1RemSet.cpp
浏览文件 @ b7f37497
......@@ -29,6 +29,7 @@
#include "gc_implementation/g1/g1BlockOffsetTable.inline.hpp"
#include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
#include "gc_implementation/g1/g1CollectorPolicy.hpp"
#include "gc_implementation/g1/g1GCPhaseTimes.hpp"
#include "gc_implementation/g1/g1OopClosures.inline.hpp"
#include "gc_implementation/g1/g1RemSet.inline.hpp"
#include "gc_implementation/g1/heapRegionSeq.inline.hpp"
......@@ -224,7 +225,7 @@ void G1RemSet::scanRS(OopsInHeapRegionClosure* oc, int worker_i) {
assert( _cards_scanned != NULL, "invariant" );
_cards_scanned[worker_i] = scanRScl.cards_done();
_g1p->record_scan_rs_time(worker_i, scan_rs_time_sec * 1000.0);
_g1p->phase_times()->record_scan_rs_time(worker_i, scan_rs_time_sec * 1000.0);
}
// Closure used for updating RSets and recording references that
......@@ -276,7 +277,7 @@ void G1RemSet::updateRS(DirtyCardQueue* into_cset_dcq, int worker_i) {
guarantee(cl.n() == 0, "Card table should be clean.");
}
_g1p->record_update_rs_time(worker_i, (os::elapsedTime() - start) * 1000.0);
_g1p->phase_times()->record_update_rs_time(worker_i, (os::elapsedTime() - start) * 1000.0);
}
class CountRSSizeClosure: public HeapRegionClosure {
......@@ -390,13 +391,13 @@ void G1RemSet::oops_into_collection_set_do(OopsInHeapRegionClosure* oc,
if (G1UseParallelRSetUpdating || (worker_i == 0)) {
updateRS(&into_cset_dcq, worker_i);
} else {
_g1p->record_update_rs_processed_buffers(worker_i, 0.0);
_g1p->record_update_rs_time(worker_i, 0.0);
_g1p->phase_times()->record_update_rs_processed_buffers(worker_i, 0.0);
_g1p->phase_times()->record_update_rs_time(worker_i, 0.0);
}
if (G1UseParallelRSetScanning || (worker_i == 0)) {
scanRS(oc, worker_i);
} else {
_g1p->record_scan_rs_time(worker_i, 0.0);
_g1p->phase_times()->record_scan_rs_time(worker_i, 0.0);
}
// We now clear the cached values of _cset_rs_update_cl for this worker
......
Markdown is supported
0% 或 .
You are about to add 0 people to the discussion. Proceed with caution.
先完成此消息的编辑！
想要评论请 注册 或