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
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
2553 // Clear the fields that point to the survivor list - they are all young now.
2554 young_list->clear_survivors();
2555
2556 _collection_set = _inc_cset_head;
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
178 _during_marking(false),
179 _in_marking_window(false),
180 _in_marking_window_im(false),
181
182 _recent_prev_end_times_for_all_gcs_sec(
183 new TruncatedSeq(NumPrevPausesForHeuristics)),
184
185 _recent_avg_pause_time_ratio(0.0),
186
187 _initiate_conc_mark_if_possible(false),
188 _during_initial_mark_pause(false),
189 _last_young_gc(false),
190 _last_gc_was_young(false),
191
192 _eden_bytes_before_gc(0),
193 _survivor_bytes_before_gc(0),
194 _capacity_before_gc(0),
195
196 _eden_cset_region_length(0),
197 _survivor_cset_region_length(0),
198 _old_cset_region_length(0),
199
200 _collection_set(NULL),
201 _collection_set_bytes_used_before(0),
202
203 // Incremental CSet attributes
204 _inc_cset_build_state(Inactive),
205 _inc_cset_head(NULL),
206 _inc_cset_tail(NULL),
819 }
820 }
821
822 return ret;
823 }
824 #endif // PRODUCT
825
826 void G1CollectorPolicy::record_full_collection_start() {
827 _cur_collection_start_sec = os::elapsedTime();
828 // Release the future to-space so that it is available for compaction into.
829 _g1->set_full_collection();
830 }
831
832 void G1CollectorPolicy::record_full_collection_end() {
833 // Consider this like a collection pause for the purposes of allocation
834 // since last pause.
835 double end_sec = os::elapsedTime();
836 double full_gc_time_sec = end_sec - _cur_collection_start_sec;
837 double full_gc_time_ms = full_gc_time_sec * 1000.0;
838
839 _trace_gen1_time_data.record_full_collection(full_gc_time_ms);
840
841 update_recent_gc_times(end_sec, full_gc_time_ms);
842
843 _g1->clear_full_collection();
844
845 // "Nuke" the heuristics that control the young/mixed GC
846 // transitions and make sure we start with young GCs after the Full GC.
847 set_gcs_are_young(true);
848 _last_young_gc = false;
849 clear_initiate_conc_mark_if_possible();
850 clear_during_initial_mark_pause();
851 _in_marking_window = false;
852 _in_marking_window_im = false;
853
854 _short_lived_surv_rate_group->start_adding_regions();
855 // also call this on any additional surv rate groups
856
857 record_survivor_regions(0, NULL, NULL);
858
859 _free_regions_at_end_of_collection = _g1->free_regions();
868 }
869
870 void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
871 size_t start_used) {
872 if (G1Log::finer()) {
873 gclog_or_tty->stamp(PrintGCTimeStamps);
874 gclog_or_tty->print("[%s", (const char*)GCCauseString("GC pause", _g1->gc_cause())
875 .append(gcs_are_young() ? " (young)" : " (mixed)"));
876 }
877
878 // We only need to do this here as the policy will only be applied
879 // to the GC we're about to start. so, no point is calculating this
880 // every time we calculate / recalculate the target young length.
881 update_survivors_policy();
882
883 assert(_g1->used() == _g1->recalculate_used(),
884 err_msg("sanity, used: "SIZE_FORMAT" recalculate_used: "SIZE_FORMAT,
885 _g1->used(), _g1->recalculate_used()));
886
887 double s_w_t_ms = (start_time_sec - _stop_world_start) * 1000.0;
888 _trace_gen0_time_data.record_start_collection(s_w_t_ms);
889 _stop_world_start = 0.0;
890
891 _cur_collection_start_sec = start_time_sec;
892 _cur_collection_pause_used_at_start_bytes = start_used;
893 _cur_collection_pause_used_regions_at_start = _g1->used_regions();
894 _pending_cards = _g1->pending_card_num();
895 _max_pending_cards = _g1->max_pending_card_num();
896
897 _bytes_in_collection_set_before_gc = 0;
898 _bytes_copied_during_gc = 0;
899
900 YoungList* young_list = _g1->young_list();
901 _eden_bytes_before_gc = young_list->eden_used_bytes();
902 _survivor_bytes_before_gc = young_list->survivor_used_bytes();
903 _capacity_before_gc = _g1->capacity();
904
905 #ifdef DEBUG
906 // initialise these to something well known so that we can spot
907 // if they are not set properly
908
909 for (int i = 0; i < _parallel_gc_threads; ++i) {
910 _par_last_gc_worker_start_times_ms[i] = -1234.0;
911 _par_last_ext_root_scan_times_ms[i] = -1234.0;
912 _par_last_satb_filtering_times_ms[i] = -1234.0;
913 _par_last_update_rs_times_ms[i] = -1234.0;
914 _par_last_update_rs_processed_buffers[i] = -1234.0;
915 _par_last_scan_rs_times_ms[i] = -1234.0;
916 _par_last_obj_copy_times_ms[i] = -1234.0;
917 _par_last_termination_times_ms[i] = -1234.0;
918 _par_last_termination_attempts[i] = -1234.0;
919 _par_last_gc_worker_end_times_ms[i] = -1234.0;
920 _par_last_gc_worker_times_ms[i] = -1234.0;
921 _par_last_gc_worker_other_times_ms[i] = -1234.0;
922 }
923 #endif
924
925 // This is initialized to zero here and is set during the evacuation
926 // pause if we actually waited for the root region scanning to finish.
927 _root_region_scan_wait_time_ms = 0.0;
928
929 _last_gc_was_young = false;
930
931 // do that for any other surv rate groups
932 _short_lived_surv_rate_group->stop_adding_regions();
933 _survivors_age_table.clear();
934
935 assert( verify_young_ages(), "region age verification" );
936 }
937
938 void G1CollectorPolicy::record_concurrent_mark_init_end(double
939 mark_init_elapsed_time_ms) {
940 _during_marking = true;
941 assert(!initiate_conc_mark_if_possible(), "we should have cleared it by now");
942 clear_during_initial_mark_pause();
943 _cur_mark_stop_world_time_ms = mark_init_elapsed_time_ms;
944 }
953 double elapsed_time_ms = (end_time_sec - _mark_remark_start_sec)*1000.0;
954 _concurrent_mark_remark_times_ms->add(elapsed_time_ms);
955 _cur_mark_stop_world_time_ms += elapsed_time_ms;
956 _prev_collection_pause_end_ms += elapsed_time_ms;
957
958 _mmu_tracker->add_pause(_mark_remark_start_sec, end_time_sec, true);
959 }
960
961 void G1CollectorPolicy::record_concurrent_mark_cleanup_start() {
962 _mark_cleanup_start_sec = os::elapsedTime();
963 }
964
965 void G1CollectorPolicy::record_concurrent_mark_cleanup_completed() {
966 _last_young_gc = true;
967 _in_marking_window = false;
968 }
969
970 void G1CollectorPolicy::record_concurrent_pause() {
971 if (_stop_world_start > 0.0) {
972 double yield_ms = (os::elapsedTime() - _stop_world_start) * 1000.0;
973 _trace_gen0_time_data.record_yield_time(yield_ms);
974 }
975 }
976
977 void G1CollectorPolicy::record_concurrent_pause_end() {
978 }
979
980 template<class T>
981 T sum_of(T* sum_arr, int start, int n, int N) {
982 T sum = (T)0;
983 for (int i = 0; i < n; i++) {
984 int j = (start + i) % N;
985 sum += sum_arr[j];
986 }
987 return sum;
988 }
989
990 void G1CollectorPolicy::print_par_stats(int level,
991 const char* str,
992 double* data,
993 bool showDecimals) {
1160 if (G1YoungSurvRateVerbose) {
1161 gclog_or_tty->print_cr("");
1162 _short_lived_surv_rate_group->print();
1163 // do that for any other surv rate groups too
1164 }
1165 #endif // PRODUCT
1166
1167 last_pause_included_initial_mark = during_initial_mark_pause();
1168 if (last_pause_included_initial_mark) {
1169 record_concurrent_mark_init_end(0.0);
1170 } else if (!_last_young_gc && need_to_start_conc_mark("end of GC")) {
1171 // Note: this might have already been set, if during the last
1172 // pause we decided to start a cycle but at the beginning of
1173 // this pause we decided to postpone it. That's OK.
1174 set_initiate_conc_mark_if_possible();
1175 }
1176
1177 _mmu_tracker->add_pause(end_time_sec - elapsed_ms/1000.0,
1178 end_time_sec, false);
1179
1180 size_t freed_bytes =
1181 _cur_collection_pause_used_at_start_bytes - cur_used_bytes;
1182 size_t surviving_bytes = _collection_set_bytes_used_before - freed_bytes;
1183
1184 double survival_fraction =
1185 (double)surviving_bytes/
1186 (double)_collection_set_bytes_used_before;
1187
1188 // These values are used to update the summary information that is
1189 // displayed when TraceGen0Time is enabled, and are output as part
1190 // of the "finer" output, in the non-parallel case.
1191
1192 double ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms);
1193 double satb_filtering_time = avg_value(_par_last_satb_filtering_times_ms);
1194 double update_rs_time = avg_value(_par_last_update_rs_times_ms);
1195 double update_rs_processed_buffers =
1196 sum_of_values(_par_last_update_rs_processed_buffers);
1197 double scan_rs_time = avg_value(_par_last_scan_rs_times_ms);
1198 double obj_copy_time = avg_value(_par_last_obj_copy_times_ms);
1199 double termination_time = avg_value(_par_last_termination_times_ms);
1207 double other_time_ms = elapsed_ms;
1208
1209 // Subtract the root region scanning wait time. It's initialized to
1210 // zero at the start of the pause.
1211 other_time_ms -= _root_region_scan_wait_time_ms;
1212
1213 if (parallel) {
1214 other_time_ms -= _cur_collection_par_time_ms;
1215 } else {
1216 other_time_ms -= known_time;
1217 }
1218
1219 // Now subtract the time taken to fix up roots in generated code
1220 other_time_ms -= _cur_collection_code_root_fixup_time_ms;
1221
1222 // Subtract the time taken to clean the card table from the
1223 // current value of "other time"
1224 other_time_ms -= _cur_clear_ct_time_ms;
1225
1226 // TraceGen0Time and TraceGen1Time summary info updating.
1227
1228 if (update_stats) {
1229 double parallel_known_time = known_time + termination_time;
1230 double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time;
1231
1232 _trace_gen0_time_data.record_end_collection(
1233 elapsed_ms, other_time_ms, _root_region_scan_wait_time_ms, _cur_collection_par_time_ms,
1234 ext_root_scan_time, satb_filtering_time, update_rs_time, scan_rs_time, obj_copy_time,
1235 termination_time, parallel_other_time, _cur_clear_ct_time_ms);
1236
1237 // this is where we update the allocation rate of the application
1238 double app_time_ms =
1239 (_cur_collection_start_sec * 1000.0 - _prev_collection_pause_end_ms);
1240 if (app_time_ms < MIN_TIMER_GRANULARITY) {
1241 // This usually happens due to the timer not having the required
1242 // granularity. Some Linuxes are the usual culprits.
1243 // We'll just set it to something (arbitrarily) small.
1244 app_time_ms = 1.0;
1245 }
1246 // We maintain the invariant that all objects allocated by mutator
1247 // threads will be allocated out of eden regions. So, we can use
1248 // the eden region number allocated since the previous GC to
1249 // calculate the application's allocate rate. The only exception
1250 // to that is humongous objects that are allocated separately. But
1251 // given that humongous object allocations do not really affect
1252 // either the pause's duration nor when the next pause will take
1253 // place we can safely ignore them here.
1254 uint regions_allocated = eden_cset_region_length();
1255 double alloc_rate_ms = (double) regions_allocated / app_time_ms;
1268 gclog_or_tty->print_cr("Recent GC Times (ms):");
1269 _recent_gc_times_ms->dump();
1270 gclog_or_tty->print_cr("(End Time=%3.3f) Recent GC End Times (s):", end_time_sec);
1271 _recent_prev_end_times_for_all_gcs_sec->dump();
1272 gclog_or_tty->print_cr("GC = %3.3f, Interval = %3.3f, Ratio = %3.3f",
1273 _recent_gc_times_ms->sum(), interval_ms, recent_avg_pause_time_ratio());
1274 // In debug mode, terminate the JVM if the user wants to debug at this point.
1275 assert(!G1FailOnFPError, "Debugging data for CR 6898948 has been dumped above");
1276 #endif // !PRODUCT
1277 // Clip ratio between 0.0 and 1.0, and continue. This will be fixed in
1278 // CR 6902692 by redoing the manner in which the ratio is incrementally computed.
1279 if (_recent_avg_pause_time_ratio < 0.0) {
1280 _recent_avg_pause_time_ratio = 0.0;
1281 } else {
1282 assert(_recent_avg_pause_time_ratio - 1.0 > 0.0, "Ctl-point invariant");
1283 _recent_avg_pause_time_ratio = 1.0;
1284 }
1285 }
1286 }
1287
1288 if (G1Log::finer()) {
1289 bool print_marking_info =
1290 _g1->mark_in_progress() && !last_pause_included_initial_mark;
1291
1292 gclog_or_tty->print_cr("%s, %1.8lf secs]",
1293 (last_pause_included_initial_mark) ? " (initial-mark)" : "",
1294 elapsed_ms / 1000.0);
1295
1296 if (_root_region_scan_wait_time_ms > 0.0) {
1297 print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
1298 }
1299 if (parallel) {
1300 print_stats(1, "Parallel Time", _cur_collection_par_time_ms, no_of_gc_threads);
1301 print_par_stats(2, "GC Worker Start", _par_last_gc_worker_start_times_ms);
1302 print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms);
1303 if (print_marking_info) {
1304 print_par_stats(2, "SATB Filtering", _par_last_satb_filtering_times_ms);
1305 }
1306 print_par_stats(2, "Update RS", _par_last_update_rs_times_ms);
1307 if (G1Log::finest()) {
1349 print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
1350 print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
1351 #ifndef PRODUCT
1352 print_stats(1, "Cur Clear CC", _cur_clear_cc_time_ms);
1353 print_stats(1, "Cum Clear CC", _cum_clear_cc_time_ms);
1354 print_stats(1, "Min Clear CC", _min_clear_cc_time_ms);
1355 print_stats(1, "Max Clear CC", _max_clear_cc_time_ms);
1356 if (_num_cc_clears > 0) {
1357 print_stats(1, "Avg Clear CC", _cum_clear_cc_time_ms / ((double)_num_cc_clears));
1358 }
1359 #endif
1360 print_stats(1, "Other", other_time_ms);
1361 print_stats(2, "Choose CSet",
1362 (_recorded_young_cset_choice_time_ms +
1363 _recorded_non_young_cset_choice_time_ms));
1364 print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
1365 print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
1366 print_stats(2, "Free CSet",
1367 (_recorded_young_free_cset_time_ms +
1368 _recorded_non_young_free_cset_time_ms));
1369 }
1370
1371 bool new_in_marking_window = _in_marking_window;
1372 bool new_in_marking_window_im = false;
1373 if (during_initial_mark_pause()) {
1374 new_in_marking_window = true;
1375 new_in_marking_window_im = true;
1376 }
1377
1378 if (_last_young_gc) {
1379 // This is supposed to to be the "last young GC" before we start
1380 // doing mixed GCs. Here we decide whether to start mixed GCs or not.
1381
1382 if (!last_pause_included_initial_mark) {
1383 if (next_gc_should_be_mixed("start mixed GCs",
1384 "do not start mixed GCs")) {
1385 set_gcs_are_young(false);
1386 }
1387 } else {
1388 ergo_verbose0(ErgoMixedGCs,
1713 return 0;
1714 }
1715 }
1716
1717 class CountCSClosure: public HeapRegionClosure {
1718 G1CollectorPolicy* _g1_policy;
1719 public:
1720 CountCSClosure(G1CollectorPolicy* g1_policy) :
1721 _g1_policy(g1_policy) {}
1722 bool doHeapRegion(HeapRegion* r) {
1723 _g1_policy->_bytes_in_collection_set_before_gc += r->used();
1724 return false;
1725 }
1726 };
1727
1728 void G1CollectorPolicy::count_CS_bytes_used() {
1729 CountCSClosure cs_closure(this);
1730 _g1->collection_set_iterate(&cs_closure);
1731 }
1732
1733 void G1CollectorPolicy::print_tracing_info() const {
1734 _trace_gen0_time_data.print();
1735 _trace_gen1_time_data.print();
1736 }
1737
1738 void G1CollectorPolicy::print_yg_surv_rate_info() const {
1739 #ifndef PRODUCT
1740 _short_lived_surv_rate_group->print_surv_rate_summary();
1741 // add this call for any other surv rate groups
1742 #endif // PRODUCT
1743 }
1744
1745 #ifndef PRODUCT
1746 // for debugging, bit of a hack...
1747 static char*
1748 region_num_to_mbs(int length) {
1749 static char buffer[64];
1750 double bytes = (double) (length * HeapRegion::GrainBytes);
1751 double mbs = bytes / (double) (1024 * 1024);
1752 sprintf(buffer, "%7.2lfMB", mbs);
1753 return buffer;
1754 }
1755 #endif // PRODUCT
2266 guarantee(_collection_set == NULL, "Precondition");
2267
2268 double base_time_ms = predict_base_elapsed_time_ms(_pending_cards);
2269 double predicted_pause_time_ms = base_time_ms;
2270 double time_remaining_ms = target_pause_time_ms - base_time_ms;
2271
2272 ergo_verbose3(ErgoCSetConstruction | ErgoHigh,
2273 "start choosing CSet",
2274 ergo_format_ms("predicted base time")
2275 ergo_format_ms("remaining time")
2276 ergo_format_ms("target pause time"),
2277 base_time_ms, time_remaining_ms, target_pause_time_ms);
2278
2279 HeapRegion* hr;
2280 double young_start_time_sec = os::elapsedTime();
2281
2282 _collection_set_bytes_used_before = 0;
2283 _last_gc_was_young = gcs_are_young() ? true : false;
2284
2285 if (_last_gc_was_young) {
2286 _trace_gen0_time_data.increment_young_collection_count();
2287 } else {
2288 _trace_gen0_time_data.increment_mixed_collection_count();
2289 }
2290
2291 // The young list is laid with the survivor regions from the previous
2292 // pause are appended to the RHS of the young list, i.e.
2293 // [Newly Young Regions ++ Survivors from last pause].
2294
2295 uint survivor_region_length = young_list->survivor_length();
2296 uint eden_region_length = young_list->length() - survivor_region_length;
2297 init_cset_region_lengths(eden_region_length, survivor_region_length);
2298 hr = young_list->first_survivor_region();
2299 while (hr != NULL) {
2300 assert(hr->is_survivor(), "badly formed young list");
2301 hr->set_young();
2302 hr = hr->get_next_young_region();
2303 }
2304
2305 // Clear the fields that point to the survivor list - they are all young now.
2306 young_list->clear_survivors();
2307
2308 _collection_set = _inc_cset_head;
2424 }
2425
2426 stop_incremental_cset_building();
2427
2428 count_CS_bytes_used();
2429
2430 ergo_verbose5(ErgoCSetConstruction,
2431 "finish choosing CSet",
2432 ergo_format_region("eden")
2433 ergo_format_region("survivors")
2434 ergo_format_region("old")
2435 ergo_format_ms("predicted pause time")
2436 ergo_format_ms("target pause time"),
2437 eden_region_length, survivor_region_length,
2438 old_cset_region_length(),
2439 predicted_pause_time_ms, target_pause_time_ms);
2440
2441 double non_young_end_time_sec = os::elapsedTime();
2442 _recorded_non_young_cset_choice_time_ms =
2443 (non_young_end_time_sec - non_young_start_time_sec) * 1000.0;
2444 }
2445
2446 void TraceGen0TimeData::record_start_collection(double time_to_stop_the_world_ms) {
2447 if(TraceGen0Time) {
2448 _all_stop_world_times_ms.add(time_to_stop_the_world_ms);
2449 }
2450 }
2451
2452 void TraceGen0TimeData::record_yield_time(double yield_time_ms) {
2453 if(TraceGen0Time) {
2454 _all_yield_times_ms.add(yield_time_ms);
2455 }
2456 }
2457
2458 void TraceGen0TimeData::record_end_collection(
2459 double total_ms,
2460 double other_ms,
2461 double root_region_scan_wait_ms,
2462 double parallel_ms,
2463 double ext_root_scan_ms,
2464 double satb_filtering_ms,
2465 double update_rs_ms,
2466 double scan_rs_ms,
2467 double obj_copy_ms,
2468 double termination_ms,
2469 double parallel_other_ms,
2470 double clear_ct_ms)
2471 {
2472 if(TraceGen0Time) {
2473 _total.add(total_ms);
2474 _other.add(other_ms);
2475 _root_region_scan_wait.add(root_region_scan_wait_ms);
2476 _parallel.add(parallel_ms);
2477 _ext_root_scan.add(ext_root_scan_ms);
2478 _satb_filtering.add(satb_filtering_ms);
2479 _update_rs.add(update_rs_ms);
2480 _scan_rs.add(scan_rs_ms);
2481 _obj_copy.add(obj_copy_ms);
2482 _termination.add(termination_ms);
2483 _parallel_other.add(parallel_other_ms);
2484 _clear_ct.add(clear_ct_ms);
2485 }
2486 }
2487
2488 void TraceGen0TimeData::increment_young_collection_count() {
2489 if(TraceGen0Time) {
2490 ++_young_pause_num;
2491 }
2492 }
2493
2494 void TraceGen0TimeData::increment_mixed_collection_count() {
2495 if(TraceGen0Time) {
2496 ++_mixed_pause_num;
2497 }
2498 }
2499
2500 void TraceGen0TimeData::print_summary(int level,
2501 const char* str,
2502 const NumberSeq* seq) const {
2503 double sum = seq->sum();
2504 LineBuffer(level + 1).append_and_print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)",
2505 str, sum / 1000.0, seq->avg());
2506 }
2507
2508 void TraceGen0TimeData::print_summary_sd(int level,
2509 const char* str,
2510 const NumberSeq* seq) const {
2511 print_summary(level, str, seq);
2512 LineBuffer(level + 6).append_and_print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)",
2513 seq->num(), seq->sd(), seq->maximum());
2514 }
2515
2516 void TraceGen0TimeData::print() const {
2517 if (!TraceGen0Time) {
2518 return;
2519 }
2520
2521 gclog_or_tty->print_cr("ALL PAUSES");
2522 print_summary_sd(0, "Total", &_total);
2523 gclog_or_tty->print_cr("");
2524 gclog_or_tty->print_cr("");
2525 gclog_or_tty->print_cr(" Young GC Pauses: %8d", _young_pause_num);
2526 gclog_or_tty->print_cr(" Mixed GC Pauses: %8d", _mixed_pause_num);
2527 gclog_or_tty->print_cr("");
2528
2529 gclog_or_tty->print_cr("EVACUATION PAUSES");
2530
2531 if (_young_pause_num == 0 && _mixed_pause_num == 0) {
2532 gclog_or_tty->print_cr("none");
2533 } else {
2534 print_summary_sd(0, "Evacuation Pauses", &_total);
2535 print_summary(1, "Root Region Scan Wait", &_root_region_scan_wait);
2536 print_summary(1, "Parallel Time", &_parallel);
2537 print_summary(2, "Ext Root Scanning", &_ext_root_scan);
2538 print_summary(2, "SATB Filtering", &_satb_filtering);
2539 print_summary(2, "Update RS", &_update_rs);
2540 print_summary(2, "Scan RS", &_scan_rs);
2541 print_summary(2, "Object Copy", &_obj_copy);
2542 print_summary(2, "Termination", &_termination);
2543 print_summary(2, "Parallel Other", &_parallel_other);
2544 print_summary(1, "Clear CT", &_clear_ct);
2545 print_summary(1, "Other", &_other);
2546 }
2547 gclog_or_tty->print_cr("");
2548
2549 gclog_or_tty->print_cr("MISC");
2550 print_summary_sd(0, "Stop World", &_all_stop_world_times_ms);
2551 print_summary_sd(0, "Yields", &_all_yield_times_ms);
2552 }
2553
2554 void TraceGen1TimeData::record_full_collection(double full_gc_time_ms) {
2555 if (TraceGen1Time) {
2556 _all_full_gc_times.add(full_gc_time_ms);
2557 }
2558 }
2559
2560 void TraceGen1TimeData::print() const {
2561 if (!TraceGen1Time) {
2562 return;
2563 }
2564
2565 if (_all_full_gc_times.num() > 0) {
2566 gclog_or_tty->print("\n%4d full_gcs: total time = %8.2f s",
2567 _all_full_gc_times.num(),
2568 _all_full_gc_times.sum() / 1000.0);
2569 gclog_or_tty->print_cr(" (avg = %8.2fms).", _all_full_gc_times.avg());
2570 gclog_or_tty->print_cr(" [std. dev = %8.2f ms, max = %8.2f ms]",
2571 _all_full_gc_times.sd(),
2572 _all_full_gc_times.maximum());
2573 }
2574 }
|