author | tschatzl |
Thu, 31 Mar 2016 12:00:08 +0200 | |
changeset 37209 | c2920cd096aa |
parent 36387 | 1c1c1c1aa3ad |
child 37214 | bc4e0e0995e6 |
permissions | -rw-r--r-- |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
1 |
/* |
36367
313c87c050f7
8076463: Add logging for the preserve CM referents task
tschatzl
parents:
35907
diff
changeset
|
2 |
* Copyright (c) 2013, 2016, Oracle and/or its affiliates. All rights reserved. |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
3 |
* DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER. |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
4 |
* |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
5 |
* This code is free software; you can redistribute it and/or modify it |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
6 |
* under the terms of the GNU General Public License version 2 only, as |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
7 |
* published by the Free Software Foundation. |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
8 |
* |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
9 |
* This code is distributed in the hope that it will be useful, but WITHOUT |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
10 |
* ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
11 |
* FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
12 |
* version 2 for more details (a copy is included in the LICENSE file that |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
13 |
* accompanied this code). |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
14 |
* |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
15 |
* You should have received a copy of the GNU General Public License version |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
16 |
* 2 along with this work; if not, write to the Free Software Foundation, |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
17 |
* Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA. |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
18 |
* |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
19 |
* Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
20 |
* or visit www.oracle.com if you need additional information or have any |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
21 |
* questions. |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
22 |
* |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
23 |
*/ |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
24 |
|
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
25 |
#include "precompiled.hpp" |
33204
b8a3901ac5b3
8069330: Adjustment of concurrent refinement thresholds does not take hot card cache into account
tschatzl
parents:
33105
diff
changeset
|
26 |
#include "gc/g1/concurrentG1Refine.hpp" |
30764 | 27 |
#include "gc/g1/g1CollectedHeap.inline.hpp" |
28 |
#include "gc/g1/g1GCPhaseTimes.hpp" |
|
29 |
#include "gc/g1/g1StringDedup.hpp" |
|
33623 | 30 |
#include "gc/g1/workerDataArray.inline.hpp" |
36374 | 31 |
#include "memory/resourceArea.hpp" |
35061 | 32 |
#include "logging/log.hpp" |
35907
57bdb6243428
8148734: G1: Make G1GCPhaseTimes keep track of the start GC time
brutisso
parents:
35887
diff
changeset
|
33 |
#include "runtime/timer.hpp" |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
34 |
#include "runtime/os.hpp" |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
35 |
|
36374 | 36 |
static const char* Indents[5] = {"", " ", " ", " ", " "}; |
35061 | 37 |
|
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
38 |
G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) : |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
39 |
_max_gc_threads(max_gc_threads) |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
40 |
{ |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
41 |
assert(max_gc_threads > 0, "Must have some GC threads"); |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
42 |
|
36374 | 43 |
_gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms):"); |
44 |
_gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms):"); |
|
29694
442c3305ba39
8027962: Per-phase timing measurements for strong roots processing
brutisso
parents:
29680
diff
changeset
|
45 |
|
442c3305ba39
8027962: Per-phase timing measurements for strong roots processing
brutisso
parents:
29680
diff
changeset
|
46 |
// Root scanning phases |
36374 | 47 |
_gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms):"); |
48 |
_gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms):"); |
|
49 |
_gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms):"); |
|
50 |
_gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms):"); |
|
51 |
_gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms):"); |
|
52 |
_gc_par_phases[FlatProfilerRoots] = new WorkerDataArray<double>(max_gc_threads, "FlatProfiler Roots (ms):"); |
|
53 |
_gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms):"); |
|
54 |
_gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms):"); |
|
55 |
_gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms):"); |
|
56 |
_gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms):"); |
|
57 |
_gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms):"); |
|
58 |
_gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms):"); |
|
59 |
_gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms):"); |
|
60 |
_gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms):"); |
|
29694
442c3305ba39
8027962: Per-phase timing measurements for strong roots processing
brutisso
parents:
29680
diff
changeset
|
61 |
|
36374 | 62 |
_gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms):"); |
63 |
if (ConcurrentG1Refine::hot_card_cache_enabled()) { |
|
64 |
_gc_par_phases[ScanHCC] = new WorkerDataArray<double>(max_gc_threads, "Scan HCC (ms):"); |
|
65 |
} else { |
|
66 |
_gc_par_phases[ScanHCC] = NULL; |
|
67 |
} |
|
68 |
_gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms):"); |
|
69 |
_gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms):"); |
|
70 |
_gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms):"); |
|
71 |
_gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms):"); |
|
72 |
_gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms):"); |
|
73 |
_gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms):"); |
|
74 |
_gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms):"); |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
75 |
|
36374 | 76 |
_update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers:"); |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
77 |
_gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers); |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
78 |
|
36374 | 79 |
_termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:"); |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
80 |
_gc_par_phases[Termination]->link_thread_work_items(_termination_attempts); |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
81 |
|
36374 | 82 |
if (UseStringDeduplication) { |
83 |
_gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):"); |
|
84 |
_gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):"); |
|
85 |
} else { |
|
86 |
_gc_par_phases[StringDedupQueueFixup] = NULL; |
|
87 |
_gc_par_phases[StringDedupTableFixup] = NULL; |
|
88 |
} |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
89 |
|
36374 | 90 |
_gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):"); |
91 |
_redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:"); |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
92 |
_gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards); |
36367
313c87c050f7
8076463: Add logging for the preserve CM referents task
tschatzl
parents:
35907
diff
changeset
|
93 |
|
36374 | 94 |
_gc_par_phases[PreserveCMReferents] = new WorkerDataArray<double>(max_gc_threads, "Parallel Preserve CM Refs (ms):"); |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
95 |
} |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
96 |
|
33739 | 97 |
void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) { |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
98 |
assert(active_gc_threads > 0, "The number of threads must be > 0"); |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
99 |
assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max number of threads"); |
35907
57bdb6243428
8148734: G1: Make G1GCPhaseTimes keep track of the start GC time
brutisso
parents:
35887
diff
changeset
|
100 |
_gc_start_counter = os::elapsed_counter(); |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
101 |
_active_gc_threads = active_gc_threads; |
33577 | 102 |
_cur_expand_heap_time_ms = 0.0; |
34612
ed475e8089ef
8144145: G1GCPhaseTimes should allow externally accounted time
ehelin
parents:
33739
diff
changeset
|
103 |
_external_accounted_time_ms = 0.0; |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
104 |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
105 |
for (int i = 0; i < GCParPhasesSentinel; i++) { |
36374 | 106 |
if (_gc_par_phases[i] != NULL) { |
107 |
_gc_par_phases[i]->reset(); |
|
108 |
} |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
109 |
} |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
110 |
} |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
111 |
|
13516
f7adc27fb367
7178363: G1: Remove the serial code for PrintGCDetails and make it a special case of the parallel code
brutisso
parents:
13288
diff
changeset
|
112 |
void G1GCPhaseTimes::note_gc_end() { |
35907
57bdb6243428
8148734: G1: Make G1GCPhaseTimes keep track of the start GC time
brutisso
parents:
35887
diff
changeset
|
113 |
_gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter); |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
114 |
for (uint i = 0; i < _active_gc_threads; i++) { |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
115 |
double worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i); |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
116 |
record_time_secs(GCWorkerTotal, i , worker_time); |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
117 |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
118 |
double worker_known_time = |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
119 |
_gc_par_phases[ExtRootScan]->get(i) + |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
120 |
_gc_par_phases[SATBFiltering]->get(i) + |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
121 |
_gc_par_phases[UpdateRS]->get(i) + |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
122 |
_gc_par_phases[ScanRS]->get(i) + |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
123 |
_gc_par_phases[CodeRoots]->get(i) + |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
124 |
_gc_par_phases[ObjCopy]->get(i) + |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
125 |
_gc_par_phases[Termination]->get(i); |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
126 |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
127 |
record_time_secs(Other, i, worker_time - worker_known_time); |
15238
2a5f251cc9ad
8006242: G1: WorkerDataArray<T>::verify() too strict for double calculations
brutisso
parents:
13877
diff
changeset
|
128 |
} |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
129 |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
130 |
for (int i = 0; i < GCParPhasesSentinel; i++) { |
36374 | 131 |
if (_gc_par_phases[i] != NULL) { |
132 |
_gc_par_phases[i]->verify(_active_gc_threads); |
|
133 |
} |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
134 |
} |
23472 | 135 |
} |
136 |
||
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
137 |
// record the time a phase took in seconds |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
138 |
void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) { |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
139 |
_gc_par_phases[phase]->set(worker_i, secs); |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
140 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
141 |
|
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
142 |
// add a number of seconds to a phase |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
143 |
void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) { |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
144 |
_gc_par_phases[phase]->add(worker_i, secs); |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
145 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
146 |
|
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
147 |
void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count) { |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
148 |
_gc_par_phases[phase]->set_thread_work_item(worker_i, count); |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
149 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
150 |
|
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
151 |
// return the average time for a phase in milliseconds |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
152 |
double G1GCPhaseTimes::average_time_ms(GCParPhases phase) { |
29809
c59a5f161524
8017462: G1: guarantee fails with UseDynamicNumberOfGCThreads
jmasa
parents:
29694
diff
changeset
|
153 |
return _gc_par_phases[phase]->average(_active_gc_threads) * 1000.0; |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
154 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
155 |
|
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
156 |
size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase) { |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
157 |
assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count"); |
29809
c59a5f161524
8017462: G1: guarantee fails with UseDynamicNumberOfGCThreads
jmasa
parents:
29694
diff
changeset
|
158 |
return _gc_par_phases[phase]->thread_work_items()->sum(_active_gc_threads); |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
159 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
160 |
|
36374 | 161 |
template <class T> |
162 |
void G1GCPhaseTimes::details(T* phase, const char* indent) { |
|
163 |
LogHandle(gc, phases, task) log; |
|
164 |
if (log.is_level(LogLevel::Trace)) { |
|
165 |
outputStream* trace_out = log.trace_stream(); |
|
166 |
trace_out->print("%s", indent); |
|
167 |
phase->print_details_on(trace_out, _active_gc_threads); |
|
168 |
} |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
169 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
170 |
|
36374 | 171 |
void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) { |
172 |
out->print("%s", Indents[indent]); |
|
173 |
phase->print_summary_on(out, _active_gc_threads, print_sum); |
|
174 |
details(phase, Indents[indent]); |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
175 |
|
36374 | 176 |
WorkerDataArray<size_t>* work_items = phase->thread_work_items(); |
177 |
if (work_items != NULL) { |
|
178 |
out->print("%s", Indents[indent + 1]); |
|
179 |
work_items->print_summary_on(out, _active_gc_threads, true); |
|
180 |
details(work_items, Indents[indent + 1]); |
|
181 |
} |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
182 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
183 |
|
36374 | 184 |
void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) { |
185 |
LogHandle(gc, phases) log; |
|
186 |
if (log.is_level(LogLevel::Debug)) { |
|
187 |
ResourceMark rm; |
|
188 |
log_phase(phase, 2, log.debug_stream(), true); |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
189 |
} |
36374 | 190 |
} |
35061 | 191 |
|
36374 | 192 |
void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) { |
193 |
LogHandle(gc, phases) log; |
|
194 |
if (log.is_level(LogLevel::Trace)) { |
|
195 |
ResourceMark rm; |
|
196 |
log_phase(phase, 3, log.trace_stream(), print_sum); |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
197 |
} |
36374 | 198 |
} |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
199 |
|
36374 | 200 |
#define PHASE_DOUBLE_FORMAT "%s%s: %.1lfms" |
201 |
#define PHASE_SIZE_FORMAT "%s%s: " SIZE_FORMAT |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
202 |
|
36374 | 203 |
#define info_line(str, value) \ |
204 |
log_info(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[1], str, value); |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
205 |
|
36374 | 206 |
#define debug_line(str, value) \ |
207 |
log_debug(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[2], str, value); |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
208 |
|
36374 | 209 |
#define trace_line(str, value) \ |
210 |
log_trace(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[3], str, value); |
|
35061 | 211 |
|
36374 | 212 |
#define trace_line_sz(str, value) \ |
213 |
log_trace(gc, phases)(PHASE_SIZE_FORMAT, Indents[3], str, value); |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
214 |
|
36374 | 215 |
#define trace_line_ms(str, value) \ |
216 |
log_trace(gc, phases)(PHASE_SIZE_FORMAT, Indents[3], str, value); |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
217 |
|
36374 | 218 |
#define info_line_and_account(str, value) \ |
219 |
info_line(str, value); \ |
|
220 |
accounted_time_ms += value; |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
221 |
|
35907
57bdb6243428
8148734: G1: Make G1GCPhaseTimes keep track of the start GC time
brutisso
parents:
35887
diff
changeset
|
222 |
void G1GCPhaseTimes::print() { |
33738
1708291bd3d7
8140508: Add utility method for logging phases to G1CollectorPolicy
ehelin
parents:
33623
diff
changeset
|
223 |
note_gc_end(); |
1708291bd3d7
8140508: Add utility method for logging phases to G1CollectorPolicy
ehelin
parents:
33623
diff
changeset
|
224 |
|
36374 | 225 |
double accounted_time_ms = _external_accounted_time_ms; |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
226 |
if (_root_region_scan_wait_time_ms > 0.0) { |
36374 | 227 |
info_line_and_account("Root Region Scan Waiting", _root_region_scan_wait_time_ms); |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
228 |
} |
27251
7d667f91ec8d
6979279: remove special-case code for ParallelGCThreads==0
mlarsson
parents:
26701
diff
changeset
|
229 |
|
36374 | 230 |
info_line_and_account("Evacuate Collection Set", _cur_collection_par_time_ms); |
231 |
trace_phase(_gc_par_phases[GCWorkerStart], false); |
|
232 |
debug_phase(_gc_par_phases[ExtRootScan]); |
|
233 |
for (int i = ThreadRoots; i <= SATBFiltering; i++) { |
|
234 |
trace_phase(_gc_par_phases[i]); |
|
235 |
} |
|
236 |
debug_phase(_gc_par_phases[UpdateRS]); |
|
237 |
if (ConcurrentG1Refine::hot_card_cache_enabled()) { |
|
238 |
trace_phase(_gc_par_phases[ScanHCC]); |
|
239 |
} |
|
240 |
debug_phase(_gc_par_phases[ScanRS]); |
|
241 |
debug_phase(_gc_par_phases[CodeRoots]); |
|
242 |
debug_phase(_gc_par_phases[ObjCopy]); |
|
243 |
debug_phase(_gc_par_phases[Termination]); |
|
244 |
debug_phase(_gc_par_phases[Other]); |
|
245 |
debug_phase(_gc_par_phases[GCWorkerTotal]); |
|
246 |
trace_phase(_gc_par_phases[GCWorkerEnd], false); |
|
247 |
||
248 |
info_line_and_account("Code Roots", _cur_collection_code_root_fixup_time_ms + _cur_strong_code_root_purge_time_ms); |
|
249 |
debug_line("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms); |
|
250 |
debug_line("Code Roots Purge", _cur_strong_code_root_purge_time_ms); |
|
251 |
||
23472 | 252 |
if (G1StringDedup::is_enabled()) { |
36374 | 253 |
info_line_and_account("String Dedup Fixup", _cur_string_dedup_fixup_time_ms); |
254 |
debug_phase(_gc_par_phases[StringDedupQueueFixup]); |
|
255 |
debug_phase(_gc_par_phases[StringDedupTableFixup]); |
|
23472 | 256 |
} |
36374 | 257 |
info_line_and_account("Clear Card Table", _cur_clear_ct_time_ms); |
258 |
info_line_and_account("Expand Heap After Collection", _cur_expand_heap_time_ms); |
|
259 |
||
260 |
double free_cset_time = _recorded_young_free_cset_time_ms + _recorded_non_young_free_cset_time_ms; |
|
261 |
info_line_and_account("Free Collection Set", free_cset_time); |
|
262 |
debug_line("Young Free Collection Set", _recorded_young_free_cset_time_ms); |
|
263 |
debug_line("Non-Young Free Collection Set", _recorded_non_young_free_cset_time_ms); |
|
264 |
info_line_and_account("Merge Per-Thread State", _recorded_merge_pss_time_ms); |
|
265 |
||
266 |
info_line("Other", _gc_pause_time_ms - accounted_time_ms); |
|
13516
f7adc27fb367
7178363: G1: Remove the serial code for PrintGCDetails and make it a special case of the parallel code
brutisso
parents:
13288
diff
changeset
|
267 |
if (_cur_verify_before_time_ms > 0.0) { |
36374 | 268 |
debug_line("Verify Before", _cur_verify_before_time_ms); |
13516
f7adc27fb367
7178363: G1: Remove the serial code for PrintGCDetails and make it a special case of the parallel code
brutisso
parents:
13288
diff
changeset
|
269 |
} |
23455
e541bff96524
8035654: Add times for evacuation failure handling in "Other" time
tschatzl
parents:
23454
diff
changeset
|
270 |
if (G1CollectedHeap::heap()->evacuation_failed()) { |
e541bff96524
8035654: Add times for evacuation failure handling in "Other" time
tschatzl
parents:
23454
diff
changeset
|
271 |
double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards + |
e541bff96524
8035654: Add times for evacuation failure handling in "Other" time
tschatzl
parents:
23454
diff
changeset
|
272 |
_cur_evac_fail_restore_remsets; |
36374 | 273 |
debug_line("Evacuation Failure", evac_fail_handling); |
274 |
trace_line("Recalculate Used", _cur_evac_fail_recalc_used); |
|
275 |
trace_line("Remove Self Forwards",_cur_evac_fail_remove_self_forwards); |
|
276 |
trace_line("Restore RemSet", _cur_evac_fail_restore_remsets); |
|
23455
e541bff96524
8035654: Add times for evacuation failure handling in "Other" time
tschatzl
parents:
23454
diff
changeset
|
277 |
} |
36374 | 278 |
debug_line("Choose CSet", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms)); |
279 |
debug_line("Preserve CM Refs", _recorded_preserve_cm_referents_time_ms); |
|
37209
c2920cd096aa
8153065: "Preserve CM refs" log message disconnected from "Parallel Preserve CM refs"
tschatzl
parents:
36387
diff
changeset
|
280 |
trace_phase(_gc_par_phases[PreserveCMReferents]); |
36387
1c1c1c1aa3ad
8058944: Unify the reporting strings for the GC debug level logging in G1
brutisso
parents:
36374
diff
changeset
|
281 |
debug_line("Reference Processing", _cur_ref_proc_time_ms); |
1c1c1c1aa3ad
8058944: Unify the reporting strings for the GC debug level logging in G1
brutisso
parents:
36374
diff
changeset
|
282 |
debug_line("Reference Enqueuing", _cur_ref_enq_time_ms); |
36374 | 283 |
debug_line("Redirty Cards", _recorded_redirty_logged_cards_time_ms); |
284 |
trace_phase(_gc_par_phases[RedirtyCards]); |
|
28379
e6784fc8fff2
8048179: Early reclaim of large objects that are referenced by a few objects
tschatzl
parents:
27251
diff
changeset
|
285 |
if (G1EagerReclaimHumongousObjects) { |
36374 | 286 |
debug_line("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms); |
287 |
trace_line_sz("Humongous Total", _cur_fast_reclaim_humongous_total); |
|
288 |
trace_line_sz("Humongous Candidate", _cur_fast_reclaim_humongous_candidates); |
|
289 |
debug_line("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms); |
|
290 |
trace_line_sz("Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed); |
|
25889
221296ac4359
8027959: Early reclamation of large objects in G1
tschatzl
parents:
25492
diff
changeset
|
291 |
} |
13516
f7adc27fb367
7178363: G1: Remove the serial code for PrintGCDetails and make it a special case of the parallel code
brutisso
parents:
13288
diff
changeset
|
292 |
if (_cur_verify_after_time_ms > 0.0) { |
36374 | 293 |
debug_line("Verify After", _cur_verify_after_time_ms); |
13516
f7adc27fb367
7178363: G1: Remove the serial code for PrintGCDetails and make it a special case of the parallel code
brutisso
parents:
13288
diff
changeset
|
294 |
} |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
295 |
} |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
296 |
|
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
297 |
G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) : |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
298 |
_phase_times(phase_times), _phase(phase), _worker_id(worker_id) { |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
299 |
if (_phase_times != NULL) { |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
300 |
_start_time = os::elapsedTime(); |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
301 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
302 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
303 |
|
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
304 |
G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() { |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
305 |
if (_phase_times != NULL) { |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
306 |
_phase_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time); |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
307 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
308 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
309 |