--- a/hotspot/src/share/vm/gc_implementation/g1/concurrentG1Refine.cpp Tue Jul 17 12:32:26 2012 -0400
+++ b/hotspot/src/share/vm/gc_implementation/g1/concurrentG1Refine.cpp Tue Jul 17 14:33:17 2012 -0700
@@ -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.
*
* 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 @@
}
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 @@
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 {
--- a/hotspot/src/share/vm/gc_implementation/g1/concurrentMark.cpp Tue Jul 17 12:32:26 2012 -0400
+++ b/hotspot/src/share/vm/gc_implementation/g1/concurrentMark.cpp Tue Jul 17 14:33:17 2012 -0700
@@ -3156,9 +3156,6 @@
_g1h->g1_policy()->record_concurrent_pause();
}
cmThread()->yield();
- if (worker_id == 0) {
- _g1h->g1_policy()->record_concurrent_pause_end();
- }
return true;
} else {
return false;
--- a/hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Tue Jul 17 12:32:26 2012 -0400
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Tue Jul 17 14:33:17 2012 -0700
@@ -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 @@
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 @@
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 @@
// 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 @@
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 @@
// 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 @@
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 @@
// 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 @@
#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 @@
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 @@
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 @@
}
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 @@
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 @@
}
}
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 @@
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 @@
// 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 @@
}
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 @@
}
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 @@
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
--- a/hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Tue Jul 17 12:32:26 2012 -0400
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Tue Jul 17 14:33:17 2012 -0700
@@ -29,6 +29,7 @@
#include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
#include "gc_implementation/g1/g1CollectorPolicy.hpp"
#include "gc_implementation/g1/g1ErgoVerbose.hpp"
+#include "gc_implementation/g1/g1GCPhaseTimes.hpp"
#include "gc_implementation/g1/g1Log.hpp"
#include "gc_implementation/g1/heapRegionRemSet.hpp"
#include "gc_implementation/shared/gcPolicyCounters.hpp"
@@ -77,57 +78,6 @@
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() :
_parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads()
? ParallelGCThreads : 1),
@@ -135,20 +85,6 @@
_recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
_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_cleanup_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
@@ -257,30 +193,9 @@
_recent_prev_end_times_for_all_gcs_sec->add(os::elapsedTime());
_prev_collection_pause_end_ms = os::elapsedTime() * 1000.0;
- _par_last_gc_worker_start_times_ms = new double[_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];
- _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];
+ _phase_times = new G1GCPhaseTimes(_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;
+ int index = MIN2(_parallel_gc_threads - 1, 7);
_pending_card_diff_seq->add(0.0);
_rs_length_diff_seq->add(rs_length_diff_defaults[index]);
@@ -824,7 +739,7 @@
#endif // PRODUCT
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.
_g1->set_full_collection();
}
@@ -833,7 +748,7 @@
// Consider this like a collection pause for the purposes of allocation
// since last pause.
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;
_trace_gen1_time_data.record_full_collection(full_gc_time_ms);
@@ -869,12 +784,6 @@
void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
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
// to the GC we're about to start. so, no point is calculating this
// every time we calculate / recalculate the target young length.
@@ -888,7 +797,7 @@
_trace_gen0_time_data.record_start_collection(s_w_t_ms);
_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_regions_at_start = _g1->used_regions();
_pending_cards = _g1->pending_card_num();
@@ -902,30 +811,6 @@
_survivor_bytes_before_gc = young_list->survivor_used_bytes();
_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;
// do that for any other surv rate groups
@@ -974,127 +859,6 @@
}
}
-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) {
if (_g1->concurrent_mark()->cmThread()->during_cycle()) {
return false;
@@ -1142,10 +906,8 @@
// Anything below that is considered to be zero
#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 elapsed_ms = _last_pause_time_ms;
- bool parallel = G1CollectedHeap::use_parallel_gc_threads();
assert(_cur_collection_pause_used_regions_at_start >= cset_region_length(),
"otherwise, the subtraction below does not make sense");
size_t rs_size =
@@ -1154,7 +916,6 @@
assert(cur_used_bytes == _g1->recalculate_used(), "It should!");
bool last_pause_included_initial_mark = false;
bool update_stats = !_g1->evacuation_failed();
- set_no_of_gc_threads(no_of_gc_threads);
#ifndef PRODUCT
if (G1YoungSurvRateVerbose) {
@@ -1174,7 +935,7 @@
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);
size_t freed_bytes =
@@ -1185,58 +946,11 @@
(double)surviving_bytes/
(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) {
- double parallel_known_time = known_time + termination_time;
- 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);
-
+ _trace_gen0_time_data.record_end_collection(pause_time_ms, phase_times());
// this is where we update the allocation rate of the application
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) {
// This usually happens due to the timer not having the required
// granularity. Some Linuxes are the usual culprits.
@@ -1257,7 +971,7 @@
double interval_ms =
(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;
if (recent_avg_pause_time_ratio() < 0.0 ||
(recent_avg_pause_time_ratio() - 1.0 > 0.0)) {
@@ -1284,90 +998,6 @@
}
}
}
-
- 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_im = false;
if (during_initial_mark_pause()) {
@@ -1406,8 +1036,6 @@
// do that for any other surv rate groupsx
if (update_stats) {
- double pause_time_ms = elapsed_ms;
-
size_t diff = 0;
if (_max_pending_cards >= _pending_cards) {
diff = _max_pending_cards - _pending_cards;
@@ -1416,7 +1044,7 @@
double cost_per_card_ms = 0.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);
}
@@ -1424,7 +1052,7 @@
double cost_per_entry_ms = 0.0;
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) {
_cost_per_entry_ms_seq->add(cost_per_entry_ms);
} else {
@@ -1464,7 +1092,7 @@
size_t copied_bytes = surviving_bytes;
double cost_per_byte_ms = 0.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) {
_cost_per_byte_ms_during_cm_seq->add(cost_per_byte_ms);
} else {
@@ -1473,21 +1101,21 @@
}
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;
if (young_cset_region_length() > 0) {
young_other_time_ms =
- _recorded_young_cset_choice_time_ms +
- _recorded_young_free_cset_time_ms;
+ phase_times()->_recorded_young_cset_choice_time_ms +
+ phase_times()->_recorded_young_free_cset_time_ms;
_young_other_cost_per_region_ms_seq->add(young_other_time_ms /
(double) young_cset_region_length());
}
double non_young_other_time_ms = 0.0;
if (old_cset_region_length() > 0) {
non_young_other_time_ms =
- _recorded_non_young_cset_choice_time_ms +
- _recorded_non_young_free_cset_time_ms;
+ phase_times()->_recorded_non_young_cset_choice_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 /
(double) old_cset_region_length());
@@ -1514,7 +1142,7 @@
// 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;
- 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();
}
@@ -2323,7 +1951,7 @@
set_recorded_rs_lengths(_inc_cset_recorded_rs_lengths);
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;
// We are doing young collections so reset this.
@@ -2439,7 +2067,7 @@
predicted_pause_time_ms, target_pause_time_ms);
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;
}
@@ -2455,33 +2083,29 @@
}
}
-void TraceGen0TimeData::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 TraceGen0TimeData::record_end_collection(double pause_time_ms, G1GCPhaseTimes* phase_times) {
if(TraceGen0Time) {
- _total.add(total_ms);
- _other.add(other_ms);
- _root_region_scan_wait.add(root_region_scan_wait_ms);
- _parallel.add(parallel_ms);
- _ext_root_scan.add(ext_root_scan_ms);
- _satb_filtering.add(satb_filtering_ms);
- _update_rs.add(update_rs_ms);
- _scan_rs.add(scan_rs_ms);
- _obj_copy.add(obj_copy_ms);
- _termination.add(termination_ms);
- _parallel_other.add(parallel_other_ms);
- _clear_ct.add(clear_ct_ms);
+ _total.add(pause_time_ms);
+ _other.add(pause_time_ms - phase_times->accounted_time_ms());
+ _root_region_scan_wait.add(phase_times->_root_region_scan_wait_time_ms);
+ _parallel.add(phase_times->_cur_collection_par_time_ms);
+ _ext_root_scan.add(phase_times->_ext_root_scan_time);
+ _satb_filtering.add(phase_times->_satb_filtering_time);
+ _update_rs.add(phase_times->_update_rs_time);
+ _scan_rs.add(phase_times->_scan_rs_time);
+ _obj_copy.add(phase_times->_obj_copy_time);
+ _termination.add(phase_times->_termination_time);
+
+ 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::print_summary(int level,
- const char* str,
+void TraceGen0TimeData::print_summary(const char* str,
const NumberSeq* seq) const {
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());
}
-void TraceGen0TimeData::print_summary_sd(int level,
- const char* str,
+void TraceGen0TimeData::print_summary_sd(const char* str,
const NumberSeq* seq) const {
- print_summary(level, str, seq);
- LineBuffer(level + 6).append_and_print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)",
- seq->num(), seq->sd(), seq->maximum());
+ print_summary(str, seq);
+ gclog_or_tty->print_cr("%+45s = %5d, std dev = %8.2lf ms, max = %8.2lf ms)",
+ "(num", seq->num(), seq->sd(), seq->maximum());
}
void TraceGen0TimeData::print() const {
@@ -2519,7 +2141,7 @@
}
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(" Young GC Pauses: %8d", _young_pause_num);
@@ -2531,24 +2153,24 @@
if (_young_pause_num == 0 && _mixed_pause_num == 0) {
gclog_or_tty->print_cr("none");
} else {
- print_summary_sd(0, "Evacuation Pauses", &_total);
- print_summary(1, "Root Region Scan Wait", &_root_region_scan_wait);
- print_summary(1, "Parallel Time", &_parallel);
- print_summary(2, "Ext Root Scanning", &_ext_root_scan);
- print_summary(2, "SATB Filtering", &_satb_filtering);
- print_summary(2, "Update RS", &_update_rs);
- print_summary(2, "Scan RS", &_scan_rs);
- print_summary(2, "Object Copy", &_obj_copy);
- print_summary(2, "Termination", &_termination);
- print_summary(2, "Parallel Other", &_parallel_other);
- print_summary(1, "Clear CT", &_clear_ct);
- print_summary(1, "Other", &_other);
+ print_summary_sd(" Evacuation Pauses", &_total);
+ print_summary(" Root Region Scan Wait", &_root_region_scan_wait);
+ print_summary(" Parallel Time", &_parallel);
+ print_summary(" Ext Root Scanning", &_ext_root_scan);
+ print_summary(" SATB Filtering", &_satb_filtering);
+ print_summary(" Update RS", &_update_rs);
+ print_summary(" Scan RS", &_scan_rs);
+ print_summary(" Object Copy", &_obj_copy);
+ print_summary(" Termination", &_termination);
+ print_summary(" Parallel Other", &_parallel_other);
+ print_summary(" Clear CT", &_clear_ct);
+ print_summary(" Other", &_other);
}
gclog_or_tty->print_cr("");
gclog_or_tty->print_cr("MISC");
- print_summary_sd(0, "Stop World", &_all_stop_world_times_ms);
- print_summary_sd(0, "Yields", &_all_yield_times_ms);
+ print_summary_sd(" Stop World", &_all_stop_world_times_ms);
+ print_summary_sd(" Yields", &_all_yield_times_ms);
}
void TraceGen1TimeData::record_full_collection(double full_gc_time_ms) {
--- a/hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp Tue Jul 17 12:32:26 2012 -0400
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp Tue Jul 17 14:33:17 2012 -0700
@@ -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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
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 @@
}
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 @@
// 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 @@
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 @@
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 @@
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 @@
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) {
--- /dev/null Thu Jan 01 00:00:00 1970 +0000
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp Tue Jul 17 14:33:17 2012 -0700
@@ -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++;
+}
--- /dev/null Thu Jan 01 00:00:00 1970 +0000
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp Tue Jul 17 14:33:17 2012 -0700
@@ -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
--- a/hotspot/src/share/vm/gc_implementation/g1/g1RemSet.cpp Tue Jul 17 12:32:26 2012 -0400
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1RemSet.cpp Tue Jul 17 14:33:17 2012 -0700
@@ -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 @@
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 @@
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 @@
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