RFR: 8346568: G1: Other time can be negative

[Thomas Schatzl]

On Fri, 4 Apr 2025 18:00:21 GMT, Sangheon Kim <sangheki at openjdk.org> wrote:

> Other time described in this bug is displayed at G1GCPhaseTimes::print_other(total_measured_time - sum_of_sub_phases). And the value can be negative for 3 reasons.
> 1. Different scope of measurement
>     - 3 variables is out of scope from total_measured_time. Those used for wait-root-region-scan, verify-before/after. 
>        (_root_region_scan_wait_time_ms, _cur_verify_before_time_ms and _cur_verify_after_time_ms)
>     - Changed not to be included in sum_of_sub_phases.
>     - One may want to include them in total_measured_time but I think it is better to be addressed in a separate ticket. 
> 2. Duplicated measurement
>     - Initial and optional evacuation time include nmethod-cleanup-time, so separated them as we are already measuring them. As there is no public getter, just added cleanup time when those evacuation time are used internally.
> 3. Pre Concurrent task execution time
>     - Sometimes the difference between the existing average time and pre-concurrent work is 2 digit milliseconds. Changed to measure exact time rather than accumulating the average value to sum_of_sub_phases and keep displaying concurrent tasks' average execution time.
> 
> Testing: tier 1 ~ 5

Changes requested by tschatzl (Reviewer).

src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp line 411:

> 409: 
> 410: double G1GCPhaseTimes::print_pre_evacuate_collection_set() const {
> 411:   const double pre_concurrent_start_ms = average_time_ms(ResetMarkingState) +

Could this assignment be moved down to just before the use?

src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp line 425:

> 423:   // Concurrent tasks of ResetMarkingState and NoteStartOfMark are triggered during
> 424:   // young collection. However, their execution time are not included in _gc_pause_time_ms.
> 425:   if (pre_concurrent_start_ms > 0.0) {

Since `pre_concurrent_start_ms` is now actually gathered, maybe print an extra line for it, with the `ResetMarkingState` and `NoteStartOfMark` log lines indented?

I.e. something like:


  if (_cur_prepare_concurrent_task_time_ms > 0.0) {
    debug_time("Prepare Concurrent Start", _cur_prepare_concurrent_task_time_ms);
    debug_phase(_gc_par_phases[ResetMarkingState], 1);
    debug_phase(_gc_par_phases[NoteStartOfMark], 1);
  }

?

Then we can also drop the calculation of the local `pre_concurrent_start_ms`.

-------------

PR Review: https://git.openjdk.org/jdk/pull/24454#pullrequestreview-2778191624
PR Review Comment: https://git.openjdk.org/jdk/pull/24454#discussion_r2050415309
PR Review Comment: https://git.openjdk.org/jdk/pull/24454#discussion_r2050420949