src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp
Index Unified diffs Context diffs Sdiffs Patch New Old Previous File Next File hs-gc-remove-define_num_seq Sdiff src/share/vm/gc_implementation/g1

src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp

Print this page




 116     va_start(ap, format);
 117     vappend(format, ap);
 118     va_end(ap);
 119   }
 120 
 121   void append_and_print_cr(const char* format, ...) {
 122     va_list ap;
 123     va_start(ap, format);
 124     vappend(format, ap);
 125     va_end(ap);
 126     gclog_or_tty->print_cr("%s", _buffer);
 127     _cur = _indent_level * INDENT_CHARS;
 128   }
 129 };
 130 
 131 G1CollectorPolicy::G1CollectorPolicy() :
 132   _parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads()
 133                         ? ParallelGCThreads : 1),
 134 
 135   _recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
 136   _all_pause_times_ms(new NumberSeq()),
 137   _stop_world_start(0.0),
 138   _all_stop_world_times_ms(new NumberSeq()),
 139   _all_yield_times_ms(new NumberSeq()),
 140 
 141   _summary(new Summary()),
 142 
 143   _cur_clear_ct_time_ms(0.0),
 144   _root_region_scan_wait_time_ms(0.0),
 145 
 146   _cur_ref_proc_time_ms(0.0),
 147   _cur_ref_enq_time_ms(0.0),
 148 
 149 #ifndef PRODUCT
 150   _min_clear_cc_time_ms(-1.0),
 151   _max_clear_cc_time_ms(-1.0),
 152   _cur_clear_cc_time_ms(0.0),
 153   _cum_clear_cc_time_ms(0.0),
 154   _num_cc_clears(0L),
 155 #endif
 156 
 157   _aux_num(10),
 158   _all_aux_times_ms(new NumberSeq[_aux_num]),
 159   _cur_aux_start_times_ms(new double[_aux_num]),
 160   _cur_aux_times_ms(new double[_aux_num]),
 161   _cur_aux_times_set(new bool[_aux_num]),
 162 
 163   _concurrent_mark_remark_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
 164   _concurrent_mark_cleanup_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
 165 
 166   _alloc_rate_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
 167   _prev_collection_pause_end_ms(0.0),
 168   _pending_card_diff_seq(new TruncatedSeq(TruncatedSeqLength)),
 169   _rs_length_diff_seq(new TruncatedSeq(TruncatedSeqLength)),
 170   _cost_per_card_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
 171   _young_cards_per_entry_ratio_seq(new TruncatedSeq(TruncatedSeqLength)),
 172   _mixed_cards_per_entry_ratio_seq(new TruncatedSeq(TruncatedSeqLength)),
 173   _cost_per_entry_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
 174   _mixed_cost_per_entry_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
 175   _cost_per_byte_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
 176   _cost_per_byte_ms_during_cm_seq(new TruncatedSeq(TruncatedSeqLength)),
 177   _constant_other_time_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
 178   _young_other_cost_per_region_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
 179   _non_young_other_cost_per_region_ms_seq(
 180                                          new TruncatedSeq(TruncatedSeqLength)),
 181 
 182   _pending_cards_seq(new TruncatedSeq(TruncatedSeqLength)),
 183   _rs_lengths_seq(new TruncatedSeq(TruncatedSeqLength)),
 184 
 185   _pause_time_target_ms((double) MaxGCPauseMillis),
 186 
 187   _gcs_are_young(true),
 188   _young_pause_num(0),
 189   _mixed_pause_num(0),
 190 
 191   _during_marking(false),
 192   _in_marking_window(false),
 193   _in_marking_window_im(false),
 194 
 195   _recent_prev_end_times_for_all_gcs_sec(
 196                                 new TruncatedSeq(NumPrevPausesForHeuristics)),
 197 
 198   _recent_avg_pause_time_ratio(0.0),
 199 
 200   _all_full_gc_times_ms(new NumberSeq()),
 201 
 202   _initiate_conc_mark_if_possible(false),
 203   _during_initial_mark_pause(false),
 204   _last_young_gc(false),
 205   _last_gc_was_young(false),
 206 
 207   _eden_bytes_before_gc(0),
 208   _survivor_bytes_before_gc(0),
 209   _capacity_before_gc(0),
 210 
 211   _eden_cset_region_length(0),
 212   _survivor_cset_region_length(0),
 213   _old_cset_region_length(0),
 214 
 215   _collection_set(NULL),
 216   _collection_set_bytes_used_before(0),
 217 
 218   // Incremental CSet attributes
 219   _inc_cset_build_state(Inactive),
 220   _inc_cset_head(NULL),
 221   _inc_cset_tail(NULL),


 834     }
 835   }
 836 
 837   return ret;
 838 }
 839 #endif // PRODUCT
 840 
 841 void G1CollectorPolicy::record_full_collection_start() {
 842   _cur_collection_start_sec = os::elapsedTime();
 843   // Release the future to-space so that it is available for compaction into.
 844   _g1->set_full_collection();
 845 }
 846 
 847 void G1CollectorPolicy::record_full_collection_end() {
 848   // Consider this like a collection pause for the purposes of allocation
 849   // since last pause.
 850   double end_sec = os::elapsedTime();
 851   double full_gc_time_sec = end_sec - _cur_collection_start_sec;
 852   double full_gc_time_ms = full_gc_time_sec * 1000.0;
 853 
 854   _all_full_gc_times_ms->add(full_gc_time_ms);
 855 
 856   update_recent_gc_times(end_sec, full_gc_time_ms);
 857 
 858   _g1->clear_full_collection();
 859 
 860   // "Nuke" the heuristics that control the young/mixed GC
 861   // transitions and make sure we start with young GCs after the Full GC.
 862   set_gcs_are_young(true);
 863   _last_young_gc = false;
 864   clear_initiate_conc_mark_if_possible();
 865   clear_during_initial_mark_pause();
 866   _in_marking_window = false;
 867   _in_marking_window_im = false;
 868 
 869   _short_lived_surv_rate_group->start_adding_regions();
 870   // also call this on any additional surv rate groups
 871 
 872   record_survivor_regions(0, NULL, NULL);
 873 
 874   _free_regions_at_end_of_collection = _g1->free_regions();


 883 }
 884 
 885 void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
 886                                                       size_t start_used) {
 887   if (G1Log::finer()) {
 888     gclog_or_tty->stamp(PrintGCTimeStamps);
 889     gclog_or_tty->print("[%s", (const char*)GCCauseString("GC pause", _g1->gc_cause())
 890       .append(gcs_are_young() ? " (young)" : " (mixed)"));
 891   }
 892 
 893   // We only need to do this here as the policy will only be applied
 894   // to the GC we're about to start. so, no point is calculating this
 895   // every time we calculate / recalculate the target young length.
 896   update_survivors_policy();
 897 
 898   assert(_g1->used() == _g1->recalculate_used(),
 899          err_msg("sanity, used: "SIZE_FORMAT" recalculate_used: "SIZE_FORMAT,
 900                  _g1->used(), _g1->recalculate_used()));
 901 
 902   double s_w_t_ms = (start_time_sec - _stop_world_start) * 1000.0;
 903   _all_stop_world_times_ms->add(s_w_t_ms);
 904   _stop_world_start = 0.0;
 905 
 906   _cur_collection_start_sec = start_time_sec;
 907   _cur_collection_pause_used_at_start_bytes = start_used;
 908   _cur_collection_pause_used_regions_at_start = _g1->used_regions();
 909   _pending_cards = _g1->pending_card_num();
 910   _max_pending_cards = _g1->max_pending_card_num();
 911 
 912   _bytes_in_collection_set_before_gc = 0;
 913   _bytes_copied_during_gc = 0;
 914 
 915   YoungList* young_list = _g1->young_list();
 916   _eden_bytes_before_gc = young_list->eden_used_bytes();
 917   _survivor_bytes_before_gc = young_list->survivor_used_bytes();
 918   _capacity_before_gc = _g1->capacity();
 919 
 920 #ifdef DEBUG
 921   // initialise these to something well known so that we can spot
 922   // if they are not set properly
 923 
 924   for (int i = 0; i < _parallel_gc_threads; ++i) {
 925     _par_last_gc_worker_start_times_ms[i] = -1234.0;
 926     _par_last_ext_root_scan_times_ms[i] = -1234.0;
 927     _par_last_satb_filtering_times_ms[i] = -1234.0;
 928     _par_last_update_rs_times_ms[i] = -1234.0;
 929     _par_last_update_rs_processed_buffers[i] = -1234.0;
 930     _par_last_scan_rs_times_ms[i] = -1234.0;
 931     _par_last_obj_copy_times_ms[i] = -1234.0;
 932     _par_last_termination_times_ms[i] = -1234.0;
 933     _par_last_termination_attempts[i] = -1234.0;
 934     _par_last_gc_worker_end_times_ms[i] = -1234.0;
 935     _par_last_gc_worker_times_ms[i] = -1234.0;
 936     _par_last_gc_worker_other_times_ms[i] = -1234.0;
 937   }
 938 #endif
 939 
 940   for (int i = 0; i < _aux_num; ++i) {
 941     _cur_aux_times_ms[i] = 0.0;
 942     _cur_aux_times_set[i] = false;
 943   }
 944 
 945   // This is initialized to zero here and is set during the evacuation
 946   // pause if we actually waited for the root region scanning to finish.
 947   _root_region_scan_wait_time_ms = 0.0;
 948 
 949   _last_gc_was_young = false;
 950 
 951   // do that for any other surv rate groups
 952   _short_lived_surv_rate_group->stop_adding_regions();
 953   _survivors_age_table.clear();
 954 
 955   assert( verify_young_ages(), "region age verification" );
 956 }
 957 
 958 void G1CollectorPolicy::record_concurrent_mark_init_end(double
 959                                                    mark_init_elapsed_time_ms) {
 960   _during_marking = true;
 961   assert(!initiate_conc_mark_if_possible(), "we should have cleared it by now");
 962   clear_during_initial_mark_pause();
 963   _cur_mark_stop_world_time_ms = mark_init_elapsed_time_ms;
 964 }


 973   double elapsed_time_ms = (end_time_sec - _mark_remark_start_sec)*1000.0;
 974   _concurrent_mark_remark_times_ms->add(elapsed_time_ms);
 975   _cur_mark_stop_world_time_ms += elapsed_time_ms;
 976   _prev_collection_pause_end_ms += elapsed_time_ms;
 977 
 978   _mmu_tracker->add_pause(_mark_remark_start_sec, end_time_sec, true);
 979 }
 980 
 981 void G1CollectorPolicy::record_concurrent_mark_cleanup_start() {
 982   _mark_cleanup_start_sec = os::elapsedTime();
 983 }
 984 
 985 void G1CollectorPolicy::record_concurrent_mark_cleanup_completed() {
 986   _last_young_gc = true;
 987   _in_marking_window = false;
 988 }
 989 
 990 void G1CollectorPolicy::record_concurrent_pause() {
 991   if (_stop_world_start > 0.0) {
 992     double yield_ms = (os::elapsedTime() - _stop_world_start) * 1000.0;
 993     _all_yield_times_ms->add(yield_ms);
 994   }
 995 }
 996 
 997 void G1CollectorPolicy::record_concurrent_pause_end() {
 998 }
 999 
1000 template<class T>
1001 T sum_of(T* sum_arr, int start, int n, int N) {
1002   T sum = (T)0;
1003   for (int i = 0; i < n; i++) {
1004     int j = (start + i) % N;
1005     sum += sum_arr[j];
1006   }
1007   return sum;
1008 }
1009 
1010 void G1CollectorPolicy::print_par_stats(int level,
1011                                         const char* str,
1012                                         double* data,
1013                                         bool showDecimals) {


1180   if (G1YoungSurvRateVerbose) {
1181     gclog_or_tty->print_cr("");
1182     _short_lived_surv_rate_group->print();
1183     // do that for any other surv rate groups too
1184   }
1185 #endif // PRODUCT
1186 
1187   last_pause_included_initial_mark = during_initial_mark_pause();
1188   if (last_pause_included_initial_mark) {
1189     record_concurrent_mark_init_end(0.0);
1190   } else if (!_last_young_gc && need_to_start_conc_mark("end of GC")) {
1191     // Note: this might have already been set, if during the last
1192     // pause we decided to start a cycle but at the beginning of
1193     // this pause we decided to postpone it. That's OK.
1194     set_initiate_conc_mark_if_possible();
1195   }
1196 
1197   _mmu_tracker->add_pause(end_time_sec - elapsed_ms/1000.0,
1198                           end_time_sec, false);
1199 
1200   // This assert is exempted when we're doing parallel collection pauses,
1201   // because the fragmentation caused by the parallel GC allocation buffers
1202   // can lead to more memory being used during collection than was used
1203   // before. Best leave this out until the fragmentation problem is fixed.
1204   // Pauses in which evacuation failed can also lead to negative
1205   // collections, since no space is reclaimed from a region containing an
1206   // object whose evacuation failed.
1207   // Further, we're now always doing parallel collection.  But I'm still
1208   // leaving this here as a placeholder for a more precise assertion later.
1209   // (DLD, 10/05.)
1210   assert((true || parallel) // Always using GC LABs now.
1211          || _g1->evacuation_failed()
1212          || _cur_collection_pause_used_at_start_bytes >= cur_used_bytes,
1213          "Negative collection");
1214 
1215   size_t freed_bytes =
1216     _cur_collection_pause_used_at_start_bytes - cur_used_bytes;
1217   size_t surviving_bytes = _collection_set_bytes_used_before - freed_bytes;
1218 
1219   double survival_fraction =
1220     (double)surviving_bytes/
1221     (double)_collection_set_bytes_used_before;
1222 
1223   // These values are used to update the summary information that is
1224   // displayed when TraceGen0Time is enabled, and are output as part
1225   // of the "finer" output, in the non-parallel case.
1226 
1227   double ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms);
1228   double satb_filtering_time = avg_value(_par_last_satb_filtering_times_ms);
1229   double update_rs_time = avg_value(_par_last_update_rs_times_ms);
1230   double update_rs_processed_buffers =
1231     sum_of_values(_par_last_update_rs_processed_buffers);
1232   double scan_rs_time = avg_value(_par_last_scan_rs_times_ms);
1233   double obj_copy_time = avg_value(_par_last_obj_copy_times_ms);
1234   double termination_time = avg_value(_par_last_termination_times_ms);


1242   double other_time_ms = elapsed_ms;
1243 
1244   // Subtract the root region scanning wait time. It's initialized to
1245   // zero at the start of the pause.
1246   other_time_ms -= _root_region_scan_wait_time_ms;
1247 
1248   if (parallel) {
1249     other_time_ms -= _cur_collection_par_time_ms;
1250   } else {
1251     other_time_ms -= known_time;
1252   }
1253 
1254   // Now subtract the time taken to fix up roots in generated code
1255   other_time_ms -= _cur_collection_code_root_fixup_time_ms;
1256 
1257   // Subtract the time taken to clean the card table from the
1258   // current value of "other time"
1259   other_time_ms -= _cur_clear_ct_time_ms;
1260 
1261   // TraceGen0Time and TraceGen1Time summary info updating.
1262   _all_pause_times_ms->add(elapsed_ms);
1263 
1264   if (update_stats) {
1265     _summary->record_total_time_ms(elapsed_ms);
1266     _summary->record_other_time_ms(other_time_ms);
1267 
1268     MainBodySummary* body_summary = _summary->main_body_summary();
1269     assert(body_summary != NULL, "should not be null!");
1270 
1271     body_summary->record_root_region_scan_wait_time_ms(
1272                                                _root_region_scan_wait_time_ms);
1273     body_summary->record_ext_root_scan_time_ms(ext_root_scan_time);
1274     body_summary->record_satb_filtering_time_ms(satb_filtering_time);
1275     body_summary->record_update_rs_time_ms(update_rs_time);
1276     body_summary->record_scan_rs_time_ms(scan_rs_time);
1277     body_summary->record_obj_copy_time_ms(obj_copy_time);
1278 
1279     if (parallel) {
1280       body_summary->record_parallel_time_ms(_cur_collection_par_time_ms);
1281       body_summary->record_termination_time_ms(termination_time);
1282 
1283       double parallel_known_time = known_time + termination_time;
1284       double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time;
1285       body_summary->record_parallel_other_time_ms(parallel_other_time);
1286     }
1287 
1288     body_summary->record_clear_ct_time_ms(_cur_clear_ct_time_ms);
1289 
1290     // We exempt parallel collection from this check because Alloc Buffer
1291     // fragmentation can produce negative collections.  Same with evac
1292     // failure.
1293     // Further, we're now always doing parallel collection.  But I'm still
1294     // leaving this here as a placeholder for a more precise assertion later.
1295     // (DLD, 10/05.
1296     assert((true || parallel)
1297            || _g1->evacuation_failed()
1298            || surviving_bytes <= _collection_set_bytes_used_before,
1299            "Or else negative collection!");
1300 
1301     // this is where we update the allocation rate of the application
1302     double app_time_ms =
1303       (_cur_collection_start_sec * 1000.0 - _prev_collection_pause_end_ms);
1304     if (app_time_ms < MIN_TIMER_GRANULARITY) {
1305       // This usually happens due to the timer not having the required
1306       // granularity. Some Linuxes are the usual culprits.
1307       // We'll just set it to something (arbitrarily) small.
1308       app_time_ms = 1.0;
1309     }
1310     // We maintain the invariant that all objects allocated by mutator
1311     // threads will be allocated out of eden regions. So, we can use
1312     // the eden region number allocated since the previous GC to
1313     // calculate the application's allocate rate. The only exception
1314     // to that is humongous objects that are allocated separately. But
1315     // given that humongous object allocations do not really affect
1316     // either the pause's duration nor when the next pause will take
1317     // place we can safely ignore them here.
1318     uint regions_allocated = eden_cset_region_length();
1319     double alloc_rate_ms = (double) regions_allocated / app_time_ms;


1332       gclog_or_tty->print_cr("Recent GC Times (ms):");
1333       _recent_gc_times_ms->dump();
1334       gclog_or_tty->print_cr("(End Time=%3.3f) Recent GC End Times (s):", end_time_sec);
1335       _recent_prev_end_times_for_all_gcs_sec->dump();
1336       gclog_or_tty->print_cr("GC = %3.3f, Interval = %3.3f, Ratio = %3.3f",
1337                              _recent_gc_times_ms->sum(), interval_ms, recent_avg_pause_time_ratio());
1338       // In debug mode, terminate the JVM if the user wants to debug at this point.
1339       assert(!G1FailOnFPError, "Debugging data for CR 6898948 has been dumped above");
1340 #endif  // !PRODUCT
1341       // Clip ratio between 0.0 and 1.0, and continue. This will be fixed in
1342       // CR 6902692 by redoing the manner in which the ratio is incrementally computed.
1343       if (_recent_avg_pause_time_ratio < 0.0) {
1344         _recent_avg_pause_time_ratio = 0.0;
1345       } else {
1346         assert(_recent_avg_pause_time_ratio - 1.0 > 0.0, "Ctl-point invariant");
1347         _recent_avg_pause_time_ratio = 1.0;
1348       }
1349     }
1350   }
1351 
1352   for (int i = 0; i < _aux_num; ++i) {
1353     if (_cur_aux_times_set[i]) {
1354       _all_aux_times_ms[i].add(_cur_aux_times_ms[i]);
1355     }
1356   }
1357 
1358   if (G1Log::finer()) {
1359     bool print_marking_info =
1360       _g1->mark_in_progress() && !last_pause_included_initial_mark;
1361 
1362     gclog_or_tty->print_cr("%s, %1.8lf secs]",
1363                            (last_pause_included_initial_mark) ? " (initial-mark)" : "",
1364                            elapsed_ms / 1000.0);
1365 
1366     if (_root_region_scan_wait_time_ms > 0.0) {
1367       print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
1368     }
1369     if (parallel) {
1370       print_stats(1, "Parallel Time", _cur_collection_par_time_ms, no_of_gc_threads);
1371       print_par_stats(2, "GC Worker Start", _par_last_gc_worker_start_times_ms);
1372       print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms);
1373       if (print_marking_info) {
1374         print_par_stats(2, "SATB Filtering", _par_last_satb_filtering_times_ms);
1375       }
1376       print_par_stats(2, "Update RS", _par_last_update_rs_times_ms);
1377       if (G1Log::finest()) {


1419     print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
1420     print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
1421 #ifndef PRODUCT
1422     print_stats(1, "Cur Clear CC", _cur_clear_cc_time_ms);
1423     print_stats(1, "Cum Clear CC", _cum_clear_cc_time_ms);
1424     print_stats(1, "Min Clear CC", _min_clear_cc_time_ms);
1425     print_stats(1, "Max Clear CC", _max_clear_cc_time_ms);
1426     if (_num_cc_clears > 0) {
1427       print_stats(1, "Avg Clear CC", _cum_clear_cc_time_ms / ((double)_num_cc_clears));
1428     }
1429 #endif
1430     print_stats(1, "Other", other_time_ms);
1431     print_stats(2, "Choose CSet",
1432                    (_recorded_young_cset_choice_time_ms +
1433                     _recorded_non_young_cset_choice_time_ms));
1434     print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
1435     print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
1436     print_stats(2, "Free CSet",
1437                    (_recorded_young_free_cset_time_ms +
1438                     _recorded_non_young_free_cset_time_ms));
1439 
1440     for (int i = 0; i < _aux_num; ++i) {
1441       if (_cur_aux_times_set[i]) {
1442         char buffer[96];
1443         sprintf(buffer, "Aux%d", i);
1444         print_stats(1, buffer, _cur_aux_times_ms[i]);
1445       }
1446     }
1447   }
1448 
1449   bool new_in_marking_window = _in_marking_window;
1450   bool new_in_marking_window_im = false;
1451   if (during_initial_mark_pause()) {
1452     new_in_marking_window = true;
1453     new_in_marking_window_im = true;
1454   }
1455 
1456   if (_last_young_gc) {
1457     // This is supposed to to be the "last young GC" before we start
1458     // doing mixed GCs. Here we decide whether to start mixed GCs or not.
1459 
1460     if (!last_pause_included_initial_mark) {
1461       if (next_gc_should_be_mixed("start mixed GCs",
1462                                   "do not start mixed GCs")) {
1463         set_gcs_are_young(false);
1464       }
1465     } else {
1466       ergo_verbose0(ErgoMixedGCs,


1791     return 0;
1792   }
1793 }
1794 
1795 class CountCSClosure: public HeapRegionClosure {
1796   G1CollectorPolicy* _g1_policy;
1797 public:
1798   CountCSClosure(G1CollectorPolicy* g1_policy) :
1799     _g1_policy(g1_policy) {}
1800   bool doHeapRegion(HeapRegion* r) {
1801     _g1_policy->_bytes_in_collection_set_before_gc += r->used();
1802     return false;
1803   }
1804 };
1805 
1806 void G1CollectorPolicy::count_CS_bytes_used() {
1807   CountCSClosure cs_closure(this);
1808   _g1->collection_set_iterate(&cs_closure);
1809 }
1810 
1811 void G1CollectorPolicy::print_summary(int level,
1812                                       const char* str,
1813                                       NumberSeq* seq) const {
1814   double sum = seq->sum();
1815   LineBuffer(level + 1).append_and_print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)",
1816                 str, sum / 1000.0, seq->avg());
1817 }
1818 
1819 void G1CollectorPolicy::print_summary_sd(int level,
1820                                          const char* str,
1821                                          NumberSeq* seq) const {
1822   print_summary(level, str, seq);
1823   LineBuffer(level + 6).append_and_print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)",
1824                 seq->num(), seq->sd(), seq->maximum());
1825 }
1826 
1827 void G1CollectorPolicy::check_other_times(int level,
1828                                         NumberSeq* other_times_ms,
1829                                         NumberSeq* calc_other_times_ms) const {
1830   bool should_print = false;
1831   LineBuffer buf(level + 2);
1832 
1833   double max_sum = MAX2(fabs(other_times_ms->sum()),
1834                         fabs(calc_other_times_ms->sum()));
1835   double min_sum = MIN2(fabs(other_times_ms->sum()),
1836                         fabs(calc_other_times_ms->sum()));
1837   double sum_ratio = max_sum / min_sum;
1838   if (sum_ratio > 1.1) {
1839     should_print = true;
1840     buf.append_and_print_cr("## CALCULATED OTHER SUM DOESN'T MATCH RECORDED ###");
1841   }
1842 
1843   double max_avg = MAX2(fabs(other_times_ms->avg()),
1844                         fabs(calc_other_times_ms->avg()));
1845   double min_avg = MIN2(fabs(other_times_ms->avg()),
1846                         fabs(calc_other_times_ms->avg()));
1847   double avg_ratio = max_avg / min_avg;
1848   if (avg_ratio > 1.1) {
1849     should_print = true;
1850     buf.append_and_print_cr("## CALCULATED OTHER AVG DOESN'T MATCH RECORDED ###");
1851   }
1852 
1853   if (other_times_ms->sum() < -0.01) {
1854     buf.append_and_print_cr("## RECORDED OTHER SUM IS NEGATIVE ###");
1855   }
1856 
1857   if (other_times_ms->avg() < -0.01) {
1858     buf.append_and_print_cr("## RECORDED OTHER AVG IS NEGATIVE ###");
1859   }
1860 
1861   if (calc_other_times_ms->sum() < -0.01) {
1862     should_print = true;
1863     buf.append_and_print_cr("## CALCULATED OTHER SUM IS NEGATIVE ###");
1864   }
1865 
1866   if (calc_other_times_ms->avg() < -0.01) {
1867     should_print = true;
1868     buf.append_and_print_cr("## CALCULATED OTHER AVG IS NEGATIVE ###");
1869   }
1870 
1871   if (should_print)
1872     print_summary(level, "Other(Calc)", calc_other_times_ms);
1873 }
1874 
1875 void G1CollectorPolicy::print_summary(PauseSummary* summary) const {
1876   bool parallel = G1CollectedHeap::use_parallel_gc_threads();
1877   MainBodySummary*    body_summary = summary->main_body_summary();
1878   if (summary->get_total_seq()->num() > 0) {
1879     print_summary_sd(0, "Evacuation Pauses", summary->get_total_seq());
1880     if (body_summary != NULL) {
1881       print_summary(1, "Root Region Scan Wait", body_summary->get_root_region_scan_wait_seq());
1882       if (parallel) {
1883         print_summary(1, "Parallel Time", body_summary->get_parallel_seq());
1884         print_summary(2, "Ext Root Scanning", body_summary->get_ext_root_scan_seq());
1885         print_summary(2, "SATB Filtering", body_summary->get_satb_filtering_seq());
1886         print_summary(2, "Update RS", body_summary->get_update_rs_seq());
1887         print_summary(2, "Scan RS", body_summary->get_scan_rs_seq());
1888         print_summary(2, "Object Copy", body_summary->get_obj_copy_seq());
1889         print_summary(2, "Termination", body_summary->get_termination_seq());
1890         print_summary(2, "Parallel Other", body_summary->get_parallel_other_seq());
1891         {
1892           NumberSeq* other_parts[] = {
1893             body_summary->get_ext_root_scan_seq(),
1894             body_summary->get_satb_filtering_seq(),
1895             body_summary->get_update_rs_seq(),
1896             body_summary->get_scan_rs_seq(),
1897             body_summary->get_obj_copy_seq(),
1898             body_summary->get_termination_seq()
1899           };
1900           NumberSeq calc_other_times_ms(body_summary->get_parallel_seq(),
1901                                         6, other_parts);
1902           check_other_times(2, body_summary->get_parallel_other_seq(),
1903                             &calc_other_times_ms);
1904         }
1905       } else {
1906         print_summary(1, "Ext Root Scanning", body_summary->get_ext_root_scan_seq());
1907         print_summary(1, "SATB Filtering", body_summary->get_satb_filtering_seq());
1908         print_summary(1, "Update RS", body_summary->get_update_rs_seq());
1909         print_summary(1, "Scan RS", body_summary->get_scan_rs_seq());
1910         print_summary(1, "Object Copy", body_summary->get_obj_copy_seq());
1911       }
1912     }
1913     print_summary(1, "Clear CT", body_summary->get_clear_ct_seq());
1914     print_summary(1, "Other", summary->get_other_seq());
1915     {
1916       if (body_summary != NULL) {
1917         NumberSeq calc_other_times_ms;
1918         if (parallel) {
1919           // parallel
1920           NumberSeq* other_parts[] = {
1921             body_summary->get_root_region_scan_wait_seq(),
1922             body_summary->get_parallel_seq(),
1923             body_summary->get_clear_ct_seq()
1924           };
1925           calc_other_times_ms = NumberSeq(summary->get_total_seq(),
1926                                           3, other_parts);
1927         } else {
1928           // serial
1929           NumberSeq* other_parts[] = {
1930             body_summary->get_root_region_scan_wait_seq(),
1931             body_summary->get_update_rs_seq(),
1932             body_summary->get_ext_root_scan_seq(),
1933             body_summary->get_satb_filtering_seq(),
1934             body_summary->get_scan_rs_seq(),
1935             body_summary->get_obj_copy_seq()
1936           };
1937           calc_other_times_ms = NumberSeq(summary->get_total_seq(),
1938                                           6, other_parts);
1939         }
1940         check_other_times(1,  summary->get_other_seq(), &calc_other_times_ms);
1941       }
1942     }
1943   } else {
1944     LineBuffer(1).append_and_print_cr("none");
1945   }
1946   LineBuffer(0).append_and_print_cr("");
1947 }
1948 
1949 void G1CollectorPolicy::print_tracing_info() const {
1950   if (TraceGen0Time) {
1951     gclog_or_tty->print_cr("ALL PAUSES");
1952     print_summary_sd(0, "Total", _all_pause_times_ms);
1953     gclog_or_tty->print_cr("");
1954     gclog_or_tty->print_cr("");
1955     gclog_or_tty->print_cr("   Young GC Pauses: %8d", _young_pause_num);
1956     gclog_or_tty->print_cr("   Mixed GC Pauses: %8d", _mixed_pause_num);
1957     gclog_or_tty->print_cr("");
1958 
1959     gclog_or_tty->print_cr("EVACUATION PAUSES");
1960     print_summary(_summary);
1961 
1962     gclog_or_tty->print_cr("MISC");
1963     print_summary_sd(0, "Stop World", _all_stop_world_times_ms);
1964     print_summary_sd(0, "Yields", _all_yield_times_ms);
1965     for (int i = 0; i < _aux_num; ++i) {
1966       if (_all_aux_times_ms[i].num() > 0) {
1967         char buffer[96];
1968         sprintf(buffer, "Aux%d", i);
1969         print_summary_sd(0, buffer, &_all_aux_times_ms[i]);
1970       }
1971     }
1972   }
1973   if (TraceGen1Time) {
1974     if (_all_full_gc_times_ms->num() > 0) {
1975       gclog_or_tty->print("\n%4d full_gcs: total time = %8.2f s",
1976                  _all_full_gc_times_ms->num(),
1977                  _all_full_gc_times_ms->sum() / 1000.0);
1978       gclog_or_tty->print_cr(" (avg = %8.2fms).", _all_full_gc_times_ms->avg());
1979       gclog_or_tty->print_cr("                     [std. dev = %8.2f ms, max = %8.2f ms]",
1980                     _all_full_gc_times_ms->sd(),
1981                     _all_full_gc_times_ms->maximum());
1982     }
1983   }
1984 }
1985 
1986 void G1CollectorPolicy::print_yg_surv_rate_info() const {
1987 #ifndef PRODUCT
1988   _short_lived_surv_rate_group->print_surv_rate_summary();
1989   // add this call for any other surv rate groups
1990 #endif // PRODUCT
1991 }
1992 
1993 #ifndef PRODUCT
1994 // for debugging, bit of a hack...
1995 static char*
1996 region_num_to_mbs(int length) {
1997   static char buffer[64];
1998   double bytes = (double) (length * HeapRegion::GrainBytes);
1999   double mbs = bytes / (double) (1024 * 1024);
2000   sprintf(buffer, "%7.2lfMB", mbs);
2001   return buffer;
2002 }
2003 #endif // PRODUCT


2513                     target_pause_time_ms));
2514   guarantee(_collection_set == NULL, "Precondition");
2515 
2516   double base_time_ms = predict_base_elapsed_time_ms(_pending_cards);
2517   double predicted_pause_time_ms = base_time_ms;
2518   double time_remaining_ms = target_pause_time_ms - base_time_ms;
2519 
2520   ergo_verbose3(ErgoCSetConstruction | ErgoHigh,
2521                 "start choosing CSet",
2522                 ergo_format_ms("predicted base time")
2523                 ergo_format_ms("remaining time")
2524                 ergo_format_ms("target pause time"),
2525                 base_time_ms, time_remaining_ms, target_pause_time_ms);
2526 
2527   HeapRegion* hr;
2528   double young_start_time_sec = os::elapsedTime();
2529 
2530   _collection_set_bytes_used_before = 0;
2531   _last_gc_was_young = gcs_are_young() ? true : false;
2532 

2533   if (_last_gc_was_young) {
2534     ++_young_pause_num;
2535   } else {
2536     ++_mixed_pause_num;
2537   }
2538 
2539   // The young list is laid with the survivor regions from the previous
2540   // pause are appended to the RHS of the young list, i.e.
2541   //   [Newly Young Regions ++ Survivors from last pause].
2542 
2543   uint survivor_region_length = young_list->survivor_length();
2544   uint eden_region_length = young_list->length() - survivor_region_length;
2545   init_cset_region_lengths(eden_region_length, survivor_region_length);
2546   hr = young_list->first_survivor_region();
2547   while (hr != NULL) {
2548     assert(hr->is_survivor(), "badly formed young list");
2549     hr->set_young();
2550     hr = hr->get_next_young_region();
2551   }
2552 


2672   }
2673 
2674   stop_incremental_cset_building();
2675 
2676   count_CS_bytes_used();
2677 
2678   ergo_verbose5(ErgoCSetConstruction,
2679                 "finish choosing CSet",
2680                 ergo_format_region("eden")
2681                 ergo_format_region("survivors")
2682                 ergo_format_region("old")
2683                 ergo_format_ms("predicted pause time")
2684                 ergo_format_ms("target pause time"),
2685                 eden_region_length, survivor_region_length,
2686                 old_cset_region_length(),
2687                 predicted_pause_time_ms, target_pause_time_ms);
2688 
2689   double non_young_end_time_sec = os::elapsedTime();
2690   _recorded_non_young_cset_choice_time_ms =
2691     (non_young_end_time_sec - non_young_start_time_sec) * 1000.0;
































































































































2692 }


 116     va_start(ap, format);
 117     vappend(format, ap);
 118     va_end(ap);
 119   }
 120 
 121   void append_and_print_cr(const char* format, ...) {
 122     va_list ap;
 123     va_start(ap, format);
 124     vappend(format, ap);
 125     va_end(ap);
 126     gclog_or_tty->print_cr("%s", _buffer);
 127     _cur = _indent_level * INDENT_CHARS;
 128   }
 129 };
 130 
 131 G1CollectorPolicy::G1CollectorPolicy() :
 132   _parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads()
 133                         ? ParallelGCThreads : 1),
 134 
 135   _recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),

 136   _stop_world_start(0.0),




 137 
 138   _cur_clear_ct_time_ms(0.0),
 139   _root_region_scan_wait_time_ms(0.0),
 140 
 141   _cur_ref_proc_time_ms(0.0),
 142   _cur_ref_enq_time_ms(0.0),
 143 
 144 #ifndef PRODUCT
 145   _min_clear_cc_time_ms(-1.0),
 146   _max_clear_cc_time_ms(-1.0),
 147   _cur_clear_cc_time_ms(0.0),
 148   _cum_clear_cc_time_ms(0.0),
 149   _num_cc_clears(0L),
 150 #endif
 151 






 152   _concurrent_mark_remark_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
 153   _concurrent_mark_cleanup_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
 154 
 155   _alloc_rate_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
 156   _prev_collection_pause_end_ms(0.0),
 157   _pending_card_diff_seq(new TruncatedSeq(TruncatedSeqLength)),
 158   _rs_length_diff_seq(new TruncatedSeq(TruncatedSeqLength)),
 159   _cost_per_card_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
 160   _young_cards_per_entry_ratio_seq(new TruncatedSeq(TruncatedSeqLength)),
 161   _mixed_cards_per_entry_ratio_seq(new TruncatedSeq(TruncatedSeqLength)),
 162   _cost_per_entry_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
 163   _mixed_cost_per_entry_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
 164   _cost_per_byte_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
 165   _cost_per_byte_ms_during_cm_seq(new TruncatedSeq(TruncatedSeqLength)),
 166   _constant_other_time_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
 167   _young_other_cost_per_region_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
 168   _non_young_other_cost_per_region_ms_seq(
 169                                          new TruncatedSeq(TruncatedSeqLength)),
 170 
 171   _pending_cards_seq(new TruncatedSeq(TruncatedSeqLength)),
 172   _rs_lengths_seq(new TruncatedSeq(TruncatedSeqLength)),
 173 
 174   _pause_time_target_ms((double) MaxGCPauseMillis),
 175 
 176   _gcs_are_young(true),
 177   _young_pause_num(0),
 178   _mixed_pause_num(0),
 179 
 180   _during_marking(false),
 181   _in_marking_window(false),
 182   _in_marking_window_im(false),
 183 
 184   _recent_prev_end_times_for_all_gcs_sec(
 185                                 new TruncatedSeq(NumPrevPausesForHeuristics)),
 186 
 187   _recent_avg_pause_time_ratio(0.0),
 188 


 189   _initiate_conc_mark_if_possible(false),
 190   _during_initial_mark_pause(false),
 191   _last_young_gc(false),
 192   _last_gc_was_young(false),
 193 
 194   _eden_bytes_before_gc(0),
 195   _survivor_bytes_before_gc(0),
 196   _capacity_before_gc(0),
 197 
 198   _eden_cset_region_length(0),
 199   _survivor_cset_region_length(0),
 200   _old_cset_region_length(0),
 201 
 202   _collection_set(NULL),
 203   _collection_set_bytes_used_before(0),
 204 
 205   // Incremental CSet attributes
 206   _inc_cset_build_state(Inactive),
 207   _inc_cset_head(NULL),
 208   _inc_cset_tail(NULL),


 821     }
 822   }
 823 
 824   return ret;
 825 }
 826 #endif // PRODUCT
 827 
 828 void G1CollectorPolicy::record_full_collection_start() {
 829   _cur_collection_start_sec = os::elapsedTime();
 830   // Release the future to-space so that it is available for compaction into.
 831   _g1->set_full_collection();
 832 }
 833 
 834 void G1CollectorPolicy::record_full_collection_end() {
 835   // Consider this like a collection pause for the purposes of allocation
 836   // since last pause.
 837   double end_sec = os::elapsedTime();
 838   double full_gc_time_sec = end_sec - _cur_collection_start_sec;
 839   double full_gc_time_ms = full_gc_time_sec * 1000.0;
 840 
 841   _trace_gen1_time_data.record_full_collection(full_gc_time_ms);
 842 
 843   update_recent_gc_times(end_sec, full_gc_time_ms);
 844 
 845   _g1->clear_full_collection();
 846 
 847   // "Nuke" the heuristics that control the young/mixed GC
 848   // transitions and make sure we start with young GCs after the Full GC.
 849   set_gcs_are_young(true);
 850   _last_young_gc = false;
 851   clear_initiate_conc_mark_if_possible();
 852   clear_during_initial_mark_pause();
 853   _in_marking_window = false;
 854   _in_marking_window_im = false;
 855 
 856   _short_lived_surv_rate_group->start_adding_regions();
 857   // also call this on any additional surv rate groups
 858 
 859   record_survivor_regions(0, NULL, NULL);
 860 
 861   _free_regions_at_end_of_collection = _g1->free_regions();


 870 }
 871 
 872 void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
 873                                                       size_t start_used) {
 874   if (G1Log::finer()) {
 875     gclog_or_tty->stamp(PrintGCTimeStamps);
 876     gclog_or_tty->print("[%s", (const char*)GCCauseString("GC pause", _g1->gc_cause())
 877       .append(gcs_are_young() ? " (young)" : " (mixed)"));
 878   }
 879 
 880   // We only need to do this here as the policy will only be applied
 881   // to the GC we're about to start. so, no point is calculating this
 882   // every time we calculate / recalculate the target young length.
 883   update_survivors_policy();
 884 
 885   assert(_g1->used() == _g1->recalculate_used(),
 886          err_msg("sanity, used: "SIZE_FORMAT" recalculate_used: "SIZE_FORMAT,
 887                  _g1->used(), _g1->recalculate_used()));
 888 
 889   double s_w_t_ms = (start_time_sec - _stop_world_start) * 1000.0;
 890   _trace_gen0_time_data.record_start_collection(s_w_t_ms);
 891   _stop_world_start = 0.0;
 892 
 893   _cur_collection_start_sec = start_time_sec;
 894   _cur_collection_pause_used_at_start_bytes = start_used;
 895   _cur_collection_pause_used_regions_at_start = _g1->used_regions();
 896   _pending_cards = _g1->pending_card_num();
 897   _max_pending_cards = _g1->max_pending_card_num();
 898 
 899   _bytes_in_collection_set_before_gc = 0;
 900   _bytes_copied_during_gc = 0;
 901 
 902   YoungList* young_list = _g1->young_list();
 903   _eden_bytes_before_gc = young_list->eden_used_bytes();
 904   _survivor_bytes_before_gc = young_list->survivor_used_bytes();
 905   _capacity_before_gc = _g1->capacity();
 906 
 907 #ifdef DEBUG
 908   // initialise these to something well known so that we can spot
 909   // if they are not set properly
 910 
 911   for (int i = 0; i < _parallel_gc_threads; ++i) {
 912     _par_last_gc_worker_start_times_ms[i] = -1234.0;
 913     _par_last_ext_root_scan_times_ms[i] = -1234.0;
 914     _par_last_satb_filtering_times_ms[i] = -1234.0;
 915     _par_last_update_rs_times_ms[i] = -1234.0;
 916     _par_last_update_rs_processed_buffers[i] = -1234.0;
 917     _par_last_scan_rs_times_ms[i] = -1234.0;
 918     _par_last_obj_copy_times_ms[i] = -1234.0;
 919     _par_last_termination_times_ms[i] = -1234.0;
 920     _par_last_termination_attempts[i] = -1234.0;
 921     _par_last_gc_worker_end_times_ms[i] = -1234.0;
 922     _par_last_gc_worker_times_ms[i] = -1234.0;
 923     _par_last_gc_worker_other_times_ms[i] = -1234.0;
 924   }
 925 #endif
 926 





 927   // This is initialized to zero here and is set during the evacuation
 928   // pause if we actually waited for the root region scanning to finish.
 929   _root_region_scan_wait_time_ms = 0.0;
 930 
 931   _last_gc_was_young = false;
 932 
 933   // do that for any other surv rate groups
 934   _short_lived_surv_rate_group->stop_adding_regions();
 935   _survivors_age_table.clear();
 936 
 937   assert( verify_young_ages(), "region age verification" );
 938 }
 939 
 940 void G1CollectorPolicy::record_concurrent_mark_init_end(double
 941                                                    mark_init_elapsed_time_ms) {
 942   _during_marking = true;
 943   assert(!initiate_conc_mark_if_possible(), "we should have cleared it by now");
 944   clear_during_initial_mark_pause();
 945   _cur_mark_stop_world_time_ms = mark_init_elapsed_time_ms;
 946 }


 955   double elapsed_time_ms = (end_time_sec - _mark_remark_start_sec)*1000.0;
 956   _concurrent_mark_remark_times_ms->add(elapsed_time_ms);
 957   _cur_mark_stop_world_time_ms += elapsed_time_ms;
 958   _prev_collection_pause_end_ms += elapsed_time_ms;
 959 
 960   _mmu_tracker->add_pause(_mark_remark_start_sec, end_time_sec, true);
 961 }
 962 
 963 void G1CollectorPolicy::record_concurrent_mark_cleanup_start() {
 964   _mark_cleanup_start_sec = os::elapsedTime();
 965 }
 966 
 967 void G1CollectorPolicy::record_concurrent_mark_cleanup_completed() {
 968   _last_young_gc = true;
 969   _in_marking_window = false;
 970 }
 971 
 972 void G1CollectorPolicy::record_concurrent_pause() {
 973   if (_stop_world_start > 0.0) {
 974     double yield_ms = (os::elapsedTime() - _stop_world_start) * 1000.0;
 975     _trace_gen0_time_data.record_yield_time(yield_ms);
 976   }
 977 }
 978 
 979 void G1CollectorPolicy::record_concurrent_pause_end() {
 980 }
 981 
 982 template<class T>
 983 T sum_of(T* sum_arr, int start, int n, int N) {
 984   T sum = (T)0;
 985   for (int i = 0; i < n; i++) {
 986     int j = (start + i) % N;
 987     sum += sum_arr[j];
 988   }
 989   return sum;
 990 }
 991 
 992 void G1CollectorPolicy::print_par_stats(int level,
 993                                         const char* str,
 994                                         double* data,
 995                                         bool showDecimals) {


1162   if (G1YoungSurvRateVerbose) {
1163     gclog_or_tty->print_cr("");
1164     _short_lived_surv_rate_group->print();
1165     // do that for any other surv rate groups too
1166   }
1167 #endif // PRODUCT
1168 
1169   last_pause_included_initial_mark = during_initial_mark_pause();
1170   if (last_pause_included_initial_mark) {
1171     record_concurrent_mark_init_end(0.0);
1172   } else if (!_last_young_gc && need_to_start_conc_mark("end of GC")) {
1173     // Note: this might have already been set, if during the last
1174     // pause we decided to start a cycle but at the beginning of
1175     // this pause we decided to postpone it. That's OK.
1176     set_initiate_conc_mark_if_possible();
1177   }
1178 
1179   _mmu_tracker->add_pause(end_time_sec - elapsed_ms/1000.0,
1180                           end_time_sec, false);
1181 















1182   size_t freed_bytes =
1183     _cur_collection_pause_used_at_start_bytes - cur_used_bytes;
1184   size_t surviving_bytes = _collection_set_bytes_used_before - freed_bytes;
1185 
1186   double survival_fraction =
1187     (double)surviving_bytes/
1188     (double)_collection_set_bytes_used_before;
1189 
1190   // These values are used to update the summary information that is
1191   // displayed when TraceGen0Time is enabled, and are output as part
1192   // of the "finer" output, in the non-parallel case.
1193 
1194   double ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms);
1195   double satb_filtering_time = avg_value(_par_last_satb_filtering_times_ms);
1196   double update_rs_time = avg_value(_par_last_update_rs_times_ms);
1197   double update_rs_processed_buffers =
1198     sum_of_values(_par_last_update_rs_processed_buffers);
1199   double scan_rs_time = avg_value(_par_last_scan_rs_times_ms);
1200   double obj_copy_time = avg_value(_par_last_obj_copy_times_ms);
1201   double termination_time = avg_value(_par_last_termination_times_ms);


1209   double other_time_ms = elapsed_ms;
1210 
1211   // Subtract the root region scanning wait time. It's initialized to
1212   // zero at the start of the pause.
1213   other_time_ms -= _root_region_scan_wait_time_ms;
1214 
1215   if (parallel) {
1216     other_time_ms -= _cur_collection_par_time_ms;
1217   } else {
1218     other_time_ms -= known_time;
1219   }
1220 
1221   // Now subtract the time taken to fix up roots in generated code
1222   other_time_ms -= _cur_collection_code_root_fixup_time_ms;
1223 
1224   // Subtract the time taken to clean the card table from the
1225   // current value of "other time"
1226   other_time_ms -= _cur_clear_ct_time_ms;
1227 
1228   // TraceGen0Time and TraceGen1Time summary info updating.

1229 
1230   if (update_stats) {


















1231     double parallel_known_time = known_time + termination_time;
1232     double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time;


1233 
1234     _trace_gen0_time_data.record_end_collection(
1235       elapsed_ms, other_time_ms, _root_region_scan_wait_time_ms, _cur_collection_par_time_ms,
1236       ext_root_scan_time, satb_filtering_time, update_rs_time, scan_rs_time, obj_copy_time,
1237       termination_time, parallel_other_time, _cur_clear_ct_time_ms);








1238 
1239     // this is where we update the allocation rate of the application
1240     double app_time_ms =
1241       (_cur_collection_start_sec * 1000.0 - _prev_collection_pause_end_ms);
1242     if (app_time_ms < MIN_TIMER_GRANULARITY) {
1243       // This usually happens due to the timer not having the required
1244       // granularity. Some Linuxes are the usual culprits.
1245       // We'll just set it to something (arbitrarily) small.
1246       app_time_ms = 1.0;
1247     }
1248     // We maintain the invariant that all objects allocated by mutator
1249     // threads will be allocated out of eden regions. So, we can use
1250     // the eden region number allocated since the previous GC to
1251     // calculate the application's allocate rate. The only exception
1252     // to that is humongous objects that are allocated separately. But
1253     // given that humongous object allocations do not really affect
1254     // either the pause's duration nor when the next pause will take
1255     // place we can safely ignore them here.
1256     uint regions_allocated = eden_cset_region_length();
1257     double alloc_rate_ms = (double) regions_allocated / app_time_ms;


1270       gclog_or_tty->print_cr("Recent GC Times (ms):");
1271       _recent_gc_times_ms->dump();
1272       gclog_or_tty->print_cr("(End Time=%3.3f) Recent GC End Times (s):", end_time_sec);
1273       _recent_prev_end_times_for_all_gcs_sec->dump();
1274       gclog_or_tty->print_cr("GC = %3.3f, Interval = %3.3f, Ratio = %3.3f",
1275                              _recent_gc_times_ms->sum(), interval_ms, recent_avg_pause_time_ratio());
1276       // In debug mode, terminate the JVM if the user wants to debug at this point.
1277       assert(!G1FailOnFPError, "Debugging data for CR 6898948 has been dumped above");
1278 #endif  // !PRODUCT
1279       // Clip ratio between 0.0 and 1.0, and continue. This will be fixed in
1280       // CR 6902692 by redoing the manner in which the ratio is incrementally computed.
1281       if (_recent_avg_pause_time_ratio < 0.0) {
1282         _recent_avg_pause_time_ratio = 0.0;
1283       } else {
1284         assert(_recent_avg_pause_time_ratio - 1.0 > 0.0, "Ctl-point invariant");
1285         _recent_avg_pause_time_ratio = 1.0;
1286       }
1287     }
1288   }
1289 






1290   if (G1Log::finer()) {
1291     bool print_marking_info =
1292       _g1->mark_in_progress() && !last_pause_included_initial_mark;
1293 
1294     gclog_or_tty->print_cr("%s, %1.8lf secs]",
1295                            (last_pause_included_initial_mark) ? " (initial-mark)" : "",
1296                            elapsed_ms / 1000.0);
1297 
1298     if (_root_region_scan_wait_time_ms > 0.0) {
1299       print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
1300     }
1301     if (parallel) {
1302       print_stats(1, "Parallel Time", _cur_collection_par_time_ms, no_of_gc_threads);
1303       print_par_stats(2, "GC Worker Start", _par_last_gc_worker_start_times_ms);
1304       print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms);
1305       if (print_marking_info) {
1306         print_par_stats(2, "SATB Filtering", _par_last_satb_filtering_times_ms);
1307       }
1308       print_par_stats(2, "Update RS", _par_last_update_rs_times_ms);
1309       if (G1Log::finest()) {


1351     print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
1352     print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
1353 #ifndef PRODUCT
1354     print_stats(1, "Cur Clear CC", _cur_clear_cc_time_ms);
1355     print_stats(1, "Cum Clear CC", _cum_clear_cc_time_ms);
1356     print_stats(1, "Min Clear CC", _min_clear_cc_time_ms);
1357     print_stats(1, "Max Clear CC", _max_clear_cc_time_ms);
1358     if (_num_cc_clears > 0) {
1359       print_stats(1, "Avg Clear CC", _cum_clear_cc_time_ms / ((double)_num_cc_clears));
1360     }
1361 #endif
1362     print_stats(1, "Other", other_time_ms);
1363     print_stats(2, "Choose CSet",
1364                    (_recorded_young_cset_choice_time_ms +
1365                     _recorded_non_young_cset_choice_time_ms));
1366     print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
1367     print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
1368     print_stats(2, "Free CSet",
1369                    (_recorded_young_free_cset_time_ms +
1370                     _recorded_non_young_free_cset_time_ms));








1371   }
1372 
1373   bool new_in_marking_window = _in_marking_window;
1374   bool new_in_marking_window_im = false;
1375   if (during_initial_mark_pause()) {
1376     new_in_marking_window = true;
1377     new_in_marking_window_im = true;
1378   }
1379 
1380   if (_last_young_gc) {
1381     // This is supposed to to be the "last young GC" before we start
1382     // doing mixed GCs. Here we decide whether to start mixed GCs or not.
1383 
1384     if (!last_pause_included_initial_mark) {
1385       if (next_gc_should_be_mixed("start mixed GCs",
1386                                   "do not start mixed GCs")) {
1387         set_gcs_are_young(false);
1388       }
1389     } else {
1390       ergo_verbose0(ErgoMixedGCs,


1715     return 0;
1716   }
1717 }
1718 
1719 class CountCSClosure: public HeapRegionClosure {
1720   G1CollectorPolicy* _g1_policy;
1721 public:
1722   CountCSClosure(G1CollectorPolicy* g1_policy) :
1723     _g1_policy(g1_policy) {}
1724   bool doHeapRegion(HeapRegion* r) {
1725     _g1_policy->_bytes_in_collection_set_before_gc += r->used();
1726     return false;
1727   }
1728 };
1729 
1730 void G1CollectorPolicy::count_CS_bytes_used() {
1731   CountCSClosure cs_closure(this);
1732   _g1->collection_set_iterate(&cs_closure);
1733 }
1734 










































































































































1735 void G1CollectorPolicy::print_tracing_info() const {
1736   _trace_gen0_time_data.print();
1737   _trace_gen1_time_data.print();
































1738 }
1739 
1740 void G1CollectorPolicy::print_yg_surv_rate_info() const {
1741 #ifndef PRODUCT
1742   _short_lived_surv_rate_group->print_surv_rate_summary();
1743   // add this call for any other surv rate groups
1744 #endif // PRODUCT
1745 }
1746 
1747 #ifndef PRODUCT
1748 // for debugging, bit of a hack...
1749 static char*
1750 region_num_to_mbs(int length) {
1751   static char buffer[64];
1752   double bytes = (double) (length * HeapRegion::GrainBytes);
1753   double mbs = bytes / (double) (1024 * 1024);
1754   sprintf(buffer, "%7.2lfMB", mbs);
1755   return buffer;
1756 }
1757 #endif // PRODUCT


2267                     target_pause_time_ms));
2268   guarantee(_collection_set == NULL, "Precondition");
2269 
2270   double base_time_ms = predict_base_elapsed_time_ms(_pending_cards);
2271   double predicted_pause_time_ms = base_time_ms;
2272   double time_remaining_ms = target_pause_time_ms - base_time_ms;
2273 
2274   ergo_verbose3(ErgoCSetConstruction | ErgoHigh,
2275                 "start choosing CSet",
2276                 ergo_format_ms("predicted base time")
2277                 ergo_format_ms("remaining time")
2278                 ergo_format_ms("target pause time"),
2279                 base_time_ms, time_remaining_ms, target_pause_time_ms);
2280 
2281   HeapRegion* hr;
2282   double young_start_time_sec = os::elapsedTime();
2283 
2284   _collection_set_bytes_used_before = 0;
2285   _last_gc_was_young = gcs_are_young() ? true : false;
2286 
2287   _trace_gen0_time_data.increment_collection_count(!_last_gc_was_young);
2288   if (_last_gc_was_young) {
2289     ++_young_pause_num;
2290   } else {
2291     ++_mixed_pause_num;
2292   }
2293 
2294   // The young list is laid with the survivor regions from the previous
2295   // pause are appended to the RHS of the young list, i.e.
2296   //   [Newly Young Regions ++ Survivors from last pause].
2297 
2298   uint survivor_region_length = young_list->survivor_length();
2299   uint eden_region_length = young_list->length() - survivor_region_length;
2300   init_cset_region_lengths(eden_region_length, survivor_region_length);
2301   hr = young_list->first_survivor_region();
2302   while (hr != NULL) {
2303     assert(hr->is_survivor(), "badly formed young list");
2304     hr->set_young();
2305     hr = hr->get_next_young_region();
2306   }
2307 


2427   }
2428 
2429   stop_incremental_cset_building();
2430 
2431   count_CS_bytes_used();
2432 
2433   ergo_verbose5(ErgoCSetConstruction,
2434                 "finish choosing CSet",
2435                 ergo_format_region("eden")
2436                 ergo_format_region("survivors")
2437                 ergo_format_region("old")
2438                 ergo_format_ms("predicted pause time")
2439                 ergo_format_ms("target pause time"),
2440                 eden_region_length, survivor_region_length,
2441                 old_cset_region_length(),
2442                 predicted_pause_time_ms, target_pause_time_ms);
2443 
2444   double non_young_end_time_sec = os::elapsedTime();
2445   _recorded_non_young_cset_choice_time_ms =
2446     (non_young_end_time_sec - non_young_start_time_sec) * 1000.0;
2447 }
2448 
2449 void TraceGen0TimeData::record_start_collection(double time_to_stop_the_world_ms) {
2450   if(TraceGen0Time) {
2451     _all_stop_world_times_ms.add(time_to_stop_the_world_ms);
2452   }
2453 }
2454 
2455 void TraceGen0TimeData::record_yield_time(double yield_time_ms) {
2456   if(TraceGen0Time) {
2457     _all_yield_times_ms.add(yield_time_ms);
2458   }
2459 }
2460 
2461 void TraceGen0TimeData::record_end_collection(
2462      double total_ms,
2463      double other_ms,
2464      double root_region_scan_wait_ms,
2465      double parallel_ms,
2466      double ext_root_scan_ms,
2467      double satb_filtering_ms,
2468      double update_rs_ms,
2469      double scan_rs_ms,
2470      double obj_copy_ms,
2471      double termination_ms,
2472      double parallel_other_ms,
2473      double clear_ct_ms)
2474 {
2475   if(TraceGen0Time) {
2476     _total.add(total_ms);
2477     _other.add(other_ms);
2478     _root_region_scan_wait.add(root_region_scan_wait_ms);
2479     _parallel.add(parallel_ms);
2480     _ext_root_scan.add(ext_root_scan_ms);
2481     _satb_filtering.add(satb_filtering_ms);
2482     _update_rs.add(update_rs_ms);
2483     _scan_rs.add(scan_rs_ms);
2484     _obj_copy.add(obj_copy_ms);
2485     _termination.add(termination_ms);
2486     _parallel_other.add(parallel_other_ms);
2487     _clear_ct.add(clear_ct_ms);
2488   }
2489 }
2490 
2491 void TraceGen0TimeData::increment_collection_count(bool mixed) {
2492   if(TraceGen0Time) {
2493     if (mixed) {
2494       ++_mixed_pause_num;
2495     } else {
2496       ++_young_pause_num;
2497     }
2498   }
2499 }
2500 
2501 void TraceGen0TimeData::print_summary(int level,
2502                                       const char* str,
2503                                       const NumberSeq* seq) const {
2504   double sum = seq->sum();
2505   LineBuffer(level + 1).append_and_print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)",
2506                 str, sum / 1000.0, seq->avg());
2507 }
2508 
2509 void TraceGen0TimeData::print_summary_sd(int level,
2510                                          const char* str,
2511                                          const NumberSeq* seq) const {
2512   print_summary(level, str, seq);
2513   LineBuffer(level + 6).append_and_print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)",
2514                 seq->num(), seq->sd(), seq->maximum());
2515 }
2516 
2517 void TraceGen0TimeData::print() const {
2518   if (!TraceGen0Time) {
2519     return;
2520   }
2521 
2522   gclog_or_tty->print_cr("ALL PAUSES");
2523   print_summary_sd(0, "Total", &_total);
2524   gclog_or_tty->print_cr("");
2525   gclog_or_tty->print_cr("");
2526   gclog_or_tty->print_cr("   Young GC Pauses: %8d", _young_pause_num);
2527   gclog_or_tty->print_cr("   Mixed GC Pauses: %8d", _mixed_pause_num);
2528   gclog_or_tty->print_cr("");
2529 
2530   gclog_or_tty->print_cr("EVACUATION PAUSES");
2531 
2532   if (_young_pause_num == 0 && _mixed_pause_num == 0) {
2533     gclog_or_tty->print_cr("none");
2534   } else {
2535     print_summary_sd(0, "Evacuation Pauses", &_total);
2536     print_summary(1, "Root Region Scan Wait", &_root_region_scan_wait);
2537     print_summary(1, "Parallel Time", &_parallel);
2538     print_summary(2, "Ext Root Scanning", &_ext_root_scan);
2539     print_summary(2, "SATB Filtering", &_satb_filtering);
2540     print_summary(2, "Update RS", &_update_rs);
2541     print_summary(2, "Scan RS", &_scan_rs);
2542     print_summary(2, "Object Copy", &_obj_copy);
2543     print_summary(2, "Termination", &_termination);
2544     print_summary(2, "Parallel Other", &_parallel_other);
2545     print_summary(1, "Clear CT", &_clear_ct);
2546     print_summary(1, "Other", &_other);
2547   }
2548   gclog_or_tty->print_cr("");
2549 
2550   gclog_or_tty->print_cr("MISC");
2551   print_summary_sd(0, "Stop World", &_all_stop_world_times_ms);
2552   print_summary_sd(0, "Yields", &_all_yield_times_ms);
2553 }
2554 
2555 void TraceGen1TimeData::record_full_collection(double full_gc_time_ms) {
2556   if (TraceGen1Time) {
2557     _all_full_gc_times.add(full_gc_time_ms);
2558   }
2559 }
2560 
2561 void TraceGen1TimeData::print() const {
2562   if (!TraceGen1Time) {
2563     return;
2564   }
2565 
2566   if (_all_full_gc_times.num() > 0) {
2567     gclog_or_tty->print("\n%4d full_gcs: total time = %8.2f s",
2568       _all_full_gc_times.num(),
2569       _all_full_gc_times.sum() / 1000.0);
2570     gclog_or_tty->print_cr(" (avg = %8.2fms).", _all_full_gc_times.avg());
2571     gclog_or_tty->print_cr("                     [std. dev = %8.2f ms, max = %8.2f ms]",
2572       _all_full_gc_times.sd(),
2573       _all_full_gc_times.maximum());
2574   }
2575 }
src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp
Index Unified diffs Context diffs Sdiffs Patch New Old Previous File Next File