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

More unaccounted other time on large machines

    Details

    • Subcomponent:
      gc

      Description

      On very large applications (e.g. 1T heap) there is still a significant amount of unaccounted time in the "Other" category.

      Investigate, change the title of this CR and improve the logging for this new phase(s). Also file follow-up issues to remedy these:

      [2968.740s][info ][gc,phases ] GC(53) Evacuate Collection Set: 175.5ms
      [2968.740s][debug][gc,phases ] GC(53) Ext Root Scanning (ms): Min: 15.3, Avg: 22.9, Max: 31.9, Diff: 16.5, Sum: 5488.6, Threads: 240
      [2968.740s][debug][gc,phases ] GC(53) Update RS (ms): Min: 7.6, Avg: 12.6, Max: 19.1, Diff: 11.5, Sum: 3015.7, Threads: 240
      [2968.740s][debug][gc,phases ] GC(53) Processed Buffers: Min: 0, Avg: 10.7, Max: 60, Diff: 60, Sum: 2557, Threads: 240
      [2968.740s][debug][gc,phases ] GC(53) Scan RS (ms): Min: 12.8, Avg: 16.9, Max: 21.0, Diff: 8.2, Sum: 4048.9, Threads: 240
      [2968.740s][debug][gc,phases ] GC(53) Code Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.6, Diff: 0.6, Sum: 16.0, Threads: 240
      [2968.740s][debug][gc,phases ] GC(53) Object Copy (ms): Min: 106.7, Avg: 107.8, Max: 109.4, Diff: 2.7, Sum: 25879.8, Threads: 240
      [2968.740s][debug][gc,phases ] GC(53) Termination (ms): Min: 0.2, Avg: 0.3, Max: 0.4, Diff: 0.2, Sum: 65.0, Threads: 240
      [2968.740s][debug][gc,phases ] GC(53) Termination Attempts: Min: 1, Avg: 1.3, Max: 2, Diff: 1, Sum: 317, Threads: 240
      [2968.740s][debug][gc,phases ] GC(53) GC Worker Other (ms): Min: 0.1, Avg: 1.7, Max: 8.6, Diff: 8.6, Sum: 396.6, Threads: 240
      [2968.740s][debug][gc,phases ] GC(53) GC Worker Total (ms): Min: 155.1, Avg: 162.1, Max: 171.6, Diff: 16.5, Sum: 38910.6, Threads: 240
      [2968.740s][info ][gc,phases ] GC(53) Code Roots: 0.2ms
      [2968.740s][debug][gc,phases ] GC(53) Code Roots Fixup: 0.2ms
      [2968.740s][debug][gc,phases ] GC(53) Code Roots Purge: 0.0ms
      [2968.740s][info ][gc,phases ] GC(53) Clear Card Table: 18.1ms
      [2968.740s][debug][gc,phases ] GC(53) Clear Card Table Serial: 6.6ms
      [2968.740s][debug][gc,phases ] GC(53) Clear Card Table (ms): Min: 0.0, Avg: 5.2, Max: 11.2, Diff: 11.2, Sum: 1244.0, Threads: 240
      [2968.740s][info ][gc,phases ] GC(53) Expand Heap After Collection: 0.0ms
      [2968.740s][info ][gc,phases ] GC(53) Free Collection Set: 54.3ms
      [2968.740s][debug][gc,phases ] GC(53) Free Collection Set Serial: 0.0ms
      [2968.740s][debug][gc,phases ] GC(53) Young Free CSet (ms): Min: 7.6, Avg: 18.6, Max: 23.9, Diff: 16.3, Sum: 1968.4, Threads: 106
      [2968.740s][debug][gc,phases ] GC(53) NonYoung Free CSet (ms): -
      [2968.740s][info ][gc,phases ] GC(53) Merge Per-Thread State: 36.5ms
      [2968.740s][info ][gc,phases ] GC(53) Other: 44.6ms
      [2968.740s][debug][gc,phases ] GC(53) Choose CSet: 0.1ms
      [2968.740s][debug][gc,phases ] GC(53) Preserve CM Refs: 10.6ms
      [2968.740s][debug][gc,phases ] GC(53) Reference Processing: 7.6ms
      [2968.740s][debug][gc,phases ] GC(53) Reference Enqueuing: 4.9ms
      [2968.740s][debug][gc,phases ] GC(53) Redirty Cards: 1.7ms
      [2968.740s][debug][gc,phases ] GC(53) Humongous Register: 1.1ms
      [2968.740s][debug][gc,phases ] GC(53) Humongous Reclaim: 0.0ms

      I.e., formatted a bit better:

      Other: 44.6ms
        Choose CSet 0.1ms
        Preserve CM Refs: 10.6ms
        Reference Processing: 7.6ms
        Reference Enqueuing: 4.9ms
        Redirty Cards: 1.7ms
        Humongous Register: 1.1ms
        Humongous Reclaim: 0.0ms

      Missing: 18.6ms

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                Unassigned
                Reporter:
                tschatzl Thomas Schatzl
              • Votes:
                0 Vote for this issue
                Watchers:
                1 Start watching this issue

                Dates

                • Created:
                  Updated: