G1 gc подозрительно длинные паузы - PullRequest
Новая
       30

G1 gc подозрительно длинные паузы

0 голосов
/ 07 ноября 2018

У меня странные паузы G1 gc - gc тратит много времени в фазе 'Ref Proc'. Я использую сервер региона hbase со следующими параметрами gc 

Java HotSpot(TM) 64-Bit Server VM (25.192-b12) for linux-amd64 JRE (1.8.0_192-b12), built on Oct  6 2018 06:46:09 by "java_re" with gcc 7.3.0
Memory: 4k page, physical 65963112k(21241308k free), swap 0k(0k free)
CommandLine flags: -XX:G1HeapRegionSize=8388608 -XX:G1HeapWastePercent=15 -XX:G1MaxNewSizePercent=20 -XX:G1MixedGCCountTarget=16 -XX:G1OldCSetRegionThresholdPercent=2 -XX:G1RSetUpdatingPauseTimePercent=5 -XX:InitialHeapSize=6442450944 -XX:InitialTenuringThreshold=1 -XX:InitiatingHeapOccupancyPercent=75 -XX:+ManagementServer -XX:MaxDirectMemorySize=16106127360 -XX:MaxGCPauseMillis=25 -XX:MaxHeapSize=6442450944 -XX:MaxTenuringThreshold=1 -XX:-OmitStackTraceInFastThrow -XX:OnOutOfMemoryError=kill -9 %p -XX:OnOutOfMemoryError=/usr/lib64/cmf/service/common/killparent.sh -XX:+ParallelRefProcEnabled -XX:+PerfDisableSharedMem -XX:+PrintAdaptiveSizePolicy -XX:+PrintGC -XX:+PrintGCApplicationStoppedTime -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintReferenceGC -XX:+PrintTenuringDistribution -XX:-ResizePLAB -XX:SurvivorRatio=6 -XX:+UnlockExperimentalVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC

Большинство пауз занимают примерно 30 мс, 99,9% - 70 мс. Но время от времени (пару раз в день) у меня паузы длиннее 500 мс, подавляющее большинство времени занимает «Ref Prof». Пример такой паузы: 

2018-11-05T20:50:31.718+0000: 48282.452: [GC pause (G1 Evacuation Pause) (mixed)
Desired survivor size 29360128 bytes, new threshold 1 (max 1)
- age   1:    6821648 bytes,    6821648 total
 48282.452: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 3250, predicted base time: 21.77 ms, remaining time: 3.23 ms, target pause time: 25.00 ms]
 48282.452: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 37 regions, survivors: 1 regions, predicted young region time: 4.87 ms]
 48282.452: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: old CSet region num reached max, old: 16 regions, max: 16 regions]
 48282.452: [G1Ergonomics (CSet Construction) added expensive regions to CSet, reason: old CSet region num not reached min, old: 16 regions, expensive: 16 regions, min: 37 regions, remaining time: 0.00 ms]
 48282.452: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 37 regions, survivors: 1 regions, old: 16 regions, predicted pause time: 37.72 ms, target pause time: 25.00 ms]
2018-11-05T20:50:31.735+0000: 48282.469: [SoftReference, 0 refs, 0.0030858 secs]2018-11-05T20:50:32.284+0000: 48283.018: [WeakReference, 2208 refs, 0.0086701 secs]2018-11-05T20:50:32.293+0000: 48283.027: [FinalReference, 58 refs, 0.0025096 secs]2018-11-05T20:50:32.295+0000: 48283.029: [PhantomReference, 0 refs, 10 refs, 0.0048406 secs]2018-11-05T20:50:32.300+0000: 48283.034: [JNI Weak Reference, 0.0000199 secs] 48283.040: [G1Ergonomics (Mixed GCs) continue mixed GCs, reason: candidate old regions available, candidate old regions: 498 regions, reclaimable: 2389907808 bytes (37.10 %), threshold: 15.00 %]
, 0.5876303 secs]
   [Parallel Time: 16.4 ms, GC Workers: 18]
      [GC Worker Start (ms): Min: 48282452.3, Avg: 48282452.6, Max: 48282453.0, Diff: 0.6]
      [Ext Root Scanning (ms): Min: 0.4, Avg: 0.8, Max: 1.3, Diff: 0.8, Sum: 13.8]
      [Update RS (ms): Min: 0.2, Avg: 1.4, Max: 2.0, Diff: 1.8, Sum: 24.5]
         [Processed Buffers: Min: 1, Avg: 3.2, Max: 8, Diff: 7, Sum: 57]
      [Scan RS (ms): Min: 5.9, Avg: 6.4, Max: 6.8, Diff: 1.0, Sum: 114.6]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 7.1, Avg: 7.2, Max: 8.1, Diff: 1.0, Sum: 129.9]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 1.1]
         [Termination Attempts: Min: 1, Avg: 1.4, Max: 3, Diff: 2, Sum: 25]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
      [GC Worker Total (ms): Min: 15.4, Avg: 15.8, Max: 16.1, Diff: 0.6, Sum: 284.2]
      [GC Worker End (ms): Min: 48282468.4, Avg: 48282468.4, Max: 48282468.4, Diff: 0.0]
   [Code Root Fixup: 0.0 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 2.0 ms]
   [Other: 569.2 ms]
      [Choose CSet: 0.2 ms]
      [Ref Proc: 565.6 ms]
      [Ref Enq: 1.2 ms]
      [Redirty Cards: 1.5 ms]
      [Humongous Register: 0.0 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.4 ms]
   [Eden: 296.0M(296.0M)->0.0B(280.0M) Survivors: 8192.0K->24.0M Heap: 4615.3M(6144.0M)->4238.7M(6144.0M)]
 [Times: user=0.43 sys=0.01, real=0.59 secs]

Многие паузы тратят около 20-30 мс в Ref Proc, и что для них характерно - например, они тратят время на сбор SoftReference [SoftReference, 0 ссылок, 0,0166254 с] Как это может занять так много времени, чтобы собрать ноль ссылок?

Как я могу уменьшить эти паузы?

...