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

*** 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,162 ----
    _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_UNINITILIAZED(phase) \
+     assert(_gc_par_phases[phase]->get(i) == uninitialized, "Phase " #phase " reported for thread that was not started");
+ 
+ double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {
+   double value = _gc_par_phases[phase]->get(worker);
+   if (value != WorkerDataArray<double>::uninitialized()) {
+     return value;
+   }
+   return 0.0;
+ }
+ 
  void G1GCPhaseTimes::note_gc_end() {
    _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
  
!   double uninitialized = WorkerDataArray<double>::uninitialized();
  
!   for (uint i = 0; i < _max_gc_threads; i++) {
!     double worker_start = _gc_par_phases[GCWorkerStart]->get(i);
!     if (worker_start != uninitialized) {
!       assert(_gc_par_phases[GCWorkerEnd]->get(i) != uninitialized, "Worker started but not ended.");
!       double total_worker_time = _gc_par_phases[GCWorkerEnd]->get(i) - _gc_par_phases[GCWorkerStart]->get(i);
!       record_time_secs(GCWorkerTotal, i , total_worker_time);
  
!       double worker_known_time =
!           worker_time(ExtRootScan, i)
!           + worker_time(SATBFiltering, i)
!           + worker_time(UpdateRS, i)
!           + worker_time(ScanRS, i)
!           + worker_time(CodeRoots, i)
!           + worker_time(ObjCopy, i)
!           + worker_time(Termination, i);
! 
!       record_time_secs(Other, i, total_worker_time - worker_known_time);
!     } else {
!       // Make sure all slots are uninitialized since this thread did not seem to have been started
!       ASSERT_PHASE_UNINITILIAZED(GCWorkerEnd);
!       ASSERT_PHASE_UNINITILIAZED(ExtRootScan);
!       ASSERT_PHASE_UNINITILIAZED(SATBFiltering);
!       ASSERT_PHASE_UNINITILIAZED(UpdateRS);
!       ASSERT_PHASE_UNINITILIAZED(ScanRS);
!       ASSERT_PHASE_UNINITILIAZED(CodeRoots);
!       ASSERT_PHASE_UNINITILIAZED(ObjCopy);
!       ASSERT_PHASE_UNINITILIAZED(Termination);
      }
    }
  }
  
+ #undef ASSERT_PHASE_UNINITILIAZED
+ 
  // 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) {
--- 169,205 ----
    _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) {