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 }
|