-
Enhancement
-
Resolution: Unresolved
-
P4
-
None
After JVM shutdown has begun, G1, Serial and Parallel may continue processing queued VM_GC_Collect_Operations.
We should investigate whether these operations can be skipped once shutdown is in progress. Allowing them to proceed can be misleading, as the JVM prints a final heap summary during shutdown, yet continues performing GC activity afterward, which may confuse users reviewing the logs.
Sample log:
[1.360s][info ][cpu ] === CPU time Statistics =============================================================
[1.360s][info ][cpu ] CPUs
[1.360s][info ][cpu ] s % utilized
[1.360s][info ][cpu ] Process
[1.360s][info ][cpu ] Total 2.6865 100.00 2.0
[1.360s][info ][cpu ] Garbage Collection 2.1653 80.60 1.6
[1.360s][info ][cpu ] GC Threads 2.0561 76.54 1.5
[1.360s][info ][cpu ] VM Thread 0.1091 4.06 0.1
[1.360s][info ][cpu ] =====================================================================================
[1.414s][info ][gc,exit ] Heap
[1.414s][info ][gc,exit ] garbage-first heap total reserved 32768K, committed 32768K, used 26280K [0x00000000fe000000, 0x0000000100000000)
[1.414s][info ][gc,exit ] region size 1024K, 6 young (6144K), 1 survivors (1024K)
[1.414s][info ][gc,exit ] Metaspace used 327K, committed 512K, reserved 1114112K
[1.414s][info ][gc,exit ] class space used 17K, committed 128K, reserved 1048576K
[1.420s][trace][gc,alloc] Thread-18: Successfully scheduled collection returning 0x00000000ff200000
[1.427s][trace][gc,alloc] Thread-25: Successfully scheduled collection returning 0x00000000ff100000
[1.448s][trace][gc,alloc] Thread-74: Successfully scheduled collection returning 0x00000000ff400000
[1.448s][trace][gc,alloc] Thread-48: Unsuccessfully scheduled collection allocating 50002 words
[1.454s][trace][gc,alloc] Thread-62: Successfully scheduled collection returning 0x00000000ff400000
[1.461s][trace][gc,alloc] Thread-49: Successfully scheduled collection returning 0x00000000ff300000
[1.468s][trace][gc,alloc] Thread-79: Successfully scheduled collection returning 0x00000000ff400000
[1.474s][trace][gc,alloc] Thread-36: Successfully scheduled collection returning 0x00000000ff300000
[1.494s][trace][gc,alloc] Thread-70: Successfully scheduled collection returning 0x00000000ff400000
[1.500s][trace][gc,alloc] Thread-91: Successfully scheduled collection returning 0x00000000ff700000
We should investigate whether these operations can be skipped once shutdown is in progress. Allowing them to proceed can be misleading, as the JVM prints a final heap summary during shutdown, yet continues performing GC activity afterward, which may confuse users reviewing the logs.
Sample log:
[1.360s][info ][cpu ] === CPU time Statistics =============================================================
[1.360s][info ][cpu ] CPUs
[1.360s][info ][cpu ] s % utilized
[1.360s][info ][cpu ] Process
[1.360s][info ][cpu ] Total 2.6865 100.00 2.0
[1.360s][info ][cpu ] Garbage Collection 2.1653 80.60 1.6
[1.360s][info ][cpu ] GC Threads 2.0561 76.54 1.5
[1.360s][info ][cpu ] VM Thread 0.1091 4.06 0.1
[1.360s][info ][cpu ] =====================================================================================
[1.414s][info ][gc,exit ] Heap
[1.414s][info ][gc,exit ] garbage-first heap total reserved 32768K, committed 32768K, used 26280K [0x00000000fe000000, 0x0000000100000000)
[1.414s][info ][gc,exit ] region size 1024K, 6 young (6144K), 1 survivors (1024K)
[1.414s][info ][gc,exit ] Metaspace used 327K, committed 512K, reserved 1114112K
[1.414s][info ][gc,exit ] class space used 17K, committed 128K, reserved 1048576K
[1.420s][trace][gc,alloc] Thread-18: Successfully scheduled collection returning 0x00000000ff200000
[1.427s][trace][gc,alloc] Thread-25: Successfully scheduled collection returning 0x00000000ff100000
[1.448s][trace][gc,alloc] Thread-74: Successfully scheduled collection returning 0x00000000ff400000
[1.448s][trace][gc,alloc] Thread-48: Unsuccessfully scheduled collection allocating 50002 words
[1.454s][trace][gc,alloc] Thread-62: Successfully scheduled collection returning 0x00000000ff400000
[1.461s][trace][gc,alloc] Thread-49: Successfully scheduled collection returning 0x00000000ff300000
[1.468s][trace][gc,alloc] Thread-79: Successfully scheduled collection returning 0x00000000ff400000
[1.474s][trace][gc,alloc] Thread-36: Successfully scheduled collection returning 0x00000000ff300000
[1.494s][trace][gc,alloc] Thread-70: Successfully scheduled collection returning 0x00000000ff400000
[1.500s][trace][gc,alloc] Thread-91: Successfully scheduled collection returning 0x00000000ff700000
- relates to
-
JDK-8366328 G1: Crash on reading os::thread_cpu_time
-
- Open
-