< prev index next >
src/share/vm/gc/g1/g1GCPhaseTimes.cpp
Print this page
*** 92,141 ****
_gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
_gc_par_phases[PreserveCMReferents] = new WorkerDataArray<double>(max_gc_threads, "Parallel Preserve CM Refs (ms):");
}
! void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) {
! assert(active_gc_threads > 0, "The number of threads must be > 0");
! assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max number of threads");
_gc_start_counter = os::elapsed_counter();
- _active_gc_threads = active_gc_threads;
_cur_expand_heap_time_ms = 0.0;
_external_accounted_time_ms = 0.0;
for (int i = 0; i < GCParPhasesSentinel; i++) {
if (_gc_par_phases[i] != NULL) {
_gc_par_phases[i]->reset();
}
}
}
void G1GCPhaseTimes::note_gc_end() {
_gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
! for (uint i = 0; i < _active_gc_threads; i++) {
double worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
record_time_secs(GCWorkerTotal, i , worker_time);
! double worker_known_time =
! _gc_par_phases[ExtRootScan]->get(i) +
! _gc_par_phases[SATBFiltering]->get(i) +
! _gc_par_phases[UpdateRS]->get(i) +
! _gc_par_phases[ScanRS]->get(i) +
! _gc_par_phases[CodeRoots]->get(i) +
! _gc_par_phases[ObjCopy]->get(i) +
! _gc_par_phases[Termination]->get(i);
record_time_secs(Other, i, worker_time - worker_known_time);
}
-
- for (int i = 0; i < GCParPhasesSentinel; i++) {
- if (_gc_par_phases[i] != NULL) {
- _gc_par_phases[i]->verify(_active_gc_threads);
- }
}
}
// record the time a phase took in seconds
void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
_gc_par_phases[phase]->set(worker_i, secs);
}
--- 92,163 ----
_gc_par_phases[RedirtyCards]->link_thread_work_items(_redirtied_cards);
_gc_par_phases[PreserveCMReferents] = new WorkerDataArray<double>(max_gc_threads, "Parallel Preserve CM Refs (ms):");
}
! void G1GCPhaseTimes::note_gc_start() {
_gc_start_counter = os::elapsed_counter();
_cur_expand_heap_time_ms = 0.0;
_external_accounted_time_ms = 0.0;
for (int i = 0; i < GCParPhasesSentinel; i++) {
if (_gc_par_phases[i] != NULL) {
_gc_par_phases[i]->reset();
}
}
}
+ #define ASSERT_PHASE_UNINITILAIZED(phase) \
+ assert(_gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started");
+
+ #define ADD_WORKER_KNOWN_TIME(phase) \
+ do { \
+ double value = _gc_par_phases[phase]->get(i); \
+ if (value != uninitialized) { \
+ worker_known_time += value; \
+ } \
+ } while(false)
+
void G1GCPhaseTimes::note_gc_end() {
_gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
!
! double uninitialized = _gc_par_phases[GCWorkerStart]->uninitialized();
!
! for (uint i = 0; i < _max_gc_threads; i++) {
! double worker_start = _gc_par_phases[GCWorkerStart]->get(i);
! if (worker_start == uninitialized) {
! // Make sure all slots are uninitialized since this thread did not seem to have been started
! ASSERT_PHASE_UNINITILAIZED(GCWorkerEnd);
! ASSERT_PHASE_UNINITILAIZED(ExtRootScan);
! ASSERT_PHASE_UNINITILAIZED(SATBFiltering);
! ASSERT_PHASE_UNINITILAIZED(UpdateRS);
! ASSERT_PHASE_UNINITILAIZED(ScanRS);
! ASSERT_PHASE_UNINITILAIZED(CodeRoots);
! ASSERT_PHASE_UNINITILAIZED(ObjCopy);
! ASSERT_PHASE_UNINITILAIZED(Termination);
! } else {
! assert(_gc_par_phases[GCWorkerEnd]->get(i) != _gc_par_phases[GCWorkerEnd]->uninitialized(), "Worker started but not ended.");
double worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
record_time_secs(GCWorkerTotal, i , worker_time);
! double worker_known_time = 0.0;
! ADD_WORKER_KNOWN_TIME(ExtRootScan);
! ADD_WORKER_KNOWN_TIME(SATBFiltering);
! ADD_WORKER_KNOWN_TIME(UpdateRS);
! ADD_WORKER_KNOWN_TIME(ScanRS);
! ADD_WORKER_KNOWN_TIME(CodeRoots);
! ADD_WORKER_KNOWN_TIME(ObjCopy);
! ADD_WORKER_KNOWN_TIME(Termination);
record_time_secs(Other, i, worker_time - worker_known_time);
}
}
}
+ #undef ADD_WORKER_KNOWN_TIME
+ #undef ASSERT_PHASE_UNINITILAIZED
+
// record the time a phase took in seconds
void G1GCPhaseTimes::record_time_secs(GCParPhases phase, uint worker_i, double secs) {
_gc_par_phases[phase]->set(worker_i, secs);
}
*** 148,184 ****
_gc_par_phases[phase]->set_thread_work_item(worker_i, count);
}
// return the average time for a phase in milliseconds
double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
! return _gc_par_phases[phase]->average(_active_gc_threads) * 1000.0;
}
size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase) {
assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
! return _gc_par_phases[phase]->thread_work_items()->sum(_active_gc_threads);
}
template <class T>
void G1GCPhaseTimes::details(T* phase, const char* indent) {
LogHandle(gc, phases, task) log;
if (log.is_level(LogLevel::Trace)) {
outputStream* trace_out = log.trace_stream();
trace_out->print("%s", indent);
! phase->print_details_on(trace_out, _active_gc_threads);
}
}
void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) {
out->print("%s", Indents[indent]);
! phase->print_summary_on(out, _active_gc_threads, print_sum);
details(phase, Indents[indent]);
WorkerDataArray<size_t>* work_items = phase->thread_work_items();
if (work_items != NULL) {
out->print("%s", Indents[indent + 1]);
! work_items->print_summary_on(out, _active_gc_threads, true);
details(work_items, Indents[indent + 1]);
}
}
void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) {
--- 170,206 ----
_gc_par_phases[phase]->set_thread_work_item(worker_i, count);
}
// return the average time for a phase in milliseconds
double G1GCPhaseTimes::average_time_ms(GCParPhases phase) {
! return _gc_par_phases[phase]->average() * 1000.0;
}
size_t G1GCPhaseTimes::sum_thread_work_items(GCParPhases phase) {
assert(_gc_par_phases[phase]->thread_work_items() != NULL, "No sub count");
! return _gc_par_phases[phase]->thread_work_items()->sum();
}
template <class T>
void G1GCPhaseTimes::details(T* phase, const char* indent) {
LogHandle(gc, phases, task) log;
if (log.is_level(LogLevel::Trace)) {
outputStream* trace_out = log.trace_stream();
trace_out->print("%s", indent);
! phase->print_details_on(trace_out);
}
}
void G1GCPhaseTimes::log_phase(WorkerDataArray<double>* phase, uint indent, outputStream* out, bool print_sum) {
out->print("%s", Indents[indent]);
! phase->print_summary_on(out, print_sum);
details(phase, Indents[indent]);
WorkerDataArray<size_t>* work_items = phase->thread_work_items();
if (work_items != NULL) {
out->print("%s", Indents[indent + 1]);
! work_items->print_summary_on(out, true);
details(work_items, Indents[indent + 1]);
}
}
void G1GCPhaseTimes::debug_phase(WorkerDataArray<double>* phase) {
< prev index next >