JVM之GC日志续

本文大概阐述和GC日志相关的jvm启动参数的一些内容。

GC日志相关基本参数

-XX:+PrintGCDetails 
  输出GC的详细日志
-XX:+PrintGCTimeStamps 
  输出GC的时间戳（以基准时间的形式）
-XX:+PrintGCDateStamps 
  输出GC的时间戳（以日期的形式，如 2013-05-04T21:53:59.234+0800）
-XX:+PrintHeapAtGC 
  在进行GC的前后打印出堆的信息
-XX:+PrintGCApplicationStoppedTime 
  输出GC造成应用暂停的时间
-XX:+PrintReferenceGC
  引用相关信息，虚、弱、强引用的个数和耗时
-Xloggc:../logs/gc.log 
  日志文件的输出路径

特殊说明：生产环境gc日志要遵循够用就好的原则，因为gc日志的时间也是会算在stw时间里的，如果gc日志的输出是同步刷盘模式，有可能会因为系统其他IO异常造成gc停顿时间的异常（由于gc打印造成的异常我们下一篇再详细介绍下）

GC日志相关特殊参数

1. GC日志滚动

-XX:+UseGCLogFileRotation

GC日志的输出会发生文件IO，有时候也会造成不必要的停顿，可以将GC日志输出到tmpfs（内存文件系统）中，但tmpfs会消耗内存，为了避免内存被浪费可以使用-XX:+UseGCLogFileRotation滚动GC日志。

2. 禁写Statistics数据

-XX:+PerfDisableSharedMem

gstst会默默的在/tmp/hperf 目录写上一点statistics数据。

如果gc时，刚好遇到PageCache刷盘，把文件阻塞了，就不能结束这个Stop the World的安全点了。用上述参数禁用jstat,用jmx来代替即可。参见：jvm-mmap-pause

3. 安全点相关参数

-XX:+PrintSafepointStatistics 
-XX:PrintSafepointStatisticsCount = 1

安全点相关日志输出如下：

         vmop                    [threads: total initially_running wait_to_block]    [time: spin block sync cleanup vmop] page_trap_count
0.257: ParallelGCFailedAllocation       [       9          0              0    ]      [     0     0     0     0     2    ]  0
0.261: no vm operation                  [       7          0              1    ]      [     0     0     0     0     0    ]  0

• vmop
  • 表示 引发STW的原因
• [thread]
  • total：安全点里的总线程数
  • initially_running：安全点时开始时正在运行状态的线程数
  • wait_to_block：在VM Operation开始前需要等待其暂停的线程数
• [time]
  • spin：等待线程响应safepoint号召的时间
  • block：暂停所有线程所用的时间
  • sync：(spin + block)，==从开始到进入安全点所耗的时间，可用于判断进入安全点耗时
  • cleanup：清理所需时间
  • vmop：真正执行VM Operation的时间

no vm operation 说明这里没有vm相关操作发生，因此表示是一个安全点

安全点对系统的健康监控是非常重要的。会使用到安全点的场景有GC、偏向锁撤销等，总之是提供一个对象状态不变的状态点，去让系统进行一系列的后续操作。

这里要顺便提一下另一个和安全点相关的jvm参数：-XX:-UseBiasedLocking

禁用偏向锁的设置参数，在有的情况下比较有效，如果并发竞争变大，会导致偏向锁撤销频繁，这个时候我们可能会看到安全点的耗时增加，进而导致了gc时间和系统响应时间增大，关于安全点和偏向锁的异常案例，我们也放在下一篇一并列举

补:性能和调优相关特殊参数

1. dump相关参数

这个应该不属于gc日志相关参数，但是都在jvm启动参数里，就顺便提下

• 1.heap dump

-XX:+HeapDumpOnOutOfMemoryError

这个参数，主要作用是，在系统发生oom异常时，自动进行heap dump操作，有些大佬说在容器环境混部情况下，在普通硬盘上会造成20秒以上的硬盘IO跑满，对其他宿主程序是很不友好的，但是按生产环境的实际运营情况看，这个参数还是非常有用的，在系统发生oom异常需要尽快重启恢复的时候，dump下来的现场文件对异常的排查是非常有帮助的。

• 2.core dump

ulimit -c unlimited

从CoreDump能够转出Heap Dump 和 Thread Dump 还有crash的地方，非常实用

2. Integer Cache

-XX:AutoBoxCacheMax=20000

对于Integer和 Long，JDK默认只缓存 -128 ~ +127，超出范围的数字就要实时构建新的Integer对象。对于性能要求很高的系统场景，可以设置此参数，据有关测算，QPS影响达4%左右。

3. 启动时预访问

 -XX:+AlwaysPreTouch

ElasticSearch和Cassandra都设置了此参数。作用是内存页预访问，可能启动时慢上一点，但访问时会更快速些，比如新生代晋升到老生代时不会临时访问页面使得GC停顿时间加长。

4. 即时编译

-XX:-UseCounterDecay
-XX:-TieredCompilation

gc默认进行技术器衰减操作，可能会导致某些临界访问量的方法，一直无法转成热点代码，所以可以使用UseCounterDecay参数来禁用计数器衰减操作。TieredCompilation是1.8默认开启的多层编译。但是业界大佬在实测时发现启动初期可能有性能减弱，有需要可以将其禁用。

总结

本篇主要概述了gc日志所涉及到的一些可能需要关注的参数设置，其中提及的一些实际案例，我们后续文章补充；也顺便列举了一些和性能相关的jvm启动参数，在大家平时有遇到类似问题可以当做个参考。

当然，和gc相关的jvm启动参数是非常多的，gc策略、并发收集线程数、eden和s区的比例、对象年代、cms的碎片压缩、G1的停顿时间等等，每一个都可以结合实际需求单独一篇来展开阐述。后续有机会再逐一补充吧