G1 日志解析

G1 GC 日志

2020-04-08T13:37:57.402+0800: 317780.856: Application time: 1.7859709 seconds
2020-04-08T13:38:00.137+0800: 317783.591: Application time: 2.7316155 seconds
{Heap before GC invocations=54601 (full 2):
 garbage-first heap   total 12582912K, used 7858402K [0x00000004c0000000, 0x00000004c0803000, 0x00000007c0000000)
  region size 8192K, 122 young (999424K), 16 survivors (131072K)
 Metaspace       used 173730K, capacity 186222K, committed 186368K, reserved 1216512K
  class space    used 17662K, capacity 19184K, committed 19200K, reserved 1048576K
2020-04-08T13:38:00.141+0800: 317783.595: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 67108864 bytes, new threshold 1 (max 8)
- age   1:  133934832 bytes,  133934832 total
, 0.1140744 secs]
   [Parallel Time: 110.4 ms, GC Workers: 5]
      [GC Worker Start (ms): Min: 317783595.6, Avg: 317783595.6, Max: 317783595.7, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 2.6, Avg: 2.9, Max: 3.3, Diff: 0.6, Sum: 14.5]
      [Update RS (ms): Min: 11.2, Avg: 11.6, Max: 11.8, Diff: 0.6, Sum: 58.1]
         [Processed Buffers: Min: 180, Avg: 198.0, Max: 209, Diff: 29, Sum: 990]
      [Scan RS (ms): Min: 10.7, Avg: 10.8, Max: 10.8, Diff: 0.1, Sum: 53.8]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 84.7, Avg: 85.0, Max: 85.1, Diff: 0.4, Sum: 424.9]
      [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.1]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 110.3, Avg: 110.3, Max: 110.3, Diff: 0.0, Sum: 551.5]
      [GC Worker End (ms): Min: 317783705.9, Avg: 317783705.9, Max: 317783705.9, Diff: 0.0]
   [Code Root Fixup: 0.3 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.2 ms]
   [Other: 3.2 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.1 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.3 ms]
      [Humongous Reclaim: 0.2 ms]
      [Free CSet: 0.2 ms]
   [Eden: 848.0M(848.0M)->0.0B(904.0M) Survivors: 128.0M->72.0M Heap: 7674.2M(12.0G)->6722.0M(12.0G)]
Heap after GC invocations=54602 (full 2):
 garbage-first heap   total 12582912K, used 6883374K [0x00000004c0000000, 0x00000004c0803000, 0x00000007c0000000)
  region size 8192K, 9 young (73728K), 9 survivors (73728K)
 Metaspace       used 173730K, capacity 186222K, committed 186368K, reserved 1216512K
  class space    used 17662K, capacity 19184K, committed 19200K, reserved 1048576K
}
 [Times: user=0.56 sys=0.00, real=0.11 secs] 
2020-04-08T13:38:00.958+0800: 317784.412: Application time: 0.7025791 seconds
2020-04-08T13:38:02.962+0800: 317786.416: Application time: 2.0001849 seconds

Desired survivor size 67108864 bytes, new threshold 1 (max 8) 分析：

-XX:+PrintTenuringDistribution 开启动态年龄日志   

-XX:MaxTenuringThreshold=8 设置的是年龄阈值，默认15（注意JVM是动态调整）实际值参考gc日志中的  new threshold 1 (max 8)

jvm是动态对对象年龄判定的，对象年龄指的是从Eden移到survivor区后 每一次minor gc年龄加1 。

源码参考：ageTable.cpp

uint AgeTable::compute_tenuring_threshold(size_t desired_survivor_size) {
  uint result;

  if (AlwaysTenure || NeverTenure) {
    assert(MaxTenuringThreshold == 0 || MaxTenuringThreshold == markOopDesc::max_age + 1,
           "MaxTenuringThreshold should be 0 or markOopDesc::max_age + 1, but is " UINTX_FORMAT, MaxTenuringThreshold);
    result = MaxTenuringThreshold;
  } else {
    size_t total = 0;
    uint age = 1;
    assert(sizes[0] == 0, "no objects with age zero should be recorded");
    while (age < table_size) {
      total += sizes[age];
      // check if including objects of age 'age' made us pass the desired
      // size, if so 'age' is the new threshold
      if (total > desired_survivor_size) break;
      age++;
    }
    result = age < MaxTenuringThreshold ? age : MaxTenuringThreshold;
  }

源码解析 ：

AlwaysTenure 标示设置的gc参数 全部晋升到老年代，neverTenure表示全部在年轻代。

desired_survivor_size表示 survivor目标使用率，默认是50 可通过参数-XX:TargetSurvivorRatio 设置

总结：

(G1 Evacuation Pause) (young) 表示发生在young区的gc (mix) 表示mix gc

Desired survivor size 67108864 bytes, new threshold 1 (max 8)  表示期望的（还需要的）survivor大小为 67108864 bytes

动态对象年龄为1 设置的最大值8.

- age   1:  133934832 bytes,  133934832 total 日志表示的对象年龄为1的对象占用的大小。