124 va_end(ap);
125 gclog_or_tty->print_cr("%s", _buffer);
126 _cur = _indent_level * INDENT_CHARS;
127 }
128 };
129
130 G1CollectorPolicy::G1CollectorPolicy() :
131 _parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads()
132 ? ParallelGCThreads : 1),
133
134 _recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
135 _all_pause_times_ms(new NumberSeq()),
136 _stop_world_start(0.0),
137 _all_stop_world_times_ms(new NumberSeq()),
138 _all_yield_times_ms(new NumberSeq()),
139
140 _summary(new Summary()),
141
142 _cur_clear_ct_time_ms(0.0),
143 _mark_closure_time_ms(0.0),
144
145 _cur_ref_proc_time_ms(0.0),
146 _cur_ref_enq_time_ms(0.0),
147
148 #ifndef PRODUCT
149 _min_clear_cc_time_ms(-1.0),
150 _max_clear_cc_time_ms(-1.0),
151 _cur_clear_cc_time_ms(0.0),
152 _cum_clear_cc_time_ms(0.0),
153 _num_cc_clears(0L),
154 #endif
155
156 _aux_num(10),
157 _all_aux_times_ms(new NumberSeq[_aux_num]),
158 _cur_aux_start_times_ms(new double[_aux_num]),
159 _cur_aux_times_ms(new double[_aux_num]),
160 _cur_aux_times_set(new bool[_aux_num]),
161
162 _concurrent_mark_remark_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
163 _concurrent_mark_cleanup_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
196
197 _young_gc_eff_seq(new TruncatedSeq(TruncatedSeqLength)),
198
199 _recent_prev_end_times_for_all_gcs_sec(
200 new TruncatedSeq(NumPrevPausesForHeuristics)),
201
202 _recent_avg_pause_time_ratio(0.0),
203
204 _all_full_gc_times_ms(new NumberSeq()),
205
206 _initiate_conc_mark_if_possible(false),
207 _during_initial_mark_pause(false),
208 _should_revert_to_young_gcs(false),
209 _last_young_gc(false),
210 _last_gc_was_young(false),
211
212 _eden_bytes_before_gc(0),
213 _survivor_bytes_before_gc(0),
214 _capacity_before_gc(0),
215
216 _prev_collection_pause_used_at_end_bytes(0),
217
218 _eden_cset_region_length(0),
219 _survivor_cset_region_length(0),
220 _old_cset_region_length(0),
221
222 _collection_set(NULL),
223 _collection_set_bytes_used_before(0),
224
225 // Incremental CSet attributes
226 _inc_cset_build_state(Inactive),
227 _inc_cset_head(NULL),
228 _inc_cset_tail(NULL),
229 _inc_cset_bytes_used_before(0),
230 _inc_cset_max_finger(NULL),
231 _inc_cset_recorded_rs_lengths(0),
232 _inc_cset_recorded_rs_lengths_diffs(0),
233 _inc_cset_predicted_elapsed_time_ms(0.0),
234 _inc_cset_predicted_elapsed_time_ms_diffs(0.0),
235
236 #ifdef _MSC_VER // the use of 'this' below gets a warning, make it go away
237 #pragma warning( disable:4355 ) // 'this' : used in base member initializer list
888
889 _free_regions_at_end_of_collection = _g1->free_regions();
890 // Reset survivors SurvRateGroup.
891 _survivor_surv_rate_group->reset();
892 update_young_list_target_length();
893 _collectionSetChooser->updateAfterFullCollection();
894 }
895
896 void G1CollectorPolicy::record_stop_world_start() {
897 _stop_world_start = os::elapsedTime();
898 }
899
900 void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
901 size_t start_used) {
902 if (PrintGCDetails) {
903 gclog_or_tty->stamp(PrintGCTimeStamps);
904 gclog_or_tty->print("[GC pause");
905 gclog_or_tty->print(" (%s)", gcs_are_young() ? "young" : "mixed");
906 }
907
908 if (!during_initial_mark_pause()) {
909 // We only need to do this here as the policy will only be applied
910 // to the GC we're about to start. so, no point is calculating this
911 // every time we calculate / recalculate the target young length.
912 update_survivors_policy();
913 } else {
914 // The marking phase has a "we only copy implicitly live
915 // objects during marking" invariant. The easiest way to ensure it
916 // holds is not to allocate any survivor regions and tenure all
917 // objects. In the future we might change this and handle survivor
918 // regions specially during marking.
919 tenure_all_objects();
920 }
921
922 assert(_g1->used() == _g1->recalculate_used(),
923 err_msg("sanity, used: "SIZE_FORMAT" recalculate_used: "SIZE_FORMAT,
924 _g1->used(), _g1->recalculate_used()));
925
926 double s_w_t_ms = (start_time_sec - _stop_world_start) * 1000.0;
927 _all_stop_world_times_ms->add(s_w_t_ms);
928 _stop_world_start = 0.0;
929
930 _cur_collection_start_sec = start_time_sec;
931 _cur_collection_pause_used_at_start_bytes = start_used;
932 _cur_collection_pause_used_regions_at_start = _g1->used_regions();
933 _pending_cards = _g1->pending_card_num();
934 _max_pending_cards = _g1->max_pending_card_num();
935
936 _bytes_in_collection_set_before_gc = 0;
937 _bytes_copied_during_gc = 0;
938
939 YoungList* young_list = _g1->young_list();
940 _eden_bytes_before_gc = young_list->eden_used_bytes();
952 _par_last_update_rs_times_ms[i] = -1234.0;
953 _par_last_update_rs_processed_buffers[i] = -1234.0;
954 _par_last_scan_rs_times_ms[i] = -1234.0;
955 _par_last_obj_copy_times_ms[i] = -1234.0;
956 _par_last_termination_times_ms[i] = -1234.0;
957 _par_last_termination_attempts[i] = -1234.0;
958 _par_last_gc_worker_end_times_ms[i] = -1234.0;
959 _par_last_gc_worker_times_ms[i] = -1234.0;
960 _par_last_gc_worker_other_times_ms[i] = -1234.0;
961 }
962 #endif
963
964 for (int i = 0; i < _aux_num; ++i) {
965 _cur_aux_times_ms[i] = 0.0;
966 _cur_aux_times_set[i] = false;
967 }
968
969 // This is initialized to zero here and is set during
970 // the evacuation pause if marking is in progress.
971 _cur_satb_drain_time_ms = 0.0;
972
973 _last_gc_was_young = false;
974
975 // do that for any other surv rate groups
976 _short_lived_surv_rate_group->stop_adding_regions();
977 _survivors_age_table.clear();
978
979 assert( verify_young_ages(), "region age verification" );
980 }
981
982 void G1CollectorPolicy::record_concurrent_mark_init_end(double
983 mark_init_elapsed_time_ms) {
984 _during_marking = true;
985 assert(!initiate_conc_mark_if_possible(), "we should have cleared it by now");
986 clear_during_initial_mark_pause();
987 _cur_mark_stop_world_time_ms = mark_init_elapsed_time_ms;
988 }
989
990 void G1CollectorPolicy::record_concurrent_mark_remark_start() {
991 _mark_remark_start_sec = os::elapsedTime();
1123 return sum;
1124 } else {
1125 return data[0];
1126 }
1127 }
1128
1129 double G1CollectorPolicy::max_sum(double* data1, double* data2) {
1130 double ret = data1[0] + data2[0];
1131
1132 if (G1CollectedHeap::use_parallel_gc_threads()) {
1133 for (uint i = 1; i < no_of_gc_threads(); ++i) {
1134 double data = data1[i] + data2[i];
1135 if (data > ret) {
1136 ret = data;
1137 }
1138 }
1139 }
1140 return ret;
1141 }
1142
1143 // Anything below that is considered to be zero
1144 #define MIN_TIMER_GRANULARITY 0.0000001
1145
1146 void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
1147 double end_time_sec = os::elapsedTime();
1148 double elapsed_ms = _last_pause_time_ms;
1149 bool parallel = G1CollectedHeap::use_parallel_gc_threads();
1150 assert(_cur_collection_pause_used_regions_at_start >= cset_region_length(),
1151 "otherwise, the subtraction below does not make sense");
1152 size_t rs_size =
1153 _cur_collection_pause_used_regions_at_start - cset_region_length();
1154 size_t cur_used_bytes = _g1->used();
1155 assert(cur_used_bytes == _g1->recalculate_used(), "It should!");
1156 bool last_pause_included_initial_mark = false;
1157 bool update_stats = !_g1->evacuation_failed();
1158 set_no_of_gc_threads(no_of_gc_threads);
1159
1160 #ifndef PRODUCT
1161 if (G1YoungSurvRateVerbose) {
1162 gclog_or_tty->print_cr("");
1163 _short_lived_surv_rate_group->print();
1164 // do that for any other surv rate groups too
1165 }
1166 #endif // PRODUCT
1167
1168 last_pause_included_initial_mark = during_initial_mark_pause();
1169 if (last_pause_included_initial_mark)
1170 record_concurrent_mark_init_end(0.0);
1171
1172 size_t marking_initiating_used_threshold =
1173 (_g1->capacity() / 100) * InitiatingHeapOccupancyPercent;
1174
1175 if (!_g1->mark_in_progress() && !_last_young_gc) {
1176 assert(!last_pause_included_initial_mark, "invariant");
1177 if (cur_used_bytes > marking_initiating_used_threshold) {
1178 if (cur_used_bytes > _prev_collection_pause_used_at_end_bytes) {
1179 assert(!during_initial_mark_pause(), "we should not see this here");
1180
1181 ergo_verbose3(ErgoConcCycles,
1182 "request concurrent cycle initiation",
1183 ergo_format_reason("occupancy higher than threshold")
1184 ergo_format_byte("occupancy")
1185 ergo_format_byte_perc("threshold"),
1186 cur_used_bytes,
1187 marking_initiating_used_threshold,
1188 (double) InitiatingHeapOccupancyPercent);
1189
1190 // Note: this might have already been set, if during the last
1191 // pause we decided to start a cycle but at the beginning of
1192 // this pause we decided to postpone it. That's OK.
1193 set_initiate_conc_mark_if_possible();
1194 } else {
1195 ergo_verbose2(ErgoConcCycles,
1196 "do not request concurrent cycle initiation",
1197 ergo_format_reason("occupancy lower than previous occupancy")
1198 ergo_format_byte("occupancy")
1199 ergo_format_byte("previous occupancy"),
1200 cur_used_bytes,
1201 _prev_collection_pause_used_at_end_bytes);
1202 }
1203 }
1204 }
1205
1206 _prev_collection_pause_used_at_end_bytes = cur_used_bytes;
1207
1208 _mmu_tracker->add_pause(end_time_sec - elapsed_ms/1000.0,
1209 end_time_sec, false);
1210
1211 // This assert is exempted when we're doing parallel collection pauses,
1212 // because the fragmentation caused by the parallel GC allocation buffers
1213 // can lead to more memory being used during collection than was used
1214 // before. Best leave this out until the fragmentation problem is fixed.
1215 // Pauses in which evacuation failed can also lead to negative
1216 // collections, since no space is reclaimed from a region containing an
1217 // object whose evacuation failed.
1218 // Further, we're now always doing parallel collection. But I'm still
1219 // leaving this here as a placeholder for a more precise assertion later.
1220 // (DLD, 10/05.)
1221 assert((true || parallel) // Always using GC LABs now.
1222 || _g1->evacuation_failed()
1223 || _cur_collection_pause_used_at_start_bytes >= cur_used_bytes,
1224 "Negative collection");
1225
1226 size_t freed_bytes =
1227 _cur_collection_pause_used_at_start_bytes - cur_used_bytes;
1240 double update_rs_time = avg_value(_par_last_update_rs_times_ms);
1241 double update_rs_processed_buffers =
1242 sum_of_values(_par_last_update_rs_processed_buffers);
1243 double scan_rs_time = avg_value(_par_last_scan_rs_times_ms);
1244 double obj_copy_time = avg_value(_par_last_obj_copy_times_ms);
1245 double termination_time = avg_value(_par_last_termination_times_ms);
1246
1247 double known_time = ext_root_scan_time +
1248 satb_filtering_time +
1249 update_rs_time +
1250 scan_rs_time +
1251 obj_copy_time;
1252
1253 double other_time_ms = elapsed_ms;
1254
1255 // Subtract the SATB drain time. It's initialized to zero at the
1256 // start of the pause and is updated during the pause if marking
1257 // is in progress.
1258 other_time_ms -= _cur_satb_drain_time_ms;
1259
1260 if (parallel) {
1261 other_time_ms -= _cur_collection_par_time_ms;
1262 } else {
1263 other_time_ms -= known_time;
1264 }
1265
1266 // Subtract the time taken to clean the card table from the
1267 // current value of "other time"
1268 other_time_ms -= _cur_clear_ct_time_ms;
1269
1270 // Subtract the time spent completing marking in the collection
1271 // set. Note if marking is not in progress during the pause
1272 // the value of _mark_closure_time_ms will be zero.
1273 other_time_ms -= _mark_closure_time_ms;
1274
1275 // TraceGen0Time and TraceGen1Time summary info updating.
1276 _all_pause_times_ms->add(elapsed_ms);
1277
1278 if (update_stats) {
1279 _summary->record_total_time_ms(elapsed_ms);
1280 _summary->record_other_time_ms(other_time_ms);
1281
1282 MainBodySummary* body_summary = _summary->main_body_summary();
1283 assert(body_summary != NULL, "should not be null!");
1284
1285 // This will be non-zero iff marking is currently in progress (i.e.
1286 // _g1->mark_in_progress() == true) and the currrent pause was not
1287 // an initial mark pause. Since the body_summary items are NumberSeqs,
1288 // however, they have to be consistent and updated in lock-step with
1289 // each other. Therefore we unconditionally record the SATB drain
1290 // time - even if it's zero.
1291 body_summary->record_satb_drain_time_ms(_cur_satb_drain_time_ms);
1292
1293 body_summary->record_ext_root_scan_time_ms(ext_root_scan_time);
1294 body_summary->record_satb_filtering_time_ms(satb_filtering_time);
1295 body_summary->record_update_rs_time_ms(update_rs_time);
1296 body_summary->record_scan_rs_time_ms(scan_rs_time);
1297 body_summary->record_obj_copy_time_ms(obj_copy_time);
1298
1299 if (parallel) {
1300 body_summary->record_parallel_time_ms(_cur_collection_par_time_ms);
1301 body_summary->record_termination_time_ms(termination_time);
1302
1303 double parallel_known_time = known_time + termination_time;
1304 double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time;
1305 body_summary->record_parallel_other_time_ms(parallel_other_time);
1306 }
1307
1308 body_summary->record_mark_closure_time_ms(_mark_closure_time_ms);
1309 body_summary->record_clear_ct_time_ms(_cur_clear_ct_time_ms);
1310
1311 // We exempt parallel collection from this check because Alloc Buffer
1368 _recent_avg_pause_time_ratio = 1.0;
1369 }
1370 }
1371 }
1372
1373 for (int i = 0; i < _aux_num; ++i) {
1374 if (_cur_aux_times_set[i]) {
1375 _all_aux_times_ms[i].add(_cur_aux_times_ms[i]);
1376 }
1377 }
1378
1379 // PrintGCDetails output
1380 if (PrintGCDetails) {
1381 bool print_marking_info =
1382 _g1->mark_in_progress() && !last_pause_included_initial_mark;
1383
1384 gclog_or_tty->print_cr("%s, %1.8lf secs]",
1385 (last_pause_included_initial_mark) ? " (initial-mark)" : "",
1386 elapsed_ms / 1000.0);
1387
1388 if (parallel) {
1389 print_stats(1, "Parallel Time", _cur_collection_par_time_ms);
1390 print_par_stats(2, "GC Worker Start", _par_last_gc_worker_start_times_ms);
1391 print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms);
1392 if (print_marking_info) {
1393 print_par_stats(2, "SATB Filtering", _par_last_satb_filtering_times_ms);
1394 }
1395 print_par_stats(2, "Update RS", _par_last_update_rs_times_ms);
1396 print_par_sizes(3, "Processed Buffers", _par_last_update_rs_processed_buffers);
1397 print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms);
1398 print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms);
1399 print_par_stats(2, "Termination", _par_last_termination_times_ms);
1400 print_par_sizes(3, "Termination Attempts", _par_last_termination_attempts);
1401 print_par_stats(2, "GC Worker End", _par_last_gc_worker_end_times_ms);
1402
1403 for (int i = 0; i < _parallel_gc_threads; i++) {
1404 _par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] - _par_last_gc_worker_start_times_ms[i];
1405
1406 double worker_known_time = _par_last_ext_root_scan_times_ms[i] +
1407 _par_last_satb_filtering_times_ms[i] +
1971 if (calc_other_times_ms->sum() < -0.01) {
1972 should_print = true;
1973 buf.append_and_print_cr("## CALCULATED OTHER SUM IS NEGATIVE ###");
1974 }
1975
1976 if (calc_other_times_ms->avg() < -0.01) {
1977 should_print = true;
1978 buf.append_and_print_cr("## CALCULATED OTHER AVG IS NEGATIVE ###");
1979 }
1980
1981 if (should_print)
1982 print_summary(level, "Other(Calc)", calc_other_times_ms);
1983 }
1984
1985 void G1CollectorPolicy::print_summary(PauseSummary* summary) const {
1986 bool parallel = G1CollectedHeap::use_parallel_gc_threads();
1987 MainBodySummary* body_summary = summary->main_body_summary();
1988 if (summary->get_total_seq()->num() > 0) {
1989 print_summary_sd(0, "Evacuation Pauses", summary->get_total_seq());
1990 if (body_summary != NULL) {
1991 if (parallel) {
1992 print_summary(1, "Parallel Time", body_summary->get_parallel_seq());
1993 print_summary(2, "Ext Root Scanning", body_summary->get_ext_root_scan_seq());
1994 print_summary(2, "SATB Filtering", body_summary->get_satb_filtering_seq());
1995 print_summary(2, "Update RS", body_summary->get_update_rs_seq());
1996 print_summary(2, "Scan RS", body_summary->get_scan_rs_seq());
1997 print_summary(2, "Object Copy", body_summary->get_obj_copy_seq());
1998 print_summary(2, "Termination", body_summary->get_termination_seq());
1999 print_summary(2, "Parallel Other", body_summary->get_parallel_other_seq());
2000 {
2001 NumberSeq* other_parts[] = {
2002 body_summary->get_ext_root_scan_seq(),
2003 body_summary->get_satb_filtering_seq(),
2004 body_summary->get_update_rs_seq(),
2005 body_summary->get_scan_rs_seq(),
2006 body_summary->get_obj_copy_seq(),
2007 body_summary->get_termination_seq()
2008 };
2009 NumberSeq calc_other_times_ms(body_summary->get_parallel_seq(),
2010 6, other_parts);
2012 &calc_other_times_ms);
2013 }
2014 } else {
2015 print_summary(1, "Ext Root Scanning", body_summary->get_ext_root_scan_seq());
2016 print_summary(1, "SATB Filtering", body_summary->get_satb_filtering_seq());
2017 print_summary(1, "Update RS", body_summary->get_update_rs_seq());
2018 print_summary(1, "Scan RS", body_summary->get_scan_rs_seq());
2019 print_summary(1, "Object Copy", body_summary->get_obj_copy_seq());
2020 }
2021 }
2022 print_summary(1, "Mark Closure", body_summary->get_mark_closure_seq());
2023 print_summary(1, "Clear CT", body_summary->get_clear_ct_seq());
2024 print_summary(1, "Other", summary->get_other_seq());
2025 {
2026 if (body_summary != NULL) {
2027 NumberSeq calc_other_times_ms;
2028 if (parallel) {
2029 // parallel
2030 NumberSeq* other_parts[] = {
2031 body_summary->get_satb_drain_seq(),
2032 body_summary->get_parallel_seq(),
2033 body_summary->get_clear_ct_seq()
2034 };
2035 calc_other_times_ms = NumberSeq(summary->get_total_seq(),
2036 3, other_parts);
2037 } else {
2038 // serial
2039 NumberSeq* other_parts[] = {
2040 body_summary->get_satb_drain_seq(),
2041 body_summary->get_update_rs_seq(),
2042 body_summary->get_ext_root_scan_seq(),
2043 body_summary->get_satb_filtering_seq(),
2044 body_summary->get_scan_rs_seq(),
2045 body_summary->get_obj_copy_seq()
2046 };
2047 calc_other_times_ms = NumberSeq(summary->get_total_seq(),
2048 6, other_parts);
2049 }
2050 check_other_times(1, summary->get_other_seq(), &calc_other_times_ms);
2051 }
2052 }
2053 } else {
2054 LineBuffer(1).append_and_print_cr("none");
2055 }
2056 LineBuffer(0).append_and_print_cr("");
2057 }
2058
2059 void G1CollectorPolicy::print_tracing_info() const {
2060 if (TraceGen0Time) {
2061 gclog_or_tty->print_cr("ALL PAUSES");
2062 print_summary_sd(0, "Total", _all_pause_times_ms);
2063 gclog_or_tty->print_cr("");
2064 gclog_or_tty->print_cr("");
2065 gclog_or_tty->print_cr(" Young GC Pauses: %8d", _young_pause_num);
2066 gclog_or_tty->print_cr(" Mixed GC Pauses: %8d", _mixed_pause_num);
2067 gclog_or_tty->print_cr("");
2068
|
124 va_end(ap);
125 gclog_or_tty->print_cr("%s", _buffer);
126 _cur = _indent_level * INDENT_CHARS;
127 }
128 };
129
130 G1CollectorPolicy::G1CollectorPolicy() :
131 _parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads()
132 ? ParallelGCThreads : 1),
133
134 _recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
135 _all_pause_times_ms(new NumberSeq()),
136 _stop_world_start(0.0),
137 _all_stop_world_times_ms(new NumberSeq()),
138 _all_yield_times_ms(new NumberSeq()),
139
140 _summary(new Summary()),
141
142 _cur_clear_ct_time_ms(0.0),
143 _mark_closure_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)),
197
198 _young_gc_eff_seq(new TruncatedSeq(TruncatedSeqLength)),
199
200 _recent_prev_end_times_for_all_gcs_sec(
201 new TruncatedSeq(NumPrevPausesForHeuristics)),
202
203 _recent_avg_pause_time_ratio(0.0),
204
205 _all_full_gc_times_ms(new NumberSeq()),
206
207 _initiate_conc_mark_if_possible(false),
208 _during_initial_mark_pause(false),
209 _should_revert_to_young_gcs(false),
210 _last_young_gc(false),
211 _last_gc_was_young(false),
212
213 _eden_bytes_before_gc(0),
214 _survivor_bytes_before_gc(0),
215 _capacity_before_gc(0),
216
217 _eden_cset_region_length(0),
218 _survivor_cset_region_length(0),
219 _old_cset_region_length(0),
220
221 _collection_set(NULL),
222 _collection_set_bytes_used_before(0),
223
224 // Incremental CSet attributes
225 _inc_cset_build_state(Inactive),
226 _inc_cset_head(NULL),
227 _inc_cset_tail(NULL),
228 _inc_cset_bytes_used_before(0),
229 _inc_cset_max_finger(NULL),
230 _inc_cset_recorded_rs_lengths(0),
231 _inc_cset_recorded_rs_lengths_diffs(0),
232 _inc_cset_predicted_elapsed_time_ms(0.0),
233 _inc_cset_predicted_elapsed_time_ms_diffs(0.0),
234
235 #ifdef _MSC_VER // the use of 'this' below gets a warning, make it go away
236 #pragma warning( disable:4355 ) // 'this' : used in base member initializer list
887
888 _free_regions_at_end_of_collection = _g1->free_regions();
889 // Reset survivors SurvRateGroup.
890 _survivor_surv_rate_group->reset();
891 update_young_list_target_length();
892 _collectionSetChooser->updateAfterFullCollection();
893 }
894
895 void G1CollectorPolicy::record_stop_world_start() {
896 _stop_world_start = os::elapsedTime();
897 }
898
899 void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
900 size_t start_used) {
901 if (PrintGCDetails) {
902 gclog_or_tty->stamp(PrintGCTimeStamps);
903 gclog_or_tty->print("[GC pause");
904 gclog_or_tty->print(" (%s)", gcs_are_young() ? "young" : "mixed");
905 }
906
907 // We only need to do this here as the policy will only be applied
908 // to the GC we're about to start. so, no point is calculating this
909 // every time we calculate / recalculate the target young length.
910 update_survivors_policy();
911
912 assert(_g1->used() == _g1->recalculate_used(),
913 err_msg("sanity, used: "SIZE_FORMAT" recalculate_used: "SIZE_FORMAT,
914 _g1->used(), _g1->recalculate_used()));
915
916 double s_w_t_ms = (start_time_sec - _stop_world_start) * 1000.0;
917 _all_stop_world_times_ms->add(s_w_t_ms);
918 _stop_world_start = 0.0;
919
920 _cur_collection_start_sec = start_time_sec;
921 _cur_collection_pause_used_at_start_bytes = start_used;
922 _cur_collection_pause_used_regions_at_start = _g1->used_regions();
923 _pending_cards = _g1->pending_card_num();
924 _max_pending_cards = _g1->max_pending_card_num();
925
926 _bytes_in_collection_set_before_gc = 0;
927 _bytes_copied_during_gc = 0;
928
929 YoungList* young_list = _g1->young_list();
930 _eden_bytes_before_gc = young_list->eden_used_bytes();
942 _par_last_update_rs_times_ms[i] = -1234.0;
943 _par_last_update_rs_processed_buffers[i] = -1234.0;
944 _par_last_scan_rs_times_ms[i] = -1234.0;
945 _par_last_obj_copy_times_ms[i] = -1234.0;
946 _par_last_termination_times_ms[i] = -1234.0;
947 _par_last_termination_attempts[i] = -1234.0;
948 _par_last_gc_worker_end_times_ms[i] = -1234.0;
949 _par_last_gc_worker_times_ms[i] = -1234.0;
950 _par_last_gc_worker_other_times_ms[i] = -1234.0;
951 }
952 #endif
953
954 for (int i = 0; i < _aux_num; ++i) {
955 _cur_aux_times_ms[i] = 0.0;
956 _cur_aux_times_set[i] = false;
957 }
958
959 // This is initialized to zero here and is set during
960 // the evacuation pause if marking is in progress.
961 _cur_satb_drain_time_ms = 0.0;
962 // This is initialized to zero here and is set during the evacuation
963 // pause if we actually waited for the root region scanning to finish.
964 _root_region_scan_wait_time_ms = 0.0;
965
966 _last_gc_was_young = false;
967
968 // do that for any other surv rate groups
969 _short_lived_surv_rate_group->stop_adding_regions();
970 _survivors_age_table.clear();
971
972 assert( verify_young_ages(), "region age verification" );
973 }
974
975 void G1CollectorPolicy::record_concurrent_mark_init_end(double
976 mark_init_elapsed_time_ms) {
977 _during_marking = true;
978 assert(!initiate_conc_mark_if_possible(), "we should have cleared it by now");
979 clear_during_initial_mark_pause();
980 _cur_mark_stop_world_time_ms = mark_init_elapsed_time_ms;
981 }
982
983 void G1CollectorPolicy::record_concurrent_mark_remark_start() {
984 _mark_remark_start_sec = os::elapsedTime();
1116 return sum;
1117 } else {
1118 return data[0];
1119 }
1120 }
1121
1122 double G1CollectorPolicy::max_sum(double* data1, double* data2) {
1123 double ret = data1[0] + data2[0];
1124
1125 if (G1CollectedHeap::use_parallel_gc_threads()) {
1126 for (uint i = 1; i < no_of_gc_threads(); ++i) {
1127 double data = data1[i] + data2[i];
1128 if (data > ret) {
1129 ret = data;
1130 }
1131 }
1132 }
1133 return ret;
1134 }
1135
1136 bool G1CollectorPolicy::need_to_start_conc_mark(const char* source, size_t alloc_word_size) {
1137 if (_g1->concurrent_mark()->cmThread()->during_cycle()) {
1138 return false;
1139 }
1140
1141 size_t marking_initiating_used_threshold =
1142 (_g1->capacity() / 100) * InitiatingHeapOccupancyPercent;
1143 size_t cur_used_bytes = _g1->non_young_capacity_bytes();
1144 size_t alloc_byte_size = alloc_word_size * HeapWordSize;
1145
1146 if ((cur_used_bytes + alloc_byte_size) > marking_initiating_used_threshold) {
1147 if (gcs_are_young()) {
1148 ergo_verbose5(ErgoConcCycles,
1149 "request concurrent cycle initiation",
1150 ergo_format_reason("occupancy higher than threshold")
1151 ergo_format_byte("occupancy")
1152 ergo_format_byte("allocation request")
1153 ergo_format_byte_perc("threshold")
1154 ergo_format_str("source"),
1155 cur_used_bytes,
1156 alloc_byte_size,
1157 marking_initiating_used_threshold,
1158 (double) InitiatingHeapOccupancyPercent,
1159 source);
1160 return true;
1161 } else {
1162 ergo_verbose5(ErgoConcCycles,
1163 "do not request concurrent cycle initiation",
1164 ergo_format_reason("still doing mixed collections")
1165 ergo_format_byte("occupancy")
1166 ergo_format_byte("allocation request")
1167 ergo_format_byte_perc("threshold")
1168 ergo_format_str("source"),
1169 cur_used_bytes,
1170 alloc_byte_size,
1171 marking_initiating_used_threshold,
1172 (double) InitiatingHeapOccupancyPercent,
1173 source);
1174 }
1175 }
1176
1177 return false;
1178 }
1179
1180 // Anything below that is considered to be zero
1181 #define MIN_TIMER_GRANULARITY 0.0000001
1182
1183 void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
1184 double end_time_sec = os::elapsedTime();
1185 double elapsed_ms = _last_pause_time_ms;
1186 bool parallel = G1CollectedHeap::use_parallel_gc_threads();
1187 assert(_cur_collection_pause_used_regions_at_start >= cset_region_length(),
1188 "otherwise, the subtraction below does not make sense");
1189 size_t rs_size =
1190 _cur_collection_pause_used_regions_at_start - cset_region_length();
1191 size_t cur_used_bytes = _g1->used();
1192 assert(cur_used_bytes == _g1->recalculate_used(), "It should!");
1193 bool last_pause_included_initial_mark = false;
1194 bool update_stats = !_g1->evacuation_failed();
1195 set_no_of_gc_threads(no_of_gc_threads);
1196
1197 #ifndef PRODUCT
1198 if (G1YoungSurvRateVerbose) {
1199 gclog_or_tty->print_cr("");
1200 _short_lived_surv_rate_group->print();
1201 // do that for any other surv rate groups too
1202 }
1203 #endif // PRODUCT
1204
1205 last_pause_included_initial_mark = during_initial_mark_pause();
1206 if (last_pause_included_initial_mark) {
1207 record_concurrent_mark_init_end(0.0);
1208 }
1209
1210 if (!_last_young_gc && need_to_start_conc_mark("end of GC")) {
1211 // Note: this might have already been set, if during the last
1212 // pause we decided to start a cycle but at the beginning of
1213 // this pause we decided to postpone it. That's OK.
1214 set_initiate_conc_mark_if_possible();
1215 }
1216
1217 _mmu_tracker->add_pause(end_time_sec - elapsed_ms/1000.0,
1218 end_time_sec, false);
1219
1220 // This assert is exempted when we're doing parallel collection pauses,
1221 // because the fragmentation caused by the parallel GC allocation buffers
1222 // can lead to more memory being used during collection than was used
1223 // before. Best leave this out until the fragmentation problem is fixed.
1224 // Pauses in which evacuation failed can also lead to negative
1225 // collections, since no space is reclaimed from a region containing an
1226 // object whose evacuation failed.
1227 // Further, we're now always doing parallel collection. But I'm still
1228 // leaving this here as a placeholder for a more precise assertion later.
1229 // (DLD, 10/05.)
1230 assert((true || parallel) // Always using GC LABs now.
1231 || _g1->evacuation_failed()
1232 || _cur_collection_pause_used_at_start_bytes >= cur_used_bytes,
1233 "Negative collection");
1234
1235 size_t freed_bytes =
1236 _cur_collection_pause_used_at_start_bytes - cur_used_bytes;
1249 double update_rs_time = avg_value(_par_last_update_rs_times_ms);
1250 double update_rs_processed_buffers =
1251 sum_of_values(_par_last_update_rs_processed_buffers);
1252 double scan_rs_time = avg_value(_par_last_scan_rs_times_ms);
1253 double obj_copy_time = avg_value(_par_last_obj_copy_times_ms);
1254 double termination_time = avg_value(_par_last_termination_times_ms);
1255
1256 double known_time = ext_root_scan_time +
1257 satb_filtering_time +
1258 update_rs_time +
1259 scan_rs_time +
1260 obj_copy_time;
1261
1262 double other_time_ms = elapsed_ms;
1263
1264 // Subtract the SATB drain time. It's initialized to zero at the
1265 // start of the pause and is updated during the pause if marking
1266 // is in progress.
1267 other_time_ms -= _cur_satb_drain_time_ms;
1268
1269 // Subtract the root region scanning wait time. It's initialized to
1270 // zero at the start of the pause.
1271 other_time_ms -= _root_region_scan_wait_time_ms;
1272
1273 if (parallel) {
1274 other_time_ms -= _cur_collection_par_time_ms;
1275 } else {
1276 other_time_ms -= known_time;
1277 }
1278
1279 // Subtract the time taken to clean the card table from the
1280 // current value of "other time"
1281 other_time_ms -= _cur_clear_ct_time_ms;
1282
1283 // Subtract the time spent completing marking in the collection
1284 // set. Note if marking is not in progress during the pause
1285 // the value of _mark_closure_time_ms will be zero.
1286 other_time_ms -= _mark_closure_time_ms;
1287
1288 // TraceGen0Time and TraceGen1Time summary info updating.
1289 _all_pause_times_ms->add(elapsed_ms);
1290
1291 if (update_stats) {
1292 _summary->record_total_time_ms(elapsed_ms);
1293 _summary->record_other_time_ms(other_time_ms);
1294
1295 MainBodySummary* body_summary = _summary->main_body_summary();
1296 assert(body_summary != NULL, "should not be null!");
1297
1298 // This will be non-zero iff marking is currently in progress (i.e.
1299 // _g1->mark_in_progress() == true) and the currrent pause was not
1300 // an initial mark pause. Since the body_summary items are NumberSeqs,
1301 // however, they have to be consistent and updated in lock-step with
1302 // each other. Therefore we unconditionally record the SATB drain
1303 // time - even if it's zero.
1304 body_summary->record_satb_drain_time_ms(_cur_satb_drain_time_ms);
1305 body_summary->record_root_region_scan_wait_time_ms(
1306 _root_region_scan_wait_time_ms);
1307
1308 body_summary->record_ext_root_scan_time_ms(ext_root_scan_time);
1309 body_summary->record_satb_filtering_time_ms(satb_filtering_time);
1310 body_summary->record_update_rs_time_ms(update_rs_time);
1311 body_summary->record_scan_rs_time_ms(scan_rs_time);
1312 body_summary->record_obj_copy_time_ms(obj_copy_time);
1313
1314 if (parallel) {
1315 body_summary->record_parallel_time_ms(_cur_collection_par_time_ms);
1316 body_summary->record_termination_time_ms(termination_time);
1317
1318 double parallel_known_time = known_time + termination_time;
1319 double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time;
1320 body_summary->record_parallel_other_time_ms(parallel_other_time);
1321 }
1322
1323 body_summary->record_mark_closure_time_ms(_mark_closure_time_ms);
1324 body_summary->record_clear_ct_time_ms(_cur_clear_ct_time_ms);
1325
1326 // We exempt parallel collection from this check because Alloc Buffer
1383 _recent_avg_pause_time_ratio = 1.0;
1384 }
1385 }
1386 }
1387
1388 for (int i = 0; i < _aux_num; ++i) {
1389 if (_cur_aux_times_set[i]) {
1390 _all_aux_times_ms[i].add(_cur_aux_times_ms[i]);
1391 }
1392 }
1393
1394 // PrintGCDetails output
1395 if (PrintGCDetails) {
1396 bool print_marking_info =
1397 _g1->mark_in_progress() && !last_pause_included_initial_mark;
1398
1399 gclog_or_tty->print_cr("%s, %1.8lf secs]",
1400 (last_pause_included_initial_mark) ? " (initial-mark)" : "",
1401 elapsed_ms / 1000.0);
1402
1403 if (_root_region_scan_wait_time_ms > 0.0) {
1404 print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
1405 }
1406 if (parallel) {
1407 print_stats(1, "Parallel Time", _cur_collection_par_time_ms);
1408 print_par_stats(2, "GC Worker Start", _par_last_gc_worker_start_times_ms);
1409 print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms);
1410 if (print_marking_info) {
1411 print_par_stats(2, "SATB Filtering", _par_last_satb_filtering_times_ms);
1412 }
1413 print_par_stats(2, "Update RS", _par_last_update_rs_times_ms);
1414 print_par_sizes(3, "Processed Buffers", _par_last_update_rs_processed_buffers);
1415 print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms);
1416 print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms);
1417 print_par_stats(2, "Termination", _par_last_termination_times_ms);
1418 print_par_sizes(3, "Termination Attempts", _par_last_termination_attempts);
1419 print_par_stats(2, "GC Worker End", _par_last_gc_worker_end_times_ms);
1420
1421 for (int i = 0; i < _parallel_gc_threads; i++) {
1422 _par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] - _par_last_gc_worker_start_times_ms[i];
1423
1424 double worker_known_time = _par_last_ext_root_scan_times_ms[i] +
1425 _par_last_satb_filtering_times_ms[i] +
1989 if (calc_other_times_ms->sum() < -0.01) {
1990 should_print = true;
1991 buf.append_and_print_cr("## CALCULATED OTHER SUM IS NEGATIVE ###");
1992 }
1993
1994 if (calc_other_times_ms->avg() < -0.01) {
1995 should_print = true;
1996 buf.append_and_print_cr("## CALCULATED OTHER AVG IS NEGATIVE ###");
1997 }
1998
1999 if (should_print)
2000 print_summary(level, "Other(Calc)", calc_other_times_ms);
2001 }
2002
2003 void G1CollectorPolicy::print_summary(PauseSummary* summary) const {
2004 bool parallel = G1CollectedHeap::use_parallel_gc_threads();
2005 MainBodySummary* body_summary = summary->main_body_summary();
2006 if (summary->get_total_seq()->num() > 0) {
2007 print_summary_sd(0, "Evacuation Pauses", summary->get_total_seq());
2008 if (body_summary != NULL) {
2009 print_summary(1, "Root Region Scan Wait", body_summary->get_root_region_scan_wait_seq());
2010 if (parallel) {
2011 print_summary(1, "Parallel Time", body_summary->get_parallel_seq());
2012 print_summary(2, "Ext Root Scanning", body_summary->get_ext_root_scan_seq());
2013 print_summary(2, "SATB Filtering", body_summary->get_satb_filtering_seq());
2014 print_summary(2, "Update RS", body_summary->get_update_rs_seq());
2015 print_summary(2, "Scan RS", body_summary->get_scan_rs_seq());
2016 print_summary(2, "Object Copy", body_summary->get_obj_copy_seq());
2017 print_summary(2, "Termination", body_summary->get_termination_seq());
2018 print_summary(2, "Parallel Other", body_summary->get_parallel_other_seq());
2019 {
2020 NumberSeq* other_parts[] = {
2021 body_summary->get_ext_root_scan_seq(),
2022 body_summary->get_satb_filtering_seq(),
2023 body_summary->get_update_rs_seq(),
2024 body_summary->get_scan_rs_seq(),
2025 body_summary->get_obj_copy_seq(),
2026 body_summary->get_termination_seq()
2027 };
2028 NumberSeq calc_other_times_ms(body_summary->get_parallel_seq(),
2029 6, other_parts);
2031 &calc_other_times_ms);
2032 }
2033 } else {
2034 print_summary(1, "Ext Root Scanning", body_summary->get_ext_root_scan_seq());
2035 print_summary(1, "SATB Filtering", body_summary->get_satb_filtering_seq());
2036 print_summary(1, "Update RS", body_summary->get_update_rs_seq());
2037 print_summary(1, "Scan RS", body_summary->get_scan_rs_seq());
2038 print_summary(1, "Object Copy", body_summary->get_obj_copy_seq());
2039 }
2040 }
2041 print_summary(1, "Mark Closure", body_summary->get_mark_closure_seq());
2042 print_summary(1, "Clear CT", body_summary->get_clear_ct_seq());
2043 print_summary(1, "Other", summary->get_other_seq());
2044 {
2045 if (body_summary != NULL) {
2046 NumberSeq calc_other_times_ms;
2047 if (parallel) {
2048 // parallel
2049 NumberSeq* other_parts[] = {
2050 body_summary->get_satb_drain_seq(),
2051 body_summary->get_root_region_scan_wait_seq(),
2052 body_summary->get_parallel_seq(),
2053 body_summary->get_clear_ct_seq()
2054 };
2055 calc_other_times_ms = NumberSeq(summary->get_total_seq(),
2056 4, other_parts);
2057 } else {
2058 // serial
2059 NumberSeq* other_parts[] = {
2060 body_summary->get_satb_drain_seq(),
2061 body_summary->get_root_region_scan_wait_seq(),
2062 body_summary->get_update_rs_seq(),
2063 body_summary->get_ext_root_scan_seq(),
2064 body_summary->get_satb_filtering_seq(),
2065 body_summary->get_scan_rs_seq(),
2066 body_summary->get_obj_copy_seq()
2067 };
2068 calc_other_times_ms = NumberSeq(summary->get_total_seq(),
2069 7, other_parts);
2070 }
2071 check_other_times(1, summary->get_other_seq(), &calc_other_times_ms);
2072 }
2073 }
2074 } else {
2075 LineBuffer(1).append_and_print_cr("none");
2076 }
2077 LineBuffer(0).append_and_print_cr("");
2078 }
2079
2080 void G1CollectorPolicy::print_tracing_info() const {
2081 if (TraceGen0Time) {
2082 gclog_or_tty->print_cr("ALL PAUSES");
2083 print_summary_sd(0, "Total", _all_pause_times_ms);
2084 gclog_or_tty->print_cr("");
2085 gclog_or_tty->print_cr("");
2086 gclog_or_tty->print_cr(" Young GC Pauses: %8d", _young_pause_num);
2087 gclog_or_tty->print_cr(" Mixed GC Pauses: %8d", _mixed_pause_num);
2088 gclog_or_tty->print_cr("");
2089
|