Я видел странное явление с длинными заголовками G C, они yongG C из G1:
и после проверки g c log, я обнаружил, что YG C не занял так много времени, но для запуска G C потребовалось много времени, как показано в журнале ниже:
[2020-02-26T21:05:33.332+0000][debug][gc,heap ] GC(45001) Heap after GC invocations=45002 (full 0): garbage-first heap total 5242880K, used 2079941K [0x00000006c0000000, 0x0000000800000000)
[2020-02-26T21:05:52.656+0000][debug][gc,heap ] GC(45002) Heap before GC invocations=45002 (full 0): garbage-first heap total 5242880K, used 4062405K [0x00000006c0000000, 0x0000000800000000)
[2020-02-26T21:06:00.759+0000][debug][gc,heap ] GC(45002) region size 4096K, 480 young (1966080K), 6 survivors (24576K)
[2020-02-26T21:06:01.664+0000][debug][gc,heap ] GC(45002) Metaspace used 147205K, capacity 150923K, committed 152960K, reserved 1183744K
[2020-02-26T21:06:01.664+0000][debug][gc,heap ] GC(45002) class space used 16073K, capacity 17538K, committed 18048K, reserved 1048576K
[2020-02-26T21:06:01.665+0000][info ][gc,start ] GC(45002) Pause Young (Normal) (G1 Evacuation Pause)
[2020-02-26T21:06:01.665+0000][info ][gc,task ] GC(45002) Using 2 workers of 2 for evacuation
[2020-02-26T21:06:01.665+0000][debug][gc,tlab ] GC(45002) TLAB totals: thrds: 531 refills: 28932 max: 1263 slow allocs: 16284 max 944 waste: 2.2% gc: 20922496B max: 481408B slow: 20006528B max: 773296B fast: 0B max: 0B
[2020-02-26T21:06:01.665+0000][debug][gc,alloc,region ] GC(45002) Mutator Allocation stats, regions: 474, wasted size: 666K ( 0.0%)
[2020-02-26T21:06:01.665+0000][debug][gc,age ] GC(45002) Desired survivor size 167772160 bytes, new threshold 6 (max threshold 6)
[2020-02-26T21:06:01.665+0000][debug][gc,ergo,cset ] GC(45002) Finish choosing CSet. old: 0 regions, predicted old region time: 0.00ms, time remaining: 192.10
[2020-02-26T21:06:01.665+0000][debug][gc,task,stats ] GC(45002) GC Termination Stats
[2020-02-26T21:06:01.665+0000][debug][gc,task,stats ] GC(45002) elapsed --strong roots-- -------termination------- ------waste (KiB)------
[2020-02-26T21:06:01.665+0000][debug][gc,task,stats ] GC(45002) thr ms ms % ms % attempts total alloc undo
[2020-02-26T21:06:01.665+0000][debug][gc,task,stats ] GC(45002) --- --------- --------- ------ --------- ------ -------- ------- ------- -------
[2020-02-26T21:06:01.708+0000][debug][gc,task,stats ] GC(45002) 1 42.69 42.60 99.79 0.00 0.00 1 3 3 0
[2020-02-26T21:06:01.708+0000][debug][gc,task,stats ] GC(45002) 0 42.74 42.60 99.66 0.00 0.00 1 4 4 0
[2020-02-26T21:06:01.708+0000][debug][gc,ergo ] GC(45002) Running G1 Clear Card Table Task using 2 workers for 6 units of work for 647 regions.
[2020-02-26T21:06:01.709+0000][debug][gc,ref ] GC(45002) Skipped phase1 of Reference Processing due to unavailable references
[2020-02-26T21:06:01.709+0000][debug][gc,ergo ] GC(45002) Running G1 Free Collection Set using 2 workers for collection set length 480
[2020-02-26T21:06:01.711+0000][debug][gc,plab ] GC(45002) Young other allocation: region end waste: 0B, regions filled: 13, direct allocated: 0B, failure used: 0B, failure wasted: 0B
[2020-02-26T21:06:01.711+0000][debug][gc,plab ] GC(45002) Young sizing: calculated: 9947896B, actual: 8561312B
[2020-02-26T21:06:01.711+0000][debug][gc,plab ] GC(45002) Old PLAB allocation: allocated: 121296B, wasted: 1656B, unused: 28296B, used: 91344B, undo waste: 0B,
[2020-02-26T21:06:01.711+0000][debug][gc,plab ] GC(45002) Old other allocation: region end waste: 0B, regions filled: 1, direct allocated: 11504B, failure used: 0B, failure wasted: 0B
[2020-02-26T21:06:01.711+0000][debug][gc,plab ] GC(45002) Old sizing: calculated: 18264B, actual: 22360B
[2020-02-26T21:06:01.711+0000][debug][gc,ihop ] GC(45002) Basic information (value update), threshold: 2301711389B (42.87), target occupancy: 5368709120B, current occupancy: 2157256192B, recent allocation size: 46258640B, recent allocation duration: 28333.23ms, recent old gen allocation rate: 1632664.05B/s, recent marking phase length: 21934.23ms
[2020-02-26T21:06:01.711+0000][debug][gc,ihop ] GC(45002) Adaptive IHOP information (value update), threshold: 2301711389B (50.44), internal target occupancy: 4563402752B, occupancy: 2157256192B, additional buffer size: 2013265920B, predicted old gen allocation rate: 11117297.23B/s, predicted marking phase length: 22345.85ms, prediction active: true
[2020-02-26T21:06:01.711+0000][debug][gc,ergo,refine ] GC(45002) Updated Refinement Zones: green: 614, yellow: 1842, red: 3070
[2020-02-26T21:06:01.711+0000][info ][gc,phases ] GC(45002) Pre Evacuate Collection Set: 0.1ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Prepare TLABs: 0.2ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Choose Collection Set: 0.0ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Humongous Register: 0.1ms
[2020-02-26T21:06:01.711+0000][info ][gc,phases ] GC(45002) Evacuate Collection Set: 42.8ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Ext Root Scanning (ms): Min: 2.6, Avg: 4.1, Max: 5.5, Diff: 2.9, Sum: 8.1, Workers: 2
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Update RS (ms): Min: 2.6, Avg: 2.9, Max: 3.2, Diff: 0.6, Sum: 5.8, Workers: 2
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Processed Buffers: Min: 197, Avg: 263.0, Max: 329, Diff: 132, Sum: 526, Workers: 2
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Scanned Cards: Min: 2535, Avg: 2589.0, Max: 2643, Diff: 108, Sum: 5178, Workers: 2
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Skipped Cards: Min: 0, Avg: 2.5, Max: 5, Diff: 5, Sum: 5, Workers: 2
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Scan RS (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.3, Workers: 2
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Scanned Cards: Min: 0, Avg: 21.5, Max: 43, Diff: 43, Sum: 43, Workers: 2
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Claimed Cards: Min: 0, Avg: 21.5, Max: 43, Diff: 43, Sum: 43, Workers: 2
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Skipped Cards: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0, Workers: 2
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 2
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) AOT Root Scanning (ms): skipped
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Object Copy (ms): Min: 33.8, Avg: 35.5, Max: 37.3, Diff: 3.5, Sum: 71.0, Workers: 2
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 2
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 2, Workers: 2
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.2, Diff: 0.0, Sum: 0.3, Workers: 2
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) GC Worker Total (ms): Min: 42.7, Avg: 42.7, Max: 42.8, Diff: 0.0, Sum: 85.5, Workers: 2
[2020-02-26T21:06:01.711+0000][info ][gc,phases ] GC(45002) Post Evacuate Collection Set: 2.4ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Code Roots Fixup: 0.0ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Clear Card Table: 0.6ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Reference Processing: 0.3ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) Reconsider SoftReferences: 0.0ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) SoftRef (ms): skipped
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) Notify Soft/WeakReferences: 0.1ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) SoftRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) WeakRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) FinalRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) Total (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 1
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) Notify and keep alive finalizable: 0.0ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) Balance queues: 0.0ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) FinalRef (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0, Workers: 2
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) Notify PhantomReferences: 0.2ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) Balance queues: 0.0ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) PhantomRef (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.0, Sum: 0.2, Workers: 2
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) SoftReference:
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) Discovered: 0
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) Cleared: 0
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) WeakReference:
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) Discovered: 0
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) Cleared: 0
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) FinalReference:
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) Discovered: 104
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) Cleared: 3
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) PhantomReference:
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) Discovered: 1209
[2020-02-26T21:06:01.711+0000][debug][gc,phases,ref ] GC(45002) Cleared: 1209
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Weak Processing: 0.1ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Merge Per-Thread State: 0.0ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Code Roots Purge: 0.0ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Redirty Cards: 0.0ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) DerivedPointerTable Update: 0.2ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Free Collection Set: 0.3ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Humongous Reclaim: 1.1ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Start New Collection Set: 0.0ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Resize TLABs: 0.1ms
[2020-02-26T21:06:01.711+0000][debug][gc,phases ] GC(45002) Expand Heap After Collection: 0.0ms
[2020-02-26T21:06:01.711+0000][info ][gc,phases ] GC(45002) Other: 9009.5ms
[2020-02-26T21:06:01.711+0000][info ][gc,heap ] GC(45002) Eden regions: 474->0(467)
[2020-02-26T21:06:01.711+0000][info ][gc,heap ] GC(45002) Survivor regions: 6->13(80)
[2020-02-26T21:06:01.711+0000][info ][gc,heap ] GC(45002) Old regions: 221->221
[2020-02-26T21:06:01.711+0000][info ][gc,heap ] GC(45002) Humongous regions: 292->281
[2020-02-26T21:06:01.711+0000][info ][gc,metaspace ] GC(45002) Metaspace: 147205K->147205K(1183744K)
[2020-02-26T21:06:01.711+0000][debug][gc,heap ] GC(45002) Heap after GC invocations=45003 (full 0): garbage-first heap total 5242880K, used 2106695K [0x00000006c0000000, 0x0000000800000000)
[2020-02-26T21:06:01.711+0000][debug][gc,heap ] GC(45002) region size 4096K, 13 young (53248K), 13 survivors (53248K)
[2020-02-26T21:06:01.711+0000][debug][gc,heap ] GC(45002) Metaspace used 147205K, capacity 150923K, committed 152960K, reserved 1183744K
[2020-02-26T21:06:01.711+0000][debug][gc,heap ] GC(45002) class space used 16073K, capacity 17538K, committed 18048K, reserved 1048576K
[2020-02-26T21:06:01.711+0000][info ][gc ] GC(45002) Pause Young (Normal) (G1 Evacuation Pause) 3971M->2057M(5120M) 46.544ms
[2020-02-26T21:06:01.711+0000][info ][gc,cpu ] GC(45002) User=0.06s Sys=0.03s Real=0.05s
Как видите, G C начинается в 2020-02-26T21: 05: 52.656 + 0000, но начинает выполнять процесс G1 G C до 2020-02-26T21: 06: 00.759 + 0000, почему это что?