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

Add gc IDs in the log of gc verification

    XMLWordPrintable

    Details

    • Type: Enhancement
    • Status: Resolved
    • Priority: P4
    • Resolution: Fixed
    • Affects Version/s: 13
    • Fix Version/s: 13
    • Component/s: hotspot
    • Labels:
      None
    • Subcomponent:
      gc
    • Resolved In Build:
      b21
    • CPU:
      generic
    • OS:
      generic

      Description

      I was confused by the log of gc verification with the following JVM args
      --------------------------------------------------------------
        -Xlog:gc \
        -Xlog:verify* \
        -XX:+UnlockDiagnosticVMOptions \
        -XX:+VerifyBeforeGC \
        -XX:+VerifyDuringGC \
        -XX:+VerifyAfterGC \
      --------------------------------------------------------------

      It is really hard to identify the gc ID for each verification.
      --------------------------------------------------------------
      [10.386s][info][gc ] GC(41) Concurrent Cycle
      [10.458s][info][gc,verify,start] Verifying Before GC
      [10.606s][info][gc,verify ] Verifying Before GC 147.827ms
      [10.609s][info][gc,verify,start] Verifying After GC
      [10.711s][info][gc,verify ] Verifying After GC 102.527ms
      [10.711s][info][gc ] GC(42) Pause Young (Normal) (G1 Evacuation Pause) 432M->271M(542M) 252.781ms
      [10.777s][info][gc,verify,start] Verifying During GC (Remark before)
      [10.929s][info][gc,verify ] Verifying During GC (Remark before) 151.954ms
      [10.930s][info][gc,verify,start] Verifying During GC (Remark after)
      [11.015s][info][gc,verify ] Verifying During GC (Remark after) 84.766ms
      [11.015s][info][gc ] GC(41) Pause Remark 430M->347M(584M) 237.802ms
      [11.017s][info][gc,verify,start] Verifying Before GC
      [11.116s][info][gc,verify ] Verifying Before GC 98.401ms
      [11.120s][info][gc,verify,start] Verifying After GC
      [11.178s][info][gc,verify ] Verifying After GC 58.365ms
      [11.178s][info][gc ] GC(43) Pause Young (Normal) (G1 Evacuation Pause) 357M->193M(584M) 160.722ms
      [11.238s][info][gc,verify,start] Verifying During GC (Cleanup before)
      [11.332s][info][gc,verify ] Verifying During GC (Cleanup before) 93.869ms
      [11.332s][info][gc,verify,start] Verifying During GC (Cleanup after)
      [11.444s][info][gc,verify ] Verifying During GC (Cleanup after) 111.939ms
      [11.445s][info][gc ] GC(41) Pause Cleanup 371M->371M(584M) 206.019ms
      [11.447s][info][gc ] GC(41) Concurrent Cycle 1060.838ms
      --------------------------------------------------------------

      So it would be better to dump the verification log with gc IDs like
      --------------------------------------------------------------
      [7.203s][info][gc ] GC(28) Concurrent Cycle
      [7.273s][info][gc,verify,start] GC(29) Verifying Before GC
      [7.408s][info][gc,verify ] GC(29) Verifying Before GC 134.369ms
      [7.409s][info][gc,verify,start] GC(29) Verifying After GC
      [7.508s][info][gc,verify ] GC(29) Verifying After GC 98.265ms
      [7.508s][info][gc ] GC(29) Pause Young (Normal) (G1 Evacuation Pause) 391M->237M(498M) 234.234ms
      [7.530s][info][gc,verify,start] GC(28) Verifying During GC (Remark before)
      [7.635s][info][gc,verify ] GC(28) Verifying During GC (Remark before) 105.395ms
      [7.636s][info][gc,verify,start] GC(28) Verifying During GC (Remark after)
      [7.700s][info][gc,verify ] GC(28) Verifying During GC (Remark after) 64.159ms
      [7.700s][info][gc ] GC(28) Pause Remark 292M->246M(498M) 170.377ms
      [7.732s][info][gc,verify,start] GC(30) Verifying Before GC
      [7.829s][info][gc,verify ] GC(30) Verifying Before GC 97.255ms
      [7.830s][info][gc,verify,start] GC(30) Verifying After GC
      [7.888s][info][gc,verify ] GC(30) Verifying After GC 58.127ms
      [7.888s][info][gc ] GC(30) Pause Young (Normal) (G1 Evacuation Pause) 350M->191M(498M) 156.586ms
      [7.902s][info][gc,verify,start] GC(28) Verifying During GC (Cleanup before)
      [7.973s][info][gc,verify ] GC(28) Verifying During GC (Cleanup before) 71.208ms
      [7.973s][info][gc,verify,start] GC(28) Verifying During GC (Cleanup after)
      [8.071s][info][gc,verify ] GC(28) Verifying During GC (Cleanup after) 98.270ms
      [8.072s][info][gc ] GC(28) Pause Cleanup 232M->232M(498M) 169.721ms
      [8.074s][info][gc ] GC(28) Concurrent Cycle 871.278ms
      [8.108s][info][gc,verify,start] GC(31) Verifying Before GC
      [8.230s][info][gc,verify ] GC(31) Verifying Before GC 122.625ms
      [8.232s][info][gc,verify,start] GC(31) Verifying After GC
      [8.324s][info][gc,verify ] GC(31) Verifying After GC 91.601ms
      [8.324s][info][gc ] GC(31) Pause Young (Prepare Mixed) (G1 Evacuation Pause) 371M->191M(498M) 216.051ms
      --------------------------------------------------------------

      It can be fixed by
      --------------------------------------------------------------
      diff -r 6a60270af76b src/hotspot/share/logging/logPrefix.hpp
      --- a/src/hotspot/share/logging/logPrefix.hpp Mon May 13 20:45:03 2019 -0700
      +++ b/src/hotspot/share/logging/logPrefix.hpp Tue May 14 13:38:11 2019 +0800
      @@ -71,6 +71,8 @@
         LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, phases, ref)) \
         LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, phases, start)) \
         LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, phases, task)) \
      + LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, phases, verify)) \
      + LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, phases, verify, start)) \
         LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, plab)) \
         LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, promotion)) \
         LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, region)) \
      @@ -88,6 +90,8 @@
         LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, task, time)) \
         DEBUG_ONLY(LOG_PREFIX(Test_log_prefix_prefixer, LOG_TAGS(logging, test))) \
         LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, tlab)) \
      + LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, verify)) \
      + LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, verify, start)) \
         LOG_PREFIX(GCId::print_prefix, LOG_TAGS(gc, workgang))


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

        Attachments

          Activity

            People

            Assignee:
            jiefu Jie Fu
            Reporter:
            jiefu Jie Fu
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: