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))
--------------------------------------------------------------
--------------------------------------------------------------
-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))
--------------------------------------------------------------