77 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers); 78 79 _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:"); 80 _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts); 81 82 if (UseStringDeduplication) { 83 _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):"); 84 _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):"); 85 } else { 86 _gc_par_phases[StringDedupQueueFixup] = NULL; 87 _gc_par_phases[StringDedupTableFixup] = NULL; 88 } 89 90 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):"); 91 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:"); 92 _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards); 93 94 _gc_par_phases[PreserveCMReferents] = new WorkerDataArray<double>(max_gc_threads, "Parallel Preserve CM Refs (ms):"); 95 } 96 97 void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) { 98 assert(active_gc_threads > 0, "The number of threads must be > 0"); 99 assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max number of threads"); 100 _gc_start_counter = os::elapsed_counter(); 101 _active_gc_threads = active_gc_threads; 102 _cur_expand_heap_time_ms = 0.0; 103 _external_accounted_time_ms = 0.0; 104 105 for (int i = 0; i < GCParPhasesSentinel; i++) { 106 if (_gc_par_phases[i] != NULL) { 107 _gc_par_phases[i]->reset(); 108 } 109 } 110 } 111 112 void G1GCPhaseTimes::note_gc_end() { 113 _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter); 114 for (uint i = 0; i < _active_gc_threads; i++) { 115 double worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i); 116 record_time_secs(GCWorkerTotal, i , worker_time); 117 118 double worker_known_time = 119 _gc_par_phases[ExtRootScan]->get(i) + 120 _gc_par_phases[SATBFiltering]->get(i) + 121 _gc_par_phases[UpdateRS]->get(i) + 122 _gc_par_phases[ScanRS]->get(i) + 123 _gc_par_phases[CodeRoots]->get(i) + 124 _gc_par_phases[ObjCopy]->get(i) + 125 _gc_par_phases[Termination]->get(i); 126 127 record_time_secs(Other, i, worker_time - worker_known_time); 128 } 129 130 for (int i = 0; i < GCParPhasesSentinel; i++) { 131 if (_gc_par_phases[i] != NULL) { 132 _gc_par_phases[i]->verify(_active_gc_threads); 133 } 134 } 135 } 136 137 // record the time a phase took in seconds 138 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) { 139 _gc_par_phases[phase]->set(worker_i, secs); 140 } 141 142 // add a number of seconds to a phase 143 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) { 144 _gc_par_phases[phase]->add(worker_i, secs); 145 } 146 147 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count) { 148 _gc_par_phases[phase]->set_thread_work_item(worker_i, count); 149 } 150 151 // return the average time for a phase in milliseconds 152 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) { 153 return _gc_par_phases[phase]->average(_active_gc_threads) * 1000.0; 154 } 155 156 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase) { 157 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count"); 158 return _gc_par_phases[phase]->thread_work_items()->sum(_active_gc_threads); 159 } 160 161 template <class T> 162 void G1GCPhaseTimes::details(T* phase, const char* indent) { 163 LogHandle(gc, phases, task) log; 164 if (log.is_level(LogLevel::Trace)) { 165 outputStream* trace_out = log.trace_stream(); 166 trace_out->print("%s", indent); 167 phase->print_details_on(trace_out, _active_gc_threads); 168 } 169 } 170 171 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) { 172 out->print("%s", Indents[indent]); 173 phase->print_summary_on(out, _active_gc_threads, print_sum); 174 details(phase, Indents[indent]); 175 176 WorkerDataArray<size_t>* work_items = phase->thread_work_items(); 177 if (work_items != NULL) { 178 out->print("%s", Indents[indent + 1]); 179 work_items->print_summary_on(out, _active_gc_threads, true); 180 details(work_items, Indents[indent + 1]); 181 } 182 } 183 184 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) { 185 LogHandle(gc, phases) log; 186 if (log.is_level(LogLevel::Debug)) { 187 ResourceMark rm; 188 log_phase(phase, 2, log.debug_stream(), true); 189 } 190 } 191 192 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) { 193 LogHandle(gc, phases) log; 194 if (log.is_level(LogLevel::Trace)) { 195 ResourceMark rm; 196 log_phase(phase, 3, log.trace_stream(), print_sum); 197 } 198 } 199 | 77 _gc_par_phases[UpdateRS]->link_thread_work_items(_update_rs_processed_buffers); 78 79 _termination_attempts = new WorkerDataArray<size_t>(max_gc_threads, "Termination Attempts:"); 80 _gc_par_phases[Termination]->link_thread_work_items(_termination_attempts); 81 82 if (UseStringDeduplication) { 83 _gc_par_phases[StringDedupQueueFixup] = new WorkerDataArray<double>(max_gc_threads, "Queue Fixup (ms):"); 84 _gc_par_phases[StringDedupTableFixup] = new WorkerDataArray<double>(max_gc_threads, "Table Fixup (ms):"); 85 } else { 86 _gc_par_phases[StringDedupQueueFixup] = NULL; 87 _gc_par_phases[StringDedupTableFixup] = NULL; 88 } 89 90 _gc_par_phases[RedirtyCards] = new WorkerDataArray<double>(max_gc_threads, "Parallel Redirty (ms):"); 91 _redirtied_cards = new WorkerDataArray<size_t>(max_gc_threads, "Redirtied Cards:"); 92 _gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards); 93 94 _gc_par_phases[PreserveCMReferents] = new WorkerDataArray<double>(max_gc_threads, "Parallel Preserve CM Refs (ms):"); 95 } 96 97 void G1GCPhaseTimes::note_gc_start() { 98 _gc_start_counter = os::elapsed_counter(); 99 _cur_expand_heap_time_ms = 0.0; 100 _external_accounted_time_ms = 0.0; 101 102 for (int i = 0; i < GCParPhasesSentinel; i++) { 103 if (_gc_par_phases[i] != NULL) { 104 _gc_par_phases[i]->reset(); 105 } 106 } 107 } 108 109 #define ASSERT_PHASE_UNINITILAIZED(phase) \ 110 assert(_gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started"); 111 112 #define ADD_WORKER_KNOWN_TIME(phase) \ 113 do { \ 114 double value = _gc_par_phases[phase]->get(i); \ 115 if (value != uninitialized) { \ 116 worker_known_time += value; \ 117 } \ 118 } while(false) 119 120 void G1GCPhaseTimes::note_gc_end() { 121 _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter); 122 123 double uninitialized = _gc_par_phases[GCWorkerStart]->uninitialized(); 124 125 for (uint i = 0; i < _max_gc_threads; i++) { 126 double worker_start = _gc_par_phases[GCWorkerStart]->get(i); 127 if (worker_start == uninitialized) { 128 // Make sure all slots are uninitialized since this thread did not seem to have been started 129 ASSERT_PHASE_UNINITILAIZED(GCWorkerEnd); 130 ASSERT_PHASE_UNINITILAIZED(ExtRootScan); 131 ASSERT_PHASE_UNINITILAIZED(SATBFiltering); 132 ASSERT_PHASE_UNINITILAIZED(UpdateRS); 133 ASSERT_PHASE_UNINITILAIZED(ScanRS); 134 ASSERT_PHASE_UNINITILAIZED(CodeRoots); 135 ASSERT_PHASE_UNINITILAIZED(ObjCopy); 136 ASSERT_PHASE_UNINITILAIZED(Termination); 137 } else { 138 assert(_gc_par_phases[GCWorkerEnd]->get(i) != _gc_par_phases[GCWorkerEnd]->uninitialized(), "Worker started but not ended."); 139 double worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i); 140 record_time_secs(GCWorkerTotal, i , worker_time); 141 142 double worker_known_time = 0.0; 143 ADD_WORKER_KNOWN_TIME(ExtRootScan); 144 ADD_WORKER_KNOWN_TIME(SATBFiltering); 145 ADD_WORKER_KNOWN_TIME(UpdateRS); 146 ADD_WORKER_KNOWN_TIME(ScanRS); 147 ADD_WORKER_KNOWN_TIME(CodeRoots); 148 ADD_WORKER_KNOWN_TIME(ObjCopy); 149 ADD_WORKER_KNOWN_TIME(Termination); 150 151 record_time_secs(Other, i, worker_time - worker_known_time); 152 } 153 } 154 } 155 156 #undef ADD_WORKER_KNOWN_TIME 157 #undef ASSERT_PHASE_UNINITILAIZED 158 159 // record the time a phase took in seconds 160 void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) { 161 _gc_par_phases[phase]->set(worker_i, secs); 162 } 163 164 // add a number of seconds to a phase 165 void G1GCPhaseTimes::add_time_secs(GCParPhases phase, uint worker_i, double secs) { 166 _gc_par_phases[phase]->add(worker_i, secs); 167 } 168 169 void G1GCPhaseTimes::record_thread_work_item(GCParPhases phase, uint worker_i, size_t count) { 170 _gc_par_phases[phase]->set_thread_work_item(worker_i, count); 171 } 172 173 // return the average time for a phase in milliseconds 174 double G1GCPhaseTimes::average_time_ms(GCParPhases phase) { 175 return _gc_par_phases[phase]->average() * 1000.0; 176 } 177 178 size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase) { 179 assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count"); 180 return _gc_par_phases[phase]->thread_work_items()->sum(); 181 } 182 183 template <class T> 184 void G1GCPhaseTimes::details(T* phase, const char* indent) { 185 LogHandle(gc, phases, task) log; 186 if (log.is_level(LogLevel::Trace)) { 187 outputStream* trace_out = log.trace_stream(); 188 trace_out->print("%s", indent); 189 phase->print_details_on(trace_out); 190 } 191 } 192 193 void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) { 194 out->print("%s", Indents[indent]); 195 phase->print_summary_on(out, print_sum); 196 details(phase, Indents[indent]); 197 198 WorkerDataArray<size_t>* work_items = phase->thread_work_items(); 199 if (work_items != NULL) { 200 out->print("%s", Indents[indent + 1]); 201 work_items->print_summary_on(out, true); 202 details(work_items, Indents[indent + 1]); 203 } 204 } 205 206 void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) { 207 LogHandle(gc, phases) log; 208 if (log.is_level(LogLevel::Debug)) { 209 ResourceMark rm; 210 log_phase(phase, 2, log.debug_stream(), true); 211 } 212 } 213 214 void G1GCPhaseTimes::trace_phase(WorkerDataArray<double>* phase, bool print_sum) { 215 LogHandle(gc, phases) log; 216 if (log.is_level(LogLevel::Trace)) { 217 ResourceMark rm; 218 log_phase(phase, 3, log.trace_stream(), print_sum); 219 } 220 } 221 |