diff src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp @ 6109:bbc900c2482a

7172279: G1: Clean up TraceGen0Time and TraceGen1Time data gathering Summary: Simplify code, remove unused code, remove ExitAfterGCNum Reviewed-by: huntch, johnc
author brutisso
date Thu, 31 May 2012 21:10:33 +0200
parents 9d679effd28c
children 922993931b3d
line wrap: on
line diff
--- a/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp	Wed May 30 10:26:24 2012 -0700
+++ b/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp	Thu May 31 21:10:33 2012 +0200
@@ -133,12 +133,7 @@
                         ? ParallelGCThreads : 1),
 
   _recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
-  _all_pause_times_ms(new NumberSeq()),
   _stop_world_start(0.0),
-  _all_stop_world_times_ms(new NumberSeq()),
-  _all_yield_times_ms(new NumberSeq()),
-
-  _summary(new Summary()),
 
   _cur_clear_ct_time_ms(0.0),
   _root_region_scan_wait_time_ms(0.0),
@@ -154,12 +149,6 @@
   _num_cc_clears(0L),
 #endif
 
-  _aux_num(10),
-  _all_aux_times_ms(new NumberSeq[_aux_num]),
-  _cur_aux_start_times_ms(new double[_aux_num]),
-  _cur_aux_times_ms(new double[_aux_num]),
-  _cur_aux_times_set(new bool[_aux_num]),
-
   _concurrent_mark_remark_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
   _concurrent_mark_cleanup_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
 
@@ -185,8 +174,6 @@
   _pause_time_target_ms((double) MaxGCPauseMillis),
 
   _gcs_are_young(true),
-  _young_pause_num(0),
-  _mixed_pause_num(0),
 
   _during_marking(false),
   _in_marking_window(false),
@@ -197,8 +184,6 @@
 
   _recent_avg_pause_time_ratio(0.0),
 
-  _all_full_gc_times_ms(new NumberSeq()),
-
   _initiate_conc_mark_if_possible(false),
   _during_initial_mark_pause(false),
   _last_young_gc(false),
@@ -851,7 +836,7 @@
   double full_gc_time_sec = end_sec - _cur_collection_start_sec;
   double full_gc_time_ms = full_gc_time_sec * 1000.0;
 
-  _all_full_gc_times_ms->add(full_gc_time_ms);
+  _trace_gen1_time_data.record_full_collection(full_gc_time_ms);
 
   update_recent_gc_times(end_sec, full_gc_time_ms);
 
@@ -900,7 +885,7 @@
                  _g1->used(), _g1->recalculate_used()));
 
   double s_w_t_ms = (start_time_sec - _stop_world_start) * 1000.0;
-  _all_stop_world_times_ms->add(s_w_t_ms);
+  _trace_gen0_time_data.record_start_collection(s_w_t_ms);
   _stop_world_start = 0.0;
 
   _cur_collection_start_sec = start_time_sec;
@@ -937,11 +922,6 @@
   }
 #endif
 
-  for (int i = 0; i < _aux_num; ++i) {
-    _cur_aux_times_ms[i] = 0.0;
-    _cur_aux_times_set[i] = false;
-  }
-
   // 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;
@@ -990,7 +970,7 @@
 void G1CollectorPolicy::record_concurrent_pause() {
   if (_stop_world_start > 0.0) {
     double yield_ms = (os::elapsedTime() - _stop_world_start) * 1000.0;
-    _all_yield_times_ms->add(yield_ms);
+    _trace_gen0_time_data.record_yield_time(yield_ms);
   }
 }
 
@@ -1197,21 +1177,6 @@
   _mmu_tracker->add_pause(end_time_sec - elapsed_ms/1000.0,
                           end_time_sec, false);
 
-  // This assert is exempted when we're doing parallel collection pauses,
-  // because the fragmentation caused by the parallel GC allocation buffers
-  // can lead to more memory being used during collection than was used
-  // before. Best leave this out until the fragmentation problem is fixed.
-  // Pauses in which evacuation failed can also lead to negative
-  // collections, since no space is reclaimed from a region containing an
-  // object whose evacuation failed.
-  // Further, we're now always doing parallel collection.  But I'm still
-  // leaving this here as a placeholder for a more precise assertion later.
-  // (DLD, 10/05.)
-  assert((true || parallel) // Always using GC LABs now.
-         || _g1->evacuation_failed()
-         || _cur_collection_pause_used_at_start_bytes >= cur_used_bytes,
-         "Negative collection");
-
   size_t freed_bytes =
     _cur_collection_pause_used_at_start_bytes - cur_used_bytes;
   size_t surviving_bytes = _collection_set_bytes_used_before - freed_bytes;
@@ -1259,44 +1224,15 @@
   other_time_ms -= _cur_clear_ct_time_ms;
 
   // TraceGen0Time and TraceGen1Time summary info updating.
-  _all_pause_times_ms->add(elapsed_ms);
 
   if (update_stats) {
-    _summary->record_total_time_ms(elapsed_ms);
-    _summary->record_other_time_ms(other_time_ms);
-
-    MainBodySummary* body_summary = _summary->main_body_summary();
-    assert(body_summary != NULL, "should not be null!");
-
-    body_summary->record_root_region_scan_wait_time_ms(
-                                               _root_region_scan_wait_time_ms);
-    body_summary->record_ext_root_scan_time_ms(ext_root_scan_time);
-    body_summary->record_satb_filtering_time_ms(satb_filtering_time);
-    body_summary->record_update_rs_time_ms(update_rs_time);
-    body_summary->record_scan_rs_time_ms(scan_rs_time);
-    body_summary->record_obj_copy_time_ms(obj_copy_time);
-
-    if (parallel) {
-      body_summary->record_parallel_time_ms(_cur_collection_par_time_ms);
-      body_summary->record_termination_time_ms(termination_time);
+    double parallel_known_time = known_time + termination_time;
+    double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time;
 
-      double parallel_known_time = known_time + termination_time;
-      double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time;
-      body_summary->record_parallel_other_time_ms(parallel_other_time);
-    }
-
-    body_summary->record_clear_ct_time_ms(_cur_clear_ct_time_ms);
-
-    // We exempt parallel collection from this check because Alloc Buffer
-    // fragmentation can produce negative collections.  Same with evac
-    // failure.
-    // Further, we're now always doing parallel collection.  But I'm still
-    // leaving this here as a placeholder for a more precise assertion later.
-    // (DLD, 10/05.
-    assert((true || parallel)
-           || _g1->evacuation_failed()
-           || surviving_bytes <= _collection_set_bytes_used_before,
-           "Or else negative collection!");
+    _trace_gen0_time_data.record_end_collection(
+      elapsed_ms, other_time_ms, _root_region_scan_wait_time_ms, _cur_collection_par_time_ms,
+      ext_root_scan_time, satb_filtering_time, update_rs_time, scan_rs_time, obj_copy_time,
+      termination_time, parallel_other_time, _cur_clear_ct_time_ms);
 
     // this is where we update the allocation rate of the application
     double app_time_ms =
@@ -1349,12 +1285,6 @@
     }
   }
 
-  for (int i = 0; i < _aux_num; ++i) {
-    if (_cur_aux_times_set[i]) {
-      _all_aux_times_ms[i].add(_cur_aux_times_ms[i]);
-    }
-  }
-
   if (G1Log::finer()) {
     bool print_marking_info =
       _g1->mark_in_progress() && !last_pause_included_initial_mark;
@@ -1436,14 +1366,6 @@
     print_stats(2, "Free CSet",
                    (_recorded_young_free_cset_time_ms +
                     _recorded_non_young_free_cset_time_ms));
-
-    for (int i = 0; i < _aux_num; ++i) {
-      if (_cur_aux_times_set[i]) {
-        char buffer[96];
-        sprintf(buffer, "Aux%d", i);
-        print_stats(1, buffer, _cur_aux_times_ms[i]);
-      }
-    }
   }
 
   bool new_in_marking_window = _in_marking_window;
@@ -1808,179 +1730,9 @@
   _g1->collection_set_iterate(&cs_closure);
 }
 
-void G1CollectorPolicy::print_summary(int level,
-                                      const char* str,
-                                      NumberSeq* seq) const {
-  double sum = seq->sum();
-  LineBuffer(level + 1).append_and_print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)",
-                str, sum / 1000.0, seq->avg());
-}
-
-void G1CollectorPolicy::print_summary_sd(int level,
-                                         const char* str,
-                                         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());
-}
-
-void G1CollectorPolicy::check_other_times(int level,
-                                        NumberSeq* other_times_ms,
-                                        NumberSeq* calc_other_times_ms) const {
-  bool should_print = false;
-  LineBuffer buf(level + 2);
-
-  double max_sum = MAX2(fabs(other_times_ms->sum()),
-                        fabs(calc_other_times_ms->sum()));
-  double min_sum = MIN2(fabs(other_times_ms->sum()),
-                        fabs(calc_other_times_ms->sum()));
-  double sum_ratio = max_sum / min_sum;
-  if (sum_ratio > 1.1) {
-    should_print = true;
-    buf.append_and_print_cr("## CALCULATED OTHER SUM DOESN'T MATCH RECORDED ###");
-  }
-
-  double max_avg = MAX2(fabs(other_times_ms->avg()),
-                        fabs(calc_other_times_ms->avg()));
-  double min_avg = MIN2(fabs(other_times_ms->avg()),
-                        fabs(calc_other_times_ms->avg()));
-  double avg_ratio = max_avg / min_avg;
-  if (avg_ratio > 1.1) {
-    should_print = true;
-    buf.append_and_print_cr("## CALCULATED OTHER AVG DOESN'T MATCH RECORDED ###");
-  }
-
-  if (other_times_ms->sum() < -0.01) {
-    buf.append_and_print_cr("## RECORDED OTHER SUM IS NEGATIVE ###");
-  }
-
-  if (other_times_ms->avg() < -0.01) {
-    buf.append_and_print_cr("## RECORDED OTHER AVG IS NEGATIVE ###");
-  }
-
-  if (calc_other_times_ms->sum() < -0.01) {
-    should_print = true;
-    buf.append_and_print_cr("## CALCULATED OTHER SUM IS NEGATIVE ###");
-  }
-
-  if (calc_other_times_ms->avg() < -0.01) {
-    should_print = true;
-    buf.append_and_print_cr("## CALCULATED OTHER AVG IS NEGATIVE ###");
-  }
-
-  if (should_print)
-    print_summary(level, "Other(Calc)", calc_other_times_ms);
-}
-
-void G1CollectorPolicy::print_summary(PauseSummary* summary) const {
-  bool parallel = G1CollectedHeap::use_parallel_gc_threads();
-  MainBodySummary*    body_summary = summary->main_body_summary();
-  if (summary->get_total_seq()->num() > 0) {
-    print_summary_sd(0, "Evacuation Pauses", summary->get_total_seq());
-    if (body_summary != NULL) {
-      print_summary(1, "Root Region Scan Wait", body_summary->get_root_region_scan_wait_seq());
-      if (parallel) {
-        print_summary(1, "Parallel Time", body_summary->get_parallel_seq());
-        print_summary(2, "Ext Root Scanning", body_summary->get_ext_root_scan_seq());
-        print_summary(2, "SATB Filtering", body_summary->get_satb_filtering_seq());
-        print_summary(2, "Update RS", body_summary->get_update_rs_seq());
-        print_summary(2, "Scan RS", body_summary->get_scan_rs_seq());
-        print_summary(2, "Object Copy", body_summary->get_obj_copy_seq());
-        print_summary(2, "Termination", body_summary->get_termination_seq());
-        print_summary(2, "Parallel Other", body_summary->get_parallel_other_seq());
-        {
-          NumberSeq* other_parts[] = {
-            body_summary->get_ext_root_scan_seq(),
-            body_summary->get_satb_filtering_seq(),
-            body_summary->get_update_rs_seq(),
-            body_summary->get_scan_rs_seq(),
-            body_summary->get_obj_copy_seq(),
-            body_summary->get_termination_seq()
-          };
-          NumberSeq calc_other_times_ms(body_summary->get_parallel_seq(),
-                                        6, other_parts);
-          check_other_times(2, body_summary->get_parallel_other_seq(),
-                            &calc_other_times_ms);
-        }
-      } else {
-        print_summary(1, "Ext Root Scanning", body_summary->get_ext_root_scan_seq());
-        print_summary(1, "SATB Filtering", body_summary->get_satb_filtering_seq());
-        print_summary(1, "Update RS", body_summary->get_update_rs_seq());
-        print_summary(1, "Scan RS", body_summary->get_scan_rs_seq());
-        print_summary(1, "Object Copy", body_summary->get_obj_copy_seq());
-      }
-    }
-    print_summary(1, "Clear CT", body_summary->get_clear_ct_seq());
-    print_summary(1, "Other", summary->get_other_seq());
-    {
-      if (body_summary != NULL) {
-        NumberSeq calc_other_times_ms;
-        if (parallel) {
-          // parallel
-          NumberSeq* other_parts[] = {
-            body_summary->get_root_region_scan_wait_seq(),
-            body_summary->get_parallel_seq(),
-            body_summary->get_clear_ct_seq()
-          };
-          calc_other_times_ms = NumberSeq(summary->get_total_seq(),
-                                          3, other_parts);
-        } else {
-          // serial
-          NumberSeq* other_parts[] = {
-            body_summary->get_root_region_scan_wait_seq(),
-            body_summary->get_update_rs_seq(),
-            body_summary->get_ext_root_scan_seq(),
-            body_summary->get_satb_filtering_seq(),
-            body_summary->get_scan_rs_seq(),
-            body_summary->get_obj_copy_seq()
-          };
-          calc_other_times_ms = NumberSeq(summary->get_total_seq(),
-                                          6, other_parts);
-        }
-        check_other_times(1,  summary->get_other_seq(), &calc_other_times_ms);
-      }
-    }
-  } else {
-    LineBuffer(1).append_and_print_cr("none");
-  }
-  LineBuffer(0).append_and_print_cr("");
-}
-
 void G1CollectorPolicy::print_tracing_info() const {
-  if (TraceGen0Time) {
-    gclog_or_tty->print_cr("ALL PAUSES");
-    print_summary_sd(0, "Total", _all_pause_times_ms);
-    gclog_or_tty->print_cr("");
-    gclog_or_tty->print_cr("");
-    gclog_or_tty->print_cr("   Young GC Pauses: %8d", _young_pause_num);
-    gclog_or_tty->print_cr("   Mixed GC Pauses: %8d", _mixed_pause_num);
-    gclog_or_tty->print_cr("");
-
-    gclog_or_tty->print_cr("EVACUATION PAUSES");
-    print_summary(_summary);
-
-    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);
-    for (int i = 0; i < _aux_num; ++i) {
-      if (_all_aux_times_ms[i].num() > 0) {
-        char buffer[96];
-        sprintf(buffer, "Aux%d", i);
-        print_summary_sd(0, buffer, &_all_aux_times_ms[i]);
-      }
-    }
-  }
-  if (TraceGen1Time) {
-    if (_all_full_gc_times_ms->num() > 0) {
-      gclog_or_tty->print("\n%4d full_gcs: total time = %8.2f s",
-                 _all_full_gc_times_ms->num(),
-                 _all_full_gc_times_ms->sum() / 1000.0);
-      gclog_or_tty->print_cr(" (avg = %8.2fms).", _all_full_gc_times_ms->avg());
-      gclog_or_tty->print_cr("                     [std. dev = %8.2f ms, max = %8.2f ms]",
-                    _all_full_gc_times_ms->sd(),
-                    _all_full_gc_times_ms->maximum());
-    }
-  }
+  _trace_gen0_time_data.print();
+  _trace_gen1_time_data.print();
 }
 
 void G1CollectorPolicy::print_yg_surv_rate_info() const {
@@ -2531,9 +2283,9 @@
   _last_gc_was_young = gcs_are_young() ? true : false;
 
   if (_last_gc_was_young) {
-    ++_young_pause_num;
+    _trace_gen0_time_data.increment_young_collection_count();
   } else {
-    ++_mixed_pause_num;
+    _trace_gen0_time_data.increment_mixed_collection_count();
   }
 
   // The young list is laid with the survivor regions from the previous
@@ -2690,3 +2442,133 @@
   _recorded_non_young_cset_choice_time_ms =
     (non_young_end_time_sec - non_young_start_time_sec) * 1000.0;
 }
+
+void TraceGen0TimeData::record_start_collection(double time_to_stop_the_world_ms) {
+  if(TraceGen0Time) {
+    _all_stop_world_times_ms.add(time_to_stop_the_world_ms);
+  }
+}
+
+void TraceGen0TimeData::record_yield_time(double yield_time_ms) {
+  if(TraceGen0Time) {
+    _all_yield_times_ms.add(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)
+{
+  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);
+  }
+}
+
+void TraceGen0TimeData::increment_young_collection_count() {
+  if(TraceGen0Time) {
+    ++_young_pause_num;
+  }
+}
+
+void TraceGen0TimeData::increment_mixed_collection_count() {
+  if(TraceGen0Time) {
+    ++_mixed_pause_num;
+  }
+}
+
+void TraceGen0TimeData::print_summary(int level,
+                                      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)",
+                str, sum / 1000.0, seq->avg());
+}
+
+void TraceGen0TimeData::print_summary_sd(int level,
+                                         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());
+}
+
+void TraceGen0TimeData::print() const {
+  if (!TraceGen0Time) {
+    return;
+  }
+
+  gclog_or_tty->print_cr("ALL PAUSES");
+  print_summary_sd(0, "Total", &_total);
+  gclog_or_tty->print_cr("");
+  gclog_or_tty->print_cr("");
+  gclog_or_tty->print_cr("   Young GC Pauses: %8d", _young_pause_num);
+  gclog_or_tty->print_cr("   Mixed GC Pauses: %8d", _mixed_pause_num);
+  gclog_or_tty->print_cr("");
+
+  gclog_or_tty->print_cr("EVACUATION PAUSES");
+
+  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);
+  }
+  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);
+}
+
+void TraceGen1TimeData::record_full_collection(double full_gc_time_ms) {
+  if (TraceGen1Time) {
+    _all_full_gc_times.add(full_gc_time_ms);
+  }
+}
+
+void TraceGen1TimeData::print() const {
+  if (!TraceGen1Time) {
+    return;
+  }
+
+  if (_all_full_gc_times.num() > 0) {
+    gclog_or_tty->print("\n%4d full_gcs: total time = %8.2f s",
+      _all_full_gc_times.num(),
+      _all_full_gc_times.sum() / 1000.0);
+    gclog_or_tty->print_cr(" (avg = %8.2fms).", _all_full_gc_times.avg());
+    gclog_or_tty->print_cr("                     [std. dev = %8.2f ms, max = %8.2f ms]",
+      _all_full_gc_times.sd(),
+      _all_full_gc_times.maximum());
+  }
+}