Print this page
JDK-8236073 G1: Use SoftMaxHeapSize to guide GC heuristics
| Split |
Close |
| Expand all |
| Collapse all |
--- old/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp
+++ new/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp
1 1 /*
2 2 * Copyright (c) 2013, 2019, Oracle and/or its affiliates. All rights reserved.
3 3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
4 4 *
5 5 * This code is free software; you can redistribute it and/or modify it
6 6 * under the terms of the GNU General Public License version 2 only, as
7 7 * published by the Free Software Foundation.
8 8 *
9 9 * This code is distributed in the hope that it will be useful, but WITHOUT
10 10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
11 11 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
12 12 * version 2 for more details (a copy is included in the LICENSE file that
13 13 * accompanied this code).
14 14 *
15 15 * You should have received a copy of the GNU General Public License version
16 16 * 2 along with this work; if not, write to the Free Software Foundation,
17 17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
18 18 *
19 19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
20 20 * or visit www.oracle.com if you need additional information or have any
21 21 * questions.
22 22 *
23 23 */
24 24
25 25 #include "precompiled.hpp"
26 26 #include "gc/g1/g1CollectedHeap.inline.hpp"
27 27 #include "gc/g1/g1GCPhaseTimes.hpp"
28 28 #include "gc/g1/g1HotCardCache.hpp"
29 29 #include "gc/g1/g1ParScanThreadState.inline.hpp"
30 30 #include "gc/g1/g1StringDedup.hpp"
31 31 #include "gc/shared/gcTimer.hpp"
32 32 #include "gc/shared/workerDataArray.inline.hpp"
33 33 #include "memory/resourceArea.hpp"
34 34 #include "logging/log.hpp"
35 35 #include "logging/logStream.hpp"
36 36 #include "runtime/timer.hpp"
37 37 #include "runtime/os.hpp"
38 38 #include "utilities/macros.hpp"
39 39
40 40 static const char* indent(uint level) {
41 41 static const char* Indents[] = {"", " ", " ", " ", " ", " "};
42 42 assert(level < ARRAY_SIZE(Indents), "Too high indent level %u", level);
43 43 return Indents[level];
44 44 }
45 45
46 46 G1GCPhaseTimes::G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads) :
47 47 _max_gc_threads(max_gc_threads),
48 48 _gc_start_counter(0),
49 49 _gc_pause_time_ms(0.0),
50 50 _ref_phase_times(gc_timer, max_gc_threads),
51 51 _weak_phase_times(max_gc_threads)
52 52 {
53 53 assert(max_gc_threads > 0, "Must have some GC threads");
54 54
55 55 _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>("GC Worker Start (ms):", max_gc_threads);
56 56 _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>("Ext Root Scanning (ms):", max_gc_threads);
57 57
58 58 // Root scanning phases
59 59 _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>("Thread Roots (ms):", max_gc_threads);
60 60 _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>("Universe Roots (ms):", max_gc_threads);
61 61 _gc_par_phases[JNIRoots] = new WorkerDataArray<double>("JNI Handles Roots (ms):", max_gc_threads);
62 62 _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>("ObjectSynchronizer Roots (ms):", max_gc_threads);
63 63 _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>("Management Roots (ms):", max_gc_threads);
64 64 _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>("SystemDictionary Roots (ms):", max_gc_threads);
65 65 _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>("CLDG Roots (ms):", max_gc_threads);
66 66 _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>("JVMTI Roots (ms):", max_gc_threads);
67 67 AOT_ONLY(_gc_par_phases[AOTCodeRoots] = new WorkerDataArray<double>("AOT Root Scan (ms):", max_gc_threads);)
68 68 _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>("CM RefProcessor Roots (ms):", max_gc_threads);
69 69
70 70 _gc_par_phases[MergeER] = new WorkerDataArray<double>("Eager Reclaim (ms):", max_gc_threads);
71 71
72 72 _gc_par_phases[MergeRS] = new WorkerDataArray<double>("Remembered Sets (ms):", max_gc_threads);
73 73 _gc_par_phases[MergeRS]->create_thread_work_items("Merged Sparse:", MergeRSMergedSparse);
74 74 _gc_par_phases[MergeRS]->create_thread_work_items("Merged Fine:", MergeRSMergedFine);
75 75 _gc_par_phases[MergeRS]->create_thread_work_items("Merged Coarse:", MergeRSMergedCoarse);
76 76 _gc_par_phases[MergeRS]->create_thread_work_items("Dirty Cards:", MergeRSDirtyCards);
77 77
78 78 _gc_par_phases[OptMergeRS] = new WorkerDataArray<double>("Optional Remembered Sets (ms):", max_gc_threads);
79 79 _gc_par_phases[OptMergeRS]->create_thread_work_items("Merged Sparse:", MergeRSMergedSparse);
80 80 _gc_par_phases[OptMergeRS]->create_thread_work_items("Merged Fine:", MergeRSMergedFine);
81 81 _gc_par_phases[OptMergeRS]->create_thread_work_items("Merged Coarse:", MergeRSMergedCoarse);
82 82 _gc_par_phases[OptMergeRS]->create_thread_work_items("Dirty Cards:", MergeRSDirtyCards);
83 83
84 84 _gc_par_phases[MergeLB] = new WorkerDataArray<double>("Log Buffers (ms):", max_gc_threads);
85 85 if (G1HotCardCache::default_use_cache()) {
86 86 _gc_par_phases[MergeHCC] = new WorkerDataArray<double>("Hot Card Cache (ms):", max_gc_threads);
87 87 _gc_par_phases[MergeHCC]->create_thread_work_items("Dirty Cards:", MergeHCCDirtyCards);
88 88 _gc_par_phases[MergeHCC]->create_thread_work_items("Skipped Cards:", MergeHCCSkippedCards);
89 89 } else {
90 90 _gc_par_phases[MergeHCC] = NULL;
91 91 }
92 92 _gc_par_phases[ScanHR] = new WorkerDataArray<double>("Scan Heap Roots (ms):", max_gc_threads);
93 93 _gc_par_phases[OptScanHR] = new WorkerDataArray<double>("Optional Scan Heap Roots (ms):", max_gc_threads);
94 94 _gc_par_phases[CodeRoots] = new WorkerDataArray<double>("Code Root Scan (ms):", max_gc_threads);
95 95 _gc_par_phases[OptCodeRoots] = new WorkerDataArray<double>("Optional Code Root Scan (ms):", max_gc_threads);
96 96 _gc_par_phases[ObjCopy] = new WorkerDataArray<double>("Object Copy (ms):", max_gc_threads);
97 97 _gc_par_phases[OptObjCopy] = new WorkerDataArray<double>("Optional Object Copy (ms):", max_gc_threads);
98 98 _gc_par_phases[Termination] = new WorkerDataArray<double>("Termination (ms):", max_gc_threads);
99 99 _gc_par_phases[OptTermination] = new WorkerDataArray<double>("Optional Termination (ms):", max_gc_threads);
100 100 _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>("GC Worker Total (ms):", max_gc_threads);
101 101 _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>("GC Worker End (ms):", max_gc_threads);
102 102 _gc_par_phases[Other] = new WorkerDataArray<double>("GC Worker Other (ms):", max_gc_threads);
103 103
104 104 _gc_par_phases[ScanHR]->create_thread_work_items("Scanned Cards:", ScanHRScannedCards);
105 105 _gc_par_phases[ScanHR]->create_thread_work_items("Scanned Blocks:", ScanHRScannedBlocks);
106 106 _gc_par_phases[ScanHR]->create_thread_work_items("Claimed Chunks:", ScanHRClaimedChunks);
107 107
108 108 _gc_par_phases[OptScanHR]->create_thread_work_items("Scanned Cards:", ScanHRScannedCards);
109 109 _gc_par_phases[OptScanHR]->create_thread_work_items("Scanned Blocks:", ScanHRScannedBlocks);
110 110 _gc_par_phases[OptScanHR]->create_thread_work_items("Claimed Chunks:", ScanHRClaimedChunks);
111 111 _gc_par_phases[OptScanHR]->create_thread_work_items("Scanned Refs:", ScanHRScannedOptRefs);
112 112 _gc_par_phases[OptScanHR]->create_thread_work_items("Used Memory:", ScanHRUsedMemory);
113 113
114 114 _gc_par_phases[MergeLB]->create_thread_work_items("Dirty Cards:", MergeLBDirtyCards);
115 115 _gc_par_phases[MergeLB]->create_thread_work_items("Skipped Cards:", MergeLBSkippedCards);
116 116
117 117 _gc_par_phases[MergePSS] = new WorkerDataArray<double>("Merge Per-Thread State", 1 /* length */, true /* is_serial */);
118 118
119 119 _gc_par_phases[MergePSS]->create_thread_work_items("Copied Bytes", MergePSSCopiedBytes, max_gc_threads);
120 120 _gc_par_phases[MergePSS]->create_thread_work_items("LAB Waste", MergePSSLABWasteBytes, max_gc_threads);
121 121 _gc_par_phases[MergePSS]->create_thread_work_items("LAB Undo Waste", MergePSSLABUndoWasteBytes, max_gc_threads);
122 122
123 123 _gc_par_phases[Termination]->create_thread_work_items("Termination Attempts:");
124 124
125 125 _gc_par_phases[OptTermination]->create_thread_work_items("Optional Termination Attempts:");
126 126
127 127 if (UseStringDeduplication) {
128 128 _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>("Queue Fixup (ms):", max_gc_threads);
129 129 _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>("Table Fixup (ms):", max_gc_threads);
130 130 } else {
131 131 _gc_par_phases[StringDedupQueueFixup] = NULL;
132 132 _gc_par_phases[StringDedupTableFixup] = NULL;
133 133 }
134 134
135 135 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>("Parallel Redirty (ms):", max_gc_threads);
136 136 _gc_par_phases[RedirtyCards]->create_thread_work_items("Redirtied Cards:");
137 137
138 138 _gc_par_phases[ParFreeCSet] = new WorkerDataArray<double>("Parallel Free Collection Set (ms):", max_gc_threads);
139 139 _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>("Young Free Collection Set (ms):", max_gc_threads);
140 140 _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>("Non-Young Free Collection Set (ms):", max_gc_threads);
141 141 _gc_par_phases[RebuildFreeList] = new WorkerDataArray<double>("Parallel Rebuild Free List (ms):", max_gc_threads);
142 142
143 143 reset();
144 144 }
145 145
146 146 void G1GCPhaseTimes::reset() {
147 147 _cur_collection_initial_evac_time_ms = 0.0;
148 148 _cur_optional_evac_time_ms = 0.0;
149 149 _cur_collection_code_root_fixup_time_ms = 0.0;
150 150 _cur_strong_code_root_purge_time_ms = 0.0;
151 151 _cur_merge_heap_roots_time_ms = 0.0;
|
↓ open down ↓ |
151 lines elided |
↑ open up ↑ |
152 152 _cur_optional_merge_heap_roots_time_ms = 0.0;
153 153 _cur_prepare_merge_heap_roots_time_ms = 0.0;
154 154 _cur_optional_prepare_merge_heap_roots_time_ms = 0.0;
155 155 _cur_evac_fail_recalc_used = 0.0;
156 156 _cur_evac_fail_remove_self_forwards = 0.0;
157 157 _cur_string_deduplication_time_ms = 0.0;
158 158 _cur_prepare_tlab_time_ms = 0.0;
159 159 _cur_resize_tlab_time_ms = 0.0;
160 160 _cur_derived_pointer_table_update_time_ms = 0.0;
161 161 _cur_clear_ct_time_ms = 0.0;
162 - _cur_expand_heap_time_ms = 0.0;
162 + _cur_resize_heap_time_ms = 0.0;
163 163 _cur_ref_proc_time_ms = 0.0;
164 164 _cur_collection_start_sec = 0.0;
165 165 _root_region_scan_wait_time_ms = 0.0;
166 166 _external_accounted_time_ms = 0.0;
167 167 _recorded_prepare_heap_roots_time_ms = 0.0;
168 168 _recorded_clear_claimed_marks_time_ms = 0.0;
169 169 _recorded_young_cset_choice_time_ms = 0.0;
170 170 _recorded_non_young_cset_choice_time_ms = 0.0;
171 171 _recorded_redirty_logged_cards_time_ms = 0.0;
172 172 _recorded_preserve_cm_referents_time_ms = 0.0;
173 173 _recorded_start_new_cset_time_ms = 0.0;
174 174 _recorded_total_free_cset_time_ms = 0.0;
175 175 _recorded_serial_free_cset_time_ms = 0.0;
176 176 _recorded_total_rebuild_freelist_time_ms = 0.0;
177 177 _recorded_serial_rebuild_freelist_time_ms = 0.0;
178 178 _cur_fast_reclaim_humongous_time_ms = 0.0;
179 179 _cur_region_register_time = 0.0;
180 180 _cur_fast_reclaim_humongous_total = 0;
181 181 _cur_fast_reclaim_humongous_candidates = 0;
182 182 _cur_fast_reclaim_humongous_reclaimed = 0;
183 183 _cur_verify_before_time_ms = 0.0;
184 184 _cur_verify_after_time_ms = 0.0;
185 185
186 186 for (int i = 0; i < GCParPhasesSentinel; i++) {
187 187 if (_gc_par_phases[i] != NULL) {
188 188 _gc_par_phases[i]->reset();
189 189 }
190 190 }
191 191
192 192 _ref_phase_times.reset();
193 193 _weak_phase_times.reset();
194 194 }
195 195
196 196 void G1GCPhaseTimes::note_gc_start() {
197 197 _gc_start_counter = os::elapsed_counter();
198 198 reset();
199 199 }
200 200
201 201 #define ASSERT_PHASE_UNINITIALIZED(phase) \
202 202 assert(_gc_par_phases[phase] == NULL || _gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started");
203 203
204 204 double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {
205 205 if (_gc_par_phases[phase] == NULL) {
206 206 return 0.0;
207 207 }
208 208 double value = _gc_par_phases[phase]->get(worker);
209 209 if (value != WorkerDataArray<double>::uninitialized()) {
210 210 return value;
211 211 }
212 212 return 0.0;
213 213 }
214 214
215 215 void G1GCPhaseTimes::note_gc_end() {
216 216 _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
217 217
218 218 double uninitialized = WorkerDataArray<double>::uninitialized();
219 219
220 220 for (uint i = 0; i < _max_gc_threads; i++) {
221 221 double worker_start = _gc_par_phases[GCWorkerStart]->get(i);
222 222 if (worker_start != uninitialized) {
223 223 assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended.");
224 224 double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
225 225 record_time_secs(GCWorkerTotal, i , total_worker_time);
226 226
227 227 double worker_known_time = worker_time(ExtRootScan, i) +
228 228 worker_time(ScanHR, i) +
229 229 worker_time(CodeRoots, i) +
230 230 worker_time(ObjCopy, i) +
231 231 worker_time(Termination, i);
232 232
233 233 record_time_secs(Other, i, total_worker_time - worker_known_time);
234 234 } else {
235 235 // Make sure all slots are uninitialized since this thread did not seem to have been started
236 236 ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd);
237 237 ASSERT_PHASE_UNINITIALIZED(ExtRootScan);
238 238 ASSERT_PHASE_UNINITIALIZED(MergeER);
239 239 ASSERT_PHASE_UNINITIALIZED(MergeRS);
240 240 ASSERT_PHASE_UNINITIALIZED(OptMergeRS);
241 241 ASSERT_PHASE_UNINITIALIZED(MergeHCC);
242 242 ASSERT_PHASE_UNINITIALIZED(MergeLB);
243 243 ASSERT_PHASE_UNINITIALIZED(ScanHR);
244 244 ASSERT_PHASE_UNINITIALIZED(CodeRoots);
245 245 ASSERT_PHASE_UNINITIALIZED(OptCodeRoots);
246 246 ASSERT_PHASE_UNINITIALIZED(ObjCopy);
247 247 ASSERT_PHASE_UNINITIALIZED(OptObjCopy);
248 248 ASSERT_PHASE_UNINITIALIZED(Termination);
249 249 }
250 250 }
251 251 }
252 252
253 253 #undef ASSERT_PHASE_UNINITIALIZED
254 254
255 255 // record the time a phase took in seconds
256 256 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_id, double secs) {
257 257 _gc_par_phases[phase]->set(worker_id, secs);
258 258 }
259 259
260 260 // add a number of seconds to a phase
261 261 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_id, double secs) {
262 262 _gc_par_phases[phase]->add(worker_id, secs);
263 263 }
264 264
265 265 void G1GCPhaseTimes::record_or_add_time_secs(GCParPhases phase, uint worker_id, double secs) {
266 266 if (_gc_par_phases[phase]->get(worker_id) == _gc_par_phases[phase]->uninitialized()) {
267 267 record_time_secs(phase, worker_id, secs);
268 268 } else {
269 269 add_time_secs(phase, worker_id, secs);
270 270 }
271 271 }
272 272
273 273 double G1GCPhaseTimes::get_time_secs(GCParPhases phase, uint worker_id) {
274 274 return _gc_par_phases[phase]->get(worker_id);
275 275 }
276 276
277 277 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_id, size_t count, uint index) {
278 278 _gc_par_phases[phase]->set_thread_work_item(worker_id, count, index);
279 279 }
280 280
281 281 void G1GCPhaseTimes::record_or_add_thread_work_item(GCParPhases phase, uint worker_id, size_t count, uint index) {
282 282 _gc_par_phases[phase]->set_or_add_thread_work_item(worker_id, count, index);
283 283 }
284 284
285 285 size_t G1GCPhaseTimes::get_thread_work_item(GCParPhases phase, uint worker_id, uint index) {
286 286 return _gc_par_phases[phase]->get_thread_work_item(worker_id, index);
287 287 }
288 288
289 289 // return the average time for a phase in milliseconds
290 290 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
291 291 if (_gc_par_phases[phase] == NULL) {
292 292 return 0.0;
293 293 }
294 294 return _gc_par_phases[phase]->average() * 1000.0;
295 295 }
296 296
297 297 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
298 298 if (_gc_par_phases[phase] == NULL) {
299 299 return 0;
300 300 }
301 301 assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count");
302 302 return _gc_par_phases[phase]->thread_work_items(index)->sum();
303 303 }
304 304
305 305 template <class T>
306 306 void G1GCPhaseTimes::details(T* phase, const char* indent_str) const {
307 307 LogTarget(Trace, gc, phases, task) lt;
308 308 if (lt.is_enabled()) {
309 309 LogStream ls(lt);
310 310 ls.print("%s", indent_str);
311 311 phase->print_details_on(&ls);
312 312 }
313 313 }
314 314
315 315 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent_level, outputStream* out, bool print_sum) const {
316 316 out->print("%s", indent(indent_level));
317 317 phase->print_summary_on(out, print_sum);
318 318 details(phase, indent(indent_level));
319 319
320 320 for (uint i = 0; i < phase->MaxThreadWorkItems; i++) {
321 321 WorkerDataArray<size_t>* work_items = phase->thread_work_items(i);
322 322 if (work_items != NULL) {
323 323 out->print("%s", indent(indent_level + 1));
324 324 work_items->print_summary_on(out, true);
325 325 details(work_items, indent(indent_level + 1));
326 326 }
327 327 }
328 328 }
329 329
330 330 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase, uint extra_indent) const {
331 331 LogTarget(Debug, gc, phases) lt;
332 332 if (lt.is_enabled()) {
333 333 ResourceMark rm;
334 334 LogStream ls(lt);
335 335 log_phase(phase, 2 + extra_indent, &ls, true);
336 336 }
337 337 }
338 338
339 339 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum, uint extra_indent) const {
340 340 LogTarget(Trace, gc, phases) lt;
341 341 if (lt.is_enabled()) {
342 342 LogStream ls(lt);
343 343 log_phase(phase, 3 + extra_indent, &ls, print_sum);
344 344 }
345 345 }
346 346
347 347 #define TIME_FORMAT "%.1lfms"
348 348
349 349 void G1GCPhaseTimes::info_time(const char* name, double value) const {
350 350 log_info(gc, phases)("%s%s: " TIME_FORMAT, indent(1), name, value);
351 351 }
352 352
353 353 void G1GCPhaseTimes::debug_time(const char* name, double value) const {
354 354 log_debug(gc, phases)("%s%s: " TIME_FORMAT, indent(2), name, value);
355 355 }
356 356
357 357 void G1GCPhaseTimes::debug_time_for_reference(const char* name, double value) const {
358 358 LogTarget(Debug, gc, phases) lt;
359 359 LogTarget(Debug, gc, phases, ref) lt2;
360 360
361 361 if (lt.is_enabled()) {
362 362 LogStream ls(lt);
363 363 ls.print_cr("%s%s: " TIME_FORMAT, indent(2), name, value);
364 364 } else if (lt2.is_enabled()) {
365 365 LogStream ls(lt2);
366 366 ls.print_cr("%s%s: " TIME_FORMAT, indent(2), name, value);
367 367 }
368 368 }
369 369
370 370 void G1GCPhaseTimes::trace_time(const char* name, double value) const {
371 371 log_trace(gc, phases)("%s%s: " TIME_FORMAT, indent(3), name, value);
372 372 }
373 373
374 374 void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
375 375 log_trace(gc, phases)("%s%s: " SIZE_FORMAT, indent(3), name, value);
376 376 }
377 377
378 378 double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
379 379 const double sum_ms = _root_region_scan_wait_time_ms +
380 380 _recorded_young_cset_choice_time_ms +
381 381 _recorded_non_young_cset_choice_time_ms +
382 382 _cur_region_register_time +
383 383 _recorded_prepare_heap_roots_time_ms +
384 384 _recorded_clear_claimed_marks_time_ms;
385 385
386 386 info_time("Pre Evacuate Collection Set", sum_ms);
387 387
388 388 if (_root_region_scan_wait_time_ms > 0.0) {
389 389 debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
390 390 }
391 391 debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
392 392 debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
393 393 debug_time("Region Register", _cur_region_register_time);
394 394 if (G1EagerReclaimHumongousObjects) {
395 395 trace_count("Humongous Total", _cur_fast_reclaim_humongous_total);
396 396 trace_count("Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
397 397 }
398 398
399 399 debug_time("Prepare Heap Roots", _recorded_prepare_heap_roots_time_ms);
400 400 if (_recorded_clear_claimed_marks_time_ms > 0.0) {
401 401 debug_time("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
402 402 }
403 403 return sum_ms;
404 404 }
405 405
406 406 double G1GCPhaseTimes::print_evacuate_optional_collection_set() const {
407 407 const double sum_ms = _cur_optional_evac_time_ms + _cur_optional_merge_heap_roots_time_ms;
408 408 if (sum_ms > 0) {
409 409 info_time("Merge Optional Heap Roots", _cur_optional_merge_heap_roots_time_ms);
410 410
411 411 debug_time("Prepare Optional Merge Heap Roots", _cur_optional_prepare_merge_heap_roots_time_ms);
412 412 debug_phase(_gc_par_phases[OptMergeRS]);
413 413
414 414 info_time("Evacuate Optional Collection Set", _cur_optional_evac_time_ms);
415 415 debug_phase(_gc_par_phases[OptScanHR]);
416 416 debug_phase(_gc_par_phases[OptObjCopy]);
417 417 debug_phase(_gc_par_phases[OptCodeRoots]);
418 418 debug_phase(_gc_par_phases[OptTermination]);
419 419 }
420 420 return sum_ms;
421 421 }
422 422
423 423 double G1GCPhaseTimes::print_evacuate_initial_collection_set() const {
424 424 info_time("Merge Heap Roots", _cur_merge_heap_roots_time_ms);
425 425
426 426 debug_time("Prepare Merge Heap Roots", _cur_prepare_merge_heap_roots_time_ms);
427 427 debug_phase(_gc_par_phases[MergeER]);
428 428 debug_phase(_gc_par_phases[MergeRS]);
429 429 if (G1HotCardCache::default_use_cache()) {
430 430 debug_phase(_gc_par_phases[MergeHCC]);
431 431 }
432 432 debug_phase(_gc_par_phases[MergeLB]);
433 433
434 434 info_time("Evacuate Collection Set", _cur_collection_initial_evac_time_ms);
435 435
436 436 trace_phase(_gc_par_phases[GCWorkerStart], false);
437 437 debug_phase(_gc_par_phases[ExtRootScan]);
438 438 for (int i = ExtRootScanSubPhasesFirst; i <= ExtRootScanSubPhasesLast; i++) {
439 439 trace_phase(_gc_par_phases[i]);
440 440 }
441 441 debug_phase(_gc_par_phases[ScanHR]);
442 442 debug_phase(_gc_par_phases[CodeRoots]);
443 443 debug_phase(_gc_par_phases[ObjCopy]);
444 444 debug_phase(_gc_par_phases[Termination]);
445 445 debug_phase(_gc_par_phases[Other]);
446 446 debug_phase(_gc_par_phases[GCWorkerTotal]);
447 447 trace_phase(_gc_par_phases[GCWorkerEnd], false);
448 448
449 449 return _cur_collection_initial_evac_time_ms + _cur_merge_heap_roots_time_ms;
450 450 }
451 451
452 452 double G1GCPhaseTimes::print_post_evacuate_collection_set() const {
453 453 const double evac_fail_handling = _cur_evac_fail_recalc_used +
454 454 _cur_evac_fail_remove_self_forwards;
455 455 assert(_gc_par_phases[MergePSS]->get(0) != WorkerDataArray<double>::uninitialized(), "must be set");
456 456 const double merge_pss = _gc_par_phases[MergePSS]->get(0) * MILLIUNITS;
457 457 const double sum_ms = evac_fail_handling +
458 458 _cur_collection_code_root_fixup_time_ms +
|
↓ open down ↓ |
286 lines elided |
↑ open up ↑ |
459 459 _recorded_preserve_cm_referents_time_ms +
460 460 _cur_ref_proc_time_ms +
461 461 (_weak_phase_times.total_time_sec() * MILLIUNITS) +
462 462 _cur_clear_ct_time_ms +
463 463 merge_pss +
464 464 _cur_strong_code_root_purge_time_ms +
465 465 _recorded_redirty_logged_cards_time_ms +
466 466 _recorded_total_free_cset_time_ms +
467 467 _recorded_total_rebuild_freelist_time_ms +
468 468 _cur_fast_reclaim_humongous_time_ms +
469 - _cur_expand_heap_time_ms +
469 + _cur_resize_heap_time_ms +
470 470 _cur_string_deduplication_time_ms;
471 471
472 472 info_time("Post Evacuate Collection Set", sum_ms);
473 473
474 474 debug_time("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms);
475 475
476 476 debug_time("Clear Card Table", _cur_clear_ct_time_ms);
477 477
478 478 debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms);
479 479 _ref_phase_times.print_all_references(2, false);
480 480 _weak_phase_times.log_print(2);
481 481
482 482 if (G1StringDedup::is_enabled()) {
483 483 debug_time("String Deduplication", _cur_string_deduplication_time_ms);
484 484 debug_phase(_gc_par_phases[StringDedupQueueFixup], 1);
485 485 debug_phase(_gc_par_phases[StringDedupTableFixup], 1);
486 486 }
487 487
488 488 if (G1CollectedHeap::heap()->evacuation_failed()) {
489 489 debug_time("Evacuation Failure", evac_fail_handling);
490 490 trace_time("Recalculate Used", _cur_evac_fail_recalc_used);
491 491 trace_time("Remove Self Forwards",_cur_evac_fail_remove_self_forwards);
492 492 }
493 493
494 494 debug_phase(_gc_par_phases[MergePSS], 0);
495 495 debug_time("Code Roots Purge", _cur_strong_code_root_purge_time_ms);
496 496
497 497 debug_time("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
498 498 trace_phase(_gc_par_phases[RedirtyCards]);
499 499 #if COMPILER2_OR_JVMCI
500 500 debug_time("DerivedPointerTable Update", _cur_derived_pointer_table_update_time_ms);
501 501 #endif
502 502
503 503 debug_time("Free Collection Set", _recorded_total_free_cset_time_ms);
504 504 trace_time("Serial Free Collection Set", _recorded_serial_free_cset_time_ms);
505 505 trace_phase(_gc_par_phases[ParFreeCSet]);
506 506 trace_phase(_gc_par_phases[YoungFreeCSet], true, 1);
507 507 trace_phase(_gc_par_phases[NonYoungFreeCSet], true, 1);
508 508
509 509 debug_time("Rebuild Free List", _recorded_total_rebuild_freelist_time_ms);
510 510 trace_time("Serial Rebuild Free List ", _recorded_serial_rebuild_freelist_time_ms);
|
↓ open down ↓ |
31 lines elided |
↑ open up ↑ |
511 511 trace_phase(_gc_par_phases[RebuildFreeList]);
512 512
513 513 if (G1EagerReclaimHumongousObjects) {
514 514 debug_time("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
515 515 trace_count("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
516 516 }
517 517 debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms);
518 518 if (UseTLAB && ResizeTLAB) {
519 519 debug_time("Resize TLABs", _cur_resize_tlab_time_ms);
520 520 }
521 - debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
521 + debug_time("Resize Heap After Collection", _cur_resize_heap_time_ms);
522 522
523 523
524 524 return sum_ms;
525 525 }
526 526
527 527 void G1GCPhaseTimes::print_other(double accounted_ms) const {
528 528 info_time("Other", _gc_pause_time_ms - accounted_ms);
529 529 }
530 530
531 531 void G1GCPhaseTimes::print() {
532 532 note_gc_end();
533 533
534 534 if (_cur_verify_before_time_ms > 0.0) {
535 535 debug_time("Verify Before", _cur_verify_before_time_ms);
536 536 }
537 537
538 538 double accounted_ms = 0.0;
539 539 accounted_ms += print_pre_evacuate_collection_set();
540 540 accounted_ms += print_evacuate_initial_collection_set();
541 541 accounted_ms += print_evacuate_optional_collection_set();
542 542 accounted_ms += print_post_evacuate_collection_set();
543 543 print_other(accounted_ms);
544 544
545 545 if (_cur_verify_after_time_ms > 0.0) {
546 546 debug_time("Verify After", _cur_verify_after_time_ms);
547 547 }
548 548 }
549 549
550 550 const char* G1GCPhaseTimes::phase_name(GCParPhases phase) {
551 551 static const char* names[] = {
552 552 "GCWorkerStart",
553 553 "ExtRootScan",
554 554 "ThreadRoots",
555 555 "UniverseRoots",
556 556 "JNIRoots",
557 557 "ObjectSynchronizerRoots",
558 558 "ManagementRoots",
559 559 "SystemDictionaryRoots",
560 560 "CLDGRoots",
561 561 "JVMTIRoots",
562 562 AOT_ONLY("AOTCodeRoots" COMMA)
563 563 "CMRefRoots",
564 564 "MergeER",
565 565 "MergeRS",
566 566 "OptMergeRS",
567 567 "MergeLB",
568 568 "MergeHCC",
569 569 "ScanHR",
570 570 "OptScanHR",
571 571 "CodeRoots",
572 572 "OptCodeRoots",
573 573 "ObjCopy",
574 574 "OptObjCopy",
575 575 "Termination",
576 576 "OptTermination",
577 577 "Other",
578 578 "GCWorkerTotal",
579 579 "GCWorkerEnd",
580 580 "StringDedupQueueFixup",
581 581 "StringDedupTableFixup",
582 582 "RedirtyCards",
583 583 "ParFreeCSet",
584 584 "YoungFreeCSet",
585 585 "NonYoungFreeCSet",
586 586 "RebuildFreeList",
587 587 "MergePSS"
588 588 //GCParPhasesSentinel only used to tell end of enum
589 589 };
590 590
591 591 STATIC_ASSERT(ARRAY_SIZE(names) == G1GCPhaseTimes::GCParPhasesSentinel); // GCParPhases enum and corresponding string array should have the same "length", this tries to assert it
592 592
593 593 return names[phase];
594 594 }
595 595
596 596 G1EvacPhaseWithTrimTimeTracker::G1EvacPhaseWithTrimTimeTracker(G1ParScanThreadState* pss, Tickspan& total_time, Tickspan& trim_time) :
597 597 _pss(pss),
598 598 _start(Ticks::now()),
599 599 _total_time(total_time),
600 600 _trim_time(trim_time),
601 601 _stopped(false) {
602 602
603 603 assert(_pss->trim_ticks().value() == 0, "Possibly remaining trim ticks left over from previous use");
604 604 }
605 605
606 606 G1EvacPhaseWithTrimTimeTracker::~G1EvacPhaseWithTrimTimeTracker() {
607 607 if (!_stopped) {
608 608 stop();
609 609 }
610 610 }
611 611
612 612 void G1EvacPhaseWithTrimTimeTracker::stop() {
613 613 assert(!_stopped, "Should only be called once");
614 614 _total_time += (Ticks::now() - _start) - _pss->trim_ticks();
615 615 _trim_time += _pss->trim_ticks();
616 616 _pss->reset_trim_ticks();
617 617 _stopped = true;
618 618 }
619 619
620 620 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id, bool must_record) :
621 621 _start_time(), _phase(phase), _phase_times(phase_times), _worker_id(worker_id), _event(), _must_record(must_record) {
622 622 if (_phase_times != NULL) {
623 623 _start_time = Ticks::now();
624 624 }
625 625 }
626 626
627 627 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
628 628 if (_phase_times != NULL) {
629 629 if (_must_record) {
630 630 _phase_times->record_time_secs(_phase, _worker_id, (Ticks::now() - _start_time).seconds());
631 631 } else {
632 632 _phase_times->record_or_add_time_secs(_phase, _worker_id, (Ticks::now() - _start_time).seconds());
633 633 }
634 634 _event.commit(GCId::current(), _worker_id, G1GCPhaseTimes::phase_name(_phase));
635 635 }
636 636 }
637 637
638 638 G1EvacPhaseTimesTracker::G1EvacPhaseTimesTracker(G1GCPhaseTimes* phase_times,
639 639 G1ParScanThreadState* pss,
640 640 G1GCPhaseTimes::GCParPhases phase,
641 641 uint worker_id) :
642 642 G1GCParPhaseTimesTracker(phase_times, phase, worker_id),
643 643 _total_time(),
644 644 _trim_time(),
645 645 _trim_tracker(pss, _total_time, _trim_time) {
646 646 }
647 647
648 648 G1EvacPhaseTimesTracker::~G1EvacPhaseTimesTracker() {
649 649 if (_phase_times != NULL) {
650 650 // Explicitly stop the trim tracker since it's not yet destructed.
651 651 _trim_tracker.stop();
652 652 // Exclude trim time by increasing the start time.
653 653 _start_time += _trim_time;
654 654 _phase_times->record_or_add_time_secs(G1GCPhaseTimes::ObjCopy, _worker_id, _trim_time.seconds());
655 655 }
656 656 }
657 657
|
↓ open down ↓ |
126 lines elided |
↑ open up ↑ |
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX