diff --git a/src/share/vm/gc_implementation/g1/concurrentG1Refine.cpp b/src/share/vm/gc_implementation/g1/concurrentG1Refine.cpp index cb802770ff7b42577aa8afb1f6f3ae59f5f7d93a..3eab85e13c8a2eb44fb88a6d82b1bff58f88c057 100644 --- a/src/share/vm/gc_implementation/g1/concurrentG1Refine.cpp +++ b/src/share/vm/gc_implementation/g1/concurrentG1Refine.cpp @@ -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 @@ bool ConcurrentG1Refine::expand_card_count_cache(int cache_size_idx) { } void ConcurrentG1Refine::clear_and_record_card_counts() { - if (G1ConcRSLogCacheSize == 0) return; + if (G1ConcRSLogCacheSize == 0) { + return; + } -#ifndef PRODUCT double start = os::elapsedTime(); -#endif if (_expand_card_counts) { int new_idx = _cache_size_index + 1; @@ -523,11 +524,8 @@ void ConcurrentG1Refine::clear_and_record_card_counts() { assert((this_epoch+1) <= max_jint, "to many periods"); // Update epoch _n_periods++; - -#ifndef PRODUCT - double elapsed = os::elapsedTime() - start; - _g1h->g1_policy()->record_cc_clear_time(elapsed * 1000.0); -#endif + double cc_clear_time_ms = (os::elapsedTime() - start) * 1000; + _g1h->g1_policy()->phase_times()->record_cc_clear_time_ms(cc_clear_time_ms); } void ConcurrentG1Refine::print_worker_threads_on(outputStream* st) const { diff --git a/src/share/vm/gc_implementation/g1/concurrentMark.cpp b/src/share/vm/gc_implementation/g1/concurrentMark.cpp index 85ea7ce3a65a0cbe4c0d7eb7e420ef77e612dd67..bee6614710510676a1e96b175b0439b01da749bd 100644 --- a/src/share/vm/gc_implementation/g1/concurrentMark.cpp +++ b/src/share/vm/gc_implementation/g1/concurrentMark.cpp @@ -3156,9 +3156,6 @@ bool ConcurrentMark::do_yield_check(uint worker_id) { _g1h->g1_policy()->record_concurrent_pause(); } cmThread()->yield(); - if (worker_id == 0) { - _g1h->g1_policy()->record_concurrent_pause_end(); - } return true; } else { return false; diff --git a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp index 85994fe9ac38547b5c78389af4c1acbc75f3aba0..c865db42883f9311a885b57f637efee8d6482bbf 100644 --- a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp +++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp @@ -33,6 +33,7 @@ #include "gc_implementation/g1/g1CollectorPolicy.hpp" #include "gc_implementation/g1/g1ErgoVerbose.hpp" #include "gc_implementation/g1/g1EvacFailure.hpp" +#include "gc_implementation/g1/g1GCPhaseTimes.hpp" #include "gc_implementation/g1/g1Log.hpp" #include "gc_implementation/g1/g1MarkSweep.hpp" #include "gc_implementation/g1/g1OopClosures.inline.hpp" @@ -2274,7 +2275,7 @@ void G1CollectedHeap::iterate_dirty_card_closure(CardTableEntryClosure* cl, while (dcqs.apply_closure_to_completed_buffer(cl, worker_i, 0, true)) { n_completed_buffers++; } - g1_policy()->record_update_rs_processed_buffers(worker_i, + g1_policy()->phase_times()->record_update_rs_processed_buffers(worker_i, (double) n_completed_buffers); dcqs.clear_n_completed_buffers(); assert(!dcqs.completed_buffers_exist_dirty(), "Completed buffers exist!"); @@ -3633,10 +3634,10 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) { gclog_or_tty->date_stamp(G1Log::fine() && PrintGCDateStamps); TraceCPUTime tcpu(G1Log::finer(), true, gclog_or_tty); - GCCauseString gc_cause_str = GCCauseString("GC pause", gc_cause()) - .append(g1_policy()->gcs_are_young() ? " (young)" : " (mixed)") - .append(g1_policy()->during_initial_mark_pause() ? " (initial-mark)" : ""); - TraceTime t(gc_cause_str, G1Log::fine() && !G1Log::finer(), true, gclog_or_tty); + int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ? + workers()->active_workers() : 1); + g1_policy()->phase_times()->note_gc_start(os::elapsedTime(), active_workers, + g1_policy()->gcs_are_young(), g1_policy()->during_initial_mark_pause(), gc_cause()); TraceCollectorStats tcs(g1mm()->incremental_collection_counters()); TraceMemoryManagerStats tms(false /* fullGC */, gc_cause()); @@ -3699,9 +3700,15 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) { // before the start GC event. _hr_printer.start_gc(false /* full */, (size_t) total_collections()); + // This timing is only used by the ergonomics to handle our pause target. + // It is unclear why this should not include the full pause. We will + // investigate this in CR 7178365. + // + // Preserving the old comment here if that helps the investigation: + // // The elapsed time induced by the start time below deliberately elides // the possible verification above. - double start_time_sec = os::elapsedTime(); + double sample_start_time_sec = os::elapsedTime(); size_t start_used_bytes = used(); #if YOUNG_LIST_VERBOSE @@ -3710,7 +3717,7 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) { g1_policy()->print_collection_set(g1_policy()->inc_cset_head(), gclog_or_tty); #endif // YOUNG_LIST_VERBOSE - g1_policy()->record_collection_pause_start(start_time_sec, + g1_policy()->record_collection_pause_start(sample_start_time_sec, start_used_bytes); double scan_wait_start = os::elapsedTime(); @@ -3719,11 +3726,12 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) { // objects on them have been correctly scanned before we start // moving them during the GC. bool waited = _cm->root_regions()->wait_until_scan_finished(); + double wait_time_ms = 0.0; if (waited) { double scan_wait_end = os::elapsedTime(); - double wait_time_ms = (scan_wait_end - scan_wait_start) * 1000.0; - g1_policy()->record_root_region_scan_wait_time(wait_time_ms); + wait_time_ms = (scan_wait_end - scan_wait_start) * 1000.0; } + g1_policy()->phase_times()->record_root_region_scan_wait_time(wait_time_ms); #if YOUNG_LIST_VERBOSE gclog_or_tty->print_cr("\nAfter recording pause start.\nYoung_list:"); @@ -3877,12 +3885,16 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) { true /* verify_fingers */); _cm->note_end_of_gc(); - double end_time_sec = os::elapsedTime(); - double pause_time_ms = (end_time_sec - start_time_sec) * MILLIUNITS; - g1_policy()->record_pause_time_ms(pause_time_ms); - int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ? - workers()->active_workers() : 1); - g1_policy()->record_collection_pause_end(active_workers); + // Collect thread local data to allow the ergonomics to use + // the collected information + g1_policy()->phase_times()->collapse_par_times(); + + // This timing is only used by the ergonomics to handle our pause target. + // It is unclear why this should not include the full pause. We will + // investigate this in CR 7178365. + double sample_end_time_sec = os::elapsedTime(); + double pause_time_ms = (sample_end_time_sec - sample_start_time_sec) * MILLIUNITS; + g1_policy()->record_collection_pause_end(pause_time_ms); MemoryService::track_memory_usage(); @@ -3929,9 +3941,6 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) { // RETIRE events are generated before the end GC event. _hr_printer.end_gc(false /* full */, (size_t) total_collections()); - // We have to do this after we decide whether to expand the heap or not. - g1_policy()->print_heap_transition(); - if (mark_in_progress()) { concurrent_mark()->update_g1_committed(); } @@ -3941,13 +3950,14 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) { #endif gc_epilogue(false); + + g1_policy()->phase_times()->note_gc_end(os::elapsedTime()); + + // We have to do this after we decide whether to expand the heap or not. + g1_policy()->print_heap_transition(); } - // The closing of the inner scope, immediately above, will complete - // logging at the "fine" level. The record_collection_pause_end() call - // above will complete logging at the "finer" level. - // - // It is not yet to safe, however, to tell the concurrent mark to + // It is not yet to safe to tell the concurrent mark to // start as we have some optional output below. We don't want the // output from the concurrent mark thread interfering with this // logging output either. @@ -4695,7 +4705,7 @@ public: if (worker_id >= _n_workers) return; // no work needed this round double start_time_ms = os::elapsedTime() * 1000.0; - _g1h->g1_policy()->record_gc_worker_start_time(worker_id, start_time_ms); + _g1h->g1_policy()->phase_times()->record_gc_worker_start_time(worker_id, start_time_ms); { ResourceMark rm; @@ -4744,8 +4754,8 @@ public: evac.do_void(); double elapsed_ms = (os::elapsedTime()-start)*1000.0; double term_ms = pss.term_time()*1000.0; - _g1h->g1_policy()->record_obj_copy_time(worker_id, elapsed_ms-term_ms); - _g1h->g1_policy()->record_termination(worker_id, term_ms, pss.term_attempts()); + _g1h->g1_policy()->phase_times()->record_obj_copy_time(worker_id, elapsed_ms-term_ms); + _g1h->g1_policy()->phase_times()->record_termination(worker_id, term_ms, pss.term_attempts()); } _g1h->g1_policy()->record_thread_age_table(pss.age_table()); _g1h->update_surviving_young_words(pss.surviving_young_words()+1); @@ -4763,7 +4773,7 @@ public: } double end_time_ms = os::elapsedTime() * 1000.0; - _g1h->g1_policy()->record_gc_worker_end_time(worker_id, end_time_ms); + _g1h->g1_policy()->phase_times()->record_gc_worker_end_time(worker_id, end_time_ms); } }; @@ -4874,15 +4884,15 @@ g1_process_strong_roots(bool collecting_perm_gen, double ext_roots_end = os::elapsedTime(); - g1_policy()->reset_obj_copy_time(worker_i); + g1_policy()->phase_times()->reset_obj_copy_time(worker_i); double obj_copy_time_sec = buf_scan_perm.closure_app_seconds() + buf_scan_non_heap_roots.closure_app_seconds(); - g1_policy()->record_obj_copy_time(worker_i, obj_copy_time_sec * 1000.0); + g1_policy()->phase_times()->record_obj_copy_time(worker_i, obj_copy_time_sec * 1000.0); double ext_root_time_ms = ((ext_roots_end - ext_roots_start) - obj_copy_time_sec) * 1000.0; - g1_policy()->record_ext_root_scan_time(worker_i, ext_root_time_ms); + g1_policy()->phase_times()->record_ext_root_scan_time(worker_i, ext_root_time_ms); // During conc marking we have to filter the per-thread SATB buffers // to make sure we remove any oops into the CSet (which will show up @@ -4893,7 +4903,7 @@ g1_process_strong_roots(bool collecting_perm_gen, } } double satb_filtering_ms = (os::elapsedTime() - ext_roots_end) * 1000.0; - g1_policy()->record_satb_filtering_time(worker_i, satb_filtering_ms); + g1_policy()->phase_times()->record_satb_filtering_time(worker_i, satb_filtering_ms); // Now scan the complement of the collection set. if (scan_rs != NULL) { @@ -5393,7 +5403,7 @@ void G1CollectedHeap::process_discovered_references() { assert(pss.refs()->is_empty(), "both queue and overflow should be empty"); double ref_proc_time = os::elapsedTime() - ref_proc_start; - g1_policy()->record_ref_proc_time(ref_proc_time * 1000.0); + g1_policy()->phase_times()->record_ref_proc_time(ref_proc_time * 1000.0); } // Weak Reference processing during an evacuation pause (part 2). @@ -5430,7 +5440,7 @@ void G1CollectedHeap::enqueue_discovered_references() { // and could signicantly increase the pause time. double ref_enq_time = os::elapsedTime() - ref_enq_start; - g1_policy()->record_ref_enq_time(ref_enq_time * 1000.0); + g1_policy()->phase_times()->record_ref_enq_time(ref_enq_time * 1000.0); } void G1CollectedHeap::evacuate_collection_set() { @@ -5493,11 +5503,11 @@ void G1CollectedHeap::evacuate_collection_set() { } double par_time_ms = (end_par_time_sec - start_par_time_sec) * 1000.0; - g1_policy()->record_par_time(par_time_ms); + g1_policy()->phase_times()->record_par_time(par_time_ms); double code_root_fixup_time_ms = (os::elapsedTime() - end_par_time_sec) * 1000.0; - g1_policy()->record_code_root_fixup_time(code_root_fixup_time_ms); + g1_policy()->phase_times()->record_code_root_fixup_time(code_root_fixup_time_ms); set_par_threads(0); @@ -5759,7 +5769,7 @@ void G1CollectedHeap::cleanUpCardTable() { } double elapsed = os::elapsedTime() - start; - g1_policy()->record_clear_ct_time(elapsed * 1000.0); + g1_policy()->phase_times()->record_clear_ct_time(elapsed * 1000.0); } void G1CollectedHeap::free_collection_set(HeapRegion* cs_head) { @@ -5868,8 +5878,8 @@ void G1CollectedHeap::free_collection_set(HeapRegion* cs_head) { NULL /* old_proxy_set */, NULL /* humongous_proxy_set */, false /* par */); - policy->record_young_free_cset_time_ms(young_time_ms); - policy->record_non_young_free_cset_time_ms(non_young_time_ms); + policy->phase_times()->record_young_free_cset_time_ms(young_time_ms); + policy->phase_times()->record_non_young_free_cset_time_ms(non_young_time_ms); } // This routine is similar to the above but does not record diff --git a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp index b91d04a09152191a38c61252f546bbddd7806c93..f07b14824d0c439d7b21ecdac2ea9e85cf72d5e5 100644 --- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp +++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp @@ -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 @@ 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 }; -// 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 @@ G1CollectorPolicy::G1CollectorPolicy() : _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 @@ G1CollectorPolicy::G1CollectorPolicy() : _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 @@ G1CollectorPolicy::verify_young_ages(HeapRegion* head, #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 @@ void G1CollectorPolicy::record_full_collection_end() { // 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_stop_world_start() { 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 @@ void G1CollectorPolicy::record_collection_pause_start(double start_time_sec, _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 @@ void G1CollectorPolicy::record_collection_pause_start(double start_time_sec, _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() { } } -void G1CollectorPolicy::record_concurrent_pause_end() { -} - -template -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 @@ bool G1CollectorPolicy::need_to_start_conc_mark(const char* source, size_t alloc // 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 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) { 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 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) { 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 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) { (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 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) { 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 @@ 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_im = false; 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 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 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) { 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 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) { 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 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) { 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 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) { } 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 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) { // 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 @@ void G1CollectorPolicy::finalize_cset(double target_pause_time_ms) { 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 @@ void G1CollectorPolicy::finalize_cset(double target_pause_time_ms) { 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_yield_time(double yield_time_ms) { } } -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::increment_mixed_collection_count() { } } -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 @@ void TraceGen0TimeData::print() const { } 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 @@ void TraceGen0TimeData::print() const { 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) { diff --git a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp index 1d2cc9f189c6077018a3b0abcd25073b75eabaca..3fa36acc3a39021e92b20580a7e9a61ada6fbc23 100644 --- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp +++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.hpp @@ -36,6 +36,7 @@ class HeapRegion; class CollectionSetChooser; +class G1GCPhaseTimes; // TraceGen0Time collects data on _both_ young and mixed evacuation pauses // (the latter may contain non-young regions - i.e. regions that are @@ -61,26 +62,14 @@ class TraceGen0TimeData : public CHeapObj { NumberSeq _parallel_other; NumberSeq _clear_ct; - void print_summary (int level, const char* str, const NumberSeq* seq) const; - void print_summary_sd (int level, const char* str, const NumberSeq* seq) const; + void print_summary(const char* str, const NumberSeq* seq) const; + void print_summary_sd(const char* str, const NumberSeq* seq) const; public: TraceGen0TimeData() : _young_pause_num(0), _mixed_pause_num(0) {}; void record_start_collection(double time_to_stop_the_world_ms); void record_yield_time(double yield_time_ms); - void record_end_collection( - double total_ms, - double other_ms, - double root_region_scan_wait_ms, - double parallel_ms, - double ext_root_scan_ms, - double satb_filtering_ms, - double update_rs_ms, - double scan_rs_ms, - double obj_copy_ms, - double termination_ms, - double parallel_other_ms, - double clear_ct_ms); + void record_end_collection(double pause_time_ms, G1GCPhaseTimes* phase_times); void increment_young_collection_count(); void increment_mixed_collection_count(); void print() const; @@ -186,25 +175,9 @@ private: CollectionSetChooser* _collectionSetChooser; - double _cur_collection_start_sec; + double _full_collection_start_sec; size_t _cur_collection_pause_used_at_start_bytes; uint _cur_collection_pause_used_regions_at_start; - double _cur_collection_par_time_ms; - - double _cur_collection_code_root_fixup_time_ms; - - double _cur_clear_ct_time_ms; - double _cur_ref_proc_time_ms; - double _cur_ref_enq_time_ms; - -#ifndef PRODUCT - // Card Table Count Cache stats - double _min_clear_cc_time_ms; // min - double _max_clear_cc_time_ms; // max - double _cur_clear_cc_time_ms; // clearing time during current pause - double _cum_clear_cc_time_ms; // cummulative clearing time - jlong _num_cc_clears; // number of times the card count cache has been cleared -#endif // These exclude marking times. TruncatedSeq* _recent_gc_times_ms; @@ -217,23 +190,6 @@ private: double _stop_world_start; - double* _par_last_gc_worker_start_times_ms; - double* _par_last_ext_root_scan_times_ms; - double* _par_last_satb_filtering_times_ms; - double* _par_last_update_rs_times_ms; - double* _par_last_update_rs_processed_buffers; - double* _par_last_scan_rs_times_ms; - double* _par_last_obj_copy_times_ms; - double* _par_last_termination_times_ms; - double* _par_last_termination_attempts; - double* _par_last_gc_worker_end_times_ms; - double* _par_last_gc_worker_times_ms; - - // Each workers 'other' time i.e. the elapsed time of the parallel - // code executed by a worker minus the sum of the individual sub-phase - // times for that worker thread. - double* _par_last_gc_worker_other_times_ms; - // indicates whether we are in young or mixed GC mode bool _gcs_are_young; @@ -306,10 +262,6 @@ private: size_t _recorded_rs_lengths; size_t _max_rs_lengths; - - double _recorded_young_free_cset_time_ms; - double _recorded_non_young_free_cset_time_ms; - double _sigma; size_t _rs_lengths_prediction; @@ -341,8 +293,7 @@ private: void set_no_of_gc_threads(uintx v) { _no_of_gc_threads = v; } double _pause_time_target_ms; - double _recorded_young_cset_choice_time_ms; - double _recorded_non_young_cset_choice_time_ms; + size_t _pending_cards; size_t _max_pending_cards; @@ -497,14 +448,6 @@ public: uint young_cset_region_length() { return eden_cset_region_length() + survivor_cset_region_length(); } - void record_young_free_cset_time_ms(double time_ms) { - _recorded_young_free_cset_time_ms = time_ms; - } - - void record_non_young_free_cset_time_ms(double time_ms) { - _recorded_non_young_free_cset_time_ms = time_ms; - } - double predict_survivor_regions_evac_time(); void cset_regions_freed() { @@ -552,19 +495,6 @@ public: } private: - void print_stats(int level, const char* str, double value); - void print_stats(int level, const char* str, double value, int workers); - void print_stats(int level, const char* str, int value); - - void print_par_stats(int level, const char* str, double* data, bool showDecimals = true); - - double avg_value (double* data); - double max_value (double* data); - double sum_of_values (double* data); - double max_sum (double* data1, double* data2); - - double _last_pause_time_ms; - size_t _bytes_in_collection_set_before_gc; size_t _bytes_copied_during_gc; @@ -638,6 +568,8 @@ private: // Stash a pointer to the g1 heap. G1CollectedHeap* _g1; + G1GCPhaseTimes* _phase_times; + // The ratio of gc time to elapsed time, computed over recent pauses. double _recent_avg_pause_time_ratio; @@ -677,7 +609,6 @@ private: double _cur_mark_stop_world_time_ms; double _mark_remark_start_sec; double _mark_cleanup_start_sec; - double _root_region_scan_wait_time_ms; // Update the young list target length either by setting it to the // desired fixed value or by calculating it using G1's pause @@ -728,6 +659,8 @@ public: return CollectorPolicy::G1CollectorPolicyKind; } + G1GCPhaseTimes* phase_times() const { return _phase_times; } + // Check the current value of the young list RSet lengths and // compare it against the last prediction. If the current value is // higher, recalculate the young list target length prediction. @@ -772,10 +705,6 @@ public: void record_concurrent_mark_init_end(double mark_init_elapsed_time_ms); - void record_root_region_scan_wait_time(double time_ms) { - _root_region_scan_wait_time_ms = time_ms; - } - void record_concurrent_mark_remark_start(); void record_concurrent_mark_remark_end(); @@ -784,97 +713,14 @@ public: void record_concurrent_mark_cleanup_completed(); void record_concurrent_pause(); - void record_concurrent_pause_end(); - void record_collection_pause_end(int no_of_gc_threads); + void record_collection_pause_end(double pause_time); void print_heap_transition(); // Record the fact that a full collection occurred. void record_full_collection_start(); void record_full_collection_end(); - void record_gc_worker_start_time(int worker_i, double ms) { - _par_last_gc_worker_start_times_ms[worker_i] = ms; - } - - void record_ext_root_scan_time(int worker_i, double ms) { - _par_last_ext_root_scan_times_ms[worker_i] = ms; - } - - void record_satb_filtering_time(int worker_i, double ms) { - _par_last_satb_filtering_times_ms[worker_i] = ms; - } - - void record_update_rs_time(int thread, double ms) { - _par_last_update_rs_times_ms[thread] = ms; - } - - void record_update_rs_processed_buffers (int thread, - double processed_buffers) { - _par_last_update_rs_processed_buffers[thread] = processed_buffers; - } - - void record_scan_rs_time(int thread, double ms) { - _par_last_scan_rs_times_ms[thread] = ms; - } - - void reset_obj_copy_time(int thread) { - _par_last_obj_copy_times_ms[thread] = 0.0; - } - - void reset_obj_copy_time() { - reset_obj_copy_time(0); - } - - void record_obj_copy_time(int thread, double ms) { - _par_last_obj_copy_times_ms[thread] += ms; - } - - void record_termination(int thread, double ms, size_t attempts) { - _par_last_termination_times_ms[thread] = ms; - _par_last_termination_attempts[thread] = (double) attempts; - } - - void record_gc_worker_end_time(int worker_i, double ms) { - _par_last_gc_worker_end_times_ms[worker_i] = ms; - } - - void record_pause_time_ms(double ms) { - _last_pause_time_ms = ms; - } - - void record_clear_ct_time(double ms) { - _cur_clear_ct_time_ms = ms; - } - - void record_par_time(double ms) { - _cur_collection_par_time_ms = ms; - } - - void record_code_root_fixup_time(double ms) { - _cur_collection_code_root_fixup_time_ms = ms; - } - - void record_ref_proc_time(double ms) { - _cur_ref_proc_time_ms = ms; - } - - void record_ref_enq_time(double ms) { - _cur_ref_enq_time_ms = ms; - } - -#ifndef PRODUCT - void record_cc_clear_time(double ms) { - if (_min_clear_cc_time_ms < 0.0 || ms <= _min_clear_cc_time_ms) - _min_clear_cc_time_ms = ms; - if (_max_clear_cc_time_ms < 0.0 || ms >= _max_clear_cc_time_ms) - _max_clear_cc_time_ms = ms; - _cur_clear_cc_time_ms = ms; - _cum_clear_cc_time_ms += ms; - _num_cc_clears++; - } -#endif - // Record how much space we copied during a GC. This is typically // called when a GC alloc region is being retired. void record_bytes_copied_during_gc(size_t bytes) { diff --git a/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp b/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp new file mode 100644 index 0000000000000000000000000000000000000000..8bb9e552492fd9d024dc6bbddb7406bdf8bb1864 --- /dev/null +++ b/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp @@ -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++; +} diff --git a/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp b/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp new file mode 100644 index 0000000000000000000000000000000000000000..d9eaf37261bddf2997a77b98be596a5d31a98672 --- /dev/null +++ b/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp @@ -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 { + 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 diff --git a/src/share/vm/gc_implementation/g1/g1RemSet.cpp b/src/share/vm/gc_implementation/g1/g1RemSet.cpp index b2bcbae937f0cf0f6858e62b7ac876b42cac9868..c3af182b251f0d9cedbdaf44271f127778c8c030 100644 --- a/src/share/vm/gc_implementation/g1/g1RemSet.cpp +++ b/src/share/vm/gc_implementation/g1/g1RemSet.cpp @@ -29,6 +29,7 @@ #include "gc_implementation/g1/g1BlockOffsetTable.inline.hpp" #include "gc_implementation/g1/g1CollectedHeap.inline.hpp" #include "gc_implementation/g1/g1CollectorPolicy.hpp" +#include "gc_implementation/g1/g1GCPhaseTimes.hpp" #include "gc_implementation/g1/g1OopClosures.inline.hpp" #include "gc_implementation/g1/g1RemSet.inline.hpp" #include "gc_implementation/g1/heapRegionSeq.inline.hpp" @@ -224,7 +225,7 @@ void G1RemSet::scanRS(OopsInHeapRegionClosure* oc, int worker_i) { assert( _cards_scanned != NULL, "invariant" ); _cards_scanned[worker_i] = scanRScl.cards_done(); - _g1p->record_scan_rs_time(worker_i, scan_rs_time_sec * 1000.0); + _g1p->phase_times()->record_scan_rs_time(worker_i, scan_rs_time_sec * 1000.0); } // Closure used for updating RSets and recording references that @@ -276,7 +277,7 @@ void G1RemSet::updateRS(DirtyCardQueue* into_cset_dcq, int worker_i) { guarantee(cl.n() == 0, "Card table should be clean."); } - _g1p->record_update_rs_time(worker_i, (os::elapsedTime() - start) * 1000.0); + _g1p->phase_times()->record_update_rs_time(worker_i, (os::elapsedTime() - start) * 1000.0); } class CountRSSizeClosure: public HeapRegionClosure { @@ -390,13 +391,13 @@ void G1RemSet::oops_into_collection_set_do(OopsInHeapRegionClosure* oc, if (G1UseParallelRSetUpdating || (worker_i == 0)) { updateRS(&into_cset_dcq, worker_i); } else { - _g1p->record_update_rs_processed_buffers(worker_i, 0.0); - _g1p->record_update_rs_time(worker_i, 0.0); + _g1p->phase_times()->record_update_rs_processed_buffers(worker_i, 0.0); + _g1p->phase_times()->record_update_rs_time(worker_i, 0.0); } if (G1UseParallelRSetScanning || (worker_i == 0)) { scanRS(oc, worker_i); } else { - _g1p->record_scan_rs_time(worker_i, 0.0); + _g1p->phase_times()->record_scan_rs_time(worker_i, 0.0); } // We now clear the cached values of _cset_rs_update_cl for this worker