PFB logs. Young gc which took place at 2019-01-29T22:26:37.545+0000: took only 0.03 seconds. Where as young gc at 2019-01-29T22:27:04.257+0000 just after 30 sec or so took 1.87 seconds. Amount of memory collected is almost same in two gcs. I am unable to understand what would cause it?
I have checked CPU load was 20% on the server.
If cpu is free it should have finished it in normal time.
Logs from application:
2019-01-29T22:26:37.545+0000: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 19922944 bytes, new threshold 15 (max 15)
- age 1: 2916480 bytes, 2916480 total
39329.271: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 1469, predicted base time: 14.84 ms, remaining time: 185.16 ms, target pause time: 200.00 ms]
39329.271: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 144 regions, survivors: 3 regions, predicted young region time: 92.66 ms]
39329.271: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 144 regions, survivors: 3 regions, old: 0 regions, predicted pause time: 107.50 ms, target pause time: 200.00 ms]
, 0.0309821 secs]
[Parallel Time: 27.7 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 39329271.8, Avg: 39329271.9, Max: 39329272.0, Diff: 0.3]
[Ext Root Scanning (ms): Min: 6.4, Avg: 7.2, Max: 8.9, Diff: 2.4, Sum: 28.7]
[Update RS (ms): Min: 0.0, Avg: 3.1, Max: 9.4, Diff: 9.4, Sum: 12.4]
[Processed Buffers: Min: 0, Avg: 10.0, Max: 24, Diff: 24, Sum: 40]
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 11.4, Avg: 16.8, Max: 19.1, Diff: 7.7, Sum: 67.4]
[Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
[GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
[GC Worker Total (ms): Min: 27.3, Avg: 27.4, Max: 27.5, Diff: 0.2, Sum: 109.6]
[GC Worker End (ms): Min: 39329299.3, Avg: 39329299.3, Max: 39329299.3, Diff: 0.0]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.3 ms]
[Other: 2.9 ms]
[Choose CSet: 0.1 ms]
[Ref Proc: 0.4 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 1.3 ms]
[Eden: 288.0M(288.0M)->0.0B(284.0M) Survivors: 6144.0K->10.0M Heap: 403.6M(492.0M)->119.6M(492.0M)]
[Times: user=0.08 sys=0.01, real=0.03 secs]
2019-01-29T22:27:04.257+0000: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 19922944 bytes, new threshold 15 (max 15)
- age 1: 6478080 bytes, 6478080 total
- age 2: 39296 bytes, 6517376 total
39356.002: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 1055, predicted base time: 13.21 ms, remaining time: 186.79 ms, target pause time: 200.00 ms]
39356.026: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 142 regions, survivors: 5 regions, predicted young region time: 78.96 ms]
39356.026: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 142 regions, survivors: 5 regions, old: 0 regions, predicted pause time: 92.17 ms, target pause time: 200.00 ms]
, 1.8688598 secs]
[Parallel Time: 1017.6 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 39356160.3, Avg: 39356164.6, Max: 39356169.7, Diff: 9.4]
[Ext Root Scanning (ms): Min: 247.7, Avg: 329.1, Max: 491.2, Diff: 243.5, Sum: 1316.5]
[Update RS (ms): Min: 0.1, Avg: 183.7, Max: 426.5, Diff: 426.4, Sum: 734.8]
[Processed Buffers: Min: 1, Avg: 10.2, Max: 35, Diff: 34, Sum: 41]
[Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.3]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 261.0, Avg: 425.0, Max: 500.8, Diff: 239.9, Sum: 1700.2]
[Termination (ms): Min: 0.0, Avg: 29.0, Max: 43.5, Diff: 43.5, Sum: 116.0]
[GC Worker Other (ms): Min: 2.0, Avg: 30.6, Max: 54.2, Diff: 52.2, Sum: 122.3]
[GC Worker Total (ms): Min: 994.4, Avg: 997.5, Max: 1001.3, Diff: 6.9, Sum: 3990.1]
[GC Worker End (ms): Min: 39357154.7, Avg: 39357162.1, Max: 39357168.5, Diff: 13.8]
[Code Root Fixup: 0.6 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 200.2 ms]
[Other: 650.5 ms]
[Choose CSet: 23.8 ms]
[Ref Proc: 0.7 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.2 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 473.1 ms]
[Eden: 284.0M(284.0M)->0.0B(2048.0K) Survivors: 10.0M->24.0M Heap: 403.6M(492.0M)->134.6M(492.0M)]
[Times: user=1.42 sys=0.12, real=1.87 secs]
