GC日志解读与分析

Demo

// GCLogAnalysis.java
import java.util.Random;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.LongAdder;
/*
演示GC日志生成与解读
*/
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;
    }
}

# 编译
javac -encoding UTF-8 GCLogAnalysis.java
# 运行
java -XX:+PrintGCDetails GCLogAnalysis
# 显示时间和将日志写入文件
java -XX:+PrintGCDetails -Xloggc:gc.demo.log -XX:+PrintGCDateStamps GCLogAnalysis
# 显示指定小的堆内存，模拟OOM
java -Xmx128m -XX:+PrintGCDetails GCLogAnalysis
java -Xmx512m -XX:+PrintGCDetails GCLogAnalysis
java -Xmx1024m -XX:+PrintGCDetails GCLogAnalysis
java -Xmx2g -XX:+PrintGCDetails GCLogAnalysis
# 使用SerialGC
java -XX:+UseSerialGC -Xms512m -Xmx512m -XX:+PrintGCDetails -Xloggc:gc.demo.log -XX:+PrintGCDateStamps GCLogAnalysis
# 使用ParallelGC
java -XX:+UseParallelGC -Xms512m -Xmx512m -XX:+PrintGCDetails -Xloggc:gc.demo.log -XX:+PrintGCDateStamps GCLogAnalysis
# 使用CMS
java -XX:+UseConcMarkSweepGC -Xms512m -Xmx512m -XX:+PrintGCDetails -Xloggc:gc.demo.log -XX:+PrintGCDateStamps GCLogAnalysis
# 使用G1
java -XX:+UseG1GC -Xms512m -Xmx512m -XX:+PrintGCDetails -Xloggc:gc.demo.log -XX:+PrintGCDateStamps GCLogAnalysis

• 随着显示指定越来越大的堆内存
  • GC次数越来越少
  • 生成的对象越来越多，GC的时间越来越短
  • 到一定程度后不再波动

• 分类（不同的GC算法和并发不同，基本不区分这两套概念）

  • YoungGC与FullGC
  • MinorGC（小型GC）与MajorGC（大型GC）

    JVM线程堆栈数据分析

    线程模型示意图

    

    JVM内部线程主要分类

• VM线程：单例的VMThread对象，负责执行VM操作

• 定时任务线程：单例的WatcherThread对象，模拟在VM中执行定时操作的计时器中断
• GC线程：垃圾收集器中，用于支持并行和并发垃圾回收的线程
• 编译器线程：将字节码编译为本地机器代码

• 信号分发线程：等待进程指示的信号，并将其分配给Java级别的信号处理方法

  安全点

• 方法代码中被植入的安全点检测入口

• 线程处于安全点状态：线程暂停执行，这个时候线程栈不再发生改变

• JVM的安全点状态：所有线程都处于安全点状态

  JVM线程转储方式

• JDK工具

  • jstack
  • jcmd
  • jconsole
  • jvisualvm
  • JavaMissionControl
• Shell命令或系统控制台
  • kill -3
  • Ctrl + Break

• JMX技术

  • ThreadMx

    堆栈线程分析工具

• fastThread

  • Java线程Dump分析器

    解决死锁两种办法

• 事前要给锁定状态加上超时时间，超时后销毁线程

• 事中如果锁定形成环则销毁其中的一个线程以断开环关系

  内存分析与相关工具

  对象内存占用格式

• 一个对象占用多少内存，可以使用Instrumentation.getObjectSize()方法估算，无法精确计算

• JOL（Java Object Layout）可以用来查看对象的内存布局

对象头和对象引用

• 64位的JVM中，对象头占据的空间是12字节（96bit=64+32），但以8字节对齐，所以一个空类的实例至少占16字节
• 32位的JVM中，对象头占据的空间是8字节，但以4的倍数对齐（32 = 4 * 8 ）所以new出来很多简单对象，甚至是new Object()，都会占用不少内存
• 通常在32位JVM中，以及内存小于-Xmx32G的64位JVM上，都默认开启了指针压缩，一个引用占的内存默认是4个字节
• 因此，64位JVM一般需要多消耗堆内存

• 对象内存占用

  • 本身的数据字段
  • 对象头
  • 补齐
  • 指针压缩

    包装类型

• 比原生数据类型消耗的内存要多，详情可以参考JavaWorld

  • Integer: 占用16字节（8+4=12 + 补齐），int占4个字节，所以Integer要比int多消耗300%的内存
  • Long: 一般占用16字节（8+8=16），对象的实际大小由底层平台的内存对齐确定，具体由特定CPU平台的JVM实现决定。看起来一个Long类型的对象，Long比原生类型long多占用了8个字节，多消耗了100%的内存
  • 多维数组：在二维数组int[dim1][dim2]中，每个嵌套的数组int[dim2]都是一个单独的Object，会额外占用16个字节的空间，当数组维度更大时，这种开销特别明显，int[128][2]实例占用3600字节，而int[256]只占用1040字节，里面有效存储空间是一样的，但开销却是3600比1040多了246%的额外开销，极端情况下byte[256][1]额外开销的比例是19倍，所以如果非要多维数组的话要个数少的要在外面即int[少][多]
  • String：String对象的空间随着内部字符数组的增长而增长，当然String类的对象有24个字节的额外开销，对于10字符以内的非空String，增加的开销比起有效载荷（每个字符2字节+4个字节的length）多占用100%-400%的内存

• 对齐是无法避免的，因为JVM内存分配时是要8字节的整数倍

  常见错误

• OutOfMemoryError:Java heap space

  • 堆内存中的空间不足以存放新创建的对象
  • 通常原因
    • 容量超出预期的访问量
    • 内存泄漏memoryLeak，系统占用的空间越来越多，最终耗尽内存
  • 解决方案
    • 增加内存
    • 改进代码
• OutOfMemoryError:PermGen space/Metaspace
  • 持久代/元信息区（方法区）空间不足
  • 通常原因
    • 加载到内存中的class数量太多或体积太大
  • 解决方案
    • 增大PermGen/Metaspace
    • -XX:MaxPermSize=512M
    • -XX:MaxMetaspaceSize=512M
    • -XX:+CMSClassUnloadingEnabled(高版本)

• OutOfMemoryError:Unable to create new native thread

  • 程序创建的线程数量已达到上限值的异常信息
  • 解决方案
    • 调整系统参数ulimit -a , echo 120000 > /proc/sys/kernel/threads-max
    • 降低Xss等参数
    • 调整代码，改变线程创建和使用方式

      内存Dump分析工具

• EclipseMAT（MemoryAnalyzerTool）

• jhat

  常用压力测试工具

• SuperBenchmarker（windows）

• wrk（Mac）

gateway-server-0.0.1-SNAPSHOT.jar

# jar -jar -XX:UseConcMarkSweepGC -Xmx512m -Xms512m gateway-server-0.0.1-SNAPSHOT.jar
# jar -jar -XX:UseConcMarkSweepGC -Xmx4g -Xms4g gateway-server-0.0.1-SNAPSHOT.jar
# jar -jar -Xmx512m -Xms512m gateway-server-0.0.1-SNAPSHOT.jar
# jar -jar -Xmx4g -Xms4g gateway-server-0.0.1-SNAPSHOT.jar

# Windows
# 管理员身份运行Powershell
# Set-ExecutionPolicy Bypass -Scope Process -Force; [System.Net.ServicePointManager]::SecurityProtocol = [System.Net.ServicePointManager]::SecurityProtocol -bor 3072; iex ((New-Object System.Net.WebClient).DownloadString('https://chocolatey.org/install.ps1'))
# choco install superbenchmarker
# sb -u http://localhost:8088/api/hello -c 20 -N 60


# Mac
# brew install wrk
# Ctrl + C
# wrk -t8 -c40 -d60s http://localhost:8088/api/hello

JVM问题分析调优经验

高分配速率

• HighAllocationRate
• 表示单位时间内分配的内存量，通常使用MB/sec作为单位
• 上一次GC后到下一次GC前年轻代使用量，两者的差值除以时间就是分配速率
• 分配速率过高就会严重影响性能，导致巨大的GC开销
• 不同情况
  • 正常系统：分配速率较低～回收速率 -> 健康
  • 内存泄漏：分配速率持续大于回收速率 -> OOM
  • 性能劣化：分配速率较高～回收速率 -> 亚健康

• 分析

  • new出来的对象放在Eden区
  • 增大Eden区就像增大蓄水池
  • 最终就会影响MinorGC的次数和时间，进而影响吞吐量

    过早提升

• PrematurePromotion

• 提升速率用于衡量单位时间内从年轻代提升到老年代的数据量，一般使用MB/sec作为单位
• JVM会将长时间存活的对象从年轻代提升到老年代。根据分代假设可能存在一种情况，老年代中不仅有存活时间长的对象，也可能有存活时间短的对象，这就是过早提升：对象存活时间还不够长的时候就被提升到了老年代
• majorGC不是为频繁回收而设计的，但majorGC现在也要清理这些生命短暂的对象，就会导致GC暂停时间过长，这会严重影响系统的吞吐量
• 一般来说过早提升的表现如下
  • 短时间内频繁的FullGC
  • 每次FullGC后老年代的使用率都很低，在10-20%或以下
  • 提升速率接近于分配速率

• 解决方案

  • 增加年轻代的大小 -Xmx64m -XX:NewSize=32m，减少FullGC次数，影响MinorGC时间
  • 减少每次批处理的数量
  • 优化数据结构，减少内存消耗

    GC疑难情况问题分析

    arthas

• https://arthas.aliyun.com/zh-cn/

  思路

• 查询业务日志，可以发现问题

  • 请求压力大
  • 波峰遭遇降级、熔断
  • 外部API依赖等
• 查看系统资源和监控信息
  • 硬件信息
  • 操作系统平台
  • 系统架构
  • 数据库日志、慢查询
• 查看性能指标
  • 实时监控
  • 历史数据
• 应用系统
  • 配置文件
  • 内存问题
  • 代码问题
  • 单元测试
• 疑难问题
  • dump线程、内存分析
  • 抽样分析、异步处理（log等）

• 优化方向

  • 集群
  • 主备
  • 读写分离
  • 分片分区
  • 数据库连接池（20-50）
  • log
    • 异步处理
    • 额外线程
    • buffer化（按1000条或128K写盘）
    • 日志轮转（减小文件体积）

      案例

      JVM问题排查分析-案例实战.md.pdf

      JVM常见面试问题

• JVM大约1000多个参数，和GC相关的有600多个

• Xmx配置堆内存时要考虑非堆的情况，默认非堆可用容量和Xmx一致，非堆不受GC影响，通常Xmx设置70%

JVM相关的常见面试问题汇总.md.pdf
Java多线程与并发面试题.pdf

55个JVM专业术语考考你（铁锚老师分享）.pdf