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

G1: Multiple GC start times leads to confusion

XMLWordPrintable

    • Icon: Enhancement Enhancement
    • Resolution: Unresolved
    • Icon: P4 P4
    • tbd
    • 15
    • hotspot
    • gc

      We have two different notions of the "start time" for a GC, both in G1GCPhaseTimes.

      (1) _gc_start_counter is the os::elapsedCounter() value obtained and recorded at the beginning of the pause. It is only used to compute the pause duration at the end, recorded in _gc_pause_time_ms. Neither of those have public accessors. The pause time is only used in the calculation of the "Other" time when logging the phase time information. This seems okay.

      (2) _cur_collection_start_sec is the os::elapsedTime() value obtained after gc_prologue and (optional) before-GC verification. It is commented as deliberately eliding the verification, though there's no mention of the elision of the prologue. It also elides waiting for root region scanning (could be large, though ascribing this time to the collection seems questionable and could mess up ergonomics), and various other probably mostly quick initializations (though update_active_workers might need to launch new threads).

      We have at least the following uses of cur_collection_start_sec:

      (a) In evacuate_optional_collection_set it is used as gc_start_time to calculate how much time has been used, to decide how many additional optional regions to collect. Ignoring verification time seems reasonable here. Ignoring the time for the other initializations seems questionable.

      (b) In record_collection_pause_end it is used to to calculate the time spent "in the application", to update the estimated allocation rate and to update IHOP. Using a time after those various setups as the end of the in-application period seems wrong. The _gc_start_counter value would be much better for this purpose.

      (c) In record_concurrent_refinement_stats it is also used to calculate the time spent "in the application", to update the estimated mutator dirty card logging rate. Again here, the _gc_start_counter value would be much better for this purpose.

      (d) also skews MMU calculation, not only by using a wrong allocation rate which determines the length between scheduled GCs, but also the pauses it uses for calculations are too small.

      (e) calculation of the pause time ratio which his based wrong which controls heap expansion.

      Other uses of cur_collection_start_sec may exist by the time this is dealt with and will need to be examined too.

            Unassigned Unassigned
            kbarrett Kim Barrett
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Created:
              Updated: