stan/jdk-24
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Merge

Browse Source
This commit is contained in:
Jon Masamitsu 2012-07-17 14:33:17 -07:00
commit 08ea4ea9b8
8 changed files with 732 additions and 663 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

16
hotspot/src/share/vm/gc_implementation/g1/concurrentG1Refine.cpp
View File

@ -1,5 +1,5 @@
/* /*
* 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. * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
* *
* This code is free software; you can redistribute it and/or modify it * 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/concurrentG1RefineThread.hpp"
#include "gc_implementation/g1/g1CollectedHeap.inline.hpp" #include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
#include "gc_implementation/g1/g1CollectorPolicy.hpp" #include "gc_implementation/g1/g1CollectorPolicy.hpp"
#include "gc_implementation/g1/g1GCPhaseTimes.hpp"
#include "gc_implementation/g1/g1RemSet.hpp" #include "gc_implementation/g1/g1RemSet.hpp"
#include "gc_implementation/g1/heapRegionSeq.inline.hpp" #include "gc_implementation/g1/heapRegionSeq.inline.hpp"
#include "memory/space.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() { void ConcurrentG1Refine::clear_and_record_card_counts() {
if (G1ConcRSLogCacheSize == 0) return; if (G1ConcRSLogCacheSize == 0) {
return;
}
#ifndef PRODUCT
double start = os::elapsedTime(); double start = os::elapsedTime();
#endif
if (_expand_card_counts) { if (_expand_card_counts) {
int new_idx = _cache_size_index + 1; 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"); assert((this_epoch+1) <= max_jint, "to many periods");
// Update epoch // Update epoch
_n_periods++; _n_periods++;
double cc_clear_time_ms = (os::elapsedTime() - start) * 1000;
#ifndef PRODUCT _g1h->g1_policy()->phase_times()->record_cc_clear_time_ms(cc_clear_time_ms);
double elapsed = os::elapsedTime() - start;
_g1h->g1_policy()->record_cc_clear_time(elapsed * 1000.0);
#endif
} }
void ConcurrentG1Refine::print_worker_threads_on(outputStream* st) const { void ConcurrentG1Refine::print_worker_threads_on(outputStream* st) const {

3
hotspot/src/share/vm/gc_implementation/g1/concurrentMark.cpp
View File

@ -3156,9 +3156,6 @@ bool ConcurrentMark::do_yield_check(uint worker_id) {
_g1h->g1_policy()->record_concurrent_pause(); _g1h->g1_policy()->record_concurrent_pause();
} }
cmThread()->yield(); cmThread()->yield();
if (worker_id == 0) {
_g1h->g1_policy()->record_concurrent_pause_end();
}
return true; return true;
} else { } else {
return false; return false;

86
hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp
View File

@ -33,6 +33,7 @@
#include "gc_implementation/g1/g1CollectorPolicy.hpp" #include "gc_implementation/g1/g1CollectorPolicy.hpp"
#include "gc_implementation/g1/g1ErgoVerbose.hpp" #include "gc_implementation/g1/g1ErgoVerbose.hpp"
#include "gc_implementation/g1/g1EvacFailure.hpp" #include "gc_implementation/g1/g1EvacFailure.hpp"
#include "gc_implementation/g1/g1GCPhaseTimes.hpp"
#include "gc_implementation/g1/g1Log.hpp" #include "gc_implementation/g1/g1Log.hpp"
#include "gc_implementation/g1/g1MarkSweep.hpp" #include "gc_implementation/g1/g1MarkSweep.hpp"
#include "gc_implementation/g1/g1OopClosures.inline.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)) { while (dcqs.apply_closure_to_completed_buffer(cl, worker_i, 0, true)) {
n_completed_buffers++; 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); (double) n_completed_buffers);
dcqs.clear_n_completed_buffers(); dcqs.clear_n_completed_buffers();
assert(!dcqs.completed_buffers_exist_dirty(), "Completed buffers exist!"); 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); gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps);
TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty); TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty);
GCCauseString gc_cause_str = GCCauseString("GC pause", gc_cause()) int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ?
.append(g1_policy()->gcs_are_young() ? " (young)" : " (mixed)") workers()->active_workers() : 1);
.append(g1_policy()->during_initial_mark_pause() ? " (initial-mark)" : ""); g1_policy()->phase_times()->note_gc_start(os::elapsedTime(), active_workers,
TraceTime t(gc_cause_str, G1Log::fine() && !G1Log::finer(), true, gclog_or_tty); g1_policy()->gcs_are_young(), g1_policy()->during_initial_mark_pause(), gc_cause());
TraceCollectorStats tcs(g1mm()->incremental_collection_counters()); TraceCollectorStats tcs(g1mm()->incremental_collection_counters());
TraceMemoryManagerStats tms(false /* fullGC */, gc_cause()); 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. // before the start GC event.
_hr_printer.start_gc(false /* full */, (size_t) total_collections()); _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 elapsed time induced by the start time below deliberately elides
// the possible verification above. // the possible verification above.
double start_time_sec = os::elapsedTime(); double sample_start_time_sec = os::elapsedTime();
size_t start_used_bytes = used(); size_t start_used_bytes = used();
#if YOUNG_LIST_VERBOSE #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); g1_policy()->print_collection_set(g1_policy()->inc_cset_head(), gclog_or_tty);
#endif // YOUNG_LIST_VERBOSE #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); start_used_bytes);
double scan_wait_start = os::elapsedTime(); 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 // objects on them have been correctly scanned before we start
// moving them during the GC. // moving them during the GC.
bool waited = _cm->root_regions()->wait_until_scan_finished(); bool waited = _cm->root_regions()->wait_until_scan_finished();
double wait_time_ms = 0.0;
if (waited) { if (waited) {
double scan_wait_end = os::elapsedTime(); double scan_wait_end = os::elapsedTime();
double wait_time_ms = (scan_wait_end - scan_wait_start) * 1000.0; wait_time_ms = (scan_wait_end - scan_wait_start) * 1000.0;
g1_policy()->record_root_region_scan_wait_time(wait_time_ms);
} }
g1_policy()->phase_times()->record_root_region_scan_wait_time(wait_time_ms);
#if YOUNG_LIST_VERBOSE #if YOUNG_LIST_VERBOSE
gclog_or_tty->print_cr("\nAfter recording pause start.\nYoung_list:"); 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 */); true /* verify_fingers */);
_cm->note_end_of_gc(); _cm->note_end_of_gc();
double end_time_sec = os::elapsedTime(); // Collect thread local data to allow the ergonomics to use
double pause_time_ms = (end_time_sec - start_time_sec) * MILLIUNITS; // the collected information
g1_policy()->record_pause_time_ms(pause_time_ms); g1_policy()->phase_times()->collapse_par_times();
int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ?
workers()->active_workers() : 1); // This timing is only used by the ergonomics to handle our pause target.
g1_policy()->record_collection_pause_end(active_workers); // 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(); 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. // RETIRE events are generated before the end GC event.
_hr_printer.end_gc(false /* full */, (size_t) total_collections()); _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()) { if (mark_in_progress()) {
concurrent_mark()->update_g1_committed(); concurrent_mark()->update_g1_committed();
} }
@ -3941,13 +3950,14 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
#endif #endif
gc_epilogue(false); 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 // It is not yet to safe to tell the concurrent mark to
// 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
// start as we have some optional output below. We don't want the // start as we have some optional output below. We don't want the
// output from the concurrent mark thread interfering with this // output from the concurrent mark thread interfering with this
// logging output either. // logging output either.
@ -4695,7 +4705,7 @@ public:
if (worker_id >= _n_workers) return; // no work needed this round if (worker_id >= _n_workers) return; // no work needed this round
double start_time_ms = os::elapsedTime() * 1000.0; 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; ResourceMark rm;
@ -4744,8 +4754,8 @@ public:
evac.do_void(); evac.do_void();
double elapsed_ms = (os::elapsedTime()-start)*1000.0; double elapsed_ms = (os::elapsedTime()-start)*1000.0;
double term_ms = pss.term_time()*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()->phase_times()->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_termination(worker_id, term_ms, pss.term_attempts());
} }
_g1h->g1_policy()->record_thread_age_table(pss.age_table()); _g1h->g1_policy()->record_thread_age_table(pss.age_table());
_g1h->update_surviving_young_words(pss.surviving_young_words()+1); _g1h->update_surviving_young_words(pss.surviving_young_words()+1);
@ -4763,7 +4773,7 @@ public:
} }
double end_time_ms = os::elapsedTime() * 1000.0; 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(); 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() + double obj_copy_time_sec = buf_scan_perm.closure_app_seconds() +
buf_scan_non_heap_roots.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 = double ext_root_time_ms =
((ext_roots_end - ext_roots_start) - obj_copy_time_sec) * 1000.0; ((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 // 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 // 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; 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. // Now scan the complement of the collection set.
if (scan_rs != NULL) { 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"); assert(pss.refs()->is_empty(), "both queue and overflow should be empty");
double ref_proc_time = os::elapsedTime() - ref_proc_start; 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). // 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. // and could signicantly increase the pause time.
double ref_enq_time = os::elapsedTime() - ref_enq_start; 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() { 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; 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 = double code_root_fixup_time_ms =
(os::elapsedTime() - end_par_time_sec) * 1000.0; (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); set_par_threads(0);
@ -5759,7 +5769,7 @@ void G1CollectedHeap::cleanUpCardTable() {
} }
double elapsed = os::elapsedTime() - start; 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) { 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 /* old_proxy_set */,
NULL /* humongous_proxy_set */, NULL /* humongous_proxy_set */,
false /* par */); false /* par */);
policy->record_young_free_cset_time_ms(young_time_ms); policy->phase_times()->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_non_young_free_cset_time_ms(non_young_time_ms);
} }
// This routine is similar to the above but does not record // This routine is similar to the above but does not record

508
hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp
View File

@ -29,6 +29,7 @@
#include "gc_implementation/g1/g1CollectedHeap.inline.hpp" #include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
#include "gc_implementation/g1/g1CollectorPolicy.hpp" #include "gc_implementation/g1/g1CollectorPolicy.hpp"
#include "gc_implementation/g1/g1ErgoVerbose.hpp" #include "gc_implementation/g1/g1ErgoVerbose.hpp"
#include "gc_implementation/g1/g1GCPhaseTimes.hpp"
#include "gc_implementation/g1/g1Log.hpp" #include "gc_implementation/g1/g1Log.hpp"
#include "gc_implementation/g1/heapRegionRemSet.hpp" #include "gc_implementation/g1/heapRegionRemSet.hpp"
#include "gc_implementation/shared/gcPolicyCounters.hpp" #include "gc_implementation/shared/gcPolicyCounters.hpp"
@ -77,57 +78,6 @@ static double non_young_other_cost_per_region_ms_defaults[] = {
1.0, 0.7, 0.7, 0.5, 0.5, 0.42, 0.42, 0.30 1.0, 0.7, 0.7, 0.5, 0.5, 0.42, 0.42, 0.30
}; };
// Help 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;
}
};
G1CollectorPolicy::G1CollectorPolicy() : G1CollectorPolicy::G1CollectorPolicy() :
_parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads() _parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads()
? ParallelGCThreads : 1), ? ParallelGCThreads : 1),
@ -135,20 +85,6 @@ G1CollectorPolicy::G1CollectorPolicy() :
_recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), _recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
_stop_world_start(0.0), _stop_world_start(0.0),
_cur_clear_ct_time_ms(0.0),
_root_region_scan_wait_time_ms(0.0),
_cur_ref_proc_time_ms(0.0),
_cur_ref_enq_time_ms(0.0),
#ifndef PRODUCT
_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),
#endif
_concurrent_mark_remark_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), _concurrent_mark_remark_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
_concurrent_mark_cleanup_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), _concurrent_mark_cleanup_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
@ -257,30 +193,9 @@ G1CollectorPolicy::G1CollectorPolicy() :
_recent_prev_end_times_for_all_gcs_sec->add(os::elapsedTime()); _recent_prev_end_times_for_all_gcs_sec->add(os::elapsedTime());
_prev_collection_pause_end_ms = os::elapsedTime() * 1000.0; _prev_collection_pause_end_ms = os::elapsedTime() * 1000.0;
_par_last_gc_worker_start_times_ms = new double[_parallel_gc_threads]; _phase_times = new G1GCPhaseTimes(_parallel_gc_threads);
_par_last_ext_root_scan_times_ms = new double[_parallel_gc_threads];
_par_last_satb_filtering_times_ms = new double[_parallel_gc_threads];
_par_last_update_rs_times_ms = new double[_parallel_gc_threads]; int index = MIN2(_parallel_gc_threads - 1, 7);
_par_last_update_rs_processed_buffers = new double[_parallel_gc_threads];
_par_last_scan_rs_times_ms = new double[_parallel_gc_threads];
_par_last_obj_copy_times_ms = new double[_parallel_gc_threads];
_par_last_termination_times_ms = new double[_parallel_gc_threads];
_par_last_termination_attempts = new double[_parallel_gc_threads];
_par_last_gc_worker_end_times_ms = new double[_parallel_gc_threads];
_par_last_gc_worker_times_ms = new double[_parallel_gc_threads];
_par_last_gc_worker_other_times_ms = new double[_parallel_gc_threads];
int index;
if (ParallelGCThreads == 0)
index = 0;
else if (ParallelGCThreads > 8)
index = 7;
else
index = ParallelGCThreads - 1;
_pending_card_diff_seq->add(0.0); _pending_card_diff_seq->add(0.0);
_rs_length_diff_seq->add(rs_length_diff_defaults[index]); _rs_length_diff_seq->add(rs_length_diff_defaults[index]);
@ -824,7 +739,7 @@ G1CollectorPolicy::verify_young_ages(HeapRegion* head,
#endif // PRODUCT #endif // PRODUCT
void G1CollectorPolicy::record_full_collection_start() { void G1CollectorPolicy::record_full_collection_start() {
_cur_collection_start_sec = os::elapsedTime(); _full_collection_start_sec = os::elapsedTime();
// Release the future to-space so that it is available for compaction into. // Release the future to-space so that it is available for compaction into.
_g1->set_full_collection(); _g1->set_full_collection();
} }
@ -833,7 +748,7 @@ void G1CollectorPolicy::record_full_collection_end() {
// Consider this like a collection pause for the purposes of allocation // Consider this like a collection pause for the purposes of allocation
// since last pause. // since last pause.
double end_sec = os::elapsedTime(); double end_sec = os::elapsedTime();
double full_gc_time_sec = end_sec - _cur_collection_start_sec; double full_gc_time_sec = end_sec - _full_collection_start_sec;
double full_gc_time_ms = full_gc_time_sec * 1000.0; double full_gc_time_ms = full_gc_time_sec * 1000.0;
_trace_gen1_time_data.record_full_collection(full_gc_time_ms); _trace_gen1_time_data.record_full_collection(full_gc_time_ms);
@ -869,12 +784,6 @@ void G1CollectorPolicy::record_stop_world_start() {
void G1CollectorPolicy::record_collection_pause_start(double start_time_sec, void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
size_t start_used) { size_t start_used) {
if (G1Log::finer()) {
gclog_or_tty->stamp(PrintGCTimeStamps);
gclog_or_tty->print("[%s", (const char*)GCCauseString("GC pause", _g1->gc_cause())
.append(gcs_are_young() ? " (young)" : " (mixed)"));
}
// We only need to do this here as the policy will only be applied // We only need to do this here as the policy will only be applied
// to the GC we're about to start. so, no point is calculating this // to the GC we're about to start. so, no point is calculating this
// every time we calculate / recalculate the target young length. // every time we calculate / recalculate the target young length.
@ -888,7 +797,7 @@ void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
_trace_gen0_time_data.record_start_collection(s_w_t_ms); _trace_gen0_time_data.record_start_collection(s_w_t_ms);
_stop_world_start = 0.0; _stop_world_start = 0.0;
_cur_collection_start_sec = start_time_sec; phase_times()->_cur_collection_start_sec = start_time_sec;
_cur_collection_pause_used_at_start_bytes = start_used; _cur_collection_pause_used_at_start_bytes = start_used;
_cur_collection_pause_used_regions_at_start = _g1->used_regions(); _cur_collection_pause_used_regions_at_start = _g1->used_regions();
_pending_cards = _g1->pending_card_num(); _pending_cards = _g1->pending_card_num();
@ -902,30 +811,6 @@ void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
_survivor_bytes_before_gc = young_list->survivor_used_bytes(); _survivor_bytes_before_gc = young_list->survivor_used_bytes();
_capacity_before_gc = _g1->capacity(); _capacity_before_gc = _g1->capacity();
#ifdef DEBUG
// initialise these to something well known so that we can spot
// if they are not set properly
for (int i = 0; i < _parallel_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
// This is initialized to zero here and is set during the evacuation
// pause if we actually waited for the root region scanning to finish.
_root_region_scan_wait_time_ms = 0.0;
_last_gc_was_young = false; _last_gc_was_young = false;
// do that for any other surv rate groups // do that for any other surv rate groups
@ -974,127 +859,6 @@ void G1CollectorPolicy::record_concurrent_pause() {
} }
} }
void G1CollectorPolicy::record_concurrent_pause_end() {
}
template<class T>
T sum_of(T* sum_arr, int start, int n, int N) {
T sum = (T)0;
for (int i = 0; i < n; i++) {
int j = (start + i) % N;
sum += sum_arr[j];
}
return sum;
}
void G1CollectorPolicy::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 < no_of_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) no_of_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 G1CollectorPolicy::print_stats(int level,
const char* str,
double value) {
LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
}
void G1CollectorPolicy::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 G1CollectorPolicy::print_stats(int level,
const char* str,
int value) {
LineBuffer(level).append_and_print_cr("[%s: %d]", str, value);
}
double G1CollectorPolicy::avg_value(double* data) {
if (G1CollectedHeap::use_parallel_gc_threads()) {
double ret = 0.0;
for (uint i = 0; i < no_of_gc_threads(); ++i) {
ret += data[i];
}
return ret / (double) no_of_gc_threads();
} else {
return data[0];
}
}
double G1CollectorPolicy::max_value(double* data) {
if (G1CollectedHeap::use_parallel_gc_threads()) {
double ret = data[0];
for (uint i = 1; i < no_of_gc_threads(); ++i) {
if (data[i] > ret) {
ret = data[i];
}
}
return ret;
} else {
return data[0];
}
}
double G1CollectorPolicy::sum_of_values(double* data) {
if (G1CollectedHeap::use_parallel_gc_threads()) {
double sum = 0.0;
for (uint i = 0; i < no_of_gc_threads(); i++) {
sum += data[i];
}
return sum;
} else {
return data[0];
}
}
double G1CollectorPolicy::max_sum(double* data1, double* data2) {
double ret = data1[0] + data2[0];
if (G1CollectedHeap::use_parallel_gc_threads()) {
for (uint i = 1; i < no_of_gc_threads(); ++i) {
double data = data1[i] + data2[i];
if (data > ret) {
ret = data;
}
}
}
return ret;
}
bool G1CollectorPolicy::need_to_start_conc_mark(const char* source, size_t alloc_word_size) { bool G1CollectorPolicy::need_to_start_conc_mark(const char* source, size_t alloc_word_size) {
if (_g1->concurrent_mark()->cmThread()->during_cycle()) { if (_g1->concurrent_mark()->cmThread()->during_cycle()) {
return false; return false;
@ -1142,10 +906,8 @@ bool G1CollectorPolicy::need_to_start_conc_mark(const char* source, size_t alloc
// Anything below that is considered to be zero // Anything below that is considered to be zero
#define MIN_TIMER_GRANULARITY 0.0000001 #define MIN_TIMER_GRANULARITY 0.0000001
void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) { void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
double end_time_sec = os::elapsedTime(); double end_time_sec = os::elapsedTime();
double elapsed_ms = _last_pause_time_ms;
bool parallel = G1CollectedHeap::use_parallel_gc_threads();
assert(_cur_collection_pause_used_regions_at_start >= cset_region_length(), assert(_cur_collection_pause_used_regions_at_start >= cset_region_length(),
"otherwise, the subtraction below does not make sense"); "otherwise, the subtraction below does not make sense");
size_t rs_size = size_t rs_size =
@ -1154,7 +916,6 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
assert(cur_used_bytes == _g1->recalculate_used(), "It should!"); assert(cur_used_bytes == _g1->recalculate_used(), "It should!");
bool last_pause_included_initial_mark = false; bool last_pause_included_initial_mark = false;
bool update_stats = !_g1->evacuation_failed(); bool update_stats = !_g1->evacuation_failed();
set_no_of_gc_threads(no_of_gc_threads);
#ifndef PRODUCT #ifndef PRODUCT
if (G1YoungSurvRateVerbose) { if (G1YoungSurvRateVerbose) {
@ -1174,7 +935,7 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
set_initiate_conc_mark_if_possible(); set_initiate_conc_mark_if_possible();
} }
_mmu_tracker->add_pause(end_time_sec - elapsed_ms/1000.0, _mmu_tracker->add_pause(end_time_sec - pause_time_ms/1000.0,
end_time_sec, false); end_time_sec, false);
size_t freed_bytes = size_t freed_bytes =
@ -1185,58 +946,11 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
(double)surviving_bytes/ (double)surviving_bytes/
(double)_collection_set_bytes_used_before; (double)_collection_set_bytes_used_before;
// These values are used to update the summary information that is
// displayed when TraceGen0Time is enabled, and are output as part
// of the "finer" output, in the non-parallel case.
double ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms);
double satb_filtering_time = avg_value(_par_last_satb_filtering_times_ms);
double update_rs_time = avg_value(_par_last_update_rs_times_ms);
double update_rs_processed_buffers =
sum_of_values(_par_last_update_rs_processed_buffers);
double scan_rs_time = avg_value(_par_last_scan_rs_times_ms);
double obj_copy_time = avg_value(_par_last_obj_copy_times_ms);
double termination_time = avg_value(_par_last_termination_times_ms);
double known_time = ext_root_scan_time +
satb_filtering_time +
update_rs_time +
scan_rs_time +
obj_copy_time;
double other_time_ms = elapsed_ms;
// Subtract the root region scanning wait time. It's initialized to
// zero at the start of the pause.
other_time_ms -= _root_region_scan_wait_time_ms;
if (parallel) {
other_time_ms -= _cur_collection_par_time_ms;
} else {
other_time_ms -= known_time;
}
// Now subtract the time taken to fix up roots in generated code
other_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"
other_time_ms -= _cur_clear_ct_time_ms;
// TraceGen0Time and TraceGen1Time summary info updating.
if (update_stats) { if (update_stats) {
double parallel_known_time = known_time + termination_time; _trace_gen0_time_data.record_end_collection(pause_time_ms, phase_times());
double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time;
_trace_gen0_time_data.record_end_collection(
elapsed_ms, other_time_ms, _root_region_scan_wait_time_ms, _cur_collection_par_time_ms,
ext_root_scan_time, satb_filtering_time, update_rs_time, scan_rs_time, obj_copy_time,
termination_time, parallel_other_time, _cur_clear_ct_time_ms);
// this is where we update the allocation rate of the application // this is where we update the allocation rate of the application
double app_time_ms = double app_time_ms =
(_cur_collection_start_sec * 1000.0 - _prev_collection_pause_end_ms); (phase_times()->_cur_collection_start_sec * 1000.0 - _prev_collection_pause_end_ms);
if (app_time_ms < MIN_TIMER_GRANULARITY) { if (app_time_ms < MIN_TIMER_GRANULARITY) {
// This usually happens due to the timer not having the required // This usually happens due to the timer not having the required
// granularity. Some Linuxes are the usual culprits. // granularity. Some Linuxes are the usual culprits.
@ -1257,7 +971,7 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
double interval_ms = double interval_ms =
(end_time_sec - _recent_prev_end_times_for_all_gcs_sec->oldest()) * 1000.0; (end_time_sec - _recent_prev_end_times_for_all_gcs_sec->oldest()) * 1000.0;
update_recent_gc_times(end_time_sec, elapsed_ms); update_recent_gc_times(end_time_sec, pause_time_ms);
_recent_avg_pause_time_ratio = _recent_gc_times_ms->sum()/interval_ms; _recent_avg_pause_time_ratio = _recent_gc_times_ms->sum()/interval_ms;
if (recent_avg_pause_time_ratio() < 0.0 || if (recent_avg_pause_time_ratio() < 0.0 ||
(recent_avg_pause_time_ratio() - 1.0 > 0.0)) { (recent_avg_pause_time_ratio() - 1.0 > 0.0)) {
@ -1284,90 +998,6 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
} }
} }
} }
if (G1Log::finer()) {
bool print_marking_info =
_g1->mark_in_progress() && !last_pause_included_initial_mark;
gclog_or_tty->print_cr("%s, %1.8lf secs]",
(last_pause_included_initial_mark) ? " (initial-mark)" : "",
elapsed_ms / 1000.0);
if (_root_region_scan_wait_time_ms > 0.0) {
print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
}
if (parallel) {
print_stats(1, "Parallel Time", _cur_collection_par_time_ms, no_of_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 (print_marking_info) {
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 */);
}
for (int i = 0; i < _parallel_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_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 (print_marking_info) {
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);
#ifndef PRODUCT
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));
}
#endif
print_stats(1, "Other", other_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));
}
bool new_in_marking_window = _in_marking_window; bool new_in_marking_window = _in_marking_window;
bool new_in_marking_window_im = false; bool new_in_marking_window_im = false;
if (during_initial_mark_pause()) { if (during_initial_mark_pause()) {
@ -1406,8 +1036,6 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
// do that for any other surv rate groupsx // do that for any other surv rate groupsx
if (update_stats) { if (update_stats) {
double pause_time_ms = elapsed_ms;
size_t diff = 0; size_t diff = 0;
if (_max_pending_cards >= _pending_cards) { if (_max_pending_cards >= _pending_cards) {
diff = _max_pending_cards - _pending_cards; diff = _max_pending_cards - _pending_cards;
@ -1416,7 +1044,7 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
double cost_per_card_ms = 0.0; double cost_per_card_ms = 0.0;
if (_pending_cards > 0) { if (_pending_cards > 0) {
cost_per_card_ms = update_rs_time / (double) _pending_cards; cost_per_card_ms = phase_times()->_update_rs_time / (double) _pending_cards;
_cost_per_card_ms_seq->add(cost_per_card_ms); _cost_per_card_ms_seq->add(cost_per_card_ms);
} }
@ -1424,7 +1052,7 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
double cost_per_entry_ms = 0.0; double cost_per_entry_ms = 0.0;
if (cards_scanned > 10) { if (cards_scanned > 10) {
cost_per_entry_ms = scan_rs_time / (double) cards_scanned; cost_per_entry_ms = phase_times()->_scan_rs_time / (double) cards_scanned;
if (_last_gc_was_young) { if (_last_gc_was_young) {
_cost_per_entry_ms_seq->add(cost_per_entry_ms); _cost_per_entry_ms_seq->add(cost_per_entry_ms);
} else { } else {
@ -1464,7 +1092,7 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
size_t copied_bytes = surviving_bytes; size_t copied_bytes = surviving_bytes;
double cost_per_byte_ms = 0.0; double cost_per_byte_ms = 0.0;
if (copied_bytes > 0) { if (copied_bytes > 0) {
cost_per_byte_ms = obj_copy_time / (double) copied_bytes; cost_per_byte_ms = phase_times()->_obj_copy_time / (double) copied_bytes;
if (_in_marking_window) { if (_in_marking_window) {
_cost_per_byte_ms_during_cm_seq->add(cost_per_byte_ms); _cost_per_byte_ms_during_cm_seq->add(cost_per_byte_ms);
} else { } else {
@ -1473,21 +1101,21 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
} }
double all_other_time_ms = pause_time_ms - double all_other_time_ms = pause_time_ms -
(update_rs_time + scan_rs_time + obj_copy_time + termination_time); (phase_times()->_update_rs_time + phase_times()->_scan_rs_time + phase_times()->_obj_copy_time + phase_times()->_termination_time);
double young_other_time_ms = 0.0; double young_other_time_ms = 0.0;
if (young_cset_region_length() > 0) { if (young_cset_region_length() > 0) {
young_other_time_ms = young_other_time_ms =
_recorded_young_cset_choice_time_ms + phase_times()->_recorded_young_cset_choice_time_ms +
_recorded_young_free_cset_time_ms; phase_times()->_recorded_young_free_cset_time_ms;
_young_other_cost_per_region_ms_seq->add(young_other_time_ms / _young_other_cost_per_region_ms_seq->add(young_other_time_ms /
(double) young_cset_region_length()); (double) young_cset_region_length());
} }
double non_young_other_time_ms = 0.0; double non_young_other_time_ms = 0.0;
if (old_cset_region_length() > 0) { if (old_cset_region_length() > 0) {
non_young_other_time_ms = non_young_other_time_ms =
_recorded_non_young_cset_choice_time_ms + phase_times()->_recorded_non_young_cset_choice_time_ms +
_recorded_non_young_free_cset_time_ms; phase_times()->_recorded_non_young_free_cset_time_ms;
_non_young_other_cost_per_region_ms_seq->add(non_young_other_time_ms / _non_young_other_cost_per_region_ms_seq->add(non_young_other_time_ms /
(double) old_cset_region_length()); (double) old_cset_region_length());
@ -1514,7 +1142,7 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
// Note that _mmu_tracker->max_gc_time() returns the time in seconds. // Note that _mmu_tracker->max_gc_time() returns the time in seconds.
double update_rs_time_goal_ms = _mmu_tracker->max_gc_time() * MILLIUNITS * G1RSetUpdatingPauseTimePercent / 100.0; double update_rs_time_goal_ms = _mmu_tracker->max_gc_time() * MILLIUNITS * G1RSetUpdatingPauseTimePercent / 100.0;
adjust_concurrent_refinement(update_rs_time, update_rs_processed_buffers, update_rs_time_goal_ms); adjust_concurrent_refinement(phase_times()->_update_rs_time, phase_times()->_update_rs_processed_buffers, update_rs_time_goal_ms);
_collectionSetChooser->verify(); _collectionSetChooser->verify();
} }
@ -2323,7 +1951,7 @@ void G1CollectorPolicy::finalize_cset(double target_pause_time_ms) {
set_recorded_rs_lengths(_inc_cset_recorded_rs_lengths); set_recorded_rs_lengths(_inc_cset_recorded_rs_lengths);
double young_end_time_sec = os::elapsedTime(); double young_end_time_sec = os::elapsedTime();
_recorded_young_cset_choice_time_ms = phase_times()->_recorded_young_cset_choice_time_ms =
(young_end_time_sec - young_start_time_sec) * 1000.0; (young_end_time_sec - young_start_time_sec) * 1000.0;
// We are doing young collections so reset this. // We are doing young collections so reset this.
@ -2439,7 +2067,7 @@ void G1CollectorPolicy::finalize_cset(double target_pause_time_ms) {
predicted_pause_time_ms, target_pause_time_ms); predicted_pause_time_ms, target_pause_time_ms);
double non_young_end_time_sec = os::elapsedTime(); double non_young_end_time_sec = os::elapsedTime();
_recorded_non_young_cset_choice_time_ms = phase_times()->_recorded_non_young_cset_choice_time_ms =
(non_young_end_time_sec - non_young_start_time_sec) * 1000.0; (non_young_end_time_sec - non_young_start_time_sec) * 1000.0;
} }
@ -2455,33 +2083,29 @@ void TraceGen0TimeData::record_yield_time(double yield_time_ms) {
} }
} }
void TraceGen0TimeData::record_end_collection( void TraceGen0TimeData::record_end_collection(double pause_time_ms, G1GCPhaseTimes* phase_times) {
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)
{
if(TraceGen0Time) { if(TraceGen0Time) {
_total.add(total_ms); _total.add(pause_time_ms);
_other.add(other_ms); _other.add(pause_time_ms - phase_times->accounted_time_ms());
_root_region_scan_wait.add(root_region_scan_wait_ms); _root_region_scan_wait.add(phase_times->_root_region_scan_wait_time_ms);
_parallel.add(parallel_ms); _parallel.add(phase_times->_cur_collection_par_time_ms);
_ext_root_scan.add(ext_root_scan_ms); _ext_root_scan.add(phase_times->_ext_root_scan_time);
_satb_filtering.add(satb_filtering_ms); _satb_filtering.add(phase_times->_satb_filtering_time);
_update_rs.add(update_rs_ms); _update_rs.add(phase_times->_update_rs_time);
_scan_rs.add(scan_rs_ms); _scan_rs.add(phase_times->_scan_rs_time);
_obj_copy.add(obj_copy_ms); _obj_copy.add(phase_times->_obj_copy_time);
_termination.add(termination_ms); _termination.add(phase_times->_termination_time);
_parallel_other.add(parallel_other_ms);
_clear_ct.add(clear_ct_ms); double parallel_known_time = phase_times->_ext_root_scan_time +
phase_times->_satb_filtering_time +
phase_times->_update_rs_time +
phase_times->_scan_rs_time +
phase_times->_obj_copy_time +
+ phase_times->_termination_time;
double parallel_other_time = phase_times->_cur_collection_par_time_ms - parallel_known_time;
_parallel_other.add(parallel_other_time);
_clear_ct.add(phase_times->_cur_clear_ct_time_ms);
} }
} }
@ -2497,20 +2121,18 @@ void TraceGen0TimeData::increment_mixed_collection_count() {
} }
} }
void TraceGen0TimeData::print_summary(int level, void TraceGen0TimeData::print_summary(const char* str,
const char* str,
const NumberSeq* seq) const { const NumberSeq* seq) const {
double sum = seq->sum(); double sum = seq->sum();
LineBuffer(level + 1).append_and_print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)", gclog_or_tty->print_cr("%-27s = %8.2lf s (avg = %8.2lf ms)",
str, sum / 1000.0, seq->avg()); str, sum / 1000.0, seq->avg());
} }
void TraceGen0TimeData::print_summary_sd(int level, void TraceGen0TimeData::print_summary_sd(const char* str,
const char* str,
const NumberSeq* seq) const { const NumberSeq* seq) const {
print_summary(level, str, seq); print_summary(str, seq);
LineBuffer(level + 6).append_and_print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)", gclog_or_tty->print_cr("%+45s = %5d, std dev = %8.2lf ms, max = %8.2lf ms)",
seq->num(), seq->sd(), seq->maximum()); "(num", seq->num(), seq->sd(), seq->maximum());
} }
void TraceGen0TimeData::print() const { void TraceGen0TimeData::print() const {
@ -2519,7 +2141,7 @@ void TraceGen0TimeData::print() const {
} }
gclog_or_tty->print_cr("ALL PAUSES"); gclog_or_tty->print_cr("ALL PAUSES");
print_summary_sd(0, "Total", &_total); print_summary_sd(" Total", &_total);
gclog_or_tty->print_cr(""); gclog_or_tty->print_cr("");
gclog_or_tty->print_cr(""); gclog_or_tty->print_cr("");
gclog_or_tty->print_cr(" Young GC Pauses: %8d", _young_pause_num); gclog_or_tty->print_cr(" Young GC Pauses: %8d", _young_pause_num);
@ -2531,24 +2153,24 @@ void TraceGen0TimeData::print() const {
if (_young_pause_num == 0 && _mixed_pause_num == 0) { if (_young_pause_num == 0 && _mixed_pause_num == 0) {
gclog_or_tty->print_cr("none"); gclog_or_tty->print_cr("none");
} else { } else {
print_summary_sd(0, "Evacuation Pauses", &_total); print_summary_sd(" Evacuation Pauses", &_total);
print_summary(1, "Root Region Scan Wait", &_root_region_scan_wait); print_summary(" Root Region Scan Wait", &_root_region_scan_wait);
print_summary(1, "Parallel Time", &_parallel); print_summary(" Parallel Time", &_parallel);
print_summary(2, "Ext Root Scanning", &_ext_root_scan); print_summary(" Ext Root Scanning", &_ext_root_scan);
print_summary(2, "SATB Filtering", &_satb_filtering); print_summary(" SATB Filtering", &_satb_filtering);
print_summary(2, "Update RS", &_update_rs); print_summary(" Update RS", &_update_rs);
print_summary(2, "Scan RS", &_scan_rs); print_summary(" Scan RS", &_scan_rs);
print_summary(2, "Object Copy", &_obj_copy); print_summary(" Object Copy", &_obj_copy);
print_summary(2, "Termination", &_termination); print_summary(" Termination", &_termination);
print_summary(2, "Parallel Other", &_parallel_other); print_summary(" Parallel Other", &_parallel_other);
print_summary(1, "Clear CT", &_clear_ct); print_summary(" Clear CT", &_clear_ct);
print_summary(1, "Other", &_other); print_summary(" Other", &_other);
} }
gclog_or_tty->print_cr(""); gclog_or_tty->print_cr("");
gclog_or_tty->print_cr("MISC"); gclog_or_tty->print_cr("MISC");
print_summary_sd(0, "Stop World", &_all_stop_world_times_ms); print_summary_sd(" Stop World", &_all_stop_world_times_ms);
print_summary_sd(0, "Yields", &_all_yield_times_ms); print_summary_sd(" Yields", &_all_yield_times_ms);
} }
void TraceGen1TimeData::record_full_collection(double full_gc_time_ms) { void TraceGen1TimeData::record_full_collection(double full_gc_time_ms) {

176
hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp
View File

@ -36,6 +36,7 @@
class HeapRegion; class HeapRegion;
class CollectionSetChooser; class CollectionSetChooser;
class G1GCPhaseTimes;
// TraceGen0Time collects data on _both_ young and mixed evacuation pauses // TraceGen0Time collects data on _both_ young and mixed evacuation pauses
// (the latter may contain non-young regions - i.e. regions that are // (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 _parallel_other;
NumberSeq _clear_ct; NumberSeq _clear_ct;
void print_summary (int level, const char* str, const NumberSeq* seq) const; void print_summary(const char* str, const NumberSeq* seq) const;
void print_summary_sd (int level, const char* str, const NumberSeq* seq) const; void print_summary_sd(const char* str, const NumberSeq* seq) const;
public: public:
TraceGen0TimeData() : _young_pause_num(0), _mixed_pause_num(0) {}; TraceGen0TimeData() : _young_pause_num(0), _mixed_pause_num(0) {};
void record_start_collection(double time_to_stop_the_world_ms); void record_start_collection(double time_to_stop_the_world_ms);
void record_yield_time(double yield_time_ms); void record_yield_time(double yield_time_ms);
void record_end_collection( void record_end_collection(double pause_time_ms, G1GCPhaseTimes* phase_times);
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 increment_young_collection_count(); void increment_young_collection_count();
void increment_mixed_collection_count(); void increment_mixed_collection_count();
void print() const; void print() const;
@ -186,25 +175,9 @@ private:
CollectionSetChooser* _collectionSetChooser; CollectionSetChooser* _collectionSetChooser;
double _cur_collection_start_sec; double _full_collection_start_sec;
size_t _cur_collection_pause_used_at_start_bytes; size_t _cur_collection_pause_used_at_start_bytes;
uint _cur_collection_pause_used_regions_at_start; 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. // These exclude marking times.
TruncatedSeq* _recent_gc_times_ms; TruncatedSeq* _recent_gc_times_ms;
@ -217,23 +190,6 @@ private:
double _stop_world_start; 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 // indicates whether we are in young or mixed GC mode
bool _gcs_are_young; bool _gcs_are_young;
@ -306,10 +262,6 @@ private:
size_t _recorded_rs_lengths; size_t _recorded_rs_lengths;
size_t _max_rs_lengths; size_t _max_rs_lengths;
double _recorded_young_free_cset_time_ms;
double _recorded_non_young_free_cset_time_ms;
double _sigma; double _sigma;
size_t _rs_lengths_prediction; size_t _rs_lengths_prediction;
@ -341,8 +293,7 @@ private:
void set_no_of_gc_threads(uintx v) { _no_of_gc_threads = v; } void set_no_of_gc_threads(uintx v) { _no_of_gc_threads = v; }
double _pause_time_target_ms; 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 _pending_cards;
size_t _max_pending_cards; size_t _max_pending_cards;
@ -497,14 +448,6 @@ public:
uint young_cset_region_length() { return eden_cset_region_length() + uint young_cset_region_length() { return eden_cset_region_length() +
survivor_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(); double predict_survivor_regions_evac_time();
void cset_regions_freed() { void cset_regions_freed() {
@ -552,19 +495,6 @@ public:
} }
private: 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_in_collection_set_before_gc;
size_t _bytes_copied_during_gc; size_t _bytes_copied_during_gc;
@ -638,6 +568,8 @@ private:
// Stash a pointer to the g1 heap. // Stash a pointer to the g1 heap.
G1CollectedHeap* _g1; G1CollectedHeap* _g1;
G1GCPhaseTimes* _phase_times;
// The ratio of gc time to elapsed time, computed over recent pauses. // The ratio of gc time to elapsed time, computed over recent pauses.
double _recent_avg_pause_time_ratio; double _recent_avg_pause_time_ratio;
@ -677,7 +609,6 @@ private:
double _cur_mark_stop_world_time_ms; double _cur_mark_stop_world_time_ms;
double _mark_remark_start_sec; double _mark_remark_start_sec;
double _mark_cleanup_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 // Update the young list target length either by setting it to the
// desired fixed value or by calculating it using G1's pause // desired fixed value or by calculating it using G1's pause
@ -728,6 +659,8 @@ public:
return CollectorPolicy::G1CollectorPolicyKind; return CollectorPolicy::G1CollectorPolicyKind;
} }
G1GCPhaseTimes* phase_times() const { return _phase_times; }
// Check the current value of the young list RSet lengths and // Check the current value of the young list RSet lengths and
// compare it against the last prediction. If the current value is // compare it against the last prediction. If the current value is
// higher, recalculate the young list target length prediction. // higher, recalculate the young list target length prediction.
@ -772,10 +705,6 @@ public:
void record_concurrent_mark_init_end(double void record_concurrent_mark_init_end(double
mark_init_elapsed_time_ms); 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_start();
void record_concurrent_mark_remark_end(); void record_concurrent_mark_remark_end();
@ -784,97 +713,14 @@ public:
void record_concurrent_mark_cleanup_completed(); void record_concurrent_mark_cleanup_completed();
void record_concurrent_pause(); 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(); void print_heap_transition();
// Record the fact that a full collection occurred. // Record the fact that a full collection occurred.
void record_full_collection_start(); void record_full_collection_start();
void record_full_collection_end(); 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 // Record how much space we copied during a GC. This is typically
// called when a GC alloc region is being retired. // called when a GC alloc region is being retired.
void record_bytes_copied_during_gc(size_t bytes) { void record_bytes_copied_during_gc(size_t bytes) {

379
hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp Normal file
View File

@ -0,0 +1,379 @@
/*
* 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++;
}

216
hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp Normal file
View File

@ -0,0 +1,216 @@
/*
* 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

11
hotspot/src/share/vm/gc_implementation/g1/g1RemSet.cpp
View File

@ -29,6 +29,7 @@
#include "gc_implementation/g1/g1BlockOffsetTable.inline.hpp" #include "gc_implementation/g1/g1BlockOffsetTable.inline.hpp"
#include "gc_implementation/g1/g1CollectedHeap.inline.hpp" #include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
#include "gc_implementation/g1/g1CollectorPolicy.hpp" #include "gc_implementation/g1/g1CollectorPolicy.hpp"
#include "gc_implementation/g1/g1GCPhaseTimes.hpp"
#include "gc_implementation/g1/g1OopClosures.inline.hpp" #include "gc_implementation/g1/g1OopClosures.inline.hpp"
#include "gc_implementation/g1/g1RemSet.inline.hpp" #include "gc_implementation/g1/g1RemSet.inline.hpp"
#include "gc_implementation/g1/heapRegionSeq.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" ); assert( _cards_scanned != NULL, "invariant" );
_cards_scanned[worker_i] = scanRScl.cards_done(); _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 // 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."); 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 { class CountRSSizeClosure: public HeapRegionClosure {
@ -390,13 +391,13 @@ void G1RemSet::oops_into_collection_set_do(OopsInHeapRegionClosure* oc,
if (G1UseParallelRSetUpdating || (worker_i == 0)) { if (G1UseParallelRSetUpdating || (worker_i == 0)) {
updateRS(&into_cset_dcq, worker_i); updateRS(&into_cset_dcq, worker_i);
} else { } else {
_g1p->record_update_rs_processed_buffers(worker_i, 0.0); _g1p->phase_times()->record_update_rs_processed_buffers(worker_i, 0.0);
_g1p->record_update_rs_time(worker_i, 0.0); _g1p->phase_times()->record_update_rs_time(worker_i, 0.0);
} }
if (G1UseParallelRSetScanning || (worker_i == 0)) { if (G1UseParallelRSetScanning || (worker_i == 0)) {
scanRS(oc, worker_i); scanRS(oc, worker_i);
} else { } 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 // We now clear the cached values of _cset_rs_update_cl for this worker