Thu, 14 Jun 2018 09:15:08 -0700
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 |