Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8154955

Negative Other Time in gc logs due to 'Wait for Root Region Scan' not included

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: P4 P4
    • 9
    • 9
    • hotspot
    • gc
    • b120

      In the gc log, sometimes with the following entry:
      [346.310s][info ][gc,phases ] GC(743) Other: -24.8ms
      [346.310s][debug][gc,phases ] GC(743) Choose CSet: 0.1ms
      [346.310s][debug][gc,phases ] GC(743) Preserve CM Refs: 0.0ms
      [346.310s][debug][gc,phases ] GC(743) Reference Processing: 0.0ms
      [346.310s][debug][gc,phases ] GC(743) Reference Enqueuing: 0.0ms
      [346.310s][debug][gc,phases ] GC(743) Redirty Cards: 0.4ms
      [346.310s][debug][gc,phases ] GC(743) Humongous Register: 0.4ms
      [346.310s][debug][gc,phases ] GC(743) Humongous Reclaim: 0.0ms

      Earlier in the log

      [345.709s][info ][gc ] GC(742) Concurrent Mark (345.709s)
      [345.709s][info ][gc,task ] GC(742) GC Workers: 1
      [345.709s][info ][gc,start ] GC(743) Pause Young (G1 Evacuation Pause) (345.709s)
      [345.709s][info ][gc,task ] GC(743) GC Workers: 4
      [345.709s][trace][gc,ergo,cset] GC(743) Start choosing CSet. pending cards: 19463 predicted base time: 28.34ms remaining time: 171.66ms target pause time: 200.00ms
      [345.709s][trace][gc,ergo,cset] GC(743) Add young regions to CSet. eden: 896 regions, survivors: 128 regions, predicted young region time: 557.11ms, target pause time: 200.00ms
      [345.709s][debug][gc,ergo,cset] GC(743) Finish choosing CSet. old: 0 regions, predicted old region time: 0.00ms, time remaining: 0.00
      [346.310s][info ][gc,phases ] GC(743) Root Region Scan Waiting: 26.5ms

      The last line for the pause does not include the Root Region Scan Waiting time.

      This workload generates a lot of dirty cards and rset changes, so marking could be long.

      The problem is in
      void G1GCPhaseTimes::print() {
      ...
        if (_root_region_scan_wait_time_ms > 0.0) {
          info_line_and_account("Root Region Scan Waiting", _root_region_scan_wait_time_ms);
        }
      ...

       info_line("Other", _gc_pause_time_ms - accounted_time_ms);
      ...
      }

      Root Region Scan Waiting is included in the accounted_time_ms, but _gc_pause_time_ms is recorded after Root Region Scan Waiting is done in G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
      ...
      wait_for_root_region_scanning();
      ...
      g1_policy()->note_gc_start(active_workers);
      ...}

      we should move g1_policy()->note_gc_start to before wait_for_root_region_scanning

            yuzhang Jenny Zhang (Inactive)
            yuzhang Jenny Zhang (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: