【G1】年轻代收集日志分析 - shenjy24/jackal-gc GitHub Wiki
执行参数
-XX:+UseG1GC -XX:+PrintGCDetails
演示代码
public class GCLogAnalysis {
private static Random random = new Random();
public static void main(String[] args) {
// 当前毫秒时间戳
long startMillis = System.currentTimeMillis();
// 持续运行毫秒数; 可根据需要进行修改
long timeoutMillis = TimeUnit.SECONDS.toMillis(1);
// 结束时间戳
long endMillis = startMillis + timeoutMillis;
LongAdder counter = new LongAdder();
System.out.println("正在执行...");
// 缓存一部分对象; 进入老年代
int cacheSize = 2000;
Object[] cachedGarbage = new Object[cacheSize];
// 在此时间范围内,持续循环
while (System.currentTimeMillis() < endMillis) {
// 生成垃圾对象
Object garbage = generateGarbage(100 * 1024);
counter.increment();
int randomIndex = random.nextInt(2 * cacheSize);
if (randomIndex < cacheSize) {
cachedGarbage[randomIndex] = garbage;
}
}
System.out.println("执行结束!共生成对象次数:" + counter.longValue());
}
// 生成对象
private static Object generateGarbage(int max) {
int randomSize = random.nextInt(max);
int type = randomSize % 4;
Object result = null;
switch (type) {
case 0:
result = new int[randomSize];
break;
case 1:
result = new byte[randomSize];
break;
case 2:
result = new double[randomSize];
break;
default:
StringBuilder builder = new StringBuilder();
String randomString = "randomString-Anything";
while (builder.length() < randomSize) {
builder.append(randomString);
builder.append(max);
builder.append(randomSize);
}
result = builder.toString();
break;
}
return result;
}
}
日志输出
//年轻代收集日志
[GC pause (G1 Evacuation Pause) (young), 0.0270064 secs]
[Parallel Time: 18.6 ms, GC Workers: 15]
[GC Worker Start (ms): Min: 904.0, Avg: 904.2, Max: 904.3, Diff: 0.2]
[Ext Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.6]
[Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4]
[Processed Buffers: Min: 0, Avg: 1.1, Max: 3, Diff: 3, Sum: 16]
[Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 17.4, Avg: 17.5, Max: 17.6, Diff: 0.2, Sum: 262.6]
[Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.9]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 15]
[GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.7]
[GC Worker Total (ms): Min: 17.6, Avg: 17.8, Max: 18.0, Diff: 0.3, Sum: 266.4]
[GC Worker End (ms): Min: 921.9, Avg: 921.9, Max: 922.1, Diff: 0.2]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.7 ms]
[Other: 7.7 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 0.7 ms]
[Ref Enq: 0.0 ms]
[Redirty Cards: 0.3 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.1 ms]
[Eden: 624.0M(624.0M)->0.0B(840.0M) Survivors: 72.0M->88.0M Heap: 1254.0M(12.1G)->767.4M(12.8G)]
[Times: user=0.09 sys=0.14, real=0.03 secs]
Heap
garbage-first heap total 13467648K, used 1420694K [0x00000003c1400000, 0x00000003c18066c0, 0x00000007c0000000)
region size 4096K, 178 young (729088K), 22 survivors (90112K)
Metaspace used 4043K, capacity 4572K, committed 4864K, reserved 1056768K
class space used 449K, capacity 460K, committed 512K, reserved 1048576K
字段释义如下：
[GC pause (G1 Evacuation Pause) (young), 0.0270064 secs]：G1转移暂停，只清理年轻代空间。持续的系统时间为0.0270064秒 。[Parallel Time: 18.6 ms, GC Workers: 15]：表明后面的活动由 15 个worker线程并行执行, 消耗时间为18.6毫秒。GC Worker Start (ms)：相对于 pause 开始的时间戳，GC的worker线程开始启动所用时间。如果Min和Max差别很大，则表明本机其他进程所使用的线程数量过多， 挤占了GC的CPU时间。Ext Root Scanning (ms)：用了多长时间来扫描堆外(non-heap)的root， 如classloaders,JNI引用,JVM的系统root等。后面显示了运行时间,sum指的是CPU时间。Update RS (ms)：更新Remembered Sets使用的时间。Processed Buffers：每个worker线程处理了多少个本地缓冲区(local buffer)。Scan RS (ms)：用了多长时间扫描来自RSet的引用。Code Root Scanning (ms)：用了多长时间来扫描实际代码中的root。Object Copy (ms)：用了多长时间来拷贝收集区内的存活对象。Termination (ms)：GC的worker线程用了多长时间来确保自身可以安全地停止， 这段时间什么也不用做，stop之后该线程就终止运行了。Termination Attempts：GC的worker线程尝试多少次try和teminate。如果worker发现还有一些任务没处理完，则这一次尝试就是失败的， 暂时还不能终止。GC Worker Other (ms)：处理一些琐碎的小活动所用的时间，在GC日志中不值得单独列出来。GC Worker Total (ms)：GC的worker线程的工作时间总计。GC Worker End (ms)：相对于pause开始的时间戳，GC的worker线程完成作业的时间。通常来说这部分数字应该大致相等， 否则就说明有太多的线程被挂起， 很可能是因为坏邻居效应(noisy neighbor) 所导致的。Code Root Fixup：释放用于管理并行活动的内部数据。一般都接近于零。这是串行执行的过程。Code Root Purge：清理其他部分数据， 也是非常快的，但如非必要则几乎等于零。这是串行执行的过程。Clear CT：清理card table中cards的时间。清理工作只是简单地删除“脏”状态， 此状态用来标识一个字段是否被更新的， 供Remembered Sets使用。Other：其他活动消耗的时间， 其中有很多也是并行执行的。Choose CSet：选择CSet使用时间，CSet是指Collection Set，和RSet(Remembered Set)一样，用于辅助GC，用空间换时间。Ref Proc：处理非强引用(non-strong)的时间，进行清理或者决定是否需要清理。Ref Enq：用来将剩下的non-strong引用排列到合适的ReferenceQueue中。Redirty Cards：重新脏化卡片。排队引用可能会更新RSet，所以需要对关联的Card重新脏化。Humongous Register和Humongous Reclaim：主要是对巨型对象回收的信息，youngGC阶段会对RSet中有引用的短命的巨型对象进行回收，巨型对象会直接回收而不需要进行转移（转移代价巨大，也没必要）。Free CSet：释放CSet中的region到free list使用时间。[Eden: 624.0M(624.0M)->0.0B(840.0M) Survivors: 72.0M->88.0M Heap: 1254.0M(12.1G)->767.4M(12.8G)]：暂停之前和暂停之后， Eden 区的使用量/总容量。 暂停之前和暂停之后， 存活区的使用量。暂停之前和暂停之后， 整个堆内存的使用量与总容量。[Times: user=0.09 sys=0.14, real=0.03 secs]：GC事件的持续时间，通过三个部分（用户线程，系统调用， 应用程序暂停的时间）来衡量。