Нет сбоев эвакуации, но все еще FullGC в G1GC

Я настраиваю G1GC, избегая FullGC. Следуя этим советам http://www.infoq.com/articles/tuning-tips-G1-GC , я не вижу никаких журналов, таких как «исчерпание пространства».

Java HotSpot(TM) 64-Bit Server VM (24.76-b04) for linux-amd64 JRE (1.7.0_76-b13), built on Dec 18 2014 16:58:39 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 32934888k(13890072k free), swap 48197628k(48197628k free)
CommandLine flags: 
-XX:AutoBoxCacheMax=3000000 -XX:ConcGCThreads=4 -XX:+DisableExplicitGC -XX:G1ReservePercent=25 -XX:+HeapDumpOnOutOfMemoryError -XX:InitialHeapSize=11811160064 -XX:MaxDirectMemorySize=1073741824 -XX:MaxGCPauseMillis=1000 -XX:MaxHeapSize=11811160064 -XX:-OmitStackTraceInFastThrow 
-XX:ParallelGCThreads=8 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps 
-XX:+PrintTenuringDistribution -XX:+UseCompressedOops -XX:+UseG1GC

По каким еще причинам GC решил бы провести полную коллекцию? Или у него все еще есть неудачи эвакуации, но журнал не включен?

70861.400: [GC pause (mixed)
Desired survivor size 37748736 bytes, new threshold 1 (max 15)
- age   1:   49450208 bytes,   49450208 total
- age   2:    3236616 bytes,   52686824 total
- age   3:   10086240 bytes,   62773064 total
- age   4:     188936 bytes,   62962000 total
- age   5:     816536 bytes,   63778536 total
- age   6:    1024560 bytes,   64803096 total
- age   7:    1341640 bytes,   66144736 total
- age   8:    1562648 bytes,   67707384 total
- age   9:      59200 bytes,   67766584 total
, 0.2471520 secs]
[Parallel Time: 225.0 ms, GC Workers: 8]
[GC Worker Start (ms): Min: 70861401.2, Avg: 70861401.4, Max: 70861401.7, Diff: 0.6]
    [Ext Root Scanning (ms): Min: 3.8, Avg: 4.1, Max: 4.5, Diff: 0.6, Sum: 33.0]
      [Update RS (ms): Min: 93.2, Avg: 93.4, Max: 93.5, Diff: 0.3, Sum: 746.9]
         [Processed Buffers: Min: 92, Avg: 108.0, Max: 124, Diff: 32, Sum: 864]
      [Scan RS (ms): Min: 29.7, Avg: 29.7, Max: 29.8, Diff: 0.1, Sum: 238.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 95.9, Avg: 96.2, Max: 97.0, Diff: 1.1, Sum: 769.6]
      [Termination (ms): Min: 0.0, Avg: 0.8, Max: 1.0, Diff: 1.0, Sum: 6.4]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 0.7]
      [GC Worker Total (ms): Min: 224.1, Avg: 224.3, Max: 224.6, Diff: 0.6, Sum: 1794.6]
      [GC Worker End (ms): Min: 70861625.7, Avg: 70861625.7, Max: 70861625.9, Diff: 0.2]
   [Code Root Fixup: 0.2 ms]
   [Code Root Migration: 0.1 ms]
   [Clear CT: 4.8 ms]
   [Other: 17.2 ms]
      [Choose CSet: 0.4 ms]
      [Ref Proc: 7.5 ms]
      [Ref Enq: 0.1 ms]
      [Free CSet: 1.0 ms]
   [Eden: 488.0M(488.0M)->0.0B(2956.0M) Survivors: 72.0M->20.0M Heap: 5882.4M(11.0G)->5394.1M(11.0G)]


71319.172: [GC pause (young) (initial-mark)
Desired survivor size 195035136 bytes, new threshold 15 (max 15)
- age   1:    3965480 bytes,    3965480 total
, 0.2243330 secs]
   [Parallel Time: 182.7 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 71319173.4, Avg: 71319173.6, Max: 71319174.0, Diff: 0.6]
      [Ext Root Scanning (ms): Min: 3.4, Avg: 4.0, Max: 4.4, Diff: 1.0, Sum: 31.8]
      [Code Root Marking (ms): Min: 2.0, Avg: 2.7, Max: 6.0, Diff: 4.0, Sum: 21.4]
      [Update RS (ms): Min: 105.7, Avg: 109.2, Max: 110.6, Diff: 4.9, Sum: 873.2]
         [Processed Buffers: Min: 115, Avg: 127.6, Max: 142, Diff: 27, Sum: 1021]
      [Scan RS (ms): Min: 11.7, Avg: 12.6, Max: 12.9, Diff: 1.1, Sum: 100.9]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.2]
      [Object Copy (ms): Min: 52.2, Avg: 52.7, Max: 52.9, Diff: 0.7, Sum: 421.2]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.2, Max: 0.6, Diff: 0.6, Sum: 1.9]
      [GC Worker Total (ms): Min: 181.0, Avg: 181.3, Max: 181.6, Diff: 0.6, Sum: 1450.7]
      [GC Worker End (ms): Min: 71319354.8, Avg: 71319355.0, Max: 71319355.3, Diff: 0.6]
   [Code Root Fixup: 0.3 ms]
   [Code Root Migration: 0.2 ms]
   [Clear CT: 3.6 ms]
   [Other: 37.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 29.8 ms]
      [Ref Enq: 0.5 ms]
      [Free CSet: 2.3 ms]
   [Eden: 2332.0M(2956.0M)->0.0B(2872.0M) Survivors: 20.0M->72.0M Heap: 7725.6M(11.0G)->5448.0M(11.0G)]
 [Times: user=1.51 sys=0.00, real=0.22 secs]
71319.397: [GC concurrent-root-region-scan-start]
71319.468: [GC concurrent-root-region-scan-end, 0.0707700 secs]
71319.468: [GC concurrent-mark-start]
71320.512: [GC pause (young)
Desired survivor size 192937984 bytes, new threshold 15 (max 15)
- age   1:   57002072 bytes,   57002072 total
- age   2:    3685360 bytes,   60687432 total
, 0.1300980 secs]
   [Parallel Time: 122.5 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 71320513.1, Avg: 71320513.3, Max: 71320513.8, Diff: 0.7]
      [Ext Root Scanning (ms): Min: 3.5, Avg: 4.0, Max: 4.3, Diff: 0.8, Sum: 32.4]
      [SATB Filtering (ms): Min: 0.0, Avg: 0.1, Max: 0.8, Diff: 0.8, Sum: 0.8]
      [Update RS (ms): Min: 75.2, Avg: 75.7, Max: 76.0, Diff: 0.8, Sum: 605.8]
         [Processed Buffers: Min: 169, Avg: 183.8, Max: 202, Diff: 33, Sum: 1470]
      [Scan RS (ms): Min: 2.9, Avg: 2.9, Max: 3.0, Diff: 0.1, Sum: 23.3]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 38.7, Avg: 38.8, Max: 38.9, Diff: 0.1, Sum: 310.4]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
      [GC Worker Total (ms): Min: 121.2, Avg: 121.7, Max: 121.9, Diff: 0.7, Sum: 973.3]
      [GC Worker End (ms): Min: 71320635.0, Avg: 71320635.0, Max: 71320635.0, Diff: 0.0]
   [Code Root Fixup: 0.2 ms]
   [Code Root Migration: 0.0 ms]
   [Clear CT: 1.4 ms]
   [Other: 6.0 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 0.7 ms]
      [Ref Enq: 0.0 ms]
      [Free CSet: 0.5 ms]
   [Eden: 260.0M(2872.0M)->0.0B(2736.0M) Survivors: 72.0M->68.0M Heap: 5828.3M(11.0G)->5562.4M(11.0G)]
 [Times: user=0.98 sys=0.00, real=0.12 secs]


71320.645: [Full GC 5562M->3567M(11G), 23.7159350 secs]
   [Eden: 0.0B(2736.0M)->0.0B(4804.0M) Survivors: 68.0M->0.0B Heap: 5562.4M(11.0G)->3567.2M(11.0G)], [Perm: 34637K->34637K(36864K)]
 [Times: user=38.34 sys=0.02, real=23.72 secs]

71344.362: [GC concurrent-mark-abort]
71436.544: [GC pause (young)
Desired survivor size 316669952 bytes, new threshold 15 (max 15)
- age   1:     448512 bytes,     448512 total
- age   2:   55511136 bytes,   55959648 total
- age   3:    3685280 bytes,   59644928 total
, 0.2012910 secs]
   [Parallel Time: 183.5 ms, GC Workers: 8]
      [GC Worker Start (ms): Min: 71436545.9, Avg: 71436546.2, Max: 71436546.6, Diff: 0.7]
      [Ext Root Scanning (ms): Min: 5.2, Avg: 5.4, Max: 5.9, Diff: 0.7, Sum: 43.3]
      [Update RS (ms): Min: 44.0, Avg: 45.8, Max: 52.6, Diff: 8.6, Sum: 366.0]
         [Processed Buffers: Min: 118, Avg: 128.2, Max: 136, Diff: 18, Sum: 1026]
      [Scan RS (ms): Min: 5.2, Avg: 11.8, Max: 13.5, Diff: 8.3, Sum: 94.4]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3]
      [Object Copy (ms): Min: 118.8, Avg: 118.9, Max: 119.1, Diff: 0.3, Sum: 951.4]
      [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.3, Max: 0.5, Diff: 0.5, Sum: 2.3]
      [GC Worker Total (ms): Min: 181.9, Avg: 182.3, Max: 182.6, Diff: 0.7, Sum: 1458.3]
      [GC Worker End (ms): Min: 71436728.2, Avg: 71436728.5, Max: 71436728.7, Diff: 0.5]
   [Code Root Fixup: 0.2 ms]
   [Code Root Migration: 0.3 ms]
   [Clear CT: 4.2 ms]
   [Other: 13.1 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 6.6 ms]
      [Ref Enq: 0.1 ms]
      [Free CSet: 3.6 ms]
   [Eden: 4804.0M(4804.0M)->0.0B(3412.0M) Survivors: 0.0B->152.0M Heap: 9208.4M(11.0G)->4554.4M(11.0G)]
 [Times: user=1.50 sys=0.00, real=0.20 secs]

Он запустил FullGC на 71320.645, но, похоже, сбоев эвакуации не произошло, есть идеи?


person Chi Shin Hsu    schedule 17.06.2015    source источник


Ответы (1)


Вероятно, не стоит запускать G1GC на Java 7. Тогда у него было много проблемного поведения. Среди них то, что для выгрузки класса требовался полный GC, это было исправлено с помощью jdk8u40

Не говоря уже о том, что журналы GC дают больше полезной информации в версии 8.

Однако возможны и другие причины, такие как выделение огромных объектов, требующее большего количества последовательных свободных областей, чем доступно. Журналы 8, вероятно, окажутся более полезными.

Редактировать: На самом деле эта функция может быть в 7u45 за флагом, попробуйте -XX:+PrintGCCause

person the8472    schedule 17.06.2015