Very long duration of Finalize marking in the Remark stage of G1GC
Ivan Shramko
vanbeast at gmail.com
Wed Oct 14 10:18:12 UTC 2015
I don't think it's in use. There is no process named "*khugepaged*".
grep -i HugePages /proc/meminfo:
AnonHugePages: 0 kB
HugePages_Total: 0
HugePages_Free: 0
HugePages_Rsvd: 0
HugePages_Surp: 0
2015-10-14 13:10 GMT+03:00 Alex Bagehot <ceeaspb at gmail.com>:
> Hi Ivan,
> Just to be sure can you confirm it is disabled *and* no longer in use?
> There's a risk it was disabled but still in use, see below:
> https://access.redhat.com/solutions/46111
> https://access.redhat.com/solutions/422283
>
> Thanks,
> Alex
>
>
>
> On Wed, Oct 14, 2015 at 10:47 AM, Ivan Shramko <vanbeast at gmail.com> wrote:
>
>> Hi Charlie!
>> I disabled transparent huge pages but it didn't help. We are still having
>> repeating pauses in Finalize Marking.
>> Best regards,
>> Ivan
>>
>> 2015-10-12 16:47 GMT+03:00 Ivan Shramko <vanbeast at gmail.com>:
>>
>>> 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
>>>>
>>>>
>>>>
>>>
>>
>> _______________________________________________
>> 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/20151014/b783df80/attachment-0001.html>
More information about the hotspot-gc-use
mailing list