Bug Summary

File:jdk/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp
Warning:line 316, column 3
Called C++ object pointer is null

Annotated Source Code

Press '?' to see keyboard shortcuts

clang -cc1 -triple x86_64-pc-linux-gnu -analyze -disable-free -disable-llvm-verifier -discard-value-names -main-file-name g1GCPhaseTimes.cpp -analyzer-store=region -analyzer-opt-analyze-nested-blocks -analyzer-checker=core -analyzer-checker=apiModeling -analyzer-checker=unix -analyzer-checker=deadcode -analyzer-checker=cplusplus -analyzer-checker=security.insecureAPI.UncheckedReturn -analyzer-checker=security.insecureAPI.getpw -analyzer-checker=security.insecureAPI.gets -analyzer-checker=security.insecureAPI.mktemp -analyzer-checker=security.insecureAPI.mkstemp -analyzer-checker=security.insecureAPI.vfork -analyzer-checker=nullability.NullPassedToNonnull -analyzer-checker=nullability.NullReturnedFromNonnull -analyzer-output plist -w -setup-static-analyzer -mrelocation-model pic -pic-level 2 -mthread-model posix -fno-delete-null-pointer-checks -mframe-pointer=all -relaxed-aliasing -fmath-errno -fno-rounding-math -masm-verbose -mconstructor-aliases -munwind-tables -target-cpu x86-64 -dwarf-column-info -fno-split-dwarf-inlining -debugger-tuning=gdb -resource-dir /usr/lib/llvm-10/lib/clang/10.0.0 -I /home/daniel/Projects/java/jdk/build/linux-x86_64-server-fastdebug/hotspot/variant-server/libjvm/objs/precompiled -D __STDC_FORMAT_MACROS -D __STDC_LIMIT_MACROS -D __STDC_CONSTANT_MACROS -D _GNU_SOURCE -D _REENTRANT -D LIBC=gnu -D LINUX -D VM_LITTLE_ENDIAN -D _LP64=1 -D ASSERT -D CHECK_UNHANDLED_OOPS -D TARGET_ARCH_x86 -D INCLUDE_SUFFIX_OS=_linux -D INCLUDE_SUFFIX_CPU=_x86 -D INCLUDE_SUFFIX_COMPILER=_gcc -D TARGET_COMPILER_gcc -D AMD64 -D HOTSPOT_LIB_ARCH="amd64" -D COMPILER1 -D COMPILER2 -I /home/daniel/Projects/java/jdk/build/linux-x86_64-server-fastdebug/hotspot/variant-server/gensrc/adfiles -I /home/daniel/Projects/java/jdk/src/hotspot/share -I /home/daniel/Projects/java/jdk/src/hotspot/os/linux -I /home/daniel/Projects/java/jdk/src/hotspot/os/posix -I /home/daniel/Projects/java/jdk/src/hotspot/cpu/x86 -I /home/daniel/Projects/java/jdk/src/hotspot/os_cpu/linux_x86 -I /home/daniel/Projects/java/jdk/build/linux-x86_64-server-fastdebug/hotspot/variant-server/gensrc -I /home/daniel/Projects/java/jdk/src/hotspot/share/precompiled -I /home/daniel/Projects/java/jdk/src/hotspot/share/include -I /home/daniel/Projects/java/jdk/src/hotspot/os/posix/include -I /home/daniel/Projects/java/jdk/build/linux-x86_64-server-fastdebug/support/modules_include/java.base -I /home/daniel/Projects/java/jdk/build/linux-x86_64-server-fastdebug/support/modules_include/java.base/linux -I /home/daniel/Projects/java/jdk/src/java.base/share/native/libjimage -I /home/daniel/Projects/java/jdk/build/linux-x86_64-server-fastdebug/hotspot/variant-server/gensrc/adfiles -I /home/daniel/Projects/java/jdk/src/hotspot/share -I /home/daniel/Projects/java/jdk/src/hotspot/os/linux -I /home/daniel/Projects/java/jdk/src/hotspot/os/posix -I /home/daniel/Projects/java/jdk/src/hotspot/cpu/x86 -I /home/daniel/Projects/java/jdk/src/hotspot/os_cpu/linux_x86 -I /home/daniel/Projects/java/jdk/build/linux-x86_64-server-fastdebug/hotspot/variant-server/gensrc -D _FORTIFY_SOURCE=2 -internal-isystem /usr/lib/gcc/x86_64-linux-gnu/7.5.0/../../../../include/c++/7.5.0 -internal-isystem /usr/lib/gcc/x86_64-linux-gnu/7.5.0/../../../../include/x86_64-linux-gnu/c++/7.5.0 -internal-isystem /usr/lib/gcc/x86_64-linux-gnu/7.5.0/../../../../include/x86_64-linux-gnu/c++/7.5.0 -internal-isystem /usr/lib/gcc/x86_64-linux-gnu/7.5.0/../../../../include/c++/7.5.0/backward -internal-isystem /usr/local/include -internal-isystem /usr/lib/llvm-10/lib/clang/10.0.0/include -internal-externc-isystem /usr/include/x86_64-linux-gnu -internal-externc-isystem /include -internal-externc-isystem /usr/include -O3 -Wno-format-zero-length -Wno-unused-parameter -Wno-unused -Wno-parentheses -Wno-comment -Wno-unknown-pragmas -Wno-address -Wno-delete-non-virtual-dtor -Wno-char-subscripts -Wno-array-bounds -Wno-int-in-bool-context -Wno-ignored-qualifiers -Wno-missing-field-initializers -Wno-implicit-fallthrough -Wno-empty-body -Wno-strict-overflow -Wno-sequence-point -Wno-maybe-uninitialized -Wno-misleading-indentation -Wno-cast-function-type -Wno-shift-negative-value -std=c++14 -fdeprecated-macro -fdebug-compilation-dir /home/daniel/Projects/java/jdk/make/hotspot -ferror-limit 19 -fmessage-length 0 -fvisibility hidden -stack-protector 1 -fno-rtti -fgnuc-version=4.2.1 -fobjc-runtime=gcc -fdiagnostics-show-option -vectorize-loops -vectorize-slp -analyzer-output=html -faddrsig -o /home/daniel/Projects/java/scan/2021-12-21-193737-8510-1 -x c++ /home/daniel/Projects/java/jdk/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp
1/*
2 * Copyright (c) 2013, 2021, Oracle and/or its affiliates. All rights reserved.
3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
4 *
5 * This code is free software; you can redistribute it and/or modify it
6 * under the terms of the GNU General Public License version 2 only, as
7 * published by the Free Software Foundation.
8 *
9 * This code is distributed in the hope that it will be useful, but WITHOUT
10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
11 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
12 * version 2 for more details (a copy is included in the LICENSE file that
13 * accompanied this code).
14 *
15 * You should have received a copy of the GNU General Public License version
16 * 2 along with this work; if not, write to the Free Software Foundation,
17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
18 *
19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
20 * or visit www.oracle.com if you need additional information or have any
21 * questions.
22 *
23 */
24
25#include "precompiled.hpp"
26#include "gc/g1/g1CollectedHeap.inline.hpp"
27#include "gc/g1/g1GCParPhaseTimesTracker.hpp"
28#include "gc/g1/g1GCPhaseTimes.hpp"
29#include "gc/g1/g1HotCardCache.hpp"
30#include "gc/g1/g1ParScanThreadState.inline.hpp"
31#include "gc/shared/gcTimer.hpp"
32#include "gc/shared/oopStorage.hpp"
33#include "gc/shared/oopStorageSet.hpp"
34#include "gc/shared/tlab_globals.hpp"
35#include "gc/shared/workerDataArray.inline.hpp"
36#include "memory/resourceArea.hpp"
37#include "logging/log.hpp"
38#include "logging/logStream.hpp"
39#include "runtime/timer.hpp"
40#include "runtime/os.hpp"
41#include "utilities/enumIterator.hpp"
42#include "utilities/macros.hpp"
43
44constexpr const char* G1GCPhaseTimes::GCMergeRSWorkItemsStrings[];
45
46G1GCPhaseTimes::G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads) :
47 _max_gc_threads(max_gc_threads),
48 _gc_start_counter(0),
49 _gc_pause_time_ms(0.0),
50 _ref_phase_times(gc_timer, max_gc_threads),
51 _weak_phase_times(max_gc_threads)
52{
53 assert(max_gc_threads > 0, "Must have some GC threads")do { if (!(max_gc_threads > 0)) { (*g_assert_poison) = 'X'
;; report_vm_error("/home/daniel/Projects/java/jdk/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp"
, 53, "assert(" "max_gc_threads > 0" ") failed", "Must have some GC threads"
); ::breakpoint(); } } while (0);
54
55 _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>("GCWorkerStart", "GC Worker Start (ms):", max_gc_threads);
56 _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>("ExtRootScan", "Ext Root Scanning (ms):", max_gc_threads);
57
58 // Root scanning phases
59 _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>("ThreadRoots", "Thread Roots (ms):", max_gc_threads);
60 _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>("CLDGRoots", "CLDG Roots (ms):", max_gc_threads);
61 _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>("CMRefRoots", "CM RefProcessor Roots (ms):", max_gc_threads);
62
63 for (auto id : EnumRange<OopStorageSet::StrongId>()) {
64 GCParPhases phase = strong_oopstorage_phase(id);
65 const char* phase_name_postfix = " Roots (ms):";
66 const char* storage_name = OopStorageSet::storage(id)->name();
67 char* oop_storage_phase_name = NEW_C_HEAP_ARRAY(char, strlen(phase_name_postfix) + strlen(storage_name) + 1, mtGC)(char*) (AllocateHeap((strlen(phase_name_postfix) + strlen(storage_name
) + 1) * sizeof(char), mtGC));
68 strcpy(oop_storage_phase_name, storage_name);
69 strcat(oop_storage_phase_name, phase_name_postfix);
70 _gc_par_phases[phase] = new WorkerDataArray<double>(storage_name, oop_storage_phase_name, max_gc_threads);
71 }
72
73 _gc_par_phases[MergeER] = new WorkerDataArray<double>("MergeER", "Eager Reclaim (ms):", max_gc_threads);
74
75 _gc_par_phases[MergeRS] = new WorkerDataArray<double>("MergeRS", "Remembered Sets (ms):", max_gc_threads);
76 for (uint i = 0; i < MergeRSContainersSentinel; i++) {
77 _gc_par_phases[MergeRS]->create_thread_work_items(GCMergeRSWorkItemsStrings[i], i);
78 }
79
80 _gc_par_phases[OptMergeRS] = new WorkerDataArray<double>("OptMergeRS", "Optional Remembered Sets (ms):", max_gc_threads);
81 for (uint i = 0; i < MergeRSContainersSentinel; i++) {
82 _gc_par_phases[OptMergeRS]->create_thread_work_items(GCMergeRSWorkItemsStrings[i], i);
83 }
84
85 _gc_par_phases[MergeLB] = new WorkerDataArray<double>("MergeLB", "Log Buffers (ms):", max_gc_threads);
86 if (G1HotCardCache::default_use_cache()) {
87 _gc_par_phases[MergeHCC] = new WorkerDataArray<double>("MergeHCC", "Hot Card Cache (ms):", max_gc_threads);
88 _gc_par_phases[MergeHCC]->create_thread_work_items("Dirty Cards:", MergeHCCDirtyCards);
89 _gc_par_phases[MergeHCC]->create_thread_work_items("Skipped Cards:", MergeHCCSkippedCards);
90 } else {
91 _gc_par_phases[MergeHCC] = NULL__null;
92 }
93 _gc_par_phases[ScanHR] = new WorkerDataArray<double>("ScanHR", "Scan Heap Roots (ms):", max_gc_threads);
94 _gc_par_phases[OptScanHR] = new WorkerDataArray<double>("OptScanHR", "Optional Scan Heap Roots (ms):", max_gc_threads);
95 _gc_par_phases[CodeRoots] = new WorkerDataArray<double>("CodeRoots", "Code Root Scan (ms):", max_gc_threads);
96 _gc_par_phases[OptCodeRoots] = new WorkerDataArray<double>("OptCodeRoots", "Optional Code Root Scan (ms):", max_gc_threads);
97 _gc_par_phases[ObjCopy] = new WorkerDataArray<double>("ObjCopy", "Object Copy (ms):", max_gc_threads);
98 _gc_par_phases[OptObjCopy] = new WorkerDataArray<double>("OptObjCopy", "Optional Object Copy (ms):", max_gc_threads);
99 _gc_par_phases[Termination] = new WorkerDataArray<double>("Termination", "Termination (ms):", max_gc_threads);
100 _gc_par_phases[OptTermination] = new WorkerDataArray<double>("OptTermination", "Optional Termination (ms):", max_gc_threads);
101 _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>("GCWorkerTotal", "GC Worker Total (ms):", max_gc_threads);
102 _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>("GCWorkerEnd", "GC Worker End (ms):", max_gc_threads);
103 _gc_par_phases[Other] = new WorkerDataArray<double>("Other", "GC Worker Other (ms):", max_gc_threads);
104 _gc_par_phases[MergePSS] = new WorkerDataArray<double>("MergePSS", "Merge Per-Thread State (ms):", max_gc_threads);
105 _gc_par_phases[RemoveSelfForwardingPtr] = new WorkerDataArray<double>("RemoveSelfForwardingPtr", "Remove Self Forwards (ms):", max_gc_threads);
106 _gc_par_phases[ClearCardTable] = new WorkerDataArray<double>("ClearLoggedCards", "Clear Logged Cards (ms):", max_gc_threads);
107 _gc_par_phases[RecalculateUsed] = new WorkerDataArray<double>("RecalculateUsed", "Recalculate Used Memory (ms):", max_gc_threads);
108 _gc_par_phases[ResetHotCardCache] = new WorkerDataArray<double>("ResetHotCardCache", "Reset Hot Card Cache (ms):", max_gc_threads);
109 _gc_par_phases[PurgeCodeRoots] = new WorkerDataArray<double>("PurgeCodeRoots", "Purge Code Roots (ms):", max_gc_threads);
110#if COMPILER2_OR_JVMCI1
111 _gc_par_phases[UpdateDerivedPointers] = new WorkerDataArray<double>("UpdateDerivedPointers", "Update Derived Pointers (ms):", max_gc_threads);
112#endif
113 _gc_par_phases[EagerlyReclaimHumongousObjects] = new WorkerDataArray<double>("EagerlyReclaimHumongousObjects", "Eagerly Reclaim Humongous Objects (ms):", max_gc_threads);
114 _gc_par_phases[RestorePreservedMarks] = new WorkerDataArray<double>("RestorePreservedMarks", "Restore Preserved Marks (ms):", max_gc_threads);
115
116 _gc_par_phases[ScanHR]->create_thread_work_items("Scanned Cards:", ScanHRScannedCards);
117 _gc_par_phases[ScanHR]->create_thread_work_items("Scanned Blocks:", ScanHRScannedBlocks);
118 _gc_par_phases[ScanHR]->create_thread_work_items("Claimed Chunks:", ScanHRClaimedChunks);
119 _gc_par_phases[ScanHR]->create_thread_work_items("Found Roots:", ScanHRFoundRoots);
120
121 _gc_par_phases[OptScanHR]->create_thread_work_items("Scanned Cards:", ScanHRScannedCards);
122 _gc_par_phases[OptScanHR]->create_thread_work_items("Scanned Blocks:", ScanHRScannedBlocks);
123 _gc_par_phases[OptScanHR]->create_thread_work_items("Claimed Chunks:", ScanHRClaimedChunks);
124 _gc_par_phases[OptScanHR]->create_thread_work_items("Found Roots:", ScanHRFoundRoots);
125 _gc_par_phases[OptScanHR]->create_thread_work_items("Scanned Refs:", ScanHRScannedOptRefs);
126 _gc_par_phases[OptScanHR]->create_thread_work_items("Used Memory:", ScanHRUsedMemory);
127
128 _gc_par_phases[MergeLB]->create_thread_work_items("Dirty Cards:", MergeLBDirtyCards);
129 _gc_par_phases[MergeLB]->create_thread_work_items("Skipped Cards:", MergeLBSkippedCards);
130
131 _gc_par_phases[MergePSS]->create_thread_work_items("Copied Bytes", MergePSSCopiedBytes);
132 _gc_par_phases[MergePSS]->create_thread_work_items("LAB Waste", MergePSSLABWasteBytes);
133 _gc_par_phases[MergePSS]->create_thread_work_items("LAB Undo Waste", MergePSSLABUndoWasteBytes);
134
135 _gc_par_phases[EagerlyReclaimHumongousObjects]->create_thread_work_items("Humongous Total", EagerlyReclaimNumTotal);
136 _gc_par_phases[EagerlyReclaimHumongousObjects]->create_thread_work_items("Humongous Candidates", EagerlyReclaimNumCandidates);
137 _gc_par_phases[EagerlyReclaimHumongousObjects]->create_thread_work_items("Humongous Reclaimed", EagerlyReclaimNumReclaimed);
138
139 _gc_par_phases[SampleCollectionSetCandidates] = new WorkerDataArray<double>("SampleCandidates", "Sample CSet Candidates (ms):", max_gc_threads);
140
141 _gc_par_phases[Termination]->create_thread_work_items("Termination Attempts:");
142
143 _gc_par_phases[OptTermination]->create_thread_work_items("Optional Termination Attempts:");
144
145 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>("RedirtyCards", "Redirty Logged Cards (ms):", max_gc_threads);
146 _gc_par_phases[RedirtyCards]->create_thread_work_items("Redirtied Cards:");
147
148 _gc_par_phases[FreeCollectionSet] = new WorkerDataArray<double>("FreeCSet", "Free Collection Set (ms):", max_gc_threads);
149 _gc_par_phases[YoungFreeCSet] = new WorkerDataArray<double>("YoungFreeCSet", "Young Free Collection Set (ms):", max_gc_threads);
150 _gc_par_phases[NonYoungFreeCSet] = new WorkerDataArray<double>("NonYoungFreeCSet", "Non-Young Free Collection Set (ms):", max_gc_threads);
151 _gc_par_phases[RebuildFreeList] = new WorkerDataArray<double>("RebuildFreeList", "Parallel Rebuild Free List (ms):", max_gc_threads);
152
153 _gc_par_phases[CLDClearClaimedMarks] = new WorkerDataArray<double>("CLDClearClaimedMarks", "Clear Claimed Marks (ms):", max_gc_threads);
154 _gc_par_phases[ResetMarkingState] = new WorkerDataArray<double>("ResetMarkingState", "Reset Marking State (ms):", max_gc_threads);
155 _gc_par_phases[NoteStartOfMark] = new WorkerDataArray<double>("NoteStartOfMark", "Note Start Of Mark (ms):", max_gc_threads);
156
157 reset();
158}
159
160void G1GCPhaseTimes::reset() {
161 _cur_collection_initial_evac_time_ms = 0.0;
162 _cur_optional_evac_time_ms = 0.0;
163 _cur_collection_nmethod_list_cleanup_time_ms = 0.0;
164 _cur_merge_heap_roots_time_ms = 0.0;
165 _cur_optional_merge_heap_roots_time_ms = 0.0;
166 _cur_prepare_merge_heap_roots_time_ms = 0.0;
167 _cur_optional_prepare_merge_heap_roots_time_ms = 0.0;
168 _cur_prepare_tlab_time_ms = 0.0;
169 _cur_resize_tlab_time_ms = 0.0;
170 _cur_post_evacuate_cleanup_1_time_ms = 0.0;
171 _cur_post_evacuate_cleanup_2_time_ms = 0.0;
172 _cur_expand_heap_time_ms = 0.0;
173 _cur_ref_proc_time_ms = 0.0;
174 _cur_collection_start_sec = 0.0;
175 _root_region_scan_wait_time_ms = 0.0;
176 _external_accounted_time_ms = 0.0;
177 _recorded_prepare_heap_roots_time_ms = 0.0;
178 _recorded_young_cset_choice_time_ms = 0.0;
179 _recorded_non_young_cset_choice_time_ms = 0.0;
180 _recorded_preserve_cm_referents_time_ms = 0.0;
181 _recorded_start_new_cset_time_ms = 0.0;
182 _recorded_serial_free_cset_time_ms = 0.0;
183 _recorded_total_rebuild_freelist_time_ms = 0.0;
184 _recorded_serial_rebuild_freelist_time_ms = 0.0;
185 _cur_region_register_time = 0.0;
186 _cur_verify_before_time_ms = 0.0;
187 _cur_verify_after_time_ms = 0.0;
188
189 for (int i = 0; i < GCParPhasesSentinel; i++) {
190 if (_gc_par_phases[i] != NULL__null) {
191 _gc_par_phases[i]->reset();
192 }
193 }
194
195 _ref_phase_times.reset();
196 _weak_phase_times.reset();
197}
198
199void G1GCPhaseTimes::record_gc_pause_start() {
200 _gc_start_counter = os::elapsed_counter();
201 reset();
202}
203
204#define ASSERT_PHASE_UNINITIALIZED(phase) \
205 assert(_gc_par_phases[phase] == NULL || _gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started")do { if (!(_gc_par_phases[phase] == __null || _gc_par_phases[
phase]->get(i) == uninitialized)) { (*g_assert_poison) = 'X'
;; report_vm_error("/home/daniel/Projects/java/jdk/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp"
, 205, "assert(" "_gc_par_phases[phase] == __null || _gc_par_phases[phase]->get(i) == uninitialized"
") failed", "Phase " #phase " reported for thread that was not started"
); ::breakpoint(); } } while (0);
206
207double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {
208 if (_gc_par_phases[phase] == NULL__null) {
209 return 0.0;
210 }
211 double value = _gc_par_phases[phase]->get(worker);
212 if (value != WorkerDataArray<double>::uninitialized()) {
213 return value;
214 }
215 return 0.0;
216}
217
218void G1GCPhaseTimes::record_gc_pause_end() {
219 _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
220
221 double uninitialized = WorkerDataArray<double>::uninitialized();
222
223 for (uint i = 0; i < _max_gc_threads; i++) {
224 double worker_start = _gc_par_phases[GCWorkerStart]->get(i);
225 if (worker_start != uninitialized) {
226 assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended.")do { if (!(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized
)) { (*g_assert_poison) = 'X';; report_vm_error("/home/daniel/Projects/java/jdk/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp"
, 226, "assert(" "_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized"
") failed", "Worker started but not ended."); ::breakpoint()
; } } while (0);
227 double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
228 record_time_secs(GCWorkerTotal, i , total_worker_time);
229
230 double worker_known_time = worker_time(ExtRootScan, i) +
231 worker_time(ScanHR, i) +
232 worker_time(CodeRoots, i) +
233 worker_time(ObjCopy, i) +
234 worker_time(Termination, i);
235
236 record_time_secs(Other, i, total_worker_time - worker_known_time);
237 } else {
238 // Make sure all slots are uninitialized since this thread did not seem to have been started
239 ASSERT_PHASE_UNINITIALIZED(GCWorkerEnd);
240 ASSERT_PHASE_UNINITIALIZED(ExtRootScan);
241 ASSERT_PHASE_UNINITIALIZED(MergeER);
242 ASSERT_PHASE_UNINITIALIZED(MergeRS);
243 ASSERT_PHASE_UNINITIALIZED(OptMergeRS);
244 ASSERT_PHASE_UNINITIALIZED(MergeHCC);
245 ASSERT_PHASE_UNINITIALIZED(MergeLB);
246 ASSERT_PHASE_UNINITIALIZED(ScanHR);
247 ASSERT_PHASE_UNINITIALIZED(CodeRoots);
248 ASSERT_PHASE_UNINITIALIZED(OptCodeRoots);
249 ASSERT_PHASE_UNINITIALIZED(ObjCopy);
250 ASSERT_PHASE_UNINITIALIZED(OptObjCopy);
251 ASSERT_PHASE_UNINITIALIZED(Termination);
252 }
253 }
254}
255
256#undef ASSERT_PHASE_UNINITIALIZED
257
258// record the time a phase took in seconds
259void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_id, double secs) {
260 _gc_par_phases[phase]->set(worker_id, secs);
261}
262
263// add a number of seconds to a phase
264void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_id, double secs) {
265 _gc_par_phases[phase]->add(worker_id, secs);
266}
267
268void G1GCPhaseTimes::record_or_add_time_secs(GCParPhases phase, uint worker_id, double secs) {
269 _gc_par_phases[phase]->set_or_add(worker_id, secs);
270}
271
272double G1GCPhaseTimes::get_time_secs(GCParPhases phase, uint worker_id) {
273 return _gc_par_phases[phase]->get(worker_id);
274}
275
276void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_id, size_t count, uint index) {
277 _gc_par_phases[phase]->set_thread_work_item(worker_id, count, index);
278}
279
280void G1GCPhaseTimes::record_or_add_thread_work_item(GCParPhases phase, uint worker_id, size_t count, uint index) {
281 _gc_par_phases[phase]->set_or_add_thread_work_item(worker_id, count, index);
282}
283
284size_t G1GCPhaseTimes::get_thread_work_item(GCParPhases phase, uint worker_id, uint index) {
285 return _gc_par_phases[phase]->get_thread_work_item(worker_id, index);
286}
287
288// return the average time for a phase in milliseconds
289double G1GCPhaseTimes::average_time_ms(GCParPhases phase) const {
290 if (_gc_par_phases[phase] == NULL__null) {
291 return 0.0;
292 }
293 return _gc_par_phases[phase]->average() * 1000.0;
294}
295
296size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase, uint index) {
297 if (_gc_par_phases[phase] == NULL__null) {
298 return 0;
299 }
300 assert(_gc_par_phases[phase]->thread_work_items(index) != NULL, "No sub count")do { if (!(_gc_par_phases[phase]->thread_work_items(index)
!= __null)) { (*g_assert_poison) = 'X';; report_vm_error("/home/daniel/Projects/java/jdk/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp"
, 300, "assert(" "_gc_par_phases[phase]->thread_work_items(index) != __null"
") failed", "No sub count"); ::breakpoint(); } } while (0);
301 return _gc_par_phases[phase]->thread_work_items(index)->sum();
302}
303
304template <class T>
305void G1GCPhaseTimes::details(T* phase, uint indent_level) const {
306 LogTarget(Trace, gc, phases, task)LogTargetImpl<LogLevel::Trace, (LogTag::_gc), (LogTag::_phases
), (LogTag::_task), (LogTag::__NO_TAG), (LogTag::__NO_TAG), (
LogTag::__NO_TAG)> lt;
307 if (lt.is_enabled()) {
308 LogStream ls(lt);
309 ls.sp(indent_level * 2);
310 phase->print_details_on(&ls);
311 }
312}
313
314void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent_level, outputStream* out, bool print_sum) const {
315 out->sp(indent_level * 2);
316 phase->print_summary_on(out, print_sum);
14
←
Called C++ object pointer is null
317 details(phase, indent_level);
318
319 for (uint i = 0; i < phase->MaxThreadWorkItems; i++) {
320 WorkerDataArray<size_t>* work_items = phase->thread_work_items(i);
321 if (work_items != NULL__null) {
322 out->sp((indent_level + 1) * 2);
323 work_items->print_summary_on(out, true);
324 details(work_items, indent_level + 1);
325 }
326 }
327}
328
329void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase, uint extra_indent) const {
330 LogTarget(Debug, gc, phases)LogTargetImpl<LogLevel::Debug, (LogTag::_gc), (LogTag::_phases
), (LogTag::__NO_TAG), (LogTag::__NO_TAG), (LogTag::__NO_TAG)
, (LogTag::__NO_TAG)> lt;
331 if (lt.is_enabled()) {
10
←
Assuming the condition is true
→
11
←
Taking true branch
→
332 ResourceMark rm;
333 LogStream ls(lt);
334 log_phase(phase, 2 + extra_indent, &ls, true);
12
←
Passing null pointer value via 1st parameter 'phase'
→
13
←
Calling 'G1GCPhaseTimes::log_phase'
→
335 }
336}
337
338void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum, uint extra_indent) const {
339 LogTarget(Trace, gc, phases)LogTargetImpl<LogLevel::Trace, (LogTag::_gc), (LogTag::_phases
), (LogTag::__NO_TAG), (LogTag::__NO_TAG), (LogTag::__NO_TAG)
, (LogTag::__NO_TAG)> lt;
340 if (lt.is_enabled()) {
341 LogStream ls(lt);
342 log_phase(phase, 3 + extra_indent, &ls, print_sum);
343 }
344}
345
346#define TIME_FORMAT"%.1lfms" "%.1lfms"
347
348void G1GCPhaseTimes::info_time(const char* name, double value) const {
349 log_info(gc, phases)(!(LogImpl<(LogTag::_gc), (LogTag::_phases), (LogTag::__NO_TAG
), (LogTag::__NO_TAG), (LogTag::__NO_TAG), (LogTag::__NO_TAG)
>::is_level(LogLevel::Info))) ? (void)0 : LogImpl<(LogTag
::_gc), (LogTag::_phases), (LogTag::__NO_TAG), (LogTag::__NO_TAG
), (LogTag::__NO_TAG), (LogTag::__NO_TAG)>::write<LogLevel
::Info>(" %s: " TIME_FORMAT"%.1lfms", name, value);
350}
351
352void G1GCPhaseTimes::debug_time(const char* name, double value) const {
353 log_debug(gc, phases)(!(LogImpl<(LogTag::_gc), (LogTag::_phases), (LogTag::__NO_TAG
), (LogTag::__NO_TAG), (LogTag::__NO_TAG), (LogTag::__NO_TAG)
>::is_level(LogLevel::Debug))) ? (void)0 : LogImpl<(LogTag
::_gc), (LogTag::_phases), (LogTag::__NO_TAG), (LogTag::__NO_TAG
), (LogTag::__NO_TAG), (LogTag::__NO_TAG)>::write<LogLevel
::Debug>(" %s: " TIME_FORMAT"%.1lfms", name, value);
354}
355
356void G1GCPhaseTimes::debug_time_for_reference(const char* name, double value) const {
357 LogTarget(Debug, gc, phases)LogTargetImpl<LogLevel::Debug, (LogTag::_gc), (LogTag::_phases
), (LogTag::__NO_TAG), (LogTag::__NO_TAG), (LogTag::__NO_TAG)
, (LogTag::__NO_TAG)> lt;
358 LogTarget(Debug, gc, phases, ref)LogTargetImpl<LogLevel::Debug, (LogTag::_gc), (LogTag::_phases
), (LogTag::_ref), (LogTag::__NO_TAG), (LogTag::__NO_TAG), (LogTag
::__NO_TAG)> lt2;
359
360 if (lt.is_enabled()) {
361 LogStream ls(lt);
362 ls.print_cr(" %s: " TIME_FORMAT"%.1lfms", name, value);
363 } else if (lt2.is_enabled()) {
364 LogStream ls(lt2);
365 ls.print_cr(" %s: " TIME_FORMAT"%.1lfms", name, value);
366 }
367}
368
369void G1GCPhaseTimes::trace_time(const char* name, double value) const {
370 log_trace(gc, phases)(!(LogImpl<(LogTag::_gc), (LogTag::_phases), (LogTag::__NO_TAG
), (LogTag::__NO_TAG), (LogTag::__NO_TAG), (LogTag::__NO_TAG)
>::is_level(LogLevel::Trace))) ? (void)0 : LogImpl<(LogTag
::_gc), (LogTag::_phases), (LogTag::__NO_TAG), (LogTag::__NO_TAG
), (LogTag::__NO_TAG), (LogTag::__NO_TAG)>::write<LogLevel
::Trace>(" %s: " TIME_FORMAT"%.1lfms", name, value);
371}
372
373void G1GCPhaseTimes::trace_count(const char* name, size_t value) const {
374 log_trace(gc, phases)(!(LogImpl<(LogTag::_gc), (LogTag::_phases), (LogTag::__NO_TAG
), (LogTag::__NO_TAG), (LogTag::__NO_TAG), (LogTag::__NO_TAG)
>::is_level(LogLevel::Trace))) ? (void)0 : LogImpl<(LogTag
::_gc), (LogTag::_phases), (LogTag::__NO_TAG), (LogTag::__NO_TAG
), (LogTag::__NO_TAG), (LogTag::__NO_TAG)>::write<LogLevel
::Trace>(" %s: " SIZE_FORMAT"%" "l" "u", name, value);
375}
376
377double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
378 const double pre_concurrent_start_ms = average_time_ms(CLDClearClaimedMarks) +
379 average_time_ms(ResetMarkingState) +
380 average_time_ms(NoteStartOfMark);
381
382 const double sum_ms = _root_region_scan_wait_time_ms +
383 _cur_prepare_tlab_time_ms +
384 _cur_concatenate_dirty_card_logs_time_ms +
385 _recorded_young_cset_choice_time_ms +
386 _recorded_non_young_cset_choice_time_ms +
387 _cur_region_register_time +
388 _recorded_prepare_heap_roots_time_ms +
389 pre_concurrent_start_ms;
390
391 info_time("Pre Evacuate Collection Set", sum_ms);
392
393 if (_root_region_scan_wait_time_ms > 0.0) {
4
←
Assuming the condition is false
→
5
←
Taking false branch
→
394 debug_time("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
395 }
396 debug_time("Prepare TLABs", _cur_prepare_tlab_time_ms);
397 debug_time("Concatenate Dirty Card Logs", _cur_concatenate_dirty_card_logs_time_ms);
398 debug_time("Choose Collection Set", (_recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms));
399 debug_time("Region Register", _cur_region_register_time);
400
401 debug_time("Prepare Heap Roots", _recorded_prepare_heap_roots_time_ms);
402
403 if (pre_concurrent_start_ms > 0.0) {
6
←
Assuming the condition is true
→
7
←
Taking true branch
→
404 debug_phase(_gc_par_phases[CLDClearClaimedMarks]);
405 debug_phase(_gc_par_phases[ResetMarkingState]);
8
←
Passing null pointer value via 1st parameter 'phase'
→
9
←
Calling 'G1GCPhaseTimes::debug_phase'
→
406 debug_phase(_gc_par_phases[NoteStartOfMark]);
407 }
408
409 return sum_ms;
410}
411
412double G1GCPhaseTimes::print_evacuate_optional_collection_set() const {
413 const double sum_ms = _cur_optional_evac_time_ms + _cur_optional_merge_heap_roots_time_ms;
414 if (sum_ms > 0) {
415 info_time("Merge Optional Heap Roots", _cur_optional_merge_heap_roots_time_ms);
416
417 debug_time("Prepare Optional Merge Heap Roots", _cur_optional_prepare_merge_heap_roots_time_ms);
418 debug_phase(_gc_par_phases[OptMergeRS]);
419
420 info_time("Evacuate Optional Collection Set", _cur_optional_evac_time_ms);
421 debug_phase(_gc_par_phases[OptScanHR]);
422 debug_phase(_gc_par_phases[OptObjCopy]);
423 debug_phase(_gc_par_phases[OptCodeRoots]);
424 debug_phase(_gc_par_phases[OptTermination]);
425 }
426 return sum_ms;
427}
428
429double G1GCPhaseTimes::print_evacuate_initial_collection_set() const {
430 info_time("Merge Heap Roots", _cur_merge_heap_roots_time_ms);
431
432 debug_time("Prepare Merge Heap Roots", _cur_prepare_merge_heap_roots_time_ms);
433 debug_phase(_gc_par_phases[MergeER]);
434 debug_phase(_gc_par_phases[MergeRS]);
435 if (G1HotCardCache::default_use_cache()) {
436 debug_phase(_gc_par_phases[MergeHCC]);
437 }
438 debug_phase(_gc_par_phases[MergeLB]);
439
440 info_time("Evacuate Collection Set", _cur_collection_initial_evac_time_ms);
441
442 trace_phase(_gc_par_phases[GCWorkerStart], false);
443 debug_phase(_gc_par_phases[ExtRootScan]);
444 for (int i = ExtRootScanSubPhasesFirst; i <= ExtRootScanSubPhasesLast; i++) {
445 trace_phase(_gc_par_phases[i]);
446 }
447 debug_phase(_gc_par_phases[ScanHR]);
448 debug_phase(_gc_par_phases[CodeRoots]);
449 debug_phase(_gc_par_phases[ObjCopy]);
450 debug_phase(_gc_par_phases[Termination]);
451 debug_phase(_gc_par_phases[Other]);
452 debug_phase(_gc_par_phases[GCWorkerTotal]);
453 trace_phase(_gc_par_phases[GCWorkerEnd], false);
454
455 return _cur_collection_initial_evac_time_ms + _cur_merge_heap_roots_time_ms;
456}
457
458double G1GCPhaseTimes::print_post_evacuate_collection_set(bool evacuation_failed) const {
459 const double sum_ms = _cur_collection_nmethod_list_cleanup_time_ms +
460 _recorded_preserve_cm_referents_time_ms +
461 _cur_ref_proc_time_ms +
462 (_weak_phase_times.total_time_sec() * MILLIUNITS) +
463 _cur_post_evacuate_cleanup_1_time_ms +
464 _cur_post_evacuate_cleanup_2_time_ms +
465 _recorded_total_rebuild_freelist_time_ms +
466 _recorded_start_new_cset_time_ms +
467 _cur_expand_heap_time_ms;
468
469 info_time("Post Evacuate Collection Set", sum_ms);
470
471 debug_time("NMethod List Cleanup", _cur_collection_nmethod_list_cleanup_time_ms);
472
473 debug_time_for_reference("Reference Processing", _cur_ref_proc_time_ms);
474 _ref_phase_times.print_all_references(2, false);
475 _weak_phase_times.log_total(2);
476 _weak_phase_times.log_subtotals(3);
477
478 debug_time("Post Evacuate Cleanup 1", _cur_post_evacuate_cleanup_1_time_ms);
479 debug_phase(_gc_par_phases[MergePSS], 1);
480 debug_phase(_gc_par_phases[ClearCardTable], 1);
481 debug_phase(_gc_par_phases[RecalculateUsed], 1);
482 if (evacuation_failed) {
483 debug_phase(_gc_par_phases[RemoveSelfForwardingPtr], 1);
484 }
485
486 trace_phase(_gc_par_phases[RedirtyCards]);
487 debug_time("Post Evacuate Cleanup 2", _cur_post_evacuate_cleanup_2_time_ms);
488 if (evacuation_failed) {
489 debug_phase(_gc_par_phases[RecalculateUsed], 1);
490 debug_phase(_gc_par_phases[RestorePreservedMarks], 1);
491 }
492 debug_phase(_gc_par_phases[ResetHotCardCache], 1);
493 debug_phase(_gc_par_phases[PurgeCodeRoots], 1);
494#if COMPILER2_OR_JVMCI1
495 debug_phase(_gc_par_phases[UpdateDerivedPointers], 1);
496#endif
497 if (G1CollectedHeap::heap()->should_do_eager_reclaim()) {
498 debug_phase(_gc_par_phases[EagerlyReclaimHumongousObjects], 1);
499 }
500 if (G1CollectedHeap::heap()->should_sample_collection_set_candidates()) {
501 debug_phase(_gc_par_phases[SampleCollectionSetCandidates], 1);
502 }
503 debug_phase(_gc_par_phases[RedirtyCards], 1);
504 debug_phase(_gc_par_phases[FreeCollectionSet], 1);
505 trace_phase(_gc_par_phases[YoungFreeCSet], true, 1);
506 trace_phase(_gc_par_phases[NonYoungFreeCSet], true, 1);
507
508 trace_time("Serial Free Collection Set", _recorded_serial_free_cset_time_ms);
509
510 debug_time("Rebuild Free List", _recorded_total_rebuild_freelist_time_ms);
511 trace_time("Serial Rebuild Free List ", _recorded_serial_rebuild_freelist_time_ms);
512 trace_phase(_gc_par_phases[RebuildFreeList]);
513
514 debug_time("Start New Collection Set", _recorded_start_new_cset_time_ms);
515 if (UseTLAB && ResizeTLAB) {
516 debug_time("Resize TLABs", _cur_resize_tlab_time_ms);
517 }
518 debug_time("Expand Heap After Collection", _cur_expand_heap_time_ms);
519
520 return sum_ms;
521}
522
523void G1GCPhaseTimes::print_other(double accounted_ms) const {
524 info_time("Other", _gc_pause_time_ms - accounted_ms);
525}
526
527void G1GCPhaseTimes::print(bool evacuation_failed) {
528 // Check if some time has been recorded for verification and only then print
529 // the message. We do not use Verify*GC here to print because VerifyGCType
530 // further limits actual verification.
531 if (_cur_verify_before_time_ms > 0.0) {
1
Assuming the condition is false
→
2
←
Taking false branch
→
532 debug_time("Verify Before", _cur_verify_before_time_ms);
533 }
534
535 double accounted_ms = 0.0;
536 accounted_ms += print_pre_evacuate_collection_set();
3
←
Calling 'G1GCPhaseTimes::print_pre_evacuate_collection_set'
→
537 accounted_ms += print_evacuate_initial_collection_set();
538 accounted_ms += print_evacuate_optional_collection_set();
539 accounted_ms += print_post_evacuate_collection_set(evacuation_failed);
540 print_other(accounted_ms);
541
542 // See above comment on the _cur_verify_before_time_ms check.
543 if (_cur_verify_after_time_ms > 0.0) {
544 debug_time("Verify After", _cur_verify_after_time_ms);
545 }
546}
547
548const char* G1GCPhaseTimes::phase_name(GCParPhases phase) {
549 G1GCPhaseTimes* phase_times = G1CollectedHeap::heap()->phase_times();
550 return phase_times->_gc_par_phases[phase]->short_name();
551}
552
553G1EvacPhaseWithTrimTimeTracker::G1EvacPhaseWithTrimTimeTracker(G1ParScanThreadState* pss, Tickspan& total_time, Tickspan& trim_time) :
554 _pss(pss),
555 _start(Ticks::now()),
556 _total_time(total_time),
557 _trim_time(trim_time),
558 _stopped(false) {
559
560 assert(_pss->trim_ticks().value() == 0, "Possibly remaining trim ticks left over from previous use")do { if (!(_pss->trim_ticks().value() == 0)) { (*g_assert_poison
) = 'X';; report_vm_error("/home/daniel/Projects/java/jdk/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp"
, 560, "assert(" "_pss->trim_ticks().value() == 0" ") failed"
, "Possibly remaining trim ticks left over from previous use"
); ::breakpoint(); } } while (0);
561}
562
563G1EvacPhaseWithTrimTimeTracker::~G1EvacPhaseWithTrimTimeTracker() {
564 if (!_stopped) {
565 stop();
566 }
567}
568
569void G1EvacPhaseWithTrimTimeTracker::stop() {
570 assert(!_stopped, "Should only be called once")do { if (!(!_stopped)) { (*g_assert_poison) = 'X';; report_vm_error
("/home/daniel/Projects/java/jdk/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp"
, 570, "assert(" "!_stopped" ") failed", "Should only be called once"
); ::breakpoint(); } } while (0);
571 _total_time += (Ticks::now() - _start) - _pss->trim_ticks();
572 _trim_time += _pss->trim_ticks();
573 _pss->reset_trim_ticks();
574 _stopped = true;
575}
576
577G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id, bool allow_multiple_record) :
578 _start_time(), _phase(phase), _phase_times(phase_times), _worker_id(worker_id), _event(), _allow_multiple_record(allow_multiple_record) {
579 if (_phase_times != NULL__null) {
580 _start_time = Ticks::now();
581 }
582}
583
584G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
585 if (_phase_times != NULL__null) {
586 if (_allow_multiple_record) {
587 _phase_times->record_or_add_time_secs(_phase, _worker_id, (Ticks::now() - _start_time).seconds());
588 } else {
589 _phase_times->record_time_secs(_phase, _worker_id, (Ticks::now() - _start_time).seconds());
590 }
591 _event.commit(GCId::current(), _worker_id, G1GCPhaseTimes::phase_name(_phase));
592 }
593}
594
595G1EvacPhaseTimesTracker::G1EvacPhaseTimesTracker(G1GCPhaseTimes* phase_times,
596 G1ParScanThreadState* pss,
597 G1GCPhaseTimes::GCParPhases phase,
598 uint worker_id) :
599 G1GCParPhaseTimesTracker(phase_times, phase, worker_id),
600 _total_time(),
601 _trim_time(),
602 _trim_tracker(pss, _total_time, _trim_time) {
603}
604
605G1EvacPhaseTimesTracker::~G1EvacPhaseTimesTracker() {
606 if (_phase_times != NULL__null) {
607 // Explicitly stop the trim tracker since it's not yet destructed.
608 _trim_tracker.stop();
609 // Exclude trim time by increasing the start time.
610 _start_time += _trim_time;
611 _phase_times->record_or_add_time_secs(G1GCPhaseTimes::ObjCopy, _worker_id, _trim_time.seconds());
612 }
613}
614