author | brutisso |
Thu, 31 Mar 2016 17:05:29 +0200 | |
changeset 37214 | bc4e0e0995e6 |
parent 37209 | c2920cd096aa |
child 37242 | 91e5f98fff6f |
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 |
|
37214
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
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 |
|
37214
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
97 |
void G1GCPhaseTimes::note_gc_start() { |
35907
57bdb6243428
8148734: G1: Make G1GCPhaseTimes keep track of the start GC time
brutisso
parents:
35887
diff
changeset
|
98 |
_gc_start_counter = os::elapsed_counter(); |
33577 | 99 |
_cur_expand_heap_time_ms = 0.0; |
34612
ed475e8089ef
8144145: G1GCPhaseTimes should allow externally accounted time
ehelin
parents:
33739
diff
changeset
|
100 |
_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
|
101 |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
102 |
for (int i = 0; i < GCParPhasesSentinel; i++) { |
36374 | 103 |
if (_gc_par_phases[i] != NULL) { |
104 |
_gc_par_phases[i]->reset(); |
|
105 |
} |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
106 |
} |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
107 |
} |
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
108 |
|
37214
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
109 |
#define ASSERT_PHASE_UNINITIALIZED(phase) \ |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
110 |
assert(_gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started"); |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
111 |
|
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
112 |
double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) { |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
113 |
double value = _gc_par_phases[phase]->get(worker); |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
114 |
if (value != WorkerDataArray<double>::uninitialized()) { |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
115 |
return value; |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
116 |
} |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
117 |
return 0.0; |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
118 |
} |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
119 |
|
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
|
120 |
void G1GCPhaseTimes::note_gc_end() { |
35907
57bdb6243428
8148734: G1: Make G1GCPhaseTimes keep track of the start GC time
brutisso
parents:
35887
diff
changeset
|
121 |
_gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter); |
37214
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
122 |
|
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
123 |
double uninitialized = WorkerDataArray<double>::uninitialized(); |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
124 |
|
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
125 |
for (uint i = 0; i < _max_gc_threads; i++) { |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
126 |
double worker_start = _gc_par_phases[GCWorkerStart]->get(i); |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
127 |
if (worker_start != uninitialized) { |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
128 |
assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended."); |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
129 |
double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i); |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
130 |
record_time_secs(GCWorkerTotal, i , total_worker_time); |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
131 |
|
37214
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
132 |
double worker_known_time = |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
133 |
worker_time(ExtRootScan, i) |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
134 |
+ worker_time(SATBFiltering, i) |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
135 |
+ worker_time(UpdateRS, i) |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
136 |
+ worker_time(ScanRS, i) |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
137 |
+ worker_time(CodeRoots, i) |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
138 |
+ worker_time(ObjCopy, i) |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
139 |
+ worker_time(Termination, i); |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
140 |
|
37214
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
141 |
record_time_secs(Other, i, total_worker_time - worker_known_time); |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
142 |
} else { |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
143 |
// Make sure all slots are uninitialized since this thread did not seem to have been started |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
144 |
ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd); |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
145 |
ASSERT_PHASE_UNINITIALIZED(ExtRootScan); |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
146 |
ASSERT_PHASE_UNINITIALIZED(SATBFiltering); |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
147 |
ASSERT_PHASE_UNINITIALIZED(UpdateRS); |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
148 |
ASSERT_PHASE_UNINITIALIZED(ScanRS); |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
149 |
ASSERT_PHASE_UNINITIALIZED(CodeRoots); |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
150 |
ASSERT_PHASE_UNINITIALIZED(ObjCopy); |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
151 |
ASSERT_PHASE_UNINITIALIZED(Termination); |
36374 | 152 |
} |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
153 |
} |
23472 | 154 |
} |
155 |
||
37214
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
156 |
#undef ASSERT_PHASE_UNINITIALIZED |
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
157 |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
158 |
// 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
|
159 |
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
|
160 |
_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
|
161 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
162 |
|
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
163 |
// 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
|
164 |
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
|
165 |
_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
|
166 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
167 |
|
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
168 |
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
|
169 |
_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
|
170 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
171 |
|
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
172 |
// 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
|
173 |
double G1GCPhaseTimes::average_time_ms(GCParPhases phase) { |
37214
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
174 |
return _gc_par_phases[phase]->average() * 1000.0; |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
175 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
176 |
|
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
177 |
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
|
178 |
assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count"); |
37214
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
179 |
return _gc_par_phases[phase]->thread_work_items()->sum(); |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
180 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
181 |
|
36374 | 182 |
template <class T> |
183 |
void G1GCPhaseTimes::details(T* phase, const char* indent) { |
|
184 |
LogHandle(gc, phases, task) log; |
|
185 |
if (log.is_level(LogLevel::Trace)) { |
|
186 |
outputStream* trace_out = log.trace_stream(); |
|
187 |
trace_out->print("%s", indent); |
|
37214
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
188 |
phase->print_details_on(trace_out); |
36374 | 189 |
} |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
190 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
191 |
|
36374 | 192 |
void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) { |
193 |
out->print("%s", Indents[indent]); |
|
37214
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
194 |
phase->print_summary_on(out, print_sum); |
36374 | 195 |
details(phase, Indents[indent]); |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
196 |
|
36374 | 197 |
WorkerDataArray<size_t>* work_items = phase->thread_work_items(); |
198 |
if (work_items != NULL) { |
|
199 |
out->print("%s", Indents[indent + 1]); |
|
37214
bc4e0e0995e6
8152952: Allow G1 phase logging to use individual number of threads
brutisso
parents:
37209
diff
changeset
|
200 |
work_items->print_summary_on(out, true); |
36374 | 201 |
details(work_items, Indents[indent + 1]); |
202 |
} |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
203 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
204 |
|
36374 | 205 |
void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) { |
206 |
LogHandle(gc, phases) log; |
|
207 |
if (log.is_level(LogLevel::Debug)) { |
|
208 |
ResourceMark rm; |
|
209 |
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
|
210 |
} |
36374 | 211 |
} |
35061 | 212 |
|
36374 | 213 |
void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) { |
214 |
LogHandle(gc, phases) log; |
|
215 |
if (log.is_level(LogLevel::Trace)) { |
|
216 |
ResourceMark rm; |
|
217 |
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
|
218 |
} |
36374 | 219 |
} |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
220 |
|
36374 | 221 |
#define PHASE_DOUBLE_FORMAT "%s%s: %.1lfms" |
222 |
#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
|
223 |
|
36374 | 224 |
#define info_line(str, value) \ |
225 |
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
|
226 |
|
36374 | 227 |
#define debug_line(str, value) \ |
228 |
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
|
229 |
|
36374 | 230 |
#define trace_line(str, value) \ |
231 |
log_trace(gc, phases)(PHASE_DOUBLE_FORMAT, Indents[3], str, value); |
|
35061 | 232 |
|
36374 | 233 |
#define trace_line_sz(str, value) \ |
234 |
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
|
235 |
|
36374 | 236 |
#define trace_line_ms(str, value) \ |
237 |
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
|
238 |
|
36374 | 239 |
#define info_line_and_account(str, value) \ |
240 |
info_line(str, value); \ |
|
241 |
accounted_time_ms += value; |
|
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
242 |
|
35907
57bdb6243428
8148734: G1: Make G1GCPhaseTimes keep track of the start GC time
brutisso
parents:
35887
diff
changeset
|
243 |
void G1GCPhaseTimes::print() { |
33738
1708291bd3d7
8140508: Add utility method for logging phases to G1CollectorPolicy
ehelin
parents:
33623
diff
changeset
|
244 |
note_gc_end(); |
1708291bd3d7
8140508: Add utility method for logging phases to G1CollectorPolicy
ehelin
parents:
33623
diff
changeset
|
245 |
|
36374 | 246 |
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
|
247 |
if (_root_region_scan_wait_time_ms > 0.0) { |
36374 | 248 |
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
|
249 |
} |
27251
7d667f91ec8d
6979279: remove special-case code for ParallelGCThreads==0
mlarsson
parents:
26701
diff
changeset
|
250 |
|
36374 | 251 |
info_line_and_account("Evacuate Collection Set", _cur_collection_par_time_ms); |
252 |
trace_phase(_gc_par_phases[GCWorkerStart], false); |
|
253 |
debug_phase(_gc_par_phases[ExtRootScan]); |
|
254 |
for (int i = ThreadRoots; i <= SATBFiltering; i++) { |
|
255 |
trace_phase(_gc_par_phases[i]); |
|
256 |
} |
|
257 |
debug_phase(_gc_par_phases[UpdateRS]); |
|
258 |
if (ConcurrentG1Refine::hot_card_cache_enabled()) { |
|
259 |
trace_phase(_gc_par_phases[ScanHCC]); |
|
260 |
} |
|
261 |
debug_phase(_gc_par_phases[ScanRS]); |
|
262 |
debug_phase(_gc_par_phases[CodeRoots]); |
|
263 |
debug_phase(_gc_par_phases[ObjCopy]); |
|
264 |
debug_phase(_gc_par_phases[Termination]); |
|
265 |
debug_phase(_gc_par_phases[Other]); |
|
266 |
debug_phase(_gc_par_phases[GCWorkerTotal]); |
|
267 |
trace_phase(_gc_par_phases[GCWorkerEnd], false); |
|
268 |
||
269 |
info_line_and_account("Code Roots", _cur_collection_code_root_fixup_time_ms + _cur_strong_code_root_purge_time_ms); |
|
270 |
debug_line("Code Roots Fixup", _cur_collection_code_root_fixup_time_ms); |
|
271 |
debug_line("Code Roots Purge", _cur_strong_code_root_purge_time_ms); |
|
272 |
||
23472 | 273 |
if (G1StringDedup::is_enabled()) { |
36374 | 274 |
info_line_and_account("String Dedup Fixup", _cur_string_dedup_fixup_time_ms); |
275 |
debug_phase(_gc_par_phases[StringDedupQueueFixup]); |
|
276 |
debug_phase(_gc_par_phases[StringDedupTableFixup]); |
|
23472 | 277 |
} |
36374 | 278 |
info_line_and_account("Clear Card Table", _cur_clear_ct_time_ms); |
279 |
info_line_and_account("Expand Heap After Collection", _cur_expand_heap_time_ms); |
|
280 |
||
281 |
double free_cset_time = _recorded_young_free_cset_time_ms + _recorded_non_young_free_cset_time_ms; |
|
282 |
info_line_and_account("Free Collection Set", free_cset_time); |
|
283 |
debug_line("Young Free Collection Set", _recorded_young_free_cset_time_ms); |
|
284 |
debug_line("Non-Young Free Collection Set", _recorded_non_young_free_cset_time_ms); |
|
285 |
info_line_and_account("Merge Per-Thread State", _recorded_merge_pss_time_ms); |
|
286 |
||
287 |
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
|
288 |
if (_cur_verify_before_time_ms > 0.0) { |
36374 | 289 |
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
|
290 |
} |
23455
e541bff96524
8035654: Add times for evacuation failure handling in "Other" time
tschatzl
parents:
23454
diff
changeset
|
291 |
if (G1CollectedHeap::heap()->evacuation_failed()) { |
e541bff96524
8035654: Add times for evacuation failure handling in "Other" time
tschatzl
parents:
23454
diff
changeset
|
292 |
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
|
293 |
_cur_evac_fail_restore_remsets; |
36374 | 294 |
debug_line("Evacuation Failure", evac_fail_handling); |
295 |
trace_line("Recalculate Used", _cur_evac_fail_recalc_used); |
|
296 |
trace_line("Remove Self Forwards",_cur_evac_fail_remove_self_forwards); |
|
297 |
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
|
298 |
} |
36374 | 299 |
debug_line("Choose CSet", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms)); |
300 |
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
|
301 |
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
|
302 |
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
|
303 |
debug_line("Reference Enqueuing", _cur_ref_enq_time_ms); |
36374 | 304 |
debug_line("Redirty Cards", _recorded_redirty_logged_cards_time_ms); |
305 |
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
|
306 |
if (G1EagerReclaimHumongousObjects) { |
36374 | 307 |
debug_line("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms); |
308 |
trace_line_sz("Humongous Total", _cur_fast_reclaim_humongous_total); |
|
309 |
trace_line_sz("Humongous Candidate", _cur_fast_reclaim_humongous_candidates); |
|
310 |
debug_line("Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms); |
|
311 |
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
|
312 |
} |
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
|
313 |
if (_cur_verify_after_time_ms > 0.0) { |
36374 | 314 |
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
|
315 |
} |
13288
331d5b6725f3
7178361: G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
brutisso
parents:
diff
changeset
|
316 |
} |
29680
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
317 |
|
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
318 |
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
|
319 |
_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
|
320 |
if (_phase_times != NULL) { |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
321 |
_start_time = os::elapsedTime(); |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
322 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
323 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
324 |
|
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
325 |
G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() { |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
326 |
if (_phase_times != NULL) { |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
327 |
_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
|
328 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
329 |
} |
e5203ed6d805
8074037: Refactor the G1GCPhaseTime logging to make it easier to add new phases
brutisso
parents:
28379
diff
changeset
|
330 |