G1收集器：CPU与Worker线程的关系及一次实际排查案例

简介
生产环境中进行故障排查的困难
测试和开发环境进行诊断需要注意的问题
准备工作
相关知识
抽样分析
在测试环境中进行验证
在生产环境中做好监控
自上而下划分 JVM 问题
标准 JVM 参数配置
问题排查手册
以可量化的方式来进行性能调优
一个简单的流程
进行排查的点
GC 问题排查实战案例
问题现象描述
CPU 负载
GC 内存使用情况
JVM 启动参数
使用 G1 垃圾收集器
长时间运行发生异常
注册 GC 事件监听
打印 GC 日志
分析 GC 日志
限制 GC 的并行线程数量
总结
参考文档

简介

一般来说，只要系统架构设计得比较合理，大部分情况下系统都能正常运行，出现系统崩溃等故障问题是小概率事件。

目的

解决问题和故障
排查系统风险隐患

分类

常规问题
疑难杂症

排查方式

逻辑严密的系统性排查；
以猜测来驱动，凭历史经验进行排查。

选择后一种方式，可能会浪费大量的时间，效果得看运气。更糟糕的是，因为基本靠蒙，所以这个过程是完全不可预测的。

生产环境中进行故障排查的困难

影响到客户的时间越短越好
解决问题最快的办法可能是重启机器，但重启可能会破坏故障现场，那样就很难排查问题的根本原因了。
安全方面的限制
一般来说，开发人员可能没有权限访问生产环境。只能进行远程故障排除。
每个要执行的操作都需要多人参与或审核，这不仅增加了执行单个操作所需的时间，而且沟通交流过程中可能会丢失一些信息。
测试和发布流程可能又要消耗几小时甚至几天，进一步增加了解决问题实际消耗的时间。
工具引发的问题
安装使用的某些工具在特点场景下可能会使情况变得更糟。

对 JVM 进行堆转储（heap dump）可能会使 JVM 暂停几十秒或更长时间。
打印更细粒度的日志可能会引入其他的并发问题，IO 开销、磁盘问题等。
增加的探测器或者分析器可能会有很大开销，导致本就缓慢的系统彻底卡死。

测试和开发环境进行诊断需要注意的问题

测试环境和生产环境使用的数据源不同。这意味着由数据量引发的性能问题可能不会在测试环境中重现。
某些问题的使用方式可能不容易复现（有时候也称之为“幽灵问题”）。例如只在 2 月 29 日这个特殊时间引起的并发问题，只在多个用户同时访问某个功能时引发，如果事先不知道原因，那也很难排查。
两个环境下的应用程序可能还不一样。生产部署的配置可能明显不同。这些差异包括：操作系统、群集、启动参数，以及不同的打包版本。

准备工作

最好在平时就先做好全面的系统监控、有针对性的应急预案，并时常进行演练。

相关知识

能力可以分为外功和内功。内功就是各种基础知识。外功就是各种工具、技能和技巧。

基础

Java 语言功底
JVM 基础知识
并发领域知识
计算机体系结构和组成原理
TCP/IP 网络体系知识
HTTP 协议和 Nginx 等服务器知识
数据库领域知识
搜索引擎使用技巧

抽样分析

了解应用程序各个部分的热点以及内存消耗，能有效防止某些问题影响到生产环境的用户。

由于数据，使用方式和环境的差异，最终只能模拟生产环境中面临的一部分问题。但使用这种技术可以预先进行风险排查，如果真的发生问题，可以在追溯问题原因时很快定位。

在测试环境中进行验证

自动化的持续集成、持续交付流程能及早暴露出很多问题。如果进行周全和彻底的测试，将进一步减少生产环境的事故。

当开发人员推动“执行某项性能优化”的任务时，如果不能提升优先级，此类任务会积压下来，永远都是待办事项。

如果将生产环境中的P1故障事件减少到80%，可以多产生2倍的收益，在这种情况下，就能推动相关人员把这些工作做好。相反地，如果不能说明改进工作的收益，则可能就没有资源去提升质量。

在生产环境中做好监控

当出现问题时，理想情况下，我们已经拥有了足以解决该问题的相关信息。
如果已经拥有了所需的信息，则可以快速跳过问题复现和信息收集的步骤。

典型的 Web 应用系统

日志监控。汇总各个服务器节点的日志，以便技术团队可以快速搜索相关的信息，日志可视化，并进行异常报警。最常用的解决方案是 ELK 技术栈，将日志保存到 Elasticsearch 中，通过 Logstash 进行分析，并使用 Kibana 来展示和查询。
系统监控。在基础架构中汇总系统指标并进行可视化查询，既简单又有效。关注CPU、内存、网络和磁盘的使用情况，可以发现系统问题并配置监控报警。
系统性能监控（APM，Application Performance Monitoring），以及用户体验监控。关注单个用户的交互，能有效展示用户感受到的系统性能和可用性问题。至少，可以知道是哪个服务在哪段时间发生了故障。比如集成 Micrometer、Pinpoint、Skywalking、Plumbr 等技术，能快速定位代码中的问题。

自上而下划分 JVM 问题

一般的问题诊断和调优套路：做好监控，定位问题，验证结果，总结归纳。

执行引擎，包括：GC、JIT 编译器
类加载子系统，这部分的问题，一般在开发过程中出现
JNI 部分，这部分问题一般在 JVM 之外
运行时数据区；Java 将内存分为 2 大块：堆内存和栈内存

线上环境的JVM问题主要集中在 GC 和内存部分。而栈内存、线程分析等问题，主要是辅助诊断 Java 程序本身的问题。

标准 JVM 参数配置

JVM 可配置参数已经达到 1000 多个，其中 GC 和内存配置相关的 JVM 参数就有 600 多个。从这个参数比例也可以看出，JVM 问题排查和性能调优的重点领域还是 GC 和内存。

常用的 JVM 配置参数

# 设置堆内存
-Xmx4g -Xms4g
# 指定 GC 算法
-XX:+UseG1GC -XX:MaxGCPauseMillis=50
# 指定 GC 并行线程数
-XX:ParallelGCThreads=4
# 打印 GC 日志
-XX:+PrintGCDetails -XX:+PrintGCDateStamps
# 指定 GC 日志文件
-Xloggc:gc.log
# 指定 Meta 区的最大值
-XX:MaxMetaspaceSize=2g
# 设置单个线程栈的大小
-Xss1m
# 指定堆内存溢出时自动进行 Dump
-XX:+HeapDumpOnOutOfMemoryError
-XX:HeapDumpPath=/usr/local/

常用的属性配置

# 指定默认的连接超时时间
-Dsun.net.client.defaultConnectTimeout=2000
-Dsun.net.client.defaultReadTimeout=2000
# 指定时区
-Duser.timezone=GMT+08
# 设置默认的文件编码为 UTF-8
-Dfile.encoding=UTF-8
# 指定随机数熵源（Entropy Source）
-Djava.security.egd=file:/dev/./urandom

问题排查手册

常用shell操作

# 查看当前路径
pwd# 查看当前目录下有哪些文件
ls -l# 查看系统负载
top# 查看剩余内存
free -h# 查看剩余磁盘
df -h# 查看当前目录的使用量
du -sh *# 系统活动情况报告
sar
-bash: sar: command not found# Linux安装sysstat
# apt-get install sysstat
# yum -y install sysstat# 查看帮助手册
man sar# 查看最近的报告
sar 1# 查看帮助手册
man sar

收集信息

收集不同的指标（CPU、内存、磁盘 IO、网络等等）
分析应用日志
分析 GC 日志
获取线程转储并分析
获取堆转储来进行分析

最容易排查的是系统硬件和操作系统问题，比如：CPU、内存、网络、磁盘 IO

以可量化的方式来进行性能调优

系统容量：比如硬件配置、设计容量；
吞吐量：最直观的指标是 TPS；
响应时间：也就是系统延迟，包括服务端延时和网络延迟。

一个简单的流程

不同的场景、不同的问题，排查方式都不一样，具体怎么来确定问题是没有固定套路的。

可以事先进行的操作：

培训：提前储备相关领域的知识点和技能、工具使用技巧等等。
监控：前面提到过，主要是 3 部分，业务日志、系统性能、APM 指标。
预警：在故障发生时，及时进行告警；在指标超过阈值时进行预警。
排查风险点：了解系统架构和部署结构，分析单点故障、扩容瓶颈等等。
评估系统性能和服务级别：例如可用性、稳定性、并发能力、扩展性等等。

事故处理规范：
相关人员：包括开发、运维、运营、QA、管理人员、客服等等。
事故级别，严重程度，影响范围、紧急程度。
汇报、沟通、咨询。
问题排查，诊断、定位，监控、分析
事故总结、分析原因、防止再现。
改进和优化、例如使用新技术、优化架构等等。

进行排查的点

查询业务日志，可以发现这类问题：请求压力大、波峰、遭遇降级、熔断等等，基础服务、外部 API 依赖。
查看系统资源和监控信息

硬件信息、操作系统平台、系统架构
排查 CPU 负载
内存不足
磁盘使用量、硬件故障、磁盘分区用满、IO 等待、IO 密集、丢数据、并发竞争等情况
排查网络：流量打满，响应超时，无响应，DNS 问题，网络抖动，防火墙问题，物理故障，网络参数调整、超时、连接数

查看性能指标，包括实时监控、历史数据。可以发现假死、卡顿、响应变慢等现象。

排查数据库，并发连接数、慢查询、索引、磁盘空间使用量、内存使用量、网络带宽、死锁、TPS、查询数据量、redo 日志、undo、binlog 日志、代理、工具 Bug。可以考虑的优化包括：集群、主备、只读实例、分片、分区。
大数据、中间件、JVM 参数。

排查系统日志，比如重启、崩溃、Kill。
APM，比如发现有些链路请求变慢等等。
排查应用系统

排查配置文件：启动参数配置、Spring 配置、JVM 监控参数、数据库参数、Log 参数、APM 配置。
内存问题，比如是否存在内存泄漏，内存溢出、批处理导致的内存放大、GC 问题等等。
GC 问题，确定 GC 算法、确定 GC 的KPI，GC 总耗时、GC 最大暂停时间、分析 GC 日志和监控指标：内存分配速度，分代提升速度，内存使用率等数据。适当时修改内存配置。
排查线程，理解线程状态、并发线程数、线程 Dump，锁资源、锁等待、死锁。
排查代码，比如安全漏洞、低效代码、算法优化、存储优化、架构调整、重构、解决业务代码 Bug、第三方库、XSS、CORS、正则。
单元测试：覆盖率、边界值、Mock 测试、集成测试。

排除资源竞争、坏邻居效应。
疑难问题排查分析

DUMP 线程
DUMP 内存
抽样分析
调整代码、异步化、削峰填谷

GC 问题排查实战案例

有一个提供高并发请求的服务，系统使用 Spring Boot 框架，指标采集使用 MicroMeter，监控数据上报给 Datadog 服务。

各种监控系统：AppOptics、Atlas、Datadog、Dynatrace、Elastic、Ganglia、Graphite、Humio、Influx、Instana、JMX、KairosDB、New Relic、Prometh eus、SignalFx、Stackdriver、StatsD、Wavefront 等等。

MicroMeter官方文档

问题现象描述

通过监控指标发现，有一个服务节点的最大 GC 暂停时间经常会达到 400ms 以上。

服务调用的超时时间为 1s，要求最大 GC 暂停时间不超过 200ms，平均暂停时间达到 100ms 以内，对客户的交易策略产生了极大的影响。

CPU 负载

GC 内存使用情况

old_gen 使用量大幅下跌，发生 FullGC。

JVM 启动参数

-Xmx4g -Xms4g

使用的是 JDK 8，启动参数中没有指定 GC，确定这个服务使用了默认的并行垃圾收集器。

很多情况下 ParallelGC 为了最大的系统处理能力，即吞吐量，而牺牲掉了单次的暂停时间，导致暂停时间会比较长。

使用 G1 垃圾收集器

新版本的 JDK 8 中 G1 很稳定，而且性能不错。
启动参数

-Xmx4g -Xms4g -XX:+UseG1GC -XX:MaxGCPauseMillis=50

服务启动成功，等待健康检测自动切换为新的服务节点，继续查看指标。
每个节点的 GC 暂停时间都降下来了，基本上在 50ms 以内，符合预期。

长时间运行发生异常

运行一段时间后，最大 GC 暂停时间达到了 1300ms。

注册 GC 事件监听

通过 JMX 注册 GC 事件监听，把相关的信息直接打印出来。

// 每个内存池都注册监听
for (GarbageCollectorMXBean mbean : ManagementFactory.getGarbageCollectorMXBeans()) {if (!(mbean instanceof NotificationEmitter)) {continue; // 假如不支持监听...}final NotificationEmitter emitter = (NotificationEmitter) mbean;// 添加监听final NotificationListener listener = getNewListener(mbean);emitter.addNotificationListener(listener, null, null);
}

在程序中监听 GC 事件，并将相关信息汇总或者输出到日志。

打印 GC 日志

修改启动参数

-Xmx4g -Xms4g -XX:+UseG1GC -XX:MaxGCPauseMillis=50
-Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps

分析 GC 日志

将 GC 日志下载到本地进行分析。

日志关键信息

Java HotSpot(TM) 64-Bit Server VM (25.162-b12) for linux-amd64 JRE (1.8.0_162-b12),built on Dec 19 2017 21:15:48 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 144145548k(58207948k free), swap 0k(0k free)
CommandLine flags: -XX:InitialHeapSize=4294967296 -XX:MaxGCPauseMillis=50 -XX:MaxHeapSize=4294967296 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC 2020-02-24T18:02:31.853+0800: 2411.124: [GC pause (G1 Evacuation Pause) (young), 1.8683418 secs][Parallel Time: 1861.0 ms, GC Workers: 48][GC Worker Start (ms): Min: 2411124.3, Avg: 2411125.4, Max: 2411126.2, Diff: 1.9][Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 2.7, Diff: 2.7, Sum: 16.8][Update RS (ms): Min: 0.0, Avg: 3.6, Max: 6.8, Diff: 6.8, Sum: 172.9][Processed Buffers: Min: 0, Avg: 2.3, Max: 8, Diff: 8, Sum: 111][Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 7.7][Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3][Object Copy (ms): Min: 1851.6, Avg: 1854.6, Max: 1857.4, Diff: 5.8, Sum: 89020.4][Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.6][Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 48][GC Worker Other (ms): Min: 0.0, Avg: 0.3, Max: 0.7, Diff: 0.6, Sum: 14.7][GC Worker Total (ms): Min: 1858.0, Avg: 1859.0, Max: 1860.3, Diff: 2.3, Sum: 89233.3][GC Worker End (ms): Min: 2412984.1, Avg: 2412984.4, Max: 2412984.6, Diff: 0.5][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 1.5 ms][Other: 5.8 ms][Choose CSet: 0.0 ms][Ref Proc: 1.7 ms][Ref Enq: 0.0 ms][Redirty Cards: 1.1 ms][Humongous Register: 0.1 ms][Humongous Reclaim: 0.0 ms][Free CSet: 2.3 ms][Eden: 2024.0M(2024.0M)->0.0B(2048.0K) Survivors: 2048.0K->254.0M Heap: 3633.6M(4096.0M)->1999.3M(4096.0M)][Times: user=1.67 sys=14.00, real=1.87 secs]

可疑的点

physical 144145548k(58207948k free)：JVM 启动时，物理内存 137GB，空闲内存 55GB。
[Parallel Time: 1861.0 ms, GC Workers: 48]：垃圾收集器工作线程 48 个。

日志信息

user=1.67：用户线程耗时 1.67s；
sys=14.00：系统调用和系统等待时间 14s；
real=1.87 secs：实际暂停时间 1.87s；
GC 之前，年轻代使用量 2GB，堆内存使用量 3.6GB，存活区 2MB，可推断出老年代使用量 1.6GB；
GC 之后，年轻代使用量为 0，堆内存使用量 2GB，存活区 254MB，那么老年代大约 1.8GB，那么“内存提升量为 200MB 左右”。

得出结论

年轻代转移暂停，复制了 400MB 左右的对象，却消耗了 1.8s，系统调用和系统等待的时间达到了 14s。
JVM 看到的物理内存 137GB。
推算出 JVM 看到的 CPU 内核数量 72个，因为 GC 工作线程 72* 5/8 ~= 48 个

一般的 CPU 和内存资源配比，常见的比例差不多是 4 核 4GB、4 核 8GB。

此处堆内存4GB，GC工作线程达到48个，查看对应的 CPU 负载监控信息。

定位到 GC 暂停时间过长的原因：
K8S 的资源隔离和 JVM 未协调好，导致 JVM 看见了 72 个 CPU 内核，默认的并行 GC 线程设置为 72* 5/8 ~= 48 个，但是 K8S 限制了这个 Pod 只能使用 4 个 CPU 内核的计算量，致使 GC 发生时，48 个线程在 4 个 CPU 核心上发生资源竞争，导致大量的上下文切换。

解决方案

限制 GC 的并行线程数量

限制 GC 的并行线程数量

启动参数

-Xmx4g -Xms4g
-XX:+UseG1GC -XX:MaxGCPauseMillis=50 -XX:ParallelGCThreads=4
-Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps

-XX:ParallelGCThreads=n
设置 STW 阶段的并行 worker 线程数量。如果逻辑处理器小于等于 8 个，则默认值 n 等于逻辑处理器的数量。

如果逻辑处理器大于 8 个，则默认值 n 大约等于处理器数量的 5/8。在大多数情况下都是个比较合理的值。如果是高配置的 SPARC 系统，则默认值 n 大约等于逻辑处理器数量的 5/16。

-XX:ConcGCThreads=n
设置并发标记的 GC 线程数量。默认值大约是 ParallelGCThreads 的四分之一。

一般来说不用指定并发标记的 GC 线程数量，只用指定并行的即可。

总结

JVM 问题排查和性能调优主要基于监控数据来进行

使用手段

指标监控
指定 JVM 启动内存
指定垃圾收集器
打印和分析 GC 日志

GC 性能维度

延迟，GC 中影响延迟的主要因素就是暂停时间。
吞吐量，主要看业务线程消耗的 CPU 资源百分比，GC 占用的部分包括：GC 暂停时间，以及高负载情况下并发 GC 消耗的 CPU 资源。
系统容量，主要说的是硬件配置，以及服务能力。

只要这些方面的指标都能够满足，各种资源占用也保持在合理范围内，就达到预期了。

参考文档

Native Memory Tracking（NMT，Native 内存跟踪）排查文档
生产环境 GC 参数调优
Linux 的性能调优的思路
why-is-troubleshooting-so-hard
Linux 工具快速教程