Very long duration of Finalize marking in the Remark stage of G1GC
Ivan Shramko
vanbeast at gmail.com
Mon Oct 19 12:07:31 UTC 2015
Hi!
Attached new log.
Best regards,
Ivan Shramko
2015-10-14 14:22 GMT+03:00 Thomas Schatzl <thomas.schatzl at oracle.com>:
> Hi,
>
> On Wed, 2015-10-14 at 14:12 +0300, Ivan Shramko wrote:
> > Hi Thomas!
> >
> > Did you mean humongous objects? We don't have them. Grepping gc log
> > with "humongous" doesn't show anything.
>
> Yes, I meant humongous objects. In the log snippet you gave, it did not
> indicate any amount of these objects too, e.g.
>
> > [Humongous Register: 0.0 ms]
> > [Humongous Reclaim: 0.0 ms]
>
> which typically indicates none. However both actions are typically very
> fast, so 0.0ms is not really unusual even in presence of some. In your
> log snippet I saw that some Humongous Register phases are 0.1ms, but
> that may just be some random variation.
>
> The options I gave you will make that clear (although I saw that you
> already have PrintAdaptiveSizePolicy enabled) because they will print
> the number of humongous objects directly.
>
> If you already mention that you are sure you do not have them, the
> mentioned issue cannot be the cause anyway.
>
> > I attached part of gc log with young gcs before long finalize marking.
> >
> > I have added JVM options you asked and will post log after next long
> > finalize pause.
>
> Maybe the new log will yield some new information. Not sure.
>
> Thanks,
> Thomas
>
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20151019/5ba9ad51/attachment-0001.html>
-------------- next part --------------
{Heap before GC invocations=10613 (full 0):
garbage-first heap total 94371840K, used 46579346K [0x00007f017c000000, 0x00007f017e005a00, 0x00007f17fc000000)
region size 32768K, 144 young (4718592K), 18 survivors (589824K)
Metaspace used 78702K, capacity 79547K, committed 79588K, reserved 79872K
2015-10-18T07:06:27.974-0400: 346692.925: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 301989888 bytes, new threshold 2 (max 15)
- age 1: 260252672 bytes, 260252672 total
- age 2: 123695976 bytes, 383948648 total
- age 3: 67812800 bytes, 451761448 total
346692.925: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 93568, predicted base time: 37.35 ms, remaining time: 62.65 ms, target pause time: 100.00 ms]
346692.925: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 126 regions, survivors: 18 regions, predicted young region time: 69.19 ms]
346692.925: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 126 regions, survivors: 18 regions, old: 0 regions, predicted pause time: 106.54 ms, target pause time: 100.00 ms]
2015-10-18T07:06:28.091-0400: 346693.042: [SoftReference, 0 refs, 0.0032346 secs]2015-10-18T07:06:28.094-0400: 346693.045: [WeakReference, 108 refs, 0.0014270 secs]2015-10-18T07:06:28.096-0400: 346693.047: [FinalReference, 718 refs, 0.0017805 secs]2015-10-18T07:06:28.097-0400: 346693.049: [PhantomReference, 13 refs, 0 refs, 0.0036647 secs]2015-10-18T07:06:28.101-0400: 346693.052: [JNI Weak Reference, 0.0000342 secs], 0.1382317 secs]
[Parallel Time: 115.1 ms, GC Workers: 32]
[GC Worker Start (ms): 346692925.7 346692925.7 346692925.7 346692925.7 346692925.7 346692925.7 346692925.7 346692925.8 346692925.8 346692925.8 346692925.8 346692925.8 346692925.8 346692925.8 346692925.9 346692925.9 346692925.9 346692925.9 346692925.9 346692925.9 346692926.0 346692926.0 346692926.0 346692926.0 346692926.0 346692926.0 346692926.1 346692926.1 346692926.1 346692926.1 346692926.1 346692926.1
Min: 346692925.7, Avg: 346692925.9, Max: 346692926.1, Diff: 0.5]
[Ext Root Scanning (ms): 1.7 0.6 0.6 0.6 0.6 0.6 0.5 0.5 0.5 0.5 0.5 0.5 0.8 0.5 0.4 0.4 0.4 0.4 0.4 0.4 0.3 0.3 0.3 0.3 0.3 0.3 0.2 0.2 0.2 0.2 0.2 0.2
Min: 0.2, Avg: 0.4, Max: 1.7, Diff: 1.6, Sum: 14.3]
[Thread Roots (ms): 0.0 0.2 0.1 0.1 0.1 0.1 0.1 0.1 0.1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 1.1]
[StringTable Roots (ms): 0.0 0.5 0.5 0.5 0.4 0.4 0.5 0.4 0.4 0.5 0.5 0.5 0.0 0.4 0.4 0.4 0.4 0.4 0.4 0.4 0.3 0.3 0.3 0.3 0.3 0.3 0.2 0.2 0.2 0.2 0.2 0.2
Min: 0.0, Avg: 0.3, Max: 0.5, Diff: 0.5, Sum: 10.6]
[Universe Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[JNI Handles Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[ObjectSynchronizer Roots (ms): 0.0 0.0 0.0 0.0 0.1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1]
[FlatProfiler Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Management Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SystemDictionary Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.8 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.8, Diff: 0.8, Sum: 0.8]
[CLDG Roots (ms): 1.7 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.1, Max: 1.7, Diff: 1.7, Sum: 1.7]
[JVMTI Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CodeCache Roots (ms): 41.4 42.6 42.4 42.6 42.5 42.5 42.5 42.5 42.5 42.5 42.6 42.5 42.2 42.5 42.5 42.6 42.5 42.6 42.6 42.5 42.6 42.6 42.6 42.6 42.5 42.5 42.6 43.2 42.6 42.5 42.5 42.5
Min: 41.4, Avg: 42.5, Max: 43.2, Diff: 1.7, Sum: 1360.6]
[CM RefProcessor Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Wait For Strong CLD (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Weak CLD Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SATB Filtering (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Update RS (ms): 10.5 11.6 11.5 12.0 11.6 11.9 11.8 11.7 13.2 11.7 12.0 11.9 11.8 12.1 11.9 11.9 11.6 11.7 11.8 11.6 11.6 11.6 12.0 12.1 11.9 11.6 11.7 11.8 11.6 12.3 11.9 11.9
Min: 10.5, Avg: 11.8, Max: 13.2, Diff: 2.7, Sum: 378.0]
[Processed Buffers: 13 14 18 13 11 14 14 13 12 12 15 12 14 11 11 12 9 11 9 10 13 15 12 11 13 12 12 12 12 12 12 12
Min: 9, Avg: 12.4, Max: 18, Diff: 9, Sum: 396]
[Scan RS (ms): 30.9 31.0 30.9 30.6 30.9 30.6 30.6 30.8 29.3 30.8 30.6 30.5 30.5 30.4 30.6 30.6 30.9 30.9 30.8 30.9 31.0 31.0 30.6 30.5 30.6 30.9 30.8 31.4 30.9 30.3 30.6 30.6
Min: 29.3, Avg: 30.7, Max: 31.4, Diff: 2.1, Sum: 982.4]
[Code Root Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): 69.5 69.6 69.5 69.7 69.8 69.4 69.7 69.9 69.2 70.6 69.2 69.9 69.5 69.3 69.7 69.2 69.7 69.0 69.0 67.6 69.1 69.3 69.0 69.3 69.9 69.5 69.2 68.7 69.6 69.5 69.9 69.4
Min: 67.6, Avg: 69.4, Max: 70.6, Diff: 3.0, Sum: 2221.3]
[Termination (ms): 1.8 1.7 1.9 1.7 1.6 1.9 1.6 1.4 2.1 0.7 2.0 1.5 1.9 2.1 1.6 2.1 1.7 2.3 2.2 3.8 2.2 2.0 2.3 2.0 1.4 1.9 2.1 2.0 1.7 1.9 1.5 1.9
Min: 0.7, Avg: 1.9, Max: 3.8, Diff: 3.1, Sum: 60.6]
[Termination Attempts: 163 158 145 170 162 141 163 149 156 49 151 162 156 138 135 154 133 140 125 100 149 151 125 157 155 149 140 146 148 162 157 155
Min: 49, Avg: 145.1, Max: 170, Diff: 121, Sum: 4644]
[GC Worker Other (ms): 0.0 0.1 0.2 0.0 0.0 0.0 0.0 0.0 0.0 0.1 0.2 0.0 0.1 0.1 0.0 0.1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.1 0.1 0.2 0.0 0.0 0.0
Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.7]
[GC Worker Total (ms): 114.5 114.6 114.7 114.5 114.5 114.5 114.5 114.4 114.4 114.4 114.5 114.4 114.5 114.4 114.3 114.4 114.3 114.3 114.3 114.3 114.2 114.2 114.2 114.2 114.2 114.2 114.2 114.2 114.2 114.1 114.1 114.1
Min: 114.1, Avg: 114.3, Max: 114.7, Diff: 0.6, Sum: 3658.5]
[GC Worker End (ms): 346693040.2 346693040.3 346693040.3 346693040.2 346693040.2 346693040.2 346693040.2 346693040.2 346693040.2 346693040.2 346693040.3 346693040.2 346693040.3 346693040.2 346693040.2 346693040.2 346693040.2 346693040.2 346693040.2 346693040.2 346693040.2 346693040.2 346693040.2 346693040.2 346693040.2 346693040.2 346693040.2 346693040.2 346693040.3 346693040.2 346693040.2 346693040.2
Min: 346693040.2, Avg: 346693040.2, Max: 346693040.3, Diff: 0.2]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 5.3 ms]
[Other: 17.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 11.5 ms]
[Ref Enq: 0.7 ms]
[Redirty Cards: 2.0 ms]
[Parallel Redirty: 1.6 1.5 1.5 1.5 1.5 1.5 1.5 1.5 1.5 1.5 1.5 1.5 1.5 1.5 1.4 1.4 1.4 1.4 1.4 1.4 0.5 0.5 0.5 0.4 0.4 0.4 0.4 0.4 0.4 0.3 0.0 0.0
Min: 0.0, Avg: 1.1, Max: 1.6, Diff: 1.6, Sum: 33.9]
[Redirtied Cards: 23267 23417 22407 23635 23469 21895 21708 20324 19484 17776 20028 20004 6757 18913 17664 18916 17459 18511 16659 12800 5207 4473 4218 4216 4258 4204 4944 3891 3355 3009 0 0
Min: 0, Avg: 13339.6, Max: 23635, Diff: 23635, Sum: 426868]
[Humongous Register: 0.2 ms]
[Humongous Total: 0]
[Humongous Candidate: 0]
[Humongous Reclaim: 0.1 ms]
[Humongous Reclaimed: 0]
[Free CSet: 2.4 ms]
[Young Free CSet: 2.4 ms]
[Non-Young Free CSet: 0.0 ms]
[Eden: 4032.0M(4032.0M)->0.0B(4032.0M) Survivors: 576.0M->576.0M Heap: 44.4G(90.0G)->41.0G(90.0G)]
Heap after GC invocations=10614 (full 0):
garbage-first heap total 94371840K, used 42977782K [0x00007f017c000000, 0x00007f017e005a00, 0x00007f17fc000000)
region size 32768K, 18 young (589824K), 18 survivors (589824K)
Metaspace used 78702K, capacity 79547K, committed 79588K, reserved 79872K
}
[Times: user=3.82 sys=0.08, real=0.14 secs]
2015-10-18T07:06:28.113-0400: 346693.065: Total time for which application threads were stopped: 0.1403935 seconds, Stopping threads took: 0.0000975 seconds
{Heap before GC invocations=10614 (full 0):
garbage-first heap total 94371840K, used 47106550K [0x00007f017c000000, 0x00007f017e005a00, 0x00007f17fc000000)
region size 32768K, 144 young (4718592K), 18 survivors (589824K)
Metaspace used 78702K, capacity 79547K, committed 79588K, reserved 79872K
2015-10-18T07:06:58.055-0400: 346723.006: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 301989888 bytes, new threshold 2 (max 15)
- age 1: 222862048 bytes, 222862048 total
- age 2: 198816712 bytes, 421678760 total
346723.006: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 77058, predicted base time: 34.23 ms, remaining time: 65.77 ms, target pause time: 100.00 ms]
346723.006: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 126 regions, survivors: 18 regions, predicted young region time: 79.29 ms]
346723.006: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 126 regions, survivors: 18 regions, old: 0 regions, predicted pause time: 113.52 ms, target pause time: 100.00 ms]
2015-10-18T07:06:58.165-0400: 346723.116: [SoftReference, 0 refs, 0.0025743 secs]2015-10-18T07:06:58.167-0400: 346723.119: [WeakReference, 74 refs, 0.0015911 secs]2015-10-18T07:06:58.169-0400: 346723.120: [FinalReference, 1094 refs, 0.0012432 secs]2015-10-18T07:06:58.170-0400: 346723.121: [PhantomReference, 13 refs, 0 refs, 0.0029009 secs]2015-10-18T07:06:58.173-0400: 346723.124: [JNI Weak Reference, 0.0000343 secs] 346723.134: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: occupancy higher than threshold, occupancy: 43822088192 bytes, allocation request: 0 bytes, threshold: 43486543845 bytes (45.00 %), source: end of GC]
, 0.1279979 secs]
[Parallel Time: 107.8 ms, GC Workers: 32]
[GC Worker Start (ms): 346723006.7 346723006.7 346723006.8 346723006.8 346723006.8 346723006.9 346723006.9 346723006.9 346723006.9 346723006.9 346723006.9 346723006.9 346723006.9 346723006.9 346723006.9 346723007.0 346723007.0 346723007.0 346723007.0 346723007.0 346723007.0 346723007.0 346723007.1 346723007.1 346723007.1 346723007.1 346723007.1 346723007.2 346723007.2 346723007.2 346723007.2 346723007.3
Min: 346723006.7, Avg: 346723007.0, Max: 346723007.3, Diff: 0.5]
[Ext Root Scanning (ms): 2.9 1.4 0.8 0.8 0.8 0.7 0.7 0.7 0.7 0.7 0.6 0.7 0.6 0.6 0.6 0.6 0.6 0.6 0.6 0.5 0.5 0.5 0.5 0.5 0.5 0.4 0.4 0.4 0.4 0.4 0.3 0.3
Min: 0.3, Avg: 0.7, Max: 2.9, Diff: 2.6, Sum: 21.1]
[Thread Roots (ms): 0.0 0.2 0.2 0.2 0.2 0.1 0.1 0.1 0.1 0.1 0.1 0.1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 1.5]
[StringTable Roots (ms): 0.0 0.0 0.6 0.6 0.6 0.6 0.6 0.3 0.6 0.6 0.6 0.6 0.6 0.6 0.6 0.6 0.6 0.6 0.5 0.5 0.5 0.5 0.5 0.5 0.4 0.4 0.4 0.4 0.4 0.3 0.3 0.3
Min: 0.0, Avg: 0.5, Max: 0.6, Diff: 0.6, Sum: 15.2]
[Universe Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[JNI Handles Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[ObjectSynchronizer Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.3 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.3, Diff: 0.3, Sum: 0.3]
[FlatProfiler Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Management Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SystemDictionary Roots (ms): 0.0 1.2 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 1.2, Diff: 1.2, Sum: 1.2]
[CLDG Roots (ms): 2.9 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.1, Max: 2.9, Diff: 2.9, Sum: 2.9]
[JVMTI Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CodeCache Roots (ms): 36.2 37.7 38.3 38.4 38.2 38.3 38.2 38.2 38.2 38.2 37.9 38.2 38.3 38.3 38.2 38.5 38.3 38.3 38.3 38.5 38.2 38.2 38.2 38.2 38.2 38.3 38.3 38.4 38.3 38.3 38.2 38.2
Min: 36.2, Avg: 38.2, Max: 38.5, Diff: 2.3, Sum: 1221.7]
[CM RefProcessor Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Wait For Strong CLD (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Weak CLD Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SATB Filtering (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Update RS (ms): 10.4 12.0 12.4 12.0 12.1 12.3 18.8 12.0 12.4 12.1 12.2 12.0 12.4 12.7 12.0 12.7 12.0 12.4 12.1 12.0 12.3 12.1 12.0 12.5 12.3 12.1 12.2 13.4 12.5 12.8 12.5 12.6
Min: 10.4, Avg: 12.4, Max: 18.8, Diff: 8.4, Sum: 398.2]
[Processed Buffers: 10 11 12 11 11 9 10 11 13 9 12 12 13 12 9 12 8 9 8 10 8 9 10 9 8 12 9 13 8 11 9 9
Min: 8, Avg: 10.2, Max: 13, Diff: 5, Sum: 327]
[Scan RS (ms): 25.8 25.6 25.9 26.4 26.2 26.0 19.4 26.3 25.8 26.1 25.7 26.3 25.9 25.6 26.2 25.8 26.3 25.9 26.2 26.5 25.9 26.2 26.2 25.7 25.9 26.2 26.1 25.1 25.9 25.5 25.7 25.6
Min: 19.4, Avg: 25.7, Max: 26.5, Diff: 7.0, Sum: 823.3]
[Code Root Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): 67.0 66.9 66.9 66.9 67.1 67.0 67.0 67.5 67.1 67.3 67.9 67.5 67.0 67.0 67.1 66.8 66.9 67.0 67.1 66.8 67.2 67.1 67.2 67.0 67.0 67.0 67.0 66.8 67.0 67.1 67.0 67.1
Min: 66.8, Avg: 67.1, Max: 67.9, Diff: 1.1, Sum: 2146.3]
[Termination (ms): 0.8 1.0 0.9 0.8 0.8 0.8 0.9 0.4 0.9 0.6 0.4 0.4 0.9 0.8 0.8 0.9 0.9 0.9 0.7 0.8 0.6 0.8 0.7 0.9 0.9 0.9 0.8 0.9 0.8 0.7 0.9 0.9
Min: 0.4, Avg: 0.8, Max: 1.0, Diff: 0.6, Sum: 25.3]
[Termination Attempts: 22 13 18 13 18 17 17 1 14 17 18 13 17 14 20 11 10 13 19 6 13 7 9 14 13 9 11 10 19 21 16 8
Min: 1, Avg: 13.8, Max: 22, Diff: 21, Sum: 441]
[GC Worker Other (ms): 0.1 0.0 0.0 0.2 0.0 0.1 0.0 0.0 0.0 0.1 0.0 0.0 0.0 0.0 0.0 0.1 0.0 0.0 0.0 0.1 0.0 0.0 0.0 0.0 0.2 0.0 0.0 0.0 0.1 0.0 0.1 0.0
Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.1, Sum: 1.5]
[GC Worker Total (ms): 107.0 107.0 106.9 107.0 106.9 106.9 106.9 106.9 106.8 106.8 106.8 106.8 106.8 106.8 106.7 106.8 106.7 106.7 106.7 106.8 106.7 106.6 106.6 106.6 106.7 106.6 106.5 106.5 106.6 106.5 106.6 106.5
Min: 106.5, Avg: 106.7, Max: 107.0, Diff: 0.6, Sum: 3415.9]
[GC Worker End (ms): 346723113.7 346723113.7 346723113.7 346723113.8 346723113.7 346723113.8 346723113.7 346723113.7 346723113.7 346723113.7 346723113.7 346723113.7 346723113.7 346723113.7 346723113.7 346723113.8 346723113.7 346723113.7 346723113.7 346723113.8 346723113.7 346723113.7 346723113.7 346723113.7 346723113.8 346723113.7 346723113.7 346723113.7 346723113.8 346723113.7 346723113.8 346723113.7
Min: 346723113.7, Avg: 346723113.7, Max: 346723113.8, Diff: 0.1]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 4.5 ms]
[Other: 15.5 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 9.8 ms]
[Ref Enq: 0.6 ms]
[Redirty Cards: 1.2 ms]
[Parallel Redirty: 0.8 0.8 0.8 0.8 0.8 0.8 0.8 0.8 0.8 0.8 0.8 0.8 0.7 0.7 0.7 0.7 0.7 0.7 0.7 0.7 0.7 0.7 0.7 0.7 0.7 0.7 0.6 0.6 0.6 0.6 0.6 0.0
Min: 0.0, Avg: 0.7, Max: 0.8, Diff: 0.8, Sum: 22.6]
[Redirtied Cards: 16384 15531 15569 16437 16135 14488 13742 14069 14114 15427 9009 8192 7936 7168 8303 8082 7026 7059 7314 7483 7062 6641 11720 7022 10834 10024 6945 10672 10346 9770 3840 0
Min: 0, Avg: 10135.8, Max: 16437, Diff: 16437, Sum: 324344]
[Humongous Register: 0.2 ms]
[Humongous Total: 0]
[Humongous Candidate: 0]
[Humongous Reclaim: 0.1 ms]
[Humongous Reclaimed: 0]
[Free CSet: 2.8 ms]
[Young Free CSet: 2.8 ms]
[Non-Young Free CSet: 0.0 ms]
[Eden: 4032.0M(4032.0M)->0.0B(4032.0M) Survivors: 576.0M->576.0M Heap: 44.9G(90.0G)->41.4G(90.0G)]
Heap after GC invocations=10615 (full 0):
garbage-first heap total 94371840K, used 43360155K [0x00007f017c000000, 0x00007f017e005a00, 0x00007f17fc000000)
region size 32768K, 18 young (589824K), 18 survivors (589824K)
Metaspace used 78702K, capacity 79547K, committed 79588K, reserved 79872K
}
[Times: user=3.57 sys=0.09, real=0.13 secs]
2015-10-18T07:06:58.184-0400: 346723.135: Total time for which application threads were stopped: 0.1313165 seconds, Stopping threads took: 0.0018426 seconds
2015-10-18T07:07:15.146-0400: 346740.097: Total time for which application threads were stopped: 0.0007456 seconds, Stopping threads took: 0.0000971 seconds
2015-10-18T07:07:16.141-0400: 346741.092: Total time for which application threads were stopped: 0.0011149 seconds, Stopping threads took: 0.0002058 seconds
2015-10-18T07:07:18.313-0400: 346743.264: Total time for which application threads were stopped: 0.0010722 seconds, Stopping threads took: 0.0001563 seconds
{Heap before GC invocations=10615 (full 0):
garbage-first heap total 94371840K, used 47488923K [0x00007f017c000000, 0x00007f017e005a00, 0x00007f17fc000000)
region size 32768K, 144 young (4718592K), 18 survivors (589824K)
Metaspace used 78702K, capacity 79547K, committed 79588K, reserved 79872K
346752.983: [G1Ergonomics (Concurrent Cycles) initiate concurrent cycle, reason: concurrent cycle initiation requested]
2015-10-18T07:07:28.032-0400: 346752.983: [GC pause (G1 Evacuation Pause) (young) (initial-mark)
Desired survivor size 301989888 bytes, new threshold 2 (max 15)
- age 1: 193262688 bytes, 193262688 total
- age 2: 195192416 bytes, 388455104 total
346752.984: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 55586, predicted base time: 30.65 ms, remaining time: 69.35 ms, target pause time: 100.00 ms]
346752.984: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 126 regions, survivors: 18 regions, predicted young region time: 83.03 ms]
346752.984: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 126 regions, survivors: 18 regions, old: 0 regions, predicted pause time: 113.68 ms, target pause time: 100.00 ms]
2015-10-18T07:07:28.153-0400: 346753.104: [SoftReference, 0 refs, 0.0031514 secs]2015-10-18T07:07:28.156-0400: 346753.107: [WeakReference, 72 refs, 0.0012962 secs]2015-10-18T07:07:28.157-0400: 346753.108: [FinalReference, 489 refs, 0.0016356 secs]2015-10-18T07:07:28.159-0400: 346753.110: [PhantomReference, 6 refs, 1 refs, 0.0029412 secs]2015-10-18T07:07:28.162-0400: 346753.113: [JNI Weak Reference, 0.0000709 secs], 0.1410925 secs]
[Parallel Time: 117.7 ms, GC Workers: 32]
[GC Worker Start (ms): 346752984.8 346752984.8 346752984.8 346752984.8 346752984.9 346752984.9 346752984.9 346752984.9 346752984.9 346752985.0 346752985.0 346752985.0 346752985.0 346752985.0 346752985.0 346752985.0 346752985.1 346752985.1 346752985.1 346752985.1 346752985.1 346752985.1 346752985.1 346752985.2 346752985.2 346752985.2 346752985.2 346752985.2 346752985.2 346752985.2 346752985.2 346752985.2
Min: 346752984.8, Avg: 346752985.0, Max: 346752985.2, Diff: 0.4]
[Ext Root Scanning (ms): 4.0 3.8 3.9 3.8 3.8 3.9 3.8 3.8 3.8 3.7 3.6 3.7 3.7 3.8 3.7 3.7 3.6 3.7 3.7 3.6 3.6 3.7 3.5 3.4 3.5 3.6 3.4 3.4 3.6 3.6 3.6 3.4
Min: 3.4, Avg: 3.7, Max: 4.0, Diff: 0.7, Sum: 117.2]
[Thread Roots (ms): 0.0 3.7 0.2 0.2 0.2 0.2 0.1 0.1 0.1 0.1 0.1 0.2 0.1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.2, Max: 3.7, Diff: 3.7, Sum: 5.5]
[StringTable Roots (ms): 0.0 0.0 0.6 0.6 0.3 0.6 0.6 0.6 0.6 0.6 0.6 0.5 0.6 0.0 0.6 0.6 0.6 0.6 0.6 0.6 0.5 0.5 0.5 0.5 0.5 0.5 0.5 0.5 0.4 0.4 0.4 0.4
Min: 0.0, Avg: 0.5, Max: 0.6, Diff: 0.6, Sum: 15.5]
[Universe Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[JNI Handles Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[ObjectSynchronizer Roots (ms): 0.0 0.0 0.0 0.0 0.3 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.3, Diff: 0.3, Sum: 0.3]
[FlatProfiler Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Management Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[SystemDictionary Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 1.1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 1.1, Diff: 1.1, Sum: 1.1]
[CLDG Roots (ms): 1.2 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 1.2, Diff: 1.2, Sum: 1.2]
[JVMTI Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[CodeCache Roots (ms): 39.6 39.8 39.6 39.6 39.7 39.5 40.0 39.6 39.6 39.6 40.3 40.1 40.1 40.0 39.7 39.6 39.6 39.6 39.6 40.0 39.6 39.6 45.7 40.2 39.7 39.6 39.7 40.3 39.6 40.0 40.3 39.8
Min: 39.5, Avg: 40.0, Max: 45.7, Diff: 6.2, Sum: 1279.5]
[CM RefProcessor Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Wait For Strong CLD (ms): 2.8 0.0 3.1 3.0 3.0 3.1 3.0 2.9 3.1 3.0 2.9 2.9 2.9 2.6 3.0 3.0 2.9 3.1 3.1 3.0 3.0 3.1 2.9 2.9 2.9 3.1 2.9 2.9 3.1 3.1 3.1 2.9
Min: 0.0, Avg: 2.9, Max: 3.1, Diff: 3.1, Sum: 92.1]
[Weak CLD Roots (ms): 0.0 0.1 0.0 0.0 0.0 0.0 0.0 0.1 0.0 0.0 0.1 0.1 0.1 0.0 0.1 0.0 0.1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.1 0.0 0.0 0.1 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 1.3]
[SATB Filtering (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Update RS (ms): 10.0 9.0 8.6 9.1 9.2 8.9 8.6 9.2 9.1 8.8 9.4 9.0 8.9 8.7 9.2 8.8 9.4 9.1 8.8 9.1 9.1 8.8 8.9 8.8 9.7 9.2 9.3 8.9 9.0 8.7 8.6 9.0
Min: 8.6, Avg: 9.0, Max: 10.0, Diff: 1.4, Sum: 288.8]
[Processed Buffers: 9 10 11 6 6 6 8 6 9 5 8 6 7 8 7 5 7 5 5 6 6 9 9 9 5 10 9 9 13 8 9 11
Min: 5, Avg: 7.7, Max: 13, Diff: 8, Sum: 247]
[Scan RS (ms): 29.6 30.8 30.9 30.5 30.5 30.6 31.4 30.4 30.5 30.8 30.9 31.1 31.3 31.3 30.5 30.8 30.2 30.5 30.9 30.9 30.5 30.8 36.9 31.4 30.0 30.4 30.5 31.4 30.5 31.2 31.7 30.8
Min: 29.6, Avg: 31.0, Max: 36.9, Diff: 7.3, Sum: 990.5]
[Code Root Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Object Copy (ms): 71.7 71.5 71.7 71.8 72.0 71.7 71.5 71.8 71.7 71.7 71.2 71.2 71.7 71.3 71.8 71.7 72.0 71.8 71.7 71.4 71.6 71.7 65.7 71.2 71.6 71.6 71.8 71.1 71.7 71.4 70.9 71.7
Min: 65.7, Avg: 71.4, Max: 72.0, Diff: 6.2, Sum: 2285.0]
[Termination (ms): 1.4 1.6 1.5 1.4 1.1 1.5 1.2 1.4 1.3 1.4 1.4 1.5 0.9 1.4 1.3 1.4 1.2 1.3 1.3 1.4 1.5 1.4 1.4 1.5 1.5 1.5 1.3 1.4 1.5 1.2 1.5 1.3
Min: 0.9, Avg: 1.4, Max: 1.6, Diff: 0.6, Sum: 44.2]
[Termination Attempts: 13 12 14 14 12 17 11 14 11 15 9 17 5 11 9 16 7 9 14 8 10 16 13 7 14 14 12 16 17 4 17 7
Min: 4, Avg: 12.0, Max: 17, Diff: 13, Sum: 385]
[GC Worker Other (ms): 0.0 0.0 0.1 0.1 0.1 0.0 0.0 0.1 0.0 0.0 0.0 0.1 0.1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.1 0.0 0.1 0.0 0.0 0.0 0.0 0.1 0.1 0.0 0.0 0.0
Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 1.5]
[GC Worker Total (ms): 116.7 116.7 116.7 116.6 116.7 116.6 116.6 116.6 116.6 116.5 116.5 116.6 116.6 116.5 116.5 116.5 116.4 116.4 116.4 116.4 116.5 116.4 116.4 116.3 116.3 116.3 116.3 116.4 116.3 116.3 116.3 116.2
Min: 116.2, Avg: 116.5, Max: 116.7, Diff: 0.5, Sum: 3727.2]
[GC Worker End (ms): 346753101.5 346753101.5 346753101.6 346753101.5 346753101.6 346753101.5 346753101.5 346753101.5 346753101.5 346753101.5 346753101.5 346753101.5 346753101.6 346753101.5 346753101.5 346753101.5 346753101.5 346753101.5 346753101.5 346753101.5 346753101.6 346753101.5 346753101.5 346753101.5 346753101.5 346753101.5 346753101.5 346753101.6 346753101.6 346753101.5 346753101.5 346753101.5
Min: 346753101.5, Avg: 346753101.5, Max: 346753101.6, Diff: 0.1]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 5.1 ms]
[Other: 18.2 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 10.7 ms]
[Ref Enq: 0.5 ms]
[Redirty Cards: 2.3 ms]
[Parallel Redirty: 1.8 1.8 1.8 1.7 1.7 1.7 1.7 1.7 1.7 1.7 1.7 1.7 1.7 1.7 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0
Min: 0.0, Avg: 0.8, Max: 1.8, Diff: 1.8, Sum: 24.3]
[Redirtied Cards: 20279 24852 24843 24186 19664 23217 23422 24870 25919 25178 23849 18080 21743 22024 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0
Min: 0, Avg: 10066.4, Max: 25919, Diff: 25919, Sum: 322126]
[Humongous Register: 0.1 ms]
[Humongous Total: 0]
[Humongous Candidate: 0]
[Humongous Reclaim: 0.1 ms]
[Humongous Reclaimed: 0]
[Free CSet: 2.5 ms]
[Young Free CSet: 2.5 ms]
[Non-Young Free CSet: 0.0 ms]
[Eden: 4032.0M(4032.0M)->0.0B(4032.0M) Survivors: 576.0M->576.0M Heap: 45.3G(90.0G)->41.7G(90.0G)]
Heap after GC invocations=10616 (full 0):
garbage-first heap total 94371840K, used 43732854K [0x00007f017c000000, 0x00007f017e005a00, 0x00007f17fc000000)
region size 32768K, 18 young (589824K), 18 survivors (589824K)
Metaspace used 78702K, capacity 79547K, committed 79588K, reserved 79872K
}
[Times: user=3.84 sys=0.08, real=0.14 secs]
2015-10-18T07:07:28.174-0400: 346753.126: [GC concurrent-root-region-scan-start]
2015-10-18T07:07:28.175-0400: 346753.126: Total time for which application threads were stopped: 0.1434439 seconds, Stopping threads took: 0.0001640 seconds
2015-10-18T07:07:28.260-0400: 346753.211: [GC concurrent-root-region-scan-end, 0.0852149 secs]
2015-10-18T07:07:28.260-0400: 346753.211: [GC concurrent-mark-start]
2015-10-18T07:07:28.965-0400: 346753.916: [GC concurrent-mark-end, 0.7049345 secs]
2015-10-18T07:07:28.966-0400: 346753.917: [GC remark 2015-10-18T07:07:28.966-0400: 346753.917: [Finalize Marking, 115.4404545 secs] 2015-10-18T07:09:24.406-0400: 346869.357: [GC ref-proc2015-10-18T07:09:24.406-0400: 346869.357: [SoftReference, 54 refs, 0.0028579 secs]2015-10-18T07:09:24.409-0400: 346869.360: [WeakReference, 418 refs, 0.0020702 secs]2015-10-18T07:09:24.411-0400: 346869.362: [FinalReference, 1633 refs, 0.0025592 secs]2015-10-18T07:09:24.414-0400: 346869.365: [PhantomReference, 6 refs, 21 refs, 0.0040350 secs]2015-10-18T07:09:24.418-0400: 346869.369: [JNI Weak Reference, 0.0001088 secs], 0.0130411 secs] 2015-10-18T07:09:24.419-0400: 346869.370: [Unloading 2015-10-18T07:09:24.420-0400: 346869.371: [System Dictionary Unloading, 0.0001458 secs] 2015-10-18T07:09:24.420-0400: 346869.371: [Parallel Unloading, 0.0153302 secs] 2015-10-18T07:09:24.435-0400: 346869.386: [Deallocate Metadata, 0.0000526 secs], 0.0159394 secs], 115.5038062 secs]
[Times: user=1641.24 sys=743.90, real=115.48 secs]
2015-10-18T07:09:24.469-0400: 346869.421: Total time for which application threads were stopped: 115.5047519 seconds, Stopping threads took: 0.0001246 seconds
2015-10-18T07:09:24.470-0400: 346869.421: [GC cleanup 41G->41G(90G), 0.1233809 secs]
[Times: user=3.83 sys=0.00, real=0.13 secs]
2015-10-18T07:09:24.594-0400: 346869.545: Total time for which application threads were stopped: 0.1240198 seconds, Stopping threads took: 0.0001006 seconds
2015-10-18T07:09:24.594-0400: 346869.545: [GC concurrent-cleanup-start]
2015-10-18T07:09:24.594-0400: 346869.545: [GC concurrent-cleanup-end, 0.0003056 secs]
2015-10-18T07:09:24.594-0400: 346869.546: Total time for which application threads were stopped: 0.0006490 seconds, Stopping threads took: 0.0001584 seconds
2015-10-18T07:09:24.597-0400: 346869.548: Total time for which application threads were stopped: 0.0006890 seconds, Stopping threads took: 0.0002038 seconds
2015-10-18T07:09:37.098-0400: 346882.049: Total time for which application threads were stopped: 0.0015512 seconds, Stopping threads took: 0.0006916 seconds
More information about the hotspot-gc-use
mailing list