Very long duration of Finalize marking in the Remark stage of G1GC
Ivan Shramko
vanbeast at gmail.com
Wed Oct 14 11:12:14 UTC 2015
Hi Thomas!
Did you mean humongous objects? We don't have them. Grepping gc log with
"humongous" doesn't show anything.
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.
Best regards,
Ivan
2015-10-14 13:38 GMT+03:00 Thomas Schatzl <thomas.schatzl at oracle.com>:
> Hi Ivan,
>
> just some random idea: do you know if your application creates very
> large arrays containing object references? I.e. in the range of a few
> hundred MB?
>
> We might run into one of them during remark sometimes, and they may
> prevent scaling, similar to
> https://bugs.openjdk.java.net/browse/JDK-8057003 .
>
> It would be nice if you could run your application with -XX:
> +UnlockExperimentalVMOptions -XX:G1LogLevel=finest -XX:
> +PrintAdaptiveSizePolicy -XX:+G1TraceEagerReclaimHumongousObjects to get
> an idea about that.
>
> It would be nice to have a log with a long remark pause and a few young
> gcs before that.
>
> This is really only a guess, so the problem might not be related at all.
>
> Thanks,
> Thomas
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20151014/54e103c6/attachment.html>
-------------- next part --------------
{Heap before GC invocations=1556 (full 0):
garbage-first heap total 94371840K, used 78351927K [0x00007f76d0000000, 0x00007f76d2005a00, 0x00007f8d50000000)
region size 32768K, 1114 young (36503552K), 53 survivors (1736704K)
Metaspace used 77160K, capacity 77951K, committed 78080K, reserved 79872K
2015-10-04T14:53:07.305-0400: 204193.136: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 1325400064 bytes, new threshold 2 (max 2)
- age 1: 523073840 bytes, 523073840 total
- age 2: 229700672 bytes, 752774512 total
204193.136: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 138447, predicted base time: 48.81 ms, remaining time: 151.19 ms, target pause time: 200.00 ms]
204193.136: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1061 regions, survivors: 53 regions, predicted young region time: 146.32 ms]
204193.136: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1061 regions, survivors: 53 regions, old: 0 regions, predicted pause time: 195.13 ms, target pause time: 200.00 ms
]
2015-10-04T14:53:07.462-0400: 204193.293: [SoftReference, 0 refs, 0.0025515 secs]2015-10-04T14:53:07.464-0400: 204193.295: [WeakReference, 362 refs, 0.0015984 secs]2015-10-04T14:53:07.466-0
400: 204193.297: [FinalReference, 90835 refs, 0.0092076 secs]2015-10-04T14:53:07.475-0400: 204193.306: [PhantomReference, 32 refs, 1 refs, 0.0030970 secs]2015-10-04T14:53:07.478-0400: 20419
3.309: [JNI Weak Reference, 0.0000245 secs], 0.1913854 secs]
[Parallel Time: 154.0 ms, GC Workers: 32]
[GC Worker Start (ms): Min: 204193137.3, Avg: 204193137.8, Max: 204193144.9, Diff: 7.5]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.6, Max: 2.4, Diff: 2.4, Sum: 17.8]
[Update RS (ms): Min: 12.7, Avg: 19.4, Max: 23.3, Diff: 10.6, Sum: 619.5]
[Processed Buffers: Min: 5, Avg: 18.2, Max: 27, Diff: 22, Sum: 581]
[Scan RS (ms): Min: 38.0, Avg: 42.1, Max: 50.3, Diff: 12.3, Sum: 1348.6]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
[Object Copy (ms): Min: 80.0, Avg: 87.7, Max: 88.3, Diff: 8.3, Sum: 2807.9]
[Termination (ms): Min: 0.0, Avg: 3.0, Max: 3.1, Diff: 3.1, Sum: 95.8]
[Termination Attempts: Min: 1, Avg: 24.8, Max: 40, Diff: 39, Sum: 792]
[GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 4.8]
[GC Worker Total (ms): Min: 145.9, Avg: 153.0, Max: 153.6, Diff: 7.7, Sum: 4894.8]
[GC Worker End (ms): Min: 204193290.7, Avg: 204193290.8, Max: 204193291.0, Diff: 0.3]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 7.7 ms]
[Other: 29.5 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 17.9 ms]
[Ref Enq: 0.9 ms]
[Redirty Cards: 1.9 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 7.6 ms]
[Eden: 33.2G(18.1G)->0.0B(37.0G) Survivors: 1696.0M->1856.0M Heap: 74.7G(90.0G)->42.1G(90.0G)]
Heap after GC invocations=1557 (full 0):
garbage-first heap total 94371840K, used 44189261K [0x00007f76d0000000, 0x00007f76d2005a00, 0x00007f8d50000000)
region size 32768K, 58 young (1900544K), 58 survivors (1900544K)
Metaspace used 77160K, capacity 77951K, committed 78080K, reserved 79872K
}
[Times: user=5.24 sys=0.11, real=0.19 secs]
2015-10-04T14:53:07.497-0400: 204193.328: Total time for which application threads were stopped: 0.1924941 seconds, Stopping threads took: 0.0003254 seconds
2015-10-04T14:53:07.536-0400: 204193.367: Total time for which application threads were stopped: 0.0024199 seconds, Stopping threads took: 0.0019603 seconds
2015-10-04T14:53:07.537-0400: 204193.368: Total time for which application threads were stopped: 0.0005090 seconds, Stopping threads took: 0.0003125 seconds
2015-10-04T14:53:07.539-0400: 204193.370: Total time for which application threads were stopped: 0.0011741 seconds, Stopping threads took: 0.0008785 seconds
2015-10-04T14:53:07.540-0400: 204193.371: Total time for which application threads were stopped: 0.0003168 seconds, Stopping threads took: 0.0000983 seconds
2015-10-04T14:53:07.542-0400: 204193.373: Total time for which application threads were stopped: 0.0012312 seconds, Stopping threads took: 0.0009565 seconds
2015-10-04T14:53:07.543-0400: 204193.374: Total time for which application threads were stopped: 0.0003502 seconds, Stopping threads took: 0.0001167 seconds
2015-10-04T14:53:07.545-0400: 204193.376: Total time for which application threads were stopped: 0.0013865 seconds, Stopping threads took: 0.0010004 seconds
2015-10-04T14:53:16.073-0400: 204201.904: Total time for which application threads were stopped: 0.0007099 seconds, Stopping threads took: 0.0000944 seconds
2015-10-04T14:53:20.731-0400: 204206.562: Total time for which application threads were stopped: 0.0006761 seconds, Stopping threads took: 0.0000973 seconds
2015-10-04T14:53:55.583-0400: 204241.414: Total time for which application threads were stopped: 0.0005850 seconds, Stopping threads took: 0.0001100 seconds
2015-10-04T14:53:55.583-0400: 204241.414: Total time for which application threads were stopped: 0.0002960 seconds, Stopping threads took: 0.0000804 seconds
2015-10-04T14:54:39.509-0400: 204285.340: Total time for which application threads were stopped: 0.0007971 seconds, Stopping threads took: 0.0002291 seconds
2015-10-04T14:54:39.510-0400: 204285.341: Total time for which application threads were stopped: 0.0002893 seconds, Stopping threads took: 0.0000419 seconds
2015-10-04T14:54:39.764-0400: 204285.595: Total time for which application threads were stopped: 0.0013350 seconds, Stopping threads took: 0.0008491 seconds
2015-10-04T14:54:41.851-0400: 204287.682: Total time for which application threads were stopped: 0.0012849 seconds, Stopping threads took: 0.0001466 seconds
2015-10-04T14:54:49.561-0400: 204295.392: Total time for which application threads were stopped: 0.0009442 seconds, Stopping threads took: 0.0002284 seconds
2015-10-04T14:54:51.683-0400: 204297.514: Total time for which application threads were stopped: 0.0005281 seconds, Stopping threads took: 0.0000984 seconds
2015-10-04T14:55:13.691-0400: 204319.522: Total time for which application threads were stopped: 0.0024420 seconds, Stopping threads took: 0.0017980 seconds
2015-10-04T14:55:34.964-0400: 204340.795: Total time for which application threads were stopped: 0.0004586 seconds, Stopping threads took: 0.0000642 seconds
2015-10-04T14:56:03.426-0400: 204369.257: Total time for which application threads were stopped: 0.0007487 seconds, Stopping threads took: 0.0001356 seconds
2015-10-04T14:56:33.823-0400: 204399.654: Total time for which application threads were stopped: 0.0005697 seconds, Stopping threads took: 0.0000907 seconds
{Heap before GC invocations=1557 (full 0):
garbage-first heap total 94371840K, used 82986573K [0x00007f76d0000000, 0x00007f76d2005a00, 0x00007f8d50000000)
region size 32768K, 1243 young (40730624K), 58 survivors (1900544K)
Metaspace used 77160K, capacity 77951K, committed 78080K, reserved 79872K
2015-10-04T14:56:33.824-0400: 204399.655: [GC pause (GCLocker Initiated GC) (young)
Desired survivor size 2617245696 bytes, new threshold 2 (max 2)
- age 1: 564311480 bytes, 564311480 total
- age 2: 233691344 bytes, 798002824 total
204399.655: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 205743, predicted base time: 59.14 ms, remaining time: 140.86 ms, target pause time: 200.00 ms]
204399.655: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1185 regions, survivors: 58 regions, predicted young region time: 133.39 ms]
204399.655: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1185 regions, survivors: 58 regions, old: 0 regions, predicted pause time: 192.52 ms, target pause time: 200.00 ms
]
2015-10-04T14:56:34.006-0400: 204399.837: [SoftReference, 0 refs, 0.0025401 secs]2015-10-04T14:56:34.008-0400: 204399.840: [WeakReference, 440 refs, 0.0015279 secs]2015-10-04T14:56:34.010-0
400: 204399.841: [FinalReference, 92689 refs, 0.0102004 secs]2015-10-04T14:56:34.020-0400: 204399.851: [PhantomReference, 14 refs, 1 refs, 0.0031138 secs]2015-10-04T14:56:34.023-0400: 20439
9.855: [JNI Weak Reference, 0.0000505 secs] 204399.874: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: occupancy higher than threshold, occupancy: 4365431603
2 bytes, allocation request: 0 bytes, threshold: 43486543845 bytes (45.00 %), source: end of GC]
, 0.2197629 secs]
[Parallel Time: 179.4 ms, GC Workers: 32]
[GC Worker Start (ms): Min: 204399656.2, Avg: 204399657.1, Max: 204399663.9, Diff: 7.7]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.6, Max: 2.5, Diff: 2.5, Sum: 18.0]
[Update RS (ms): Min: 21.8, Avg: 28.3, Max: 29.7, Diff: 7.9, Sum: 905.3]
[Processed Buffers: Min: 12, Avg: 26.4, Max: 33, Diff: 21, Sum: 844]
[Scan RS (ms): Min: 39.4, Avg: 41.3, Max: 41.9, Diff: 2.5, Sum: 1321.5]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
[Object Copy (ms): Min: 107.2, Avg: 107.7, Max: 108.2, Diff: 1.0, Sum: 3446.6]
[Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 7.6]
[Termination Attempts: Min: 1, Avg: 71.9, Max: 94, Diff: 93, Sum: 2302]
[GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 5.6]
[GC Worker Total (ms): Min: 171.4, Avg: 178.3, Max: 179.3, Diff: 7.9, Sum: 5704.8]
[GC Worker End (ms): Min: 204399835.2, Avg: 204399835.4, Max: 204399835.6, Diff: 0.3]
[Code Root Fixup: 0.1 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 8.3 ms]
[Other: 32.0 ms]
[Choose CSet: 0.1 ms]
[Ref Proc: 18.9 ms]
[Ref Enq: 0.7 ms]
[Redirty Cards: 1.7 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 8.9 ms]
[Eden: 37.0G(37.0G)->0.0B(36.7G) Survivors: 1856.0M->1856.0M Heap: 79.2G(90.0G)->42.4G(90.0G)]
Heap after GC invocations=1558 (full 0):
garbage-first heap total 94371840K, used 44499150K [0x00007f76d0000000, 0x00007f76d2005a00, 0x00007f8d50000000)
region size 32768K, 58 young (1900544K), 58 survivors (1900544K)
Metaspace used 77160K, capacity 77951K, committed 78080K, reserved 79872K
}
[Times: user=6.07 sys=0.19, real=0.22 secs]
2015-10-04T14:56:34.044-0400: 204399.875: Total time for which application threads were stopped: 0.2204766 seconds, Stopping threads took: 0.0001223 seconds
2015-10-04T14:56:34.075-0400: 204399.907: Total time for which application threads were stopped: 0.0010407 seconds, Stopping threads took: 0.0006153 seconds
2015-10-04T14:56:34.077-0400: 204399.908: Total time for which application threads were stopped: 0.0005106 seconds, Stopping threads took: 0.0001712 seconds
2015-10-04T14:56:34.077-0400: 204399.908: Total time for which application threads were stopped: 0.0002922 seconds, Stopping threads took: 0.0000431 seconds
2015-10-04T14:56:34.079-0400: 204399.910: Total time for which application threads were stopped: 0.0007010 seconds, Stopping threads took: 0.0002168 seconds
2015-10-04T14:56:34.080-0400: 204399.911: Total time for which application threads were stopped: 0.0003869 seconds, Stopping threads took: 0.0001520 seconds
2015-10-04T14:56:34.081-0400: 204399.912: Total time for which application threads were stopped: 0.0015659 seconds, Stopping threads took: 0.0001263 seconds
2015-10-04T14:57:00.447-0400: 204426.278: Total time for which application threads were stopped: 0.0006533 seconds, Stopping threads took: 0.0000893 seconds
2015-10-04T14:57:22.384-0400: 204448.216: Total time for which application threads were stopped: 0.0007878 seconds, Stopping threads took: 0.0002240 seconds
2015-10-04T14:57:25.372-0400: 204451.203: Total time for which application threads were stopped: 0.0007839 seconds, Stopping threads took: 0.0001125 seconds
2015-10-04T14:57:48.038-0400: 204473.870: Total time for which application threads were stopped: 0.0006679 seconds, Stopping threads took: 0.0000809 seconds
2015-10-04T14:57:52.957-0400: 204478.788: Total time for which application threads were stopped: 0.0009843 seconds, Stopping threads took: 0.0003051 seconds
2015-10-04T14:58:07.151-0400: 204492.982: Total time for which application threads were stopped: 0.0007069 seconds, Stopping threads took: 0.0001032 seconds
2015-10-04T14:58:15.571-0400: 204501.402: Total time for which application threads were stopped: 0.0007719 seconds, Stopping threads took: 0.0001712 seconds
2015-10-04T14:58:30.156-0400: 204515.988: Total time for which application threads were stopped: 0.0007603 seconds, Stopping threads took: 0.0001050 seconds
2015-10-04T14:59:55.163-0400: 204600.995: Total time for which application threads were stopped: 0.0008706 seconds, Stopping threads took: 0.0001749 seconds
2015-10-04T14:59:55.201-0400: 204601.032: Total time for which application threads were stopped: 0.0005852 seconds, Stopping threads took: 0.0001521 seconds
2015-10-04T14:59:55.202-0400: 204601.033: Total time for which application threads were stopped: 0.0004847 seconds, Stopping threads took: 0.0001346 seconds
2015-10-04T14:59:55.519-0400: 204601.350: Total time for which application threads were stopped: 0.0007758 seconds, Stopping threads took: 0.0001170 seconds
2015-10-04T14:59:57.666-0400: 204603.497: Total time for which application threads were stopped: 0.0007808 seconds, Stopping threads took: 0.0001688 seconds
2015-10-04T15:00:05.193-0400: 204611.024: Total time for which application threads were stopped: 0.0005358 seconds, Stopping threads took: 0.0001350 seconds
{Heap before GC invocations=1558 (full 0):
garbage-first heap total 94371840K, used 83001550K [0x00007f76d0000000, 0x00007f76d2005a00, 0x00007f8d50000000)
region size 32768K, 1234 young (40435712K), 58 survivors (1900544K)
Metaspace used 77160K, capacity 77951K, committed 78080K, reserved 79872K
204611.028: [G1Ergonomics (Concurrent Cycles) initiate concurrent cycle, reason: concurrent cycle initiation requested]
2015-10-04T15:00:05.197-0400: 204611.028: [GC pause (GCLocker Initiated GC) (young) (initial-mark)
Desired survivor size 2600468480 bytes, new threshold 2 (max 2)
- age 1: 621290376 bytes, 621290376 total
- age 2: 245159208 bytes, 866449584 total
204611.029: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 184157, predicted base time: 57.32 ms, remaining time: 142.68 ms, target pause time: 200.00 ms]
204611.029: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1176 regions, survivors: 58 regions, predicted young region time: 131.19 ms]
204611.029: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1176 regions, survivors: 58 regions, old: 0 regions, predicted pause time: 188.51 ms, target pause time: 200.00 ms]
2015-10-04T15:00:05.416-0400: 204611.247: [SoftReference, 0 refs, 0.0023502 secs]2015-10-04T15:00:05.418-0400: 204611.249: [WeakReference, 394 refs, 0.0018755 secs]2015-10-04T15:00:05.420-0400: 204611.251: [FinalReference, 91704 refs, 0.
0081225 secs]2015-10-04T15:00:05.428-0400: 204611.259: [PhantomReference, 29 refs, 1 refs, 0.0048953 secs]2015-10-04T15:00:05.433-0400: 204611.264: [JNI Weak Reference, 0.0000229 secs], 0.2600007 secs]
[Parallel Time: 215.1 ms, GC Workers: 32]
[GC Worker Start (ms): Min: 204611030.3, Avg: 204611030.5, Max: 204611030.6, Diff: 0.4]
[Ext Root Scanning (ms): Min: 2.5, Avg: 3.2, Max: 8.3, Diff: 5.8, Sum: 103.2]
[Update RS (ms): Min: 19.0, Avg: 24.5, Max: 35.3, Diff: 16.3, Sum: 782.9]
[Processed Buffers: Min: 7, Avg: 23.7, Max: 31, Diff: 24, Sum: 758]
[Scan RS (ms): Min: 40.4, Avg: 42.2, Max: 43.0, Diff: 2.6, Sum: 1349.0]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
[Object Copy (ms): Min: 131.5, Avg: 140.0, Max: 142.4, Diff: 10.9, Sum: 4480.1]
[Termination (ms): Min: 1.9, Avg: 4.1, Max: 4.6, Diff: 2.7, Sum: 130.8]
[Termination Attempts: Min: 262, Avg: 544.9, Max: 599, Diff: 337, Sum: 17437]
[GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 7.1]
[GC Worker Total (ms): Min: 213.8, Avg: 214.2, Max: 214.5, Diff: 0.7, Sum: 6853.3]
[GC Worker End (ms): Min: 204611244.4, Avg: 204611244.6, Max: 204611244.8, Diff: 0.4]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 8.4 ms]
[Other: 36.4 ms]
[Choose CSet: 0.1 ms]
[Ref Proc: 19.1 ms]
[Ref Enq: 0.8 ms]
[Redirty Cards: 2.0 ms]
[Humongous Register: 0.0 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 11.5 ms]
[Eden: 36.8G(36.7G)->0.0B(35.8G) Survivors: 1856.0M->1568.0M Heap: 79.2G(90.0G)->42.4G(90.0G)]
Heap after GC invocations=1559 (full 0):
garbage-first heap total 94371840K, used 44456740K [0x00007f76d0000000, 0x00007f76d2005a00, 0x00007f8d50000000)
region size 32768K, 49 young (1605632K), 49 survivors (1605632K)
Metaspace used 77160K, capacity 77951K, committed 78080K, reserved 79872K
}
[Times: user=7.11 sys=0.18, real=0.26 secs]
2015-10-04T15:00:05.457-0400: 204611.288: [GC concurrent-root-region-scan-start]
2015-10-04T15:00:05.457-0400: 204611.288: Total time for which application threads were stopped: 0.2607079 seconds, Stopping threads took: 0.0000623 seconds
2015-10-04T15:00:05.593-0400: 204611.424: [GC concurrent-root-region-scan-end, 0.1359037 secs]
2015-10-04T15:00:05.593-0400: 204611.424: [GC concurrent-mark-start]
2015-10-04T15:00:06.238-0400: 204612.069: [GC concurrent-mark-end, 0.6448793 secs]
2015-10-04T15:00:06.238-0400: 204612.069: [GC remark 2015-10-04T15:00:06.238-0400: 204612.069: [Finalize Marking, 82.5606577 secs] 2015-10-04T15:01:28.799-0400: 204694.630: [GC ref-proc2015-10-04T15:01:28.799-0400: 204694.630: [SoftRefer
ence, 64 refs, 0.0031041 secs]2015-10-04T15:01:28.802-0400: 204694.633: [WeakReference, 383 refs, 0.0023197 secs]2015-10-04T15:01:28.805-0400: 204694.636: [FinalReference, 100288 refs, 0.0330312 secs]2015-10-04T15:01:28.838-0400: 204694.
669: [PhantomReference, 2 refs, 37 refs, 0.0030514 secs]2015-10-04T15:01:28.841-0400: 204694.672: [JNI Weak Reference, 0.0000915 secs], 0.0539037 secs] 2015-10-04T15:01:28.853-0400: 204694.684: [Unloading, 0.0130054 secs], 82.6649201 sec
s]
[Times: user=1139.19 sys=393.93, real=82.65 secs]
2015-10-04T15:01:28.903-0400: 204694.735: Total time for which application threads were stopped: 82.6655358 seconds, Stopping threads took: 0.0000918 seconds
2015-10-04T15:01:28.904-0400: 204694.735: [GC cleanup 42G->42G(90G), 0.1166196 secs]
More information about the hotspot-gc-use
mailing list