Mercurial > hg > graal-jvmci-8

comparison src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp @ 6219:922993931b3d

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause Summary: Also reviewed by: vitalyd@gmail.com. Move the timing out of G1CollectorPolicy into the G1GCPhaseTimes class Reviewed-by: johnc
author brutisso
date Wed, 11 Jul 2012 22:47:38 +0200
parents bbc900c2482a
children a2f7274eb6ef
comparison
equal deleted inserted replaced
6196:3759236eea14 6219:922993931b3d
27 #include "gc_implementation/g1/concurrentMark.hpp" 27 #include "gc_implementation/g1/concurrentMark.hpp"
28 #include "gc_implementation/g1/concurrentMarkThread.inline.hpp" 28 #include "gc_implementation/g1/concurrentMarkThread.inline.hpp"
29 #include "gc_implementation/g1/g1CollectedHeap.inline.hpp" 29 #include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
30 #include "gc_implementation/g1/g1CollectorPolicy.hpp" 30 #include "gc_implementation/g1/g1CollectorPolicy.hpp"
31 #include "gc_implementation/g1/g1ErgoVerbose.hpp" 31 #include "gc_implementation/g1/g1ErgoVerbose.hpp"
32 #include "gc_implementation/g1/g1GCPhaseTimes.hpp"
32 #include "gc_implementation/g1/g1Log.hpp" 33 #include "gc_implementation/g1/g1Log.hpp"
33 #include "gc_implementation/g1/heapRegionRemSet.hpp" 34 #include "gc_implementation/g1/heapRegionRemSet.hpp"
34 #include "gc_implementation/shared/gcPolicyCounters.hpp" 35 #include "gc_implementation/shared/gcPolicyCounters.hpp"
35 #include "runtime/arguments.hpp" 36 #include "runtime/arguments.hpp"
36 #include "runtime/java.hpp" 37 #include "runtime/java.hpp"
75 76
76 static double non_young_other_cost_per_region_ms_defaults[] = { 77 static double non_young_other_cost_per_region_ms_defaults[] = {
77 1.0, 0.7, 0.7, 0.5, 0.5, 0.42, 0.42, 0.30 78 1.0, 0.7, 0.7, 0.5, 0.5, 0.42, 0.42, 0.30
78 }; 79 };
79 80
80 // Help class for avoiding interleaved logging
81 class LineBuffer: public StackObj {
82
83 private:
84 static const int BUFFER_LEN = 1024;
85 static const int INDENT_CHARS = 3;
86 char _buffer[BUFFER_LEN];
87 int _indent_level;
88 int _cur;
89
90 void vappend(const char* format, va_list ap) {
91 int res = vsnprintf(&_buffer[_cur], BUFFER_LEN - _cur, format, ap);
92 if (res != -1) {
93 _cur += res;
94 } else {
95 DEBUG_ONLY(warning("buffer too small in LineBuffer");)
96 _buffer[BUFFER_LEN -1] = 0;
97 _cur = BUFFER_LEN; // vsnprintf above should not add to _buffer if we are called again
98 }
99 }
100
101 public:
102 explicit LineBuffer(int indent_level): _indent_level(indent_level), _cur(0) {
103 for (; (_cur < BUFFER_LEN && _cur < (_indent_level * INDENT_CHARS)); _cur++) {
104 _buffer[_cur] = ' ';
105 }
106 }
107
108 #ifndef PRODUCT
109 ~LineBuffer() {
110 assert(_cur == _indent_level * INDENT_CHARS, "pending data in buffer - append_and_print_cr() not called?");
111 }
112 #endif
113
114 void append(const char* format, ...) {
115 va_list ap;
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() : 81 G1CollectorPolicy::G1CollectorPolicy() :
132 _parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads() 82 _parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads()
133 ? ParallelGCThreads : 1), 83 ? ParallelGCThreads : 1),
134 84
135 _recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), 85 _recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
136 _stop_world_start(0.0), 86 _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 87
152 _concurrent_mark_remark_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), 88 _concurrent_mark_remark_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
153 _concurrent_mark_cleanup_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)), 89 _concurrent_mark_cleanup_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
154 90
155 _alloc_rate_ms_seq(new TruncatedSeq(TruncatedSeqLength)), 91 _alloc_rate_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
255 } 191 }
256 192
257 _recent_prev_end_times_for_all_gcs_sec->add(os::elapsedTime()); 193 _recent_prev_end_times_for_all_gcs_sec->add(os::elapsedTime());
258 _prev_collection_pause_end_ms = os::elapsedTime() * 1000.0; 194 _prev_collection_pause_end_ms = os::elapsedTime() * 1000.0;
259 195
260 _par_last_gc_worker_start_times_ms = new double[_parallel_gc_threads]; 196 _phase_times = new G1GCPhaseTimes(_parallel_gc_threads);
261 _par_last_ext_root_scan_times_ms = new double[_parallel_gc_threads]; 197
262 _par_last_satb_filtering_times_ms = new double[_parallel_gc_threads]; 198 int index = MIN2(_parallel_gc_threads - 1, 7);
263
264 _par_last_update_rs_times_ms = new double[_parallel_gc_threads];
265 _par_last_update_rs_processed_buffers = new double[_parallel_gc_threads];
266
267 _par_last_scan_rs_times_ms = new double[_parallel_gc_threads];
268
269 _par_last_obj_copy_times_ms = new double[_parallel_gc_threads];
270
271 _par_last_termination_times_ms = new double[_parallel_gc_threads];
272 _par_last_termination_attempts = new double[_parallel_gc_threads];
273 _par_last_gc_worker_end_times_ms = new double[_parallel_gc_threads];
274 _par_last_gc_worker_times_ms = new double[_parallel_gc_threads];
275 _par_last_gc_worker_other_times_ms = new double[_parallel_gc_threads];
276
277 int index;
278 if (ParallelGCThreads == 0)
279 index = 0;
280 else if (ParallelGCThreads > 8)
281 index = 7;
282 else
283 index = ParallelGCThreads - 1;
284 199
285 _pending_card_diff_seq->add(0.0); 200 _pending_card_diff_seq->add(0.0);
286 _rs_length_diff_seq->add(rs_length_diff_defaults[index]); 201 _rs_length_diff_seq->add(rs_length_diff_defaults[index]);
287 _cost_per_card_ms_seq->add(cost_per_card_ms_defaults[index]); 202 _cost_per_card_ms_seq->add(cost_per_card_ms_defaults[index]);
288 _young_cards_per_entry_ratio_seq->add( 203 _young_cards_per_entry_ratio_seq->add(
822 return ret; 737 return ret;
823 } 738 }
824 #endif // PRODUCT 739 #endif // PRODUCT
825 740
826 void G1CollectorPolicy::record_full_collection_start() { 741 void G1CollectorPolicy::record_full_collection_start() {
827 _cur_collection_start_sec = os::elapsedTime(); 742 _full_collection_start_sec = os::elapsedTime();
828 // Release the future to-space so that it is available for compaction into. 743 // Release the future to-space so that it is available for compaction into.
829 _g1->set_full_collection(); 744 _g1->set_full_collection();
830 } 745 }
831 746
832 void G1CollectorPolicy::record_full_collection_end() { 747 void G1CollectorPolicy::record_full_collection_end() {
833 // Consider this like a collection pause for the purposes of allocation 748 // Consider this like a collection pause for the purposes of allocation
834 // since last pause. 749 // since last pause.
835 double end_sec = os::elapsedTime(); 750 double end_sec = os::elapsedTime();
836 double full_gc_time_sec = end_sec - _cur_collection_start_sec; 751 double full_gc_time_sec = end_sec - _full_collection_start_sec;
837 double full_gc_time_ms = full_gc_time_sec * 1000.0; 752 double full_gc_time_ms = full_gc_time_sec * 1000.0;
838 753
839 _trace_gen1_time_data.record_full_collection(full_gc_time_ms); 754 _trace_gen1_time_data.record_full_collection(full_gc_time_ms);
840 755
841 update_recent_gc_times(end_sec, full_gc_time_ms); 756 update_recent_gc_times(end_sec, full_gc_time_ms);
867 _stop_world_start = os::elapsedTime(); 782 _stop_world_start = os::elapsedTime();
868 } 783 }
869 784
870 void G1CollectorPolicy::record_collection_pause_start(double start_time_sec, 785 void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
871 size_t start_used) { 786 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 787 // 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 788 // to the GC we're about to start. so, no point is calculating this
880 // every time we calculate / recalculate the target young length. 789 // every time we calculate / recalculate the target young length.
881 update_survivors_policy(); 790 update_survivors_policy();
882 791
886 795
887 double s_w_t_ms = (start_time_sec - _stop_world_start) * 1000.0; 796 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); 797 _trace_gen0_time_data.record_start_collection(s_w_t_ms);
889 _stop_world_start = 0.0; 798 _stop_world_start = 0.0;
890 799
891 _cur_collection_start_sec = start_time_sec; 800 phase_times()->_cur_collection_start_sec = start_time_sec;
892 _cur_collection_pause_used_at_start_bytes = start_used; 801 _cur_collection_pause_used_at_start_bytes = start_used;
893 _cur_collection_pause_used_regions_at_start = _g1->used_regions(); 802 _cur_collection_pause_used_regions_at_start = _g1->used_regions();
894 _pending_cards = _g1->pending_card_num(); 803 _pending_cards = _g1->pending_card_num();
895 _max_pending_cards = _g1->max_pending_card_num(); 804 _max_pending_cards = _g1->max_pending_card_num();
896 805
899 808
900 YoungList* young_list = _g1->young_list(); 809 YoungList* young_list = _g1->young_list();
901 _eden_bytes_before_gc = young_list->eden_used_bytes(); 810 _eden_bytes_before_gc = young_list->eden_used_bytes();
902 _survivor_bytes_before_gc = young_list->survivor_used_bytes(); 811 _survivor_bytes_before_gc = young_list->survivor_used_bytes();
903 _capacity_before_gc = _g1->capacity(); 812 _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 813
929 _last_gc_was_young = false; 814 _last_gc_was_young = false;
930 815
931 // do that for any other surv rate groups 816 // do that for any other surv rate groups
932 _short_lived_surv_rate_group->stop_adding_regions(); 817 _short_lived_surv_rate_group->stop_adding_regions();
970 void G1CollectorPolicy::record_concurrent_pause() { 855 void G1CollectorPolicy::record_concurrent_pause() {
971 if (_stop_world_start > 0.0) { 856 if (_stop_world_start > 0.0) {
972 double yield_ms = (os::elapsedTime() - _stop_world_start) * 1000.0; 857 double yield_ms = (os::elapsedTime() - _stop_world_start) * 1000.0;
973 _trace_gen0_time_data.record_yield_time(yield_ms); 858 _trace_gen0_time_data.record_yield_time(yield_ms);
974 } 859 }
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) {
994 double min = data[0], max = data[0];
995 double total = 0.0;
996 LineBuffer buf(level);
997 buf.append("[%s (ms):", str);
998 for (uint i = 0; i < no_of_gc_threads(); ++i) {
999 double val = data[i];
1000 if (val < min)
1001 min = val;
1002 if (val > max)
1003 max = val;
1004 total += val;
1005 if (G1Log::finest()) {
1006 if (showDecimals) {
1007 buf.append(" %.1lf", val);
1008 } else {
1009 buf.append(" %d", (int)val);
1010 }
1011 }
1012 }
1013
1014 if (G1Log::finest()) {
1015 buf.append_and_print_cr("");
1016 }
1017 double avg = total / (double) no_of_gc_threads();
1018 if (showDecimals) {
1019 buf.append_and_print_cr(" Min: %.1lf, Avg: %.1lf, Max: %.1lf, Diff: %.1lf, Sum: %.1lf]",
1020 min, avg, max, max - min, total);
1021 } else {
1022 buf.append_and_print_cr(" Min: %d, Avg: %d, Max: %d, Diff: %d, Sum: %d]",
1023 (int)min, (int)avg, (int)max, (int)max - (int)min, (int)total);
1024 }
1025 }
1026
1027 void G1CollectorPolicy::print_stats(int level,
1028 const char* str,
1029 double value) {
1030 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
1031 }
1032
1033 void G1CollectorPolicy::print_stats(int level,
1034 const char* str,
1035 double value,
1036 int workers) {
1037 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %d]", str, value, workers);
1038 }
1039
1040 void G1CollectorPolicy::print_stats(int level,
1041 const char* str,
1042 int value) {
1043 LineBuffer(level).append_and_print_cr("[%s: %d]", str, value);
1044 }
1045
1046 double G1CollectorPolicy::avg_value(double* data) {
1047 if (G1CollectedHeap::use_parallel_gc_threads()) {
1048 double ret = 0.0;
1049 for (uint i = 0; i < no_of_gc_threads(); ++i) {
1050 ret += data[i];
1051 }
1052 return ret / (double) no_of_gc_threads();
1053 } else {
1054 return data[0];
1055 }
1056 }
1057
1058 double G1CollectorPolicy::max_value(double* data) {
1059 if (G1CollectedHeap::use_parallel_gc_threads()) {
1060 double ret = data[0];
1061 for (uint i = 1; i < no_of_gc_threads(); ++i) {
1062 if (data[i] > ret) {
1063 ret = data[i];
1064 }
1065 }
1066 return ret;
1067 } else {
1068 return data[0];
1069 }
1070 }
1071
1072 double G1CollectorPolicy::sum_of_values(double* data) {
1073 if (G1CollectedHeap::use_parallel_gc_threads()) {
1074 double sum = 0.0;
1075 for (uint i = 0; i < no_of_gc_threads(); i++) {
1076 sum += data[i];
1077 }
1078 return sum;
1079 } else {
1080 return data[0];
1081 }
1082 }
1083
1084 double G1CollectorPolicy::max_sum(double* data1, double* data2) {
1085 double ret = data1[0] + data2[0];
1086
1087 if (G1CollectedHeap::use_parallel_gc_threads()) {
1088 for (uint i = 1; i < no_of_gc_threads(); ++i) {
1089 double data = data1[i] + data2[i];
1090 if (data > ret) {
1091 ret = data;
1092 }
1093 }
1094 }
1095 return ret;
1096 } 860 }
1097 861
1098 bool G1CollectorPolicy::need_to_start_conc_mark(const char* source, size_t alloc_word_size) { 862 bool G1CollectorPolicy::need_to_start_conc_mark(const char* source, size_t alloc_word_size) {
1099 if (_g1->concurrent_mark()->cmThread()->during_cycle()) { 863 if (_g1->concurrent_mark()->cmThread()->during_cycle()) {
1100 return false; 864 return false;
1140 } 904 }
1141 905
1142 // Anything below that is considered to be zero 906 // Anything below that is considered to be zero
1143 #define MIN_TIMER_GRANULARITY 0.0000001 907 #define MIN_TIMER_GRANULARITY 0.0000001
1144 908
1145 void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) { 909 void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
1146 double end_time_sec = os::elapsedTime(); 910 double end_time_sec = os::elapsedTime();
1147 double elapsed_ms = _last_pause_time_ms;
1148 bool parallel = G1CollectedHeap::use_parallel_gc_threads();
1149 assert(_cur_collection_pause_used_regions_at_start >= cset_region_length(), 911 assert(_cur_collection_pause_used_regions_at_start >= cset_region_length(),
1150 "otherwise, the subtraction below does not make sense"); 912 "otherwise, the subtraction below does not make sense");
1151 size_t rs_size = 913 size_t rs_size =
1152 _cur_collection_pause_used_regions_at_start - cset_region_length(); 914 _cur_collection_pause_used_regions_at_start - cset_region_length();
1153 size_t cur_used_bytes = _g1->used(); 915 size_t cur_used_bytes = _g1->used();
1154 assert(cur_used_bytes == _g1->recalculate_used(), "It should!"); 916 assert(cur_used_bytes == _g1->recalculate_used(), "It should!");
1155 bool last_pause_included_initial_mark = false; 917 bool last_pause_included_initial_mark = false;
1156 bool update_stats = !_g1->evacuation_failed(); 918 bool update_stats = !_g1->evacuation_failed();
1157 set_no_of_gc_threads(no_of_gc_threads);
1158 919
1159 #ifndef PRODUCT 920 #ifndef PRODUCT
1160 if (G1YoungSurvRateVerbose) { 921 if (G1YoungSurvRateVerbose) {
1161 gclog_or_tty->print_cr(""); 922 gclog_or_tty->print_cr("");
1162 _short_lived_surv_rate_group->print(); 923 _short_lived_surv_rate_group->print();
1172 // pause we decided to start a cycle but at the beginning of 933 // pause we decided to start a cycle but at the beginning of
1173 // this pause we decided to postpone it. That's OK. 934 // this pause we decided to postpone it. That's OK.
1174 set_initiate_conc_mark_if_possible(); 935 set_initiate_conc_mark_if_possible();
1175 } 936 }
1176 937
1177 _mmu_tracker->add_pause(end_time_sec - elapsed_ms/1000.0, 938 _mmu_tracker->add_pause(end_time_sec - pause_time_ms/1000.0,
1178 end_time_sec, false); 939 end_time_sec, false);
1179 940
1180 size_t freed_bytes = 941 size_t freed_bytes =
1181 _cur_collection_pause_used_at_start_bytes - cur_used_bytes; 942 _cur_collection_pause_used_at_start_bytes - cur_used_bytes;
1182 size_t surviving_bytes = _collection_set_bytes_used_before - freed_bytes; 943 size_t surviving_bytes = _collection_set_bytes_used_before - freed_bytes;
1183 944
1184 double survival_fraction = 945 double survival_fraction =
1185 (double)surviving_bytes/ 946 (double)surviving_bytes/
1186 (double)_collection_set_bytes_used_before; 947 (double)_collection_set_bytes_used_before;
1187 948
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);
1200
1201 double known_time = ext_root_scan_time +
1202 satb_filtering_time +
1203 update_rs_time +
1204 scan_rs_time +
1205 obj_copy_time;
1206
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) { 949 if (update_stats) {
1229 double parallel_known_time = known_time + termination_time; 950 _trace_gen0_time_data.record_end_collection(pause_time_ms, phase_times());
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 951 // this is where we update the allocation rate of the application
1238 double app_time_ms = 952 double app_time_ms =
1239 (_cur_collection_start_sec * 1000.0 - _prev_collection_pause_end_ms); 953 (phase_times()->_cur_collection_start_sec * 1000.0 - _prev_collection_pause_end_ms);
1240 if (app_time_ms < MIN_TIMER_GRANULARITY) { 954 if (app_time_ms < MIN_TIMER_GRANULARITY) {
1241 // This usually happens due to the timer not having the required 955 // This usually happens due to the timer not having the required
1242 // granularity. Some Linuxes are the usual culprits. 956 // granularity. Some Linuxes are the usual culprits.
1243 // We'll just set it to something (arbitrarily) small. 957 // We'll just set it to something (arbitrarily) small.
1244 app_time_ms = 1.0; 958 app_time_ms = 1.0;
1255 double alloc_rate_ms = (double) regions_allocated / app_time_ms; 969 double alloc_rate_ms = (double) regions_allocated / app_time_ms;
1256 _alloc_rate_ms_seq->add(alloc_rate_ms); 970 _alloc_rate_ms_seq->add(alloc_rate_ms);
1257 971
1258 double interval_ms = 972 double interval_ms =
1259 (end_time_sec - _recent_prev_end_times_for_all_gcs_sec->oldest()) * 1000.0; 973 (end_time_sec - _recent_prev_end_times_for_all_gcs_sec->oldest()) * 1000.0;
1260 update_recent_gc_times(end_time_sec, elapsed_ms); 974 update_recent_gc_times(end_time_sec, pause_time_ms);
1261 _recent_avg_pause_time_ratio = _recent_gc_times_ms->sum()/interval_ms; 975 _recent_avg_pause_time_ratio = _recent_gc_times_ms->sum()/interval_ms;
1262 if (recent_avg_pause_time_ratio() < 0.0 || 976 if (recent_avg_pause_time_ratio() < 0.0 ||
1263 (recent_avg_pause_time_ratio() - 1.0 > 0.0)) { 977 (recent_avg_pause_time_ratio() - 1.0 > 0.0)) {
1264 #ifndef PRODUCT 978 #ifndef PRODUCT
1265 // Dump info to allow post-facto debugging 979 // Dump info to allow post-facto debugging
1282 assert(_recent_avg_pause_time_ratio - 1.0 > 0.0, "Ctl-point invariant"); 996 assert(_recent_avg_pause_time_ratio - 1.0 > 0.0, "Ctl-point invariant");
1283 _recent_avg_pause_time_ratio = 1.0; 997 _recent_avg_pause_time_ratio = 1.0;
1284 } 998 }
1285 } 999 }
1286 } 1000 }
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()) {
1308 print_par_stats(3, "Processed Buffers", _par_last_update_rs_processed_buffers,
1309 false /* showDecimals */);
1310 }
1311 print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms);
1312 print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms);
1313 print_par_stats(2, "Termination", _par_last_termination_times_ms);
1314 if (G1Log::finest()) {
1315 print_par_stats(3, "Termination Attempts", _par_last_termination_attempts,
1316 false /* showDecimals */);
1317 }
1318
1319 for (int i = 0; i < _parallel_gc_threads; i++) {
1320 _par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] -
1321 _par_last_gc_worker_start_times_ms[i];
1322
1323 double worker_known_time = _par_last_ext_root_scan_times_ms[i] +
1324 _par_last_satb_filtering_times_ms[i] +
1325 _par_last_update_rs_times_ms[i] +
1326 _par_last_scan_rs_times_ms[i] +
1327 _par_last_obj_copy_times_ms[i] +
1328 _par_last_termination_times_ms[i];
1329
1330 _par_last_gc_worker_other_times_ms[i] = _par_last_gc_worker_times_ms[i] -
1331 worker_known_time;
1332 }
1333
1334 print_par_stats(2, "GC Worker Other", _par_last_gc_worker_other_times_ms);
1335 print_par_stats(2, "GC Worker Total", _par_last_gc_worker_times_ms);
1336 print_par_stats(2, "GC Worker End", _par_last_gc_worker_end_times_ms);
1337 } else {
1338 print_stats(1, "Ext Root Scanning", ext_root_scan_time);
1339 if (print_marking_info) {
1340 print_stats(1, "SATB Filtering", satb_filtering_time);
1341 }
1342 print_stats(1, "Update RS", update_rs_time);
1343 if (G1Log::finest()) {
1344 print_stats(2, "Processed Buffers", (int)update_rs_processed_buffers);
1345 }
1346 print_stats(1, "Scan RS", scan_rs_time);
1347 print_stats(1, "Object Copying", obj_copy_time);
1348 }
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; 1001 bool new_in_marking_window = _in_marking_window;
1372 bool new_in_marking_window_im = false; 1002 bool new_in_marking_window_im = false;
1373 if (during_initial_mark_pause()) { 1003 if (during_initial_mark_pause()) {
1374 new_in_marking_window = true; 1004 new_in_marking_window = true;
1375 new_in_marking_window_im = true; 1005 new_in_marking_window_im = true;
1404 1034
1405 _short_lived_surv_rate_group->start_adding_regions(); 1035 _short_lived_surv_rate_group->start_adding_regions();
1406 // do that for any other surv rate groupsx 1036 // do that for any other surv rate groupsx
1407 1037
1408 if (update_stats) { 1038 if (update_stats) {
1409 double pause_time_ms = elapsed_ms;
1410
1411 size_t diff = 0; 1039 size_t diff = 0;
1412 if (_max_pending_cards >= _pending_cards) { 1040 if (_max_pending_cards >= _pending_cards) {
1413 diff = _max_pending_cards - _pending_cards; 1041 diff = _max_pending_cards - _pending_cards;
1414 } 1042 }
1415 _pending_card_diff_seq->add((double) diff); 1043 _pending_card_diff_seq->add((double) diff);
1416 1044
1417 double cost_per_card_ms = 0.0; 1045 double cost_per_card_ms = 0.0;
1418 if (_pending_cards > 0) { 1046 if (_pending_cards > 0) {
1419 cost_per_card_ms = update_rs_time / (double) _pending_cards; 1047 cost_per_card_ms = phase_times()->_update_rs_time / (double) _pending_cards;
1420 _cost_per_card_ms_seq->add(cost_per_card_ms); 1048 _cost_per_card_ms_seq->add(cost_per_card_ms);
1421 } 1049 }
1422 1050
1423 size_t cards_scanned = _g1->cards_scanned(); 1051 size_t cards_scanned = _g1->cards_scanned();
1424 1052
1425 double cost_per_entry_ms = 0.0; 1053 double cost_per_entry_ms = 0.0;
1426 if (cards_scanned > 10) { 1054 if (cards_scanned > 10) {
1427 cost_per_entry_ms = scan_rs_time / (double) cards_scanned; 1055 cost_per_entry_ms = phase_times()->_scan_rs_time / (double) cards_scanned;
1428 if (_last_gc_was_young) { 1056 if (_last_gc_was_young) {
1429 _cost_per_entry_ms_seq->add(cost_per_entry_ms); 1057 _cost_per_entry_ms_seq->add(cost_per_entry_ms);
1430 } else { 1058 } else {
1431 _mixed_cost_per_entry_ms_seq->add(cost_per_entry_ms); 1059 _mixed_cost_per_entry_ms_seq->add(cost_per_entry_ms);
1432 } 1060 }
1462 _rs_length_diff_seq->add((double) rs_length_diff); 1090 _rs_length_diff_seq->add((double) rs_length_diff);
1463 1091
1464 size_t copied_bytes = surviving_bytes; 1092 size_t copied_bytes = surviving_bytes;
1465 double cost_per_byte_ms = 0.0; 1093 double cost_per_byte_ms = 0.0;
1466 if (copied_bytes > 0) { 1094 if (copied_bytes > 0) {
1467 cost_per_byte_ms = obj_copy_time / (double) copied_bytes; 1095 cost_per_byte_ms = phase_times()->_obj_copy_time / (double) copied_bytes;
1468 if (_in_marking_window) { 1096 if (_in_marking_window) {
1469 _cost_per_byte_ms_during_cm_seq->add(cost_per_byte_ms); 1097 _cost_per_byte_ms_during_cm_seq->add(cost_per_byte_ms);
1470 } else { 1098 } else {
1471 _cost_per_byte_ms_seq->add(cost_per_byte_ms); 1099 _cost_per_byte_ms_seq->add(cost_per_byte_ms);
1472 } 1100 }
1473 } 1101 }
1474 1102
1475 double all_other_time_ms = pause_time_ms - 1103 double all_other_time_ms = pause_time_ms -
1476 (update_rs_time + scan_rs_time + obj_copy_time + termination_time); 1104 (phase_times()->_update_rs_time + phase_times()->_scan_rs_time + phase_times()->_obj_copy_time + phase_times()->_termination_time);
1477 1105
1478 double young_other_time_ms = 0.0; 1106 double young_other_time_ms = 0.0;
1479 if (young_cset_region_length() > 0) { 1107 if (young_cset_region_length() > 0) {
1480 young_other_time_ms = 1108 young_other_time_ms =
1481 _recorded_young_cset_choice_time_ms + 1109 phase_times()->_recorded_young_cset_choice_time_ms +
1482 _recorded_young_free_cset_time_ms; 1110 phase_times()->_recorded_young_free_cset_time_ms;
1483 _young_other_cost_per_region_ms_seq->add(young_other_time_ms / 1111 _young_other_cost_per_region_ms_seq->add(young_other_time_ms /
1484 (double) young_cset_region_length()); 1112 (double) young_cset_region_length());
1485 } 1113 }
1486 double non_young_other_time_ms = 0.0; 1114 double non_young_other_time_ms = 0.0;
1487 if (old_cset_region_length() > 0) { 1115 if (old_cset_region_length() > 0) {
1488 non_young_other_time_ms = 1116 non_young_other_time_ms =
1489 _recorded_non_young_cset_choice_time_ms + 1117 phase_times()->_recorded_non_young_cset_choice_time_ms +
1490 _recorded_non_young_free_cset_time_ms; 1118 phase_times()->_recorded_non_young_free_cset_time_ms;
1491 1119
1492 _non_young_other_cost_per_region_ms_seq->add(non_young_other_time_ms / 1120 _non_young_other_cost_per_region_ms_seq->add(non_young_other_time_ms /
1493 (double) old_cset_region_length()); 1121 (double) old_cset_region_length());
1494 } 1122 }
1495 1123
1512 _free_regions_at_end_of_collection = _g1->free_regions(); 1140 _free_regions_at_end_of_collection = _g1->free_regions();
1513 update_young_list_target_length(); 1141 update_young_list_target_length();
1514 1142
1515 // Note that _mmu_tracker->max_gc_time() returns the time in seconds. 1143 // Note that _mmu_tracker->max_gc_time() returns the time in seconds.
1516 double update_rs_time_goal_ms = _mmu_tracker->max_gc_time() * MILLIUNITS * G1RSetUpdatingPauseTimePercent / 100.0; 1144 double update_rs_time_goal_ms = _mmu_tracker->max_gc_time() * MILLIUNITS * G1RSetUpdatingPauseTimePercent / 100.0;
1517 adjust_concurrent_refinement(update_rs_time, update_rs_processed_buffers, update_rs_time_goal_ms); 1145 adjust_concurrent_refinement(phase_times()->_update_rs_time, phase_times()->_update_rs_processed_buffers, update_rs_time_goal_ms);
1518 1146
1519 _collectionSetChooser->verify(); 1147 _collectionSetChooser->verify();
1520 } 1148 }
1521 1149
1522 #define EXT_SIZE_FORMAT "%.1f%s" 1150 #define EXT_SIZE_FORMAT "%.1f%s"
2321 // The number of recorded young regions is the incremental 1949 // The number of recorded young regions is the incremental
2322 // collection set's current size 1950 // collection set's current size
2323 set_recorded_rs_lengths(_inc_cset_recorded_rs_lengths); 1951 set_recorded_rs_lengths(_inc_cset_recorded_rs_lengths);
2324 1952
2325 double young_end_time_sec = os::elapsedTime(); 1953 double young_end_time_sec = os::elapsedTime();
2326 _recorded_young_cset_choice_time_ms = 1954 phase_times()->_recorded_young_cset_choice_time_ms =
2327 (young_end_time_sec - young_start_time_sec) * 1000.0; 1955 (young_end_time_sec - young_start_time_sec) * 1000.0;
2328 1956
2329 // We are doing young collections so reset this. 1957 // We are doing young collections so reset this.
2330 non_young_start_time_sec = young_end_time_sec; 1958 non_young_start_time_sec = young_end_time_sec;
2331 1959
2437 eden_region_length, survivor_region_length, 2065 eden_region_length, survivor_region_length,
2438 old_cset_region_length(), 2066 old_cset_region_length(),
2439 predicted_pause_time_ms, target_pause_time_ms); 2067 predicted_pause_time_ms, target_pause_time_ms);
2440 2068
2441 double non_young_end_time_sec = os::elapsedTime(); 2069 double non_young_end_time_sec = os::elapsedTime();
2442 _recorded_non_young_cset_choice_time_ms = 2070 phase_times()->_recorded_non_young_cset_choice_time_ms =
2443 (non_young_end_time_sec - non_young_start_time_sec) * 1000.0; 2071 (non_young_end_time_sec - non_young_start_time_sec) * 1000.0;
2444 } 2072 }
2445 2073
2446 void TraceGen0TimeData::record_start_collection(double time_to_stop_the_world_ms) { 2074 void TraceGen0TimeData::record_start_collection(double time_to_stop_the_world_ms) {
2447 if(TraceGen0Time) { 2075 if(TraceGen0Time) {
2453 if(TraceGen0Time) { 2081 if(TraceGen0Time) {
2454 _all_yield_times_ms.add(yield_time_ms); 2082 _all_yield_times_ms.add(yield_time_ms);
2455 } 2083 }
2456 } 2084 }
2457 2085
2458 void TraceGen0TimeData::record_end_collection( 2086 void TraceGen0TimeData::record_end_collection(double pause_time_ms, G1GCPhaseTimes* phase_times) {
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) { 2087 if(TraceGen0Time) {
2473 _total.add(total_ms); 2088 _total.add(pause_time_ms);
2474 _other.add(other_ms); 2089 _other.add(pause_time_ms - phase_times->accounted_time_ms());
2475 _root_region_scan_wait.add(root_region_scan_wait_ms); 2090 _root_region_scan_wait.add(phase_times->_root_region_scan_wait_time_ms);
2476 _parallel.add(parallel_ms); 2091 _parallel.add(phase_times->_cur_collection_par_time_ms);
2477 _ext_root_scan.add(ext_root_scan_ms); 2092 _ext_root_scan.add(phase_times->_ext_root_scan_time);
2478 _satb_filtering.add(satb_filtering_ms); 2093 _satb_filtering.add(phase_times->_satb_filtering_time);
2479 _update_rs.add(update_rs_ms); 2094 _update_rs.add(phase_times->_update_rs_time);
2480 _scan_rs.add(scan_rs_ms); 2095 _scan_rs.add(phase_times->_scan_rs_time);
2481 _obj_copy.add(obj_copy_ms); 2096 _obj_copy.add(phase_times->_obj_copy_time);
2482 _termination.add(termination_ms); 2097 _termination.add(phase_times->_termination_time);
2483 _parallel_other.add(parallel_other_ms); 2098
2484 _clear_ct.add(clear_ct_ms); 2099 double parallel_known_time = phase_times->_ext_root_scan_time +
2100 phase_times->_satb_filtering_time +
2101 phase_times->_update_rs_time +
2102 phase_times->_scan_rs_time +
2103 phase_times->_obj_copy_time +
2104 + phase_times->_termination_time;
2105
2106 double parallel_other_time = phase_times->_cur_collection_par_time_ms - parallel_known_time;
2107 _parallel_other.add(parallel_other_time);
2108 _clear_ct.add(phase_times->_cur_clear_ct_time_ms);
2485 } 2109 }
2486 } 2110 }
2487 2111
2488 void TraceGen0TimeData::increment_young_collection_count() { 2112 void TraceGen0TimeData::increment_young_collection_count() {
2489 if(TraceGen0Time) { 2113 if(TraceGen0Time) {
2495 if(TraceGen0Time) { 2119 if(TraceGen0Time) {
2496 ++_mixed_pause_num; 2120 ++_mixed_pause_num;
2497 } 2121 }
2498 } 2122 }
2499 2123
2500 void TraceGen0TimeData::print_summary(int level, 2124 void TraceGen0TimeData::print_summary(const char* str,
2501 const char* str,
2502 const NumberSeq* seq) const { 2125 const NumberSeq* seq) const {
2503 double sum = seq->sum(); 2126 double sum = seq->sum();
2504 LineBuffer(level + 1).append_and_print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)", 2127 gclog_or_tty->print_cr("%-27s = %8.2lf s (avg = %8.2lf ms)",
2505 str, sum / 1000.0, seq->avg()); 2128 str, sum / 1000.0, seq->avg());
2506 } 2129 }
2507 2130
2508 void TraceGen0TimeData::print_summary_sd(int level, 2131 void TraceGen0TimeData::print_summary_sd(const char* str,
2509 const char* str,
2510 const NumberSeq* seq) const { 2132 const NumberSeq* seq) const {
2511 print_summary(level, str, seq); 2133 print_summary(str, seq);
2512 LineBuffer(level + 6).append_and_print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)", 2134 gclog_or_tty->print_cr("%+45s = %5d, std dev = %8.2lf ms, max = %8.2lf ms)",
2513 seq->num(), seq->sd(), seq->maximum()); 2135 "(num", seq->num(), seq->sd(), seq->maximum());
2514 } 2136 }
2515 2137
2516 void TraceGen0TimeData::print() const { 2138 void TraceGen0TimeData::print() const {
2517 if (!TraceGen0Time) { 2139 if (!TraceGen0Time) {
2518 return; 2140 return;
2519 } 2141 }
2520 2142
2521 gclog_or_tty->print_cr("ALL PAUSES"); 2143 gclog_or_tty->print_cr("ALL PAUSES");
2522 print_summary_sd(0, "Total", &_total); 2144 print_summary_sd(" Total", &_total);
2523 gclog_or_tty->print_cr(""); 2145 gclog_or_tty->print_cr("");
2524 gclog_or_tty->print_cr(""); 2146 gclog_or_tty->print_cr("");
2525 gclog_or_tty->print_cr(" Young GC Pauses: %8d", _young_pause_num); 2147 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); 2148 gclog_or_tty->print_cr(" Mixed GC Pauses: %8d", _mixed_pause_num);
2527 gclog_or_tty->print_cr(""); 2149 gclog_or_tty->print_cr("");
2529 gclog_or_tty->print_cr("EVACUATION PAUSES"); 2151 gclog_or_tty->print_cr("EVACUATION PAUSES");
2530 2152
2531 if (_young_pause_num == 0 && _mixed_pause_num == 0) { 2153 if (_young_pause_num == 0 && _mixed_pause_num == 0) {
2532 gclog_or_tty->print_cr("none"); 2154 gclog_or_tty->print_cr("none");
2533 } else { 2155 } else {
2534 print_summary_sd(0, "Evacuation Pauses", &_total); 2156 print_summary_sd(" Evacuation Pauses", &_total);
2535 print_summary(1, "Root Region Scan Wait", &_root_region_scan_wait); 2157 print_summary(" Root Region Scan Wait", &_root_region_scan_wait);
2536 print_summary(1, "Parallel Time", &_parallel); 2158 print_summary(" Parallel Time", &_parallel);
2537 print_summary(2, "Ext Root Scanning", &_ext_root_scan); 2159 print_summary(" Ext Root Scanning", &_ext_root_scan);
2538 print_summary(2, "SATB Filtering", &_satb_filtering); 2160 print_summary(" SATB Filtering", &_satb_filtering);
2539 print_summary(2, "Update RS", &_update_rs); 2161 print_summary(" Update RS", &_update_rs);
2540 print_summary(2, "Scan RS", &_scan_rs); 2162 print_summary(" Scan RS", &_scan_rs);
2541 print_summary(2, "Object Copy", &_obj_copy); 2163 print_summary(" Object Copy", &_obj_copy);
2542 print_summary(2, "Termination", &_termination); 2164 print_summary(" Termination", &_termination);
2543 print_summary(2, "Parallel Other", &_parallel_other); 2165 print_summary(" Parallel Other", &_parallel_other);
2544 print_summary(1, "Clear CT", &_clear_ct); 2166 print_summary(" Clear CT", &_clear_ct);
2545 print_summary(1, "Other", &_other); 2167 print_summary(" Other", &_other);
2546 } 2168 }
2547 gclog_or_tty->print_cr(""); 2169 gclog_or_tty->print_cr("");
2548 2170
2549 gclog_or_tty->print_cr("MISC"); 2171 gclog_or_tty->print_cr("MISC");
2550 print_summary_sd(0, "Stop World", &_all_stop_world_times_ms); 2172 print_summary_sd(" Stop World", &_all_stop_world_times_ms);
2551 print_summary_sd(0, "Yields", &_all_yield_times_ms); 2173 print_summary_sd(" Yields", &_all_yield_times_ms);
2552 } 2174 }
2553 2175
2554 void TraceGen1TimeData::record_full_collection(double full_gc_time_ms) { 2176 void TraceGen1TimeData::record_full_collection(double full_gc_time_ms) {
2555 if (TraceGen1Time) { 2177 if (TraceGen1Time) {
2556 _all_full_gc_times.add(full_gc_time_ms); 2178 _all_full_gc_times.add(full_gc_time_ms);