Mercurial > hg > truffle
comparison src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp @ 6219:922993931b3d
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); |