src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp

Thu, 14 Jun 2018 09:15:08 -0700

author
kevinw
date
Thu, 14 Jun 2018 09:15:08 -0700
changeset 9327
f96fcd9e1e1b
parent 8310
6c57a16d0238
child 9448
73d689add964
child 9478
f3108e56b502
permissions
-rw-r--r--

8081202: Hotspot compile warning: "Invalid suffix on literal; C++11 requires a space between literal and identifier"
Summary: Need to add a space between macro identifier and string literal
Reviewed-by: bpittore, stefank, dholmes, kbarrett

brutisso@3923 1 /*
tschatzl@7893 2 * Copyright (c) 2013, 2014, Oracle and/or its affiliates. All rights reserved.
brutisso@3923 3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
brutisso@3923 4 *
brutisso@3923 5 * This code is free software; you can redistribute it and/or modify it
brutisso@3923 6 * under the terms of the GNU General Public License version 2 only, as
brutisso@3923 7 * published by the Free Software Foundation.
brutisso@3923 8 *
brutisso@3923 9 * This code is distributed in the hope that it will be useful, but WITHOUT
brutisso@3923 10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
brutisso@3923 11 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
brutisso@3923 12 * version 2 for more details (a copy is included in the LICENSE file that
brutisso@3923 13 * accompanied this code).
brutisso@3923 14 *
brutisso@3923 15 * You should have received a copy of the GNU General Public License version
brutisso@3923 16 * 2 along with this work; if not, write to the Free Software Foundation,
brutisso@3923 17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
brutisso@3923 18 *
brutisso@3923 19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
brutisso@3923 20 * or visit www.oracle.com if you need additional information or have any
brutisso@3923 21 * questions.
brutisso@3923 22 *
brutisso@3923 23 */
brutisso@3923 24
brutisso@3923 25 #include "precompiled.hpp"
brutisso@3923 26 #include "gc_implementation/g1/g1CollectedHeap.inline.hpp"
brutisso@3923 27 #include "gc_implementation/g1/g1GCPhaseTimes.hpp"
brutisso@3923 28 #include "gc_implementation/g1/g1Log.hpp"
pliden@6413 29 #include "gc_implementation/g1/g1StringDedup.hpp"
brutisso@7658 30 #include "memory/allocation.hpp"
brutisso@7658 31 #include "runtime/os.hpp"
brutisso@3923 32
brutisso@3923 33 // Helper class for avoiding interleaved logging
brutisso@3923 34 class LineBuffer: public StackObj {
brutisso@3923 35
brutisso@3923 36 private:
brutisso@3923 37 static const int BUFFER_LEN = 1024;
brutisso@3923 38 static const int INDENT_CHARS = 3;
brutisso@3923 39 char _buffer[BUFFER_LEN];
brutisso@3923 40 int _indent_level;
brutisso@3923 41 int _cur;
brutisso@3923 42
drchase@6680 43 void vappend(const char* format, va_list ap) ATTRIBUTE_PRINTF(2, 0) {
brutisso@3923 44 int res = vsnprintf(&_buffer[_cur], BUFFER_LEN - _cur, format, ap);
brutisso@3923 45 if (res != -1) {
brutisso@3923 46 _cur += res;
brutisso@3923 47 } else {
brutisso@3923 48 DEBUG_ONLY(warning("buffer too small in LineBuffer");)
brutisso@3923 49 _buffer[BUFFER_LEN -1] = 0;
brutisso@3923 50 _cur = BUFFER_LEN; // vsnprintf above should not add to _buffer if we are called again
brutisso@3923 51 }
brutisso@3923 52 }
brutisso@3923 53
brutisso@3923 54 public:
brutisso@3923 55 explicit LineBuffer(int indent_level): _indent_level(indent_level), _cur(0) {
brutisso@3923 56 for (; (_cur < BUFFER_LEN && _cur < (_indent_level * INDENT_CHARS)); _cur++) {
brutisso@3923 57 _buffer[_cur] = ' ';
brutisso@3923 58 }
brutisso@3923 59 }
brutisso@3923 60
brutisso@3923 61 #ifndef PRODUCT
brutisso@3923 62 ~LineBuffer() {
brutisso@3923 63 assert(_cur == _indent_level * INDENT_CHARS, "pending data in buffer - append_and_print_cr() not called?");
brutisso@3923 64 }
brutisso@3923 65 #endif
brutisso@3923 66
drchase@6680 67 void append(const char* format, ...) ATTRIBUTE_PRINTF(2, 3) {
brutisso@3923 68 va_list ap;
brutisso@3923 69 va_start(ap, format);
brutisso@3923 70 vappend(format, ap);
brutisso@3923 71 va_end(ap);
brutisso@3923 72 }
brutisso@3923 73
brutisso@7658 74 void print_cr() {
brutisso@7658 75 gclog_or_tty->print_cr("%s", _buffer);
brutisso@7658 76 _cur = _indent_level * INDENT_CHARS;
brutisso@7658 77 }
brutisso@7658 78
drchase@6680 79 void append_and_print_cr(const char* format, ...) ATTRIBUTE_PRINTF(2, 3) {
brutisso@3923 80 va_list ap;
brutisso@3923 81 va_start(ap, format);
brutisso@3923 82 vappend(format, ap);
brutisso@3923 83 va_end(ap);
brutisso@7658 84 print_cr();
brutisso@3923 85 }
brutisso@3923 86 };
brutisso@3923 87
brutisso@4015 88 template <class T>
brutisso@7658 89 class WorkerDataArray : public CHeapObj<mtGC> {
brutisso@7658 90 friend class G1GCParPhasePrinter;
brutisso@7658 91 T* _data;
brutisso@7658 92 uint _length;
brutisso@7658 93 const char* _title;
brutisso@7658 94 bool _print_sum;
brutisso@7658 95 int _log_level;
brutisso@7658 96 uint _indent_level;
brutisso@7658 97 bool _enabled;
brutisso@7658 98
brutisso@7658 99 WorkerDataArray<size_t>* _thread_work_items;
brutisso@7658 100
brutisso@7658 101 NOT_PRODUCT(T uninitialized();)
brutisso@7658 102
brutisso@7658 103 // We are caching the sum and average to only have to calculate them once.
brutisso@7658 104 // This is not done in an MT-safe way. It is intended to allow single
brutisso@7658 105 // threaded code to call sum() and average() multiple times in any order
brutisso@7658 106 // without having to worry about the cost.
brutisso@7658 107 bool _has_new_data;
brutisso@7658 108 T _sum;
brutisso@7658 109 T _min;
brutisso@7658 110 T _max;
brutisso@7658 111 double _average;
brutisso@7658 112
brutisso@7658 113 public:
brutisso@7658 114 WorkerDataArray(uint length, const char* title, bool print_sum, int log_level, uint indent_level) :
brutisso@7658 115 _title(title), _length(0), _print_sum(print_sum), _log_level(log_level), _indent_level(indent_level),
brutisso@7658 116 _has_new_data(true), _thread_work_items(NULL), _enabled(true) {
brutisso@7658 117 assert(length > 0, "Must have some workers to store data for");
brutisso@7658 118 _length = length;
brutisso@7658 119 _data = NEW_C_HEAP_ARRAY(T, _length, mtGC);
brutisso@4015 120 }
brutisso@4015 121
brutisso@7658 122 ~WorkerDataArray() {
brutisso@7658 123 FREE_C_HEAP_ARRAY(T, _data, mtGC);
brutisso@4015 124 }
brutisso@4015 125
brutisso@7658 126 void link_thread_work_items(WorkerDataArray<size_t>* thread_work_items) {
brutisso@7658 127 _thread_work_items = thread_work_items;
brutisso@4015 128 }
brutisso@4015 129
brutisso@7658 130 WorkerDataArray<size_t>* thread_work_items() { return _thread_work_items; }
brutisso@7658 131
brutisso@7658 132 void set(uint worker_i, T value) {
brutisso@7658 133 assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
brutisso@7658 134 assert(_data[worker_i] == WorkerDataArray<T>::uninitialized(), err_msg("Overwriting data for worker %d in %s", worker_i, _title));
brutisso@7658 135 _data[worker_i] = value;
brutisso@7658 136 _has_new_data = true;
brutisso@4015 137 }
brutisso@7658 138
brutisso@7658 139 void set_thread_work_item(uint worker_i, size_t value) {
brutisso@7658 140 assert(_thread_work_items != NULL, "No sub count");
brutisso@7658 141 _thread_work_items->set(worker_i, value);
brutisso@7658 142 }
brutisso@7658 143
brutisso@7658 144 T get(uint worker_i) {
brutisso@7658 145 assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
brutisso@7658 146 assert(_data[worker_i] != WorkerDataArray<T>::uninitialized(), err_msg("No data added for worker %d", worker_i));
brutisso@7658 147 return _data[worker_i];
brutisso@7658 148 }
brutisso@7658 149
brutisso@7658 150 void add(uint worker_i, T value) {
brutisso@7658 151 assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
brutisso@7658 152 assert(_data[worker_i] != WorkerDataArray<T>::uninitialized(), err_msg("No data to add to for worker %d", worker_i));
brutisso@7658 153 _data[worker_i] += value;
brutisso@7658 154 _has_new_data = true;
brutisso@7658 155 }
brutisso@7658 156
dbuck@8310 157 double average(uint active_threads){
dbuck@8310 158 calculate_totals(active_threads);
brutisso@7658 159 return _average;
brutisso@7658 160 }
brutisso@7658 161
dbuck@8310 162 T sum(uint active_threads) {
dbuck@8310 163 calculate_totals(active_threads);
brutisso@7658 164 return _sum;
brutisso@7658 165 }
brutisso@7658 166
dbuck@8310 167 T minimum(uint active_threads) {
dbuck@8310 168 calculate_totals(active_threads);
brutisso@7658 169 return _min;
brutisso@7658 170 }
brutisso@7658 171
dbuck@8310 172 T maximum(uint active_threads) {
dbuck@8310 173 calculate_totals(active_threads);
brutisso@7658 174 return _max;
brutisso@7658 175 }
brutisso@7658 176
brutisso@7658 177 void reset() PRODUCT_RETURN;
dbuck@8310 178 void verify(uint active_threads) PRODUCT_RETURN;
brutisso@7658 179
brutisso@7658 180 void set_enabled(bool enabled) { _enabled = enabled; }
brutisso@7658 181
brutisso@7658 182 int log_level() { return _log_level; }
brutisso@7658 183
brutisso@7658 184 private:
brutisso@7658 185
dbuck@8310 186 void calculate_totals(uint active_threads){
brutisso@7658 187 if (!_has_new_data) {
brutisso@7658 188 return;
brutisso@7658 189 }
brutisso@7658 190
brutisso@7658 191 _sum = (T)0;
brutisso@7658 192 _min = _data[0];
brutisso@7658 193 _max = _min;
dbuck@8310 194 assert(active_threads <= _length, "Wrong number of active threads");
dbuck@8310 195 for (uint i = 0; i < active_threads; ++i) {
brutisso@7658 196 T val = _data[i];
brutisso@7658 197 _sum += val;
brutisso@7658 198 _min = MIN2(_min, val);
brutisso@7658 199 _max = MAX2(_max, val);
brutisso@7658 200 }
dbuck@8310 201 _average = (double)_sum / (double)active_threads;
brutisso@7658 202 _has_new_data = false;
brutisso@7658 203 }
brutisso@7658 204 };
brutisso@7658 205
brutisso@4015 206
jmasa@4097 207 #ifndef PRODUCT
brutisso@4015 208
brutisso@7658 209 template <>
brutisso@7658 210 size_t WorkerDataArray<size_t>::uninitialized() {
brutisso@7658 211 return (size_t)-1;
brutisso@7658 212 }
brutisso@7658 213
brutisso@7658 214 template <>
brutisso@7658 215 double WorkerDataArray<double>::uninitialized() {
brutisso@7658 216 return -1.0;
brutisso@7658 217 }
brutisso@4475 218
brutisso@4015 219 template <class T>
brutisso@4015 220 void WorkerDataArray<T>::reset() {
brutisso@4015 221 for (uint i = 0; i < _length; i++) {
brutisso@7658 222 _data[i] = WorkerDataArray<T>::uninitialized();
brutisso@7658 223 }
brutisso@7658 224 if (_thread_work_items != NULL) {
brutisso@7658 225 _thread_work_items->reset();
brutisso@4015 226 }
brutisso@4015 227 }
brutisso@4015 228
brutisso@4015 229 template <class T>
dbuck@8310 230 void WorkerDataArray<T>::verify(uint active_threads) {
brutisso@7658 231 if (!_enabled) {
brutisso@7658 232 return;
brutisso@7658 233 }
brutisso@7658 234
dbuck@8310 235 assert(active_threads <= _length, "Wrong number of active threads");
dbuck@8310 236 for (uint i = 0; i < active_threads; i++) {
brutisso@7658 237 assert(_data[i] != WorkerDataArray<T>::uninitialized(),
brutisso@7658 238 err_msg("Invalid data for worker %u in '%s'", i, _title));
brutisso@7658 239 }
brutisso@7658 240 if (_thread_work_items != NULL) {
dbuck@8310 241 _thread_work_items->verify(active_threads);
brutisso@4015 242 }
brutisso@4015 243 }
brutisso@4015 244
brutisso@4015 245 #endif
brutisso@4015 246
brutisso@3923 247 G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
brutisso@7658 248 _max_gc_threads(max_gc_threads)
brutisso@3923 249 {
brutisso@3923 250 assert(max_gc_threads > 0, "Must have some GC threads");
brutisso@7658 251
brutisso@7658 252 _gc_par_phases[GCWorkerStart] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Start (ms)", false, G1Log::LevelFiner, 2);
brutisso@7658 253 _gc_par_phases[ExtRootScan] = new WorkerDataArray<double>(max_gc_threads, "Ext Root Scanning (ms)", true, G1Log::LevelFiner, 2);
brutisso@7660 254
brutisso@7660 255 // Root scanning phases
brutisso@7660 256 _gc_par_phases[ThreadRoots] = new WorkerDataArray<double>(max_gc_threads, "Thread Roots (ms)", true, G1Log::LevelFinest, 3);
brutisso@7660 257 _gc_par_phases[StringTableRoots] = new WorkerDataArray<double>(max_gc_threads, "StringTable Roots (ms)", true, G1Log::LevelFinest, 3);
brutisso@7660 258 _gc_par_phases[UniverseRoots] = new WorkerDataArray<double>(max_gc_threads, "Universe Roots (ms)", true, G1Log::LevelFinest, 3);
brutisso@7660 259 _gc_par_phases[JNIRoots] = new WorkerDataArray<double>(max_gc_threads, "JNI Handles Roots (ms)", true, G1Log::LevelFinest, 3);
brutisso@7660 260 _gc_par_phases[ObjectSynchronizerRoots] = new WorkerDataArray<double>(max_gc_threads, "ObjectSynchronizer Roots (ms)", true, G1Log::LevelFinest, 3);
brutisso@7660 261 _gc_par_phases[FlatProfilerRoots] = new WorkerDataArray<double>(max_gc_threads, "FlatProfiler Roots (ms)", true, G1Log::LevelFinest, 3);
brutisso@7660 262 _gc_par_phases[ManagementRoots] = new WorkerDataArray<double>(max_gc_threads, "Management Roots (ms)", true, G1Log::LevelFinest, 3);
brutisso@7660 263 _gc_par_phases[SystemDictionaryRoots] = new WorkerDataArray<double>(max_gc_threads, "SystemDictionary Roots (ms)", true, G1Log::LevelFinest, 3);
brutisso@7660 264 _gc_par_phases[CLDGRoots] = new WorkerDataArray<double>(max_gc_threads, "CLDG Roots (ms)", true, G1Log::LevelFinest, 3);
brutisso@7660 265 _gc_par_phases[JVMTIRoots] = new WorkerDataArray<double>(max_gc_threads, "JVMTI Roots (ms)", true, G1Log::LevelFinest, 3);
brutisso@7660 266 _gc_par_phases[CodeCacheRoots] = new WorkerDataArray<double>(max_gc_threads, "CodeCache Roots (ms)", true, G1Log::LevelFinest, 3);
brutisso@7660 267 _gc_par_phases[CMRefRoots] = new WorkerDataArray<double>(max_gc_threads, "CM RefProcessor Roots (ms)", true, G1Log::LevelFinest, 3);
brutisso@7660 268 _gc_par_phases[WaitForStrongCLD] = new WorkerDataArray<double>(max_gc_threads, "Wait For Strong CLD (ms)", true, G1Log::LevelFinest, 3);
brutisso@7660 269 _gc_par_phases[WeakCLDRoots] = new WorkerDataArray<double>(max_gc_threads, "Weak CLD Roots (ms)", true, G1Log::LevelFinest, 3);
brutisso@7660 270 _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms)", true, G1Log::LevelFinest, 3);
brutisso@7660 271
brutisso@7658 272 _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms)", true, G1Log::LevelFiner, 2);
brutisso@7658 273 _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms)", true, G1Log::LevelFiner, 2);
brutisso@7658 274 _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms)", true, G1Log::LevelFiner, 2);
brutisso@7658 275 _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms)", true, G1Log::LevelFiner, 2);
brutisso@7658 276 _gc_par_phases[Termination] = new WorkerDataArray<double>(max_gc_threads, "Termination (ms)", true, G1Log::LevelFiner, 2);
brutisso@7658 277 _gc_par_phases[GCWorkerTotal] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Total (ms)", true, G1Log::LevelFiner, 2);
brutisso@7658 278 _gc_par_phases[GCWorkerEnd] = new WorkerDataArray<double>(max_gc_threads, "GC Worker End (ms)", false, G1Log::LevelFiner, 2);
brutisso@7658 279 _gc_par_phases[Other] = new WorkerDataArray<double>(max_gc_threads, "GC Worker Other (ms)", true, G1Log::LevelFiner, 2);
brutisso@7658 280
brutisso@7658 281 _update_rs_processed_buffers = new WorkerDataArray<size_t>(max_gc_threads, "Processed Buffers", true, G1Log::LevelFiner, 3);
brutisso@7658 282 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers);
brutisso@7658 283
brutisso@7658 284 _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts", true, G1Log::LevelFinest, 3);
brutisso@7658 285 _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts);
brutisso@7658 286
brutisso@7658 287 _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms)", true, G1Log::LevelFiner, 2);
brutisso@7658 288 _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms)", true, G1Log::LevelFiner, 2);
brutisso@7658 289
brutisso@7658 290 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty", true, G1Log::LevelFinest, 3);
brutisso@7658 291 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards", true, G1Log::LevelFinest, 3);
brutisso@7658 292 _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
brutisso@3923 293 }
brutisso@3923 294
brutisso@7658 295 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads, bool mark_in_progress) {
brutisso@3923 296 assert(active_gc_threads > 0, "The number of threads must be > 0");
brutisso@7658 297 assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max number of threads");
brutisso@3923 298 _active_gc_threads = active_gc_threads;
brutisso@3923 299
brutisso@7658 300 for (int i = 0; i < GCParPhasesSentinel; i++) {
brutisso@7658 301 _gc_par_phases[i]->reset();
brutisso@7658 302 }
tschatzl@6930 303
brutisso@7658 304 _gc_par_phases[StringDedupQueueFixup]->set_enabled(G1StringDedup::is_enabled());
brutisso@7658 305 _gc_par_phases[StringDedupTableFixup]->set_enabled(G1StringDedup::is_enabled());
brutisso@3923 306 }
brutisso@3923 307
brutisso@4015 308 void G1GCPhaseTimes::note_gc_end() {
brutisso@7658 309 for (uint i = 0; i < _active_gc_threads; i++) {
brutisso@7658 310 double worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
brutisso@7658 311 record_time_secs(GCWorkerTotal, i , worker_time);
brutisso@3923 312
brutisso@7658 313 double worker_known_time =
brutisso@7658 314 _gc_par_phases[ExtRootScan]->get(i) +
brutisso@7658 315 _gc_par_phases[SATBFiltering]->get(i) +
brutisso@7658 316 _gc_par_phases[UpdateRS]->get(i) +
brutisso@7658 317 _gc_par_phases[ScanRS]->get(i) +
brutisso@7658 318 _gc_par_phases[CodeRoots]->get(i) +
brutisso@7658 319 _gc_par_phases[ObjCopy]->get(i) +
brutisso@7658 320 _gc_par_phases[Termination]->get(i);
brutisso@3923 321
brutisso@7658 322 record_time_secs(Other, i, worker_time - worker_known_time);
brutisso@4475 323 }
brutisso@3923 324
brutisso@7658 325 for (int i = 0; i < GCParPhasesSentinel; i++) {
dbuck@8310 326 _gc_par_phases[i]->verify(_active_gc_threads);
brutisso@7658 327 }
pliden@6413 328 }
pliden@6413 329
brutisso@3923 330 void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
brutisso@3923 331 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms]", str, value);
brutisso@3923 332 }
brutisso@3923 333
tschatzl@7010 334 void G1GCPhaseTimes::print_stats(int level, const char* str, size_t value) {
kevinw@9327 335 LineBuffer(level).append_and_print_cr("[%s: " SIZE_FORMAT "]", str, value);
tschatzl@7010 336 }
tschatzl@7010 337
vkempik@6552 338 void G1GCPhaseTimes::print_stats(int level, const char* str, double value, uint workers) {
brutisso@7658 339 LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %u]", str, value, workers);
brutisso@3923 340 }
brutisso@3923 341
brutisso@3923 342 double G1GCPhaseTimes::accounted_time_ms() {
brutisso@3923 343 // Subtract the root region scanning wait time. It's initialized to
brutisso@3923 344 // zero at the start of the pause.
brutisso@3923 345 double misc_time_ms = _root_region_scan_wait_time_ms;
brutisso@3923 346
brutisso@3923 347 misc_time_ms += _cur_collection_par_time_ms;
brutisso@3923 348
brutisso@3923 349 // Now subtract the time taken to fix up roots in generated code
brutisso@3923 350 misc_time_ms += _cur_collection_code_root_fixup_time_ms;
brutisso@3923 351
tschatzl@6402 352 // Strong code root purge time
tschatzl@6402 353 misc_time_ms += _cur_strong_code_root_purge_time_ms;
tschatzl@6402 354
pliden@6413 355 if (G1StringDedup::is_enabled()) {
pliden@6413 356 // String dedup fixup time
pliden@6413 357 misc_time_ms += _cur_string_dedup_fixup_time_ms;
pliden@6413 358 }
pliden@6413 359
brutisso@3923 360 // Subtract the time taken to clean the card table from the
brutisso@3923 361 // current value of "other time"
brutisso@3923 362 misc_time_ms += _cur_clear_ct_time_ms;
brutisso@3923 363
brutisso@3923 364 return misc_time_ms;
brutisso@3923 365 }
brutisso@3923 366
brutisso@7658 367 // record the time a phase took in seconds
brutisso@7658 368 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
brutisso@7658 369 _gc_par_phases[phase]->set(worker_i, secs);
brutisso@7658 370 }
brutisso@7658 371
brutisso@7658 372 // add a number of seconds to a phase
brutisso@7658 373 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) {
brutisso@7658 374 _gc_par_phases[phase]->add(worker_i, secs);
brutisso@7658 375 }
brutisso@7658 376
brutisso@7658 377 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count) {
brutisso@7658 378 _gc_par_phases[phase]->set_thread_work_item(worker_i, count);
brutisso@7658 379 }
brutisso@7658 380
brutisso@7658 381 // return the average time for a phase in milliseconds
brutisso@7658 382 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
dbuck@8310 383 return _gc_par_phases[phase]->average(_active_gc_threads) * 1000.0;
brutisso@7658 384 }
brutisso@7658 385
brutisso@7658 386 double G1GCPhaseTimes::get_time_ms(GCParPhases phase, uint worker_i) {
brutisso@7658 387 return _gc_par_phases[phase]->get(worker_i) * 1000.0;
brutisso@7658 388 }
brutisso@7658 389
brutisso@7658 390 double G1GCPhaseTimes::sum_time_ms(GCParPhases phase) {
dbuck@8310 391 return _gc_par_phases[phase]->sum(_active_gc_threads) * 1000.0;
brutisso@7658 392 }
brutisso@7658 393
brutisso@7658 394 double G1GCPhaseTimes::min_time_ms(GCParPhases phase) {
dbuck@8310 395 return _gc_par_phases[phase]->minimum(_active_gc_threads) * 1000.0;
brutisso@7658 396 }
brutisso@7658 397
brutisso@7658 398 double G1GCPhaseTimes::max_time_ms(GCParPhases phase) {
dbuck@8310 399 return _gc_par_phases[phase]->maximum(_active_gc_threads) * 1000.0;
brutisso@7658 400 }
brutisso@7658 401
brutisso@7658 402 size_t G1GCPhaseTimes::get_thread_work_item(GCParPhases phase, uint worker_i) {
brutisso@7658 403 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
brutisso@7658 404 return _gc_par_phases[phase]->thread_work_items()->get(worker_i);
brutisso@7658 405 }
brutisso@7658 406
brutisso@7658 407 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase) {
brutisso@7658 408 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
dbuck@8310 409 return _gc_par_phases[phase]->thread_work_items()->sum(_active_gc_threads);
brutisso@7658 410 }
brutisso@7658 411
brutisso@7658 412 double G1GCPhaseTimes::average_thread_work_items(GCParPhases phase) {
brutisso@7658 413 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
dbuck@8310 414 return _gc_par_phases[phase]->thread_work_items()->average(_active_gc_threads);
brutisso@7658 415 }
brutisso@7658 416
brutisso@7658 417 size_t G1GCPhaseTimes::min_thread_work_items(GCParPhases phase) {
brutisso@7658 418 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
dbuck@8310 419 return _gc_par_phases[phase]->thread_work_items()->minimum(_active_gc_threads);
brutisso@7658 420 }
brutisso@7658 421
brutisso@7658 422 size_t G1GCPhaseTimes::max_thread_work_items(GCParPhases phase) {
brutisso@7658 423 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
dbuck@8310 424 return _gc_par_phases[phase]->thread_work_items()->maximum(_active_gc_threads);
brutisso@7658 425 }
brutisso@7658 426
brutisso@7658 427 class G1GCParPhasePrinter : public StackObj {
brutisso@7658 428 G1GCPhaseTimes* _phase_times;
brutisso@7658 429 public:
brutisso@7658 430 G1GCParPhasePrinter(G1GCPhaseTimes* phase_times) : _phase_times(phase_times) {}
brutisso@7658 431
brutisso@7658 432 void print(G1GCPhaseTimes::GCParPhases phase_id) {
brutisso@7658 433 WorkerDataArray<double>* phase = _phase_times->_gc_par_phases[phase_id];
brutisso@7658 434
brutisso@7658 435 if (phase->_log_level > G1Log::level() || !phase->_enabled) {
brutisso@7658 436 return;
brutisso@7658 437 }
brutisso@7658 438
brutisso@7658 439 if (phase->_length == 1) {
brutisso@7658 440 print_single_length(phase_id, phase);
brutisso@7658 441 } else {
brutisso@7658 442 print_multi_length(phase_id, phase);
brutisso@7658 443 }
brutisso@7658 444 }
brutisso@7658 445
brutisso@7658 446 private:
brutisso@7658 447
brutisso@7658 448 void print_single_length(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) {
brutisso@7658 449 // No need for min, max, average and sum for only one worker
brutisso@7658 450 LineBuffer buf(phase->_indent_level);
brutisso@7658 451 buf.append_and_print_cr("[%s: %.1lf]", phase->_title, _phase_times->get_time_ms(phase_id, 0));
brutisso@7658 452
brutisso@7658 453 if (phase->_thread_work_items != NULL) {
brutisso@7658 454 LineBuffer buf2(phase->_thread_work_items->_indent_level);
kevinw@9327 455 buf2.append_and_print_cr("[%s: " SIZE_FORMAT "]", phase->_thread_work_items->_title, _phase_times->sum_thread_work_items(phase_id));
brutisso@7658 456 }
brutisso@7658 457 }
brutisso@7658 458
brutisso@7658 459 void print_time_values(LineBuffer& buf, G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) {
dbuck@8310 460 uint active_length = _phase_times->_active_gc_threads;
dbuck@8310 461 for (uint i = 0; i < active_length; ++i) {
brutisso@7658 462 buf.append(" %.1lf", _phase_times->get_time_ms(phase_id, i));
brutisso@7658 463 }
brutisso@7658 464 buf.print_cr();
brutisso@7658 465 }
brutisso@7658 466
brutisso@7658 467 void print_count_values(LineBuffer& buf, G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<size_t>* thread_work_items) {
dbuck@8310 468 uint active_length = _phase_times->_active_gc_threads;
dbuck@8310 469 for (uint i = 0; i < active_length; ++i) {
brutisso@7658 470 buf.append(" " SIZE_FORMAT, _phase_times->get_thread_work_item(phase_id, i));
brutisso@7658 471 }
brutisso@7658 472 buf.print_cr();
brutisso@7658 473 }
brutisso@7658 474
brutisso@7658 475 void print_thread_work_items(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<size_t>* thread_work_items) {
brutisso@7658 476 LineBuffer buf(thread_work_items->_indent_level);
brutisso@7658 477 buf.append("[%s:", thread_work_items->_title);
brutisso@7658 478
brutisso@7658 479 if (G1Log::finest()) {
brutisso@7658 480 print_count_values(buf, phase_id, thread_work_items);
brutisso@7658 481 }
brutisso@7658 482
brutisso@7658 483 assert(thread_work_items->_print_sum, err_msg("%s does not have print sum true even though it is a count", thread_work_items->_title));
brutisso@7658 484
brutisso@7658 485 buf.append_and_print_cr(" Min: " SIZE_FORMAT ", Avg: %.1lf, Max: " SIZE_FORMAT ", Diff: " SIZE_FORMAT ", Sum: " SIZE_FORMAT "]",
brutisso@7658 486 _phase_times->min_thread_work_items(phase_id), _phase_times->average_thread_work_items(phase_id), _phase_times->max_thread_work_items(phase_id),
brutisso@7658 487 _phase_times->max_thread_work_items(phase_id) - _phase_times->min_thread_work_items(phase_id), _phase_times->sum_thread_work_items(phase_id));
brutisso@7658 488 }
brutisso@7658 489
brutisso@7658 490 void print_multi_length(G1GCPhaseTimes::GCParPhases phase_id, WorkerDataArray<double>* phase) {
brutisso@7658 491 LineBuffer buf(phase->_indent_level);
brutisso@7658 492 buf.append("[%s:", phase->_title);
brutisso@7658 493
brutisso@7658 494 if (G1Log::finest()) {
brutisso@7658 495 print_time_values(buf, phase_id, phase);
brutisso@7658 496 }
brutisso@7658 497
brutisso@7658 498 buf.append(" Min: %.1lf, Avg: %.1lf, Max: %.1lf, Diff: %.1lf",
brutisso@7658 499 _phase_times->min_time_ms(phase_id), _phase_times->average_time_ms(phase_id), _phase_times->max_time_ms(phase_id),
brutisso@7658 500 _phase_times->max_time_ms(phase_id) - _phase_times->min_time_ms(phase_id));
brutisso@7658 501
brutisso@7658 502 if (phase->_print_sum) {
brutisso@7658 503 // for things like the start and end times the sum is not
brutisso@7658 504 // that relevant
brutisso@7658 505 buf.append(", Sum: %.1lf", _phase_times->sum_time_ms(phase_id));
brutisso@7658 506 }
brutisso@7658 507
brutisso@7658 508 buf.append_and_print_cr("]");
brutisso@7658 509
brutisso@7658 510 if (phase->_thread_work_items != NULL) {
brutisso@7658 511 print_thread_work_items(phase_id, phase->_thread_work_items);
brutisso@7658 512 }
brutisso@7658 513 }
brutisso@7658 514 };
brutisso@7658 515
brutisso@4015 516 void G1GCPhaseTimes::print(double pause_time_sec) {
brutisso@7658 517 G1GCParPhasePrinter par_phase_printer(this);
brutisso@7658 518
brutisso@3923 519 if (_root_region_scan_wait_time_ms > 0.0) {
brutisso@3923 520 print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
brutisso@3923 521 }
brutisso@7658 522
brutisso@7658 523 print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads);
brutisso@7658 524 for (int i = 0; i <= GCMainParPhasesLast; i++) {
brutisso@7658 525 par_phase_printer.print((GCParPhases) i);
brutisso@3923 526 }
brutisso@7658 527
brutisso@3923 528 print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
tschatzl@6402 529 print_stats(1, "Code Root Purge", _cur_strong_code_root_purge_time_ms);
pliden@6413 530 if (G1StringDedup::is_enabled()) {
pliden@6413 531 print_stats(1, "String Dedup Fixup", _cur_string_dedup_fixup_time_ms, _active_gc_threads);
brutisso@7658 532 for (int i = StringDedupPhasesFirst; i <= StringDedupPhasesLast; i++) {
brutisso@7658 533 par_phase_printer.print((GCParPhases) i);
brutisso@7658 534 }
pliden@6413 535 }
brutisso@3923 536 print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
brutisso@4015 537 double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms();
brutisso@3923 538 print_stats(1, "Other", misc_time_ms);
brutisso@4015 539 if (_cur_verify_before_time_ms > 0.0) {
brutisso@4015 540 print_stats(2, "Verify Before", _cur_verify_before_time_ms);
brutisso@4015 541 }
tschatzl@6406 542 if (G1CollectedHeap::heap()->evacuation_failed()) {
tschatzl@6406 543 double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards +
tschatzl@6406 544 _cur_evac_fail_restore_remsets;
tschatzl@6406 545 print_stats(2, "Evacuation Failure", evac_fail_handling);
tschatzl@6406 546 if (G1Log::finest()) {
tschatzl@6406 547 print_stats(3, "Recalculate Used", _cur_evac_fail_recalc_used);
tschatzl@6406 548 print_stats(3, "Remove Self Forwards", _cur_evac_fail_remove_self_forwards);
tschatzl@6406 549 print_stats(3, "Restore RemSet", _cur_evac_fail_restore_remsets);
tschatzl@6406 550 }
tschatzl@6406 551 }
brutisso@3923 552 print_stats(2, "Choose CSet",
brutisso@3923 553 (_recorded_young_cset_choice_time_ms +
brutisso@3923 554 _recorded_non_young_cset_choice_time_ms));
brutisso@3923 555 print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
brutisso@3923 556 print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
tschatzl@7218 557 print_stats(2, "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
brutisso@7658 558 par_phase_printer.print(RedirtyCards);
tschatzl@7828 559
tschatzl@7828 560 if (G1EagerReclaimHumongousObjects) {
tschatzl@7828 561 print_stats(2, "Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
tschatzl@7010 562 if (G1Log::finest()) {
tschatzl@7010 563 print_stats(3, "Humongous Total", _cur_fast_reclaim_humongous_total);
tschatzl@7010 564 print_stats(3, "Humongous Candidate", _cur_fast_reclaim_humongous_candidates);
tschatzl@7828 565 }
tschatzl@7828 566 print_stats(2, "Humongous Reclaim", _cur_fast_reclaim_humongous_time_ms);
tschatzl@7828 567 if (G1Log::finest()) {
tschatzl@7010 568 print_stats(3, "Humongous Reclaimed", _cur_fast_reclaim_humongous_reclaimed);
tschatzl@7010 569 }
tschatzl@7010 570 }
brutisso@3923 571 print_stats(2, "Free CSet",
brutisso@3923 572 (_recorded_young_free_cset_time_ms +
brutisso@3923 573 _recorded_non_young_free_cset_time_ms));
tschatzl@6404 574 if (G1Log::finest()) {
tschatzl@6404 575 print_stats(3, "Young Free CSet", _recorded_young_free_cset_time_ms);
tschatzl@6404 576 print_stats(3, "Non-Young Free CSet", _recorded_non_young_free_cset_time_ms);
tschatzl@6404 577 }
brutisso@4015 578 if (_cur_verify_after_time_ms > 0.0) {
brutisso@4015 579 print_stats(2, "Verify After", _cur_verify_after_time_ms);
brutisso@4015 580 }
brutisso@3923 581 }
brutisso@7658 582
brutisso@7658 583 G1GCParPhaseTimesTracker::G1GCParPhaseTimesTracker(G1GCPhaseTimes* phase_times, G1GCPhaseTimes::GCParPhases phase, uint worker_id) :
brutisso@7658 584 _phase_times(phase_times), _phase(phase), _worker_id(worker_id) {
brutisso@7658 585 if (_phase_times != NULL) {
brutisso@7658 586 _start_time = os::elapsedTime();
brutisso@7658 587 }
brutisso@7658 588 }
brutisso@7658 589
brutisso@7658 590 G1GCParPhaseTimesTracker::~G1GCParPhaseTimesTracker() {
brutisso@7658 591 if (_phase_times != NULL) {
brutisso@7658 592 _phase_times->record_time_secs(_phase, _worker_id, os::elapsedTime() - _start_time);
brutisso@7658 593 }
brutisso@7658 594 }
brutisso@7658 595

mercurial