提交 880ae9c1 编写于 作者: T tonyp

6946048: G1: improvements to +PrintGCDetails output

Summary: Small improvements to G1's PrintGCDetails output. It also includes minor formatting details.
Reviewed-by: ysr, johnc
上级 7a0c8373
...@@ -3972,6 +3972,10 @@ public: ...@@ -3972,6 +3972,10 @@ public:
void work(int i) { void work(int i) {
if (i >= _n_workers) return; // no work needed this round if (i >= _n_workers) return; // no work needed this round
double start_time_ms = os::elapsedTime() * 1000.0;
_g1h->g1_policy()->record_gc_worker_start_time(i, start_time_ms);
ResourceMark rm; ResourceMark rm;
HandleMark hm; HandleMark hm;
...@@ -4019,7 +4023,7 @@ public: ...@@ -4019,7 +4023,7 @@ public:
double elapsed_ms = (os::elapsedTime()-start)*1000.0; double elapsed_ms = (os::elapsedTime()-start)*1000.0;
double term_ms = pss.term_time()*1000.0; double term_ms = pss.term_time()*1000.0;
_g1h->g1_policy()->record_obj_copy_time(i, elapsed_ms-term_ms); _g1h->g1_policy()->record_obj_copy_time(i, elapsed_ms-term_ms);
_g1h->g1_policy()->record_termination_time(i, term_ms); _g1h->g1_policy()->record_termination(i, term_ms, pss.term_attempts());
} }
_g1h->g1_policy()->record_thread_age_table(pss.age_table()); _g1h->g1_policy()->record_thread_age_table(pss.age_table());
_g1h->update_surviving_young_words(pss.surviving_young_words()+1); _g1h->update_surviving_young_words(pss.surviving_young_words()+1);
...@@ -4043,7 +4047,8 @@ public: ...@@ -4043,7 +4047,8 @@ public:
double term = pss.term_time(); double term = pss.term_time();
gclog_or_tty->print(" Elapsed: %7.2f ms.\n" gclog_or_tty->print(" Elapsed: %7.2f ms.\n"
" Strong roots: %7.2f ms (%6.2f%%)\n" " Strong roots: %7.2f ms (%6.2f%%)\n"
" Termination: %7.2f ms (%6.2f%%) (in %d entries)\n", " Termination: %7.2f ms (%6.2f%%) "
"(in "SIZE_FORMAT" entries)\n",
elapsed * 1000.0, elapsed * 1000.0,
strong_roots * 1000.0, (strong_roots*100.0/elapsed), strong_roots * 1000.0, (strong_roots*100.0/elapsed),
term * 1000.0, (term*100.0/elapsed), term * 1000.0, (term*100.0/elapsed),
...@@ -4059,6 +4064,8 @@ public: ...@@ -4059,6 +4064,8 @@ public:
assert(pss.refs_to_scan() == 0, "Task queue should be empty"); assert(pss.refs_to_scan() == 0, "Task queue should be empty");
assert(pss.overflowed_refs_to_scan() == 0, "Overflow queue should be empty"); assert(pss.overflowed_refs_to_scan() == 0, "Overflow queue should be empty");
double end_time_ms = os::elapsedTime() * 1000.0;
_g1h->g1_policy()->record_gc_worker_end_time(i, end_time_ms);
} }
}; };
......
...@@ -1549,7 +1549,7 @@ protected: ...@@ -1549,7 +1549,7 @@ protected:
int _hash_seed; int _hash_seed;
int _queue_num; int _queue_num;
int _term_attempts; size_t _term_attempts;
#if G1_DETAILED_STATS #if G1_DETAILED_STATS
int _pushes, _pops, _steals, _steal_attempts; int _pushes, _pops, _steals, _steal_attempts;
int _overflow_pushes; int _overflow_pushes;
...@@ -1727,7 +1727,7 @@ public: ...@@ -1727,7 +1727,7 @@ public:
int* hash_seed() { return &_hash_seed; } int* hash_seed() { return &_hash_seed; }
int queue_num() { return _queue_num; } int queue_num() { return _queue_num; }
int term_attempts() { return _term_attempts; } size_t term_attempts() { return _term_attempts; }
void note_term_attempt() { _term_attempts++; } void note_term_attempt() { _term_attempts++; }
#if G1_DETAILED_STATS #if G1_DETAILED_STATS
......
...@@ -231,20 +231,21 @@ G1CollectorPolicy::G1CollectorPolicy() : ...@@ -231,20 +231,21 @@ G1CollectorPolicy::G1CollectorPolicy() :
_recent_prev_end_times_for_all_gcs_sec->add(os::elapsedTime()); _recent_prev_end_times_for_all_gcs_sec->add(os::elapsedTime());
_prev_collection_pause_end_ms = os::elapsedTime() * 1000.0; _prev_collection_pause_end_ms = os::elapsedTime() * 1000.0;
_par_last_gc_worker_start_times_ms = new double[_parallel_gc_threads];
_par_last_ext_root_scan_times_ms = new double[_parallel_gc_threads]; _par_last_ext_root_scan_times_ms = new double[_parallel_gc_threads];
_par_last_mark_stack_scan_times_ms = new double[_parallel_gc_threads]; _par_last_mark_stack_scan_times_ms = new double[_parallel_gc_threads];
_par_last_update_rs_start_times_ms = new double[_parallel_gc_threads];
_par_last_update_rs_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_update_rs_processed_buffers = new double[_parallel_gc_threads];
_par_last_scan_rs_start_times_ms = new double[_parallel_gc_threads];
_par_last_scan_rs_times_ms = new double[_parallel_gc_threads]; _par_last_scan_rs_times_ms = new double[_parallel_gc_threads];
_par_last_scan_new_refs_times_ms = new double[_parallel_gc_threads]; _par_last_scan_new_refs_times_ms = new double[_parallel_gc_threads];
_par_last_obj_copy_times_ms = new double[_parallel_gc_threads]; _par_last_obj_copy_times_ms = new double[_parallel_gc_threads];
_par_last_termination_times_ms = new double[_parallel_gc_threads]; _par_last_termination_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];
// start conservatively // start conservatively
_expensive_region_limit_ms = 0.5 * (double) MaxGCPauseMillis; _expensive_region_limit_ms = 0.5 * (double) MaxGCPauseMillis;
...@@ -836,16 +837,17 @@ void G1CollectorPolicy::record_collection_pause_start(double start_time_sec, ...@@ -836,16 +837,17 @@ void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
// if they are not set properly // if they are not set properly
for (int i = 0; i < _parallel_gc_threads; ++i) { for (int i = 0; i < _parallel_gc_threads; ++i) {
_par_last_ext_root_scan_times_ms[i] = -666.0; _par_last_gc_worker_start_times_ms[i] = -1234.0;
_par_last_mark_stack_scan_times_ms[i] = -666.0; _par_last_ext_root_scan_times_ms[i] = -1234.0;
_par_last_update_rs_start_times_ms[i] = -666.0; _par_last_mark_stack_scan_times_ms[i] = -1234.0;
_par_last_update_rs_times_ms[i] = -666.0; _par_last_update_rs_times_ms[i] = -1234.0;
_par_last_update_rs_processed_buffers[i] = -666.0; _par_last_update_rs_processed_buffers[i] = -1234.0;
_par_last_scan_rs_start_times_ms[i] = -666.0; _par_last_scan_rs_times_ms[i] = -1234.0;
_par_last_scan_rs_times_ms[i] = -666.0; _par_last_scan_new_refs_times_ms[i] = -1234.0;
_par_last_scan_new_refs_times_ms[i] = -666.0; _par_last_obj_copy_times_ms[i] = -1234.0;
_par_last_obj_copy_times_ms[i] = -666.0; _par_last_termination_times_ms[i] = -1234.0;
_par_last_termination_times_ms[i] = -666.0; _par_last_termination_attempts[i] = -1234.0;
_par_last_gc_worker_end_times_ms[i] = -1234.0;
} }
#endif #endif
...@@ -996,7 +998,7 @@ T sum_of(T* sum_arr, int start, int n, int N) { ...@@ -996,7 +998,7 @@ T sum_of(T* sum_arr, int start, int n, int N) {
return sum; return sum;
} }
void G1CollectorPolicy::print_par_stats (int level, void G1CollectorPolicy::print_par_stats(int level,
const char* str, const char* str,
double* data, double* data,
bool summary) { bool summary) {
...@@ -1027,7 +1029,7 @@ void G1CollectorPolicy::print_par_stats (int level, ...@@ -1027,7 +1029,7 @@ void G1CollectorPolicy::print_par_stats (int level,
gclog_or_tty->print_cr("]"); gclog_or_tty->print_cr("]");
} }
void G1CollectorPolicy::print_par_buffers (int level, void G1CollectorPolicy::print_par_sizes(int level,
const char* str, const char* str,
double* data, double* data,
bool summary) { bool summary) {
...@@ -1375,15 +1377,22 @@ void G1CollectorPolicy::record_collection_pause_end(bool abandoned) { ...@@ -1375,15 +1377,22 @@ void G1CollectorPolicy::record_collection_pause_end(bool abandoned) {
} }
if (parallel) { if (parallel) {
print_stats(1, "Parallel Time", _cur_collection_par_time_ms); print_stats(1, "Parallel Time", _cur_collection_par_time_ms);
print_par_stats(2, "Update RS (Start)", _par_last_update_rs_start_times_ms, false); print_par_stats(2, "GC Worker Start Time",
_par_last_gc_worker_start_times_ms, false);
print_par_stats(2, "Update RS", _par_last_update_rs_times_ms); print_par_stats(2, "Update RS", _par_last_update_rs_times_ms);
print_par_buffers(3, "Processed Buffers", print_par_sizes(3, "Processed Buffers",
_par_last_update_rs_processed_buffers, true); _par_last_update_rs_processed_buffers, true);
print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms); print_par_stats(2, "Ext Root Scanning",
print_par_stats(2, "Mark Stack Scanning", _par_last_mark_stack_scan_times_ms); _par_last_ext_root_scan_times_ms);
print_par_stats(2, "Mark Stack Scanning",
_par_last_mark_stack_scan_times_ms);
print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms); 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, "Object Copy", _par_last_obj_copy_times_ms);
print_par_stats(2, "Termination", _par_last_termination_times_ms); print_par_stats(2, "Termination", _par_last_termination_times_ms);
print_par_sizes(3, "Termination Attempts",
_par_last_termination_attempts, true);
print_par_stats(2, "GC Worker End Time",
_par_last_gc_worker_end_times_ms, false);
print_stats(2, "Other", parallel_other_time); print_stats(2, "Other", parallel_other_time);
print_stats(1, "Clear CT", _cur_clear_ct_time_ms); print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
} else { } else {
......
...@@ -171,16 +171,17 @@ protected: ...@@ -171,16 +171,17 @@ protected:
double* _cur_aux_times_ms; double* _cur_aux_times_ms;
bool* _cur_aux_times_set; bool* _cur_aux_times_set;
double* _par_last_gc_worker_start_times_ms;
double* _par_last_ext_root_scan_times_ms; double* _par_last_ext_root_scan_times_ms;
double* _par_last_mark_stack_scan_times_ms; double* _par_last_mark_stack_scan_times_ms;
double* _par_last_update_rs_start_times_ms;
double* _par_last_update_rs_times_ms; double* _par_last_update_rs_times_ms;
double* _par_last_update_rs_processed_buffers; double* _par_last_update_rs_processed_buffers;
double* _par_last_scan_rs_start_times_ms;
double* _par_last_scan_rs_times_ms; double* _par_last_scan_rs_times_ms;
double* _par_last_scan_new_refs_times_ms; double* _par_last_scan_new_refs_times_ms;
double* _par_last_obj_copy_times_ms; double* _par_last_obj_copy_times_ms;
double* _par_last_termination_times_ms; double* _par_last_termination_times_ms;
double* _par_last_termination_attempts;
double* _par_last_gc_worker_end_times_ms;
// indicates that we are in young GC mode // indicates that we are in young GC mode
bool _in_young_gc_mode; bool _in_young_gc_mode;
...@@ -559,13 +560,14 @@ public: ...@@ -559,13 +560,14 @@ public:
} }
protected: protected:
void print_stats (int level, const char* str, double value); void print_stats(int level, const char* str, double value);
void print_stats (int level, const char* str, int value); void print_stats(int level, const char* str, int value);
void print_par_stats (int level, const char* str, double* data) {
void print_par_stats(int level, const char* str, double* data) {
print_par_stats(level, str, data, true); print_par_stats(level, str, data, true);
} }
void print_par_stats (int level, const char* str, double* data, bool summary); void print_par_stats(int level, const char* str, double* data, bool summary);
void print_par_buffers (int level, const char* str, double* data, bool summary); void print_par_sizes(int level, const char* str, double* data, bool summary);
void check_other_times(int level, void check_other_times(int level,
NumberSeq* other_times_ms, NumberSeq* other_times_ms,
...@@ -891,6 +893,10 @@ public: ...@@ -891,6 +893,10 @@ public:
virtual void record_full_collection_start(); virtual void record_full_collection_start();
virtual void record_full_collection_end(); virtual 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) { void record_ext_root_scan_time(int worker_i, double ms) {
_par_last_ext_root_scan_times_ms[worker_i] = ms; _par_last_ext_root_scan_times_ms[worker_i] = ms;
} }
...@@ -912,10 +918,6 @@ public: ...@@ -912,10 +918,6 @@ public:
_all_mod_union_times_ms->add(ms); _all_mod_union_times_ms->add(ms);
} }
void record_update_rs_start_time(int thread, double ms) {
_par_last_update_rs_start_times_ms[thread] = ms;
}
void record_update_rs_time(int thread, double ms) { void record_update_rs_time(int thread, double ms) {
_par_last_update_rs_times_ms[thread] = ms; _par_last_update_rs_times_ms[thread] = ms;
} }
...@@ -925,10 +927,6 @@ public: ...@@ -925,10 +927,6 @@ public:
_par_last_update_rs_processed_buffers[thread] = processed_buffers; _par_last_update_rs_processed_buffers[thread] = processed_buffers;
} }
void record_scan_rs_start_time(int thread, double ms) {
_par_last_scan_rs_start_times_ms[thread] = ms;
}
void record_scan_rs_time(int thread, double ms) { void record_scan_rs_time(int thread, double ms) {
_par_last_scan_rs_times_ms[thread] = ms; _par_last_scan_rs_times_ms[thread] = ms;
} }
...@@ -953,16 +951,13 @@ public: ...@@ -953,16 +951,13 @@ public:
_par_last_obj_copy_times_ms[thread] += ms; _par_last_obj_copy_times_ms[thread] += ms;
} }
void record_obj_copy_time(double ms) { void record_termination(int thread, double ms, size_t attempts) {
record_obj_copy_time(0, ms);
}
void record_termination_time(int thread, double ms) {
_par_last_termination_times_ms[thread] = ms; _par_last_termination_times_ms[thread] = ms;
_par_last_termination_attempts[thread] = (double) attempts;
} }
void record_termination_time(double ms) { void record_gc_worker_end_time(int worker_i, double ms) {
record_termination_time(0, ms); _par_last_gc_worker_end_times_ms[worker_i] = ms;
} }
void record_pause_time_ms(double ms) { void record_pause_time_ms(double ms) {
......
...@@ -303,7 +303,6 @@ void HRInto_G1RemSet::scanRS(OopsInHeapRegionClosure* oc, int worker_i) { ...@@ -303,7 +303,6 @@ void HRInto_G1RemSet::scanRS(OopsInHeapRegionClosure* oc, int worker_i) {
assert( _cards_scanned != NULL, "invariant" ); assert( _cards_scanned != NULL, "invariant" );
_cards_scanned[worker_i] = scanRScl.cards_done(); _cards_scanned[worker_i] = scanRScl.cards_done();
_g1p->record_scan_rs_start_time(worker_i, rs_time_start * 1000.0);
_g1p->record_scan_rs_time(worker_i, scan_rs_time_sec * 1000.0); _g1p->record_scan_rs_time(worker_i, scan_rs_time_sec * 1000.0);
} }
...@@ -311,8 +310,6 @@ void HRInto_G1RemSet::updateRS(int worker_i) { ...@@ -311,8 +310,6 @@ void HRInto_G1RemSet::updateRS(int worker_i) {
ConcurrentG1Refine* cg1r = _g1->concurrent_g1_refine(); ConcurrentG1Refine* cg1r = _g1->concurrent_g1_refine();
double start = os::elapsedTime(); double start = os::elapsedTime();
_g1p->record_update_rs_start_time(worker_i, start * 1000.0);
// Apply the appropriate closure to all remaining log entries. // Apply the appropriate closure to all remaining log entries.
_g1->iterate_dirty_card_closure(false, worker_i); _g1->iterate_dirty_card_closure(false, worker_i);
// Now there should be no dirty cards. // Now there should be no dirty cards.
...@@ -471,7 +468,6 @@ HRInto_G1RemSet::oops_into_collection_set_do(OopsInHeapRegionClosure* oc, ...@@ -471,7 +468,6 @@ HRInto_G1RemSet::oops_into_collection_set_do(OopsInHeapRegionClosure* oc,
updateRS(worker_i); updateRS(worker_i);
scanNewRefsRS(oc, worker_i); scanNewRefsRS(oc, worker_i);
} else { } else {
_g1p->record_update_rs_start_time(worker_i, os::elapsedTime() * 1000.0);
_g1p->record_update_rs_processed_buffers(worker_i, 0.0); _g1p->record_update_rs_processed_buffers(worker_i, 0.0);
_g1p->record_update_rs_time(worker_i, 0.0); _g1p->record_update_rs_time(worker_i, 0.0);
_g1p->record_scan_new_refs_time(worker_i, 0.0); _g1p->record_scan_new_refs_time(worker_i, 0.0);
...@@ -479,7 +475,6 @@ HRInto_G1RemSet::oops_into_collection_set_do(OopsInHeapRegionClosure* oc, ...@@ -479,7 +475,6 @@ HRInto_G1RemSet::oops_into_collection_set_do(OopsInHeapRegionClosure* oc,
if (G1UseParallelRSetScanning || (worker_i == 0)) { if (G1UseParallelRSetScanning || (worker_i == 0)) {
scanRS(oc, worker_i); scanRS(oc, worker_i);
} else { } else {
_g1p->record_scan_rs_start_time(worker_i, os::elapsedTime() * 1000.0);
_g1p->record_scan_rs_time(worker_i, 0.0); _g1p->record_scan_rs_time(worker_i, 0.0);
} }
} else { } else {
......
Markdown is supported
0% .
You are about to add 0 people to the discussion. Proceed with caution.
先完成此消息的编辑!
想要评论请 注册