Very long duration of Finalize marking in the Remark stage of G1GC
Ivan Shramko
vanbeast at gmail.com
Mon Oct 12 13:47:02 UTC 2015
Hi Charlie!
Thanks for the reply. We use Linux (CentOS 6 64 bit). I didn't notice any
swapping activity while server was running. But transparent huge pages
option was enabled. I will try to disable it and report if it helps or not.
Best regards,
Ivan
2015-10-12 15:40 GMT+03:00 charlie hunt <charlie.hunt at oracle.com>:
> Hi Ivan,
>
> The remark pause (in addition to high “Finalize Marking”) also has a
> rather high reported sys CPU time. Usually when I see high sys CPU time, it
> is often a symptom of paging to/from virtual memory, or if you are running
> on Linux it is a symptom of transparent huge pages being enabled. Fwiw, I
> don’t think I’ve seen a high “Finalize Marking” time like what you have
> here.
>
> Could you confirm you are not paging to/from virtual memory, and if you
> are running on Linux, can you also confirm transparent huge pages are
> disabled?
>
> thanks,
>
> charlie
>
>
>
> On Oct 12, 2015, at 4:14 AM, Ivan Shramko <vanbeast at gmail.com> wrote:
>
> Application becomes unresponsive on high load while G1 garbage collector
> is in the Remark stage(Finalize marking).
> This is part of the gc log:
>
> {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]
>
>
> Java version:
> Java version "1.8.0_60"Java(TM) SE Runtime Environment (build 1.8.0_60-b27)Java HotSpot(TM) 64-Bit Server VM (build 25.60-b23, mixed mode)
>
> Server has 128GB of RAM and 32 cores(with HyperThreading).
>
> GC-related JVM options:
>
> -XX:InitialHeapSize=107374182400 -XX:+ManagementServer -XX:MaxHeapSize=107374182400 -XX:-OmitStackTraceInFastThrow -XX:+PrintGC
> -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+TieredCompilation -XX:+UseCondCardMark -XX:+UseG1GC
> -XX:ParallelGCThreads=32 -XX:+UnlockDiagnosticVMOptions -XX:ParGCCardsPerStrideChunk=32678 -XX:+ParallelRefProcEnabled -J-XX:MaxGCPauseMillis=100
>
>
> Any ideas what can be the reason?
>
>
>
>
> _______________________________________________
> hotspot-gc-use mailing list
> hotspot-gc-use at openjdk.java.net
> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20151012/92a27aa1/attachment.html>
More information about the hotspot-gc-use
mailing list