跳至主要內容

高并发场景的JVM调优案例：从GC时间30%到1%的完整过程

老张2026/4/30大约 12 分钟

高并发场景的JVM调优案例：从GC时间30%到1%的完整过程

适读人群：Java中高级开发工程师、架构师 | 阅读时长：约22分钟 | 适用JDK版本：JDK 11 / 17 / 21

开篇故事

这是2022年6月发生的一个真实调优案例，是我职业生涯里做过的最彻底也最有成就感的一次JVM调优。

项目背景：一个电商平台的商品详情接口，承担核心流量，峰值QPS约5000。服务部署在8核16G的机器上，JDK 11，G1 GC。

问题现象：监控显示GC时间占系统总运行时间的比例持续在25%-35%之间，平均GC时间比例是28%，意味着每秒有接近0.28秒在做GC，吞吐量损失严重。同时P99延迟经常出现200-500ms的尖峰，正好对应GC停顿时间。

系统已经在生产环境跑了一年多，代码逻辑也没什么变化。为什么GC会这么严重？

排查路线：

  1. 看GC日志（jstat + GC日志文件分析）
  2. 分析对象分配热点（async-profiler）
  3. 找到根因（字符串和数组的大量临时创建）
  4. 逐步优化（代码层+JVM参数）
  5. 验证效果（压测对比）

最终结果：GC时间占比从28%降到了0.9%，P99延迟从偶发500ms降到了稳定35ms以内。系统TPS从峰值4800提升到了5600（提升17%）。

一、问题诊断过程

第一步：收集基线数据

# 连续收集5分钟的GC统计
jstat -gcutil <pid> 5000 60 > /tmp/gc_baseline.txt

# 关键数据摘录（初始状态）
# S0     S1     E      O      M     YGC    YGCT    FGC    FGCT     GCT
# 0.00  45.23  82.34  67.89  89.23   8456   42.34    234   18.89  61.23
#
# 每秒GC次数：8456 / (运行时间秒数) ≈ 每秒2.8次Young GC
# 总GC时间：61.23秒（运行约220秒）
# GC占比：61.23 / 220 ≈ 27.8%

发现：

  • Young GC次数极多，每秒2.8次
  • Full GC也不少，234次
  • Old Gen使用率67.89%，说明老年代有一定压力
  • Metaspace 89.23%，比较高

第二步：分析对象分配热点

# async-profiler采样60秒内存分配热点
./profiler.sh -e alloc -d 60 -f /tmp/alloc_flame.html <pid>

# 打开火焰图，最宽的几列是：
# 1. java.lang.String (占总分配量35%)
# 2. [B (byte[]) (占总分配量28%)
# 3. [C (char[]) (占总分配量12%)
# 4. java.util.HashMap$Node (占总分配量8%)

这三类对象（String、byte[]、char[]）加起来占了75%的内存分配。这是典型的字符串处理密集型应用的特征。

追踪String分配的调用栈（在火焰图中向下展开）：

String (35% of allocations)
└── ObjectMapper.writeValueAsString (15%)
    └── ProductDetailController.getDetail (15%)
└── StringUtils.join (12%)
    └── TagService.getTagNames (12%)
└── MessageFormat.format (8%)
    └── LogUtils.buildTraceLog (8%)

找到了三个热点：

  1. JSON序列化：每次接口调用都对整个商品详情对象做JSON序列化（包含150+字段），然后再做裁剪，非常浪费
  2. 标签名拼接：每次都用StringUtils.join把List<String>拼接成一个字符串，再split给前端，完全没必要
  3. 日志追踪：每次请求都用MessageFormat.format生成追踪日志，即使不在DEBUG模式

第三步：分析Full GC原因

# 查看GC日志中的Full GC原因
grep "Full GC" /var/log/gc.log | head -20

# 发现大量：
# [Full GC (Metadata GC Threshold) ...]
# Metaspace触发Full GC！

# 查看Metaspace使用情况
jstat -gcmetacapacity <pid>
# MCMN  MCMX   MC    CCSMN CCSMX  CCSC  YGC  FGC  FGCT
# 0.0 1048576.0 456789.0  0.0 1048576.0 45678.0 8456 234  18.89

# Metaspace没有设置上限！(MCMX = 1048576KB = 1GB)
# MC(当前) = 456789KB ≈ 446MB，还在增长

发现第二个问题：Metaspace没有设置上限，且在持续增长，每次增长就触发Full GC。增长原因：这个服务用了规则引擎，每次规则更新都会动态生成新的脚本类，旧的脚本ClassLoader没有正确释放，导致Metaspace持续增长。

二、根因总结与优化方案

问题一：JSON序列化浪费

根因：商品详情对象有150+字段，每次调用都完整序列化整个对象（约8KB的JSON字符串），然后由前端按需取字段。实际上，列表页只需要10个字段，详情页需要50个字段，没有区分。

优化方案：引入DTO分层，列表接口返回精简DTO（10字段），详情接口返回完整DTO（50字段），消除150个字段的全量序列化。

问题二：标签名拼接

根因：前端需要展示标签，后端把List<String>拼成逗号分隔的字符串传给前端，前端再split解析。完全没必要的序列化/反序列化往返。

优化方案：直接返回List<String>，前端直接使用，消除字符串拼接和split操作。

问题三：日志追踪

根因：每次请求都执行MessageFormat.format()生成追踪日志字符串，即使日志级别是INFO（不打印DEBUG日志），字符串创建的开销已经发生了。

优化方案：改为延迟求值：

// 差：无论是否打印日志，都会执行format
logger.debug(MessageFormat.format("Request trace: id={0}, cost={1}ms", id, cost));

// 好：只有实际需要打印时才求值（Java 8+ Lambda延迟求值）
logger.debug("Request trace: id={}, cost={}ms", id, cost);  // SLF4J占位符，延迟拼接

// 或者显式判断
if (logger.isDebugEnabled()) {
    logger.debug(MessageFormat.format("...", id, cost));
}

问题四：Metaspace泄漏

根因：规则引擎的ClassLoader没有正确管理生命周期，每次规则更新都创建新ClassLoader但从不释放旧的，Metaspace持续增长。

优化方案：修复ClassLoader生命周期管理（参见668篇），同时设置-XX:MaxMetaspaceSize=512m作为保护上限。

三、优化实施过程

迭代一：DTO分层（最大收益）

// 修改前：所有接口都返回完整ProductDetail（150+字段）
public ProductDetail getDetail(Long productId) {
    return productDetailService.findById(productId);
}

// 修改后：区分列表DTO和详情DTO
// 列表接口（10字段）
public ProductListDto getListItem(Long productId) {
    ProductDetail detail = productDetailService.findById(productId);
    return ProductListDto.fromDetail(detail);  // 只复制10个字段
}

// 详情接口（50字段）
public ProductDetailDto getFullDetail(Long productId) {
    ProductDetail detail = productDetailService.findById(productId);
    return ProductDetailDto.fromDetail(detail);  // 复制50个字段
}

效果：JSON序列化的字节数从平均8KB降到列表接口1.2KB、详情接口3.5KB。内存分配量下降约45%，Young GC频率从每秒2.8次降到每秒1.1次。

迭代二：标签处理优化

// 修改前：把List<String>转成逗号分隔字符串
String tagNames = String.join(",", tagService.getTagNames(productId));
// tagNames大概是：电子产品,家用电器,节能认证...

// 修改后：直接返回List，消除字符串操作
List<String> tagNames = tagService.getTagNames(productId);
// 让Jackson直接序列化List<String>为JSON数组：["电子产品","家用电器","节能认证"]

效果：字符串分配量进一步下降约12%，Young GC频率降到每秒0.8次。

迭代三：修复Metaspace泄漏

修复规则引擎ClassLoader管理问题（代码修改略），并添加JVM参数：

# 添加Metaspace保护上限
-XX:MetaspaceSize=128m
-XX:MaxMetaspaceSize=512m

效果：Full GC从每分钟约3.2次降到几乎为零（偶发一次）。Total GC时间大幅下降。

迭代四：JVM参数调整

在代码优化后，根据新的GC行为调整JVM参数：

# 修改前（历史遗留配置）
-Xms8g -Xmx8g
-XX:+UseG1GC
-XX:MaxGCPauseMillis=200
# 没有设置年轻代大小，G1默认约25%年轻代

# 修改后
-Xms8g -Xmx8g
-XX:+UseG1GC
-XX:MaxGCPauseMillis=100     # 代码优化后GC工作量减少，可以设更严格目标
-XX:G1NewSizePercent=20       # 年轻代下限20%
-XX:G1MaxNewSizePercent=40    # 年轻代上限40%（提升年轻代比例）
-XX:InitiatingHeapOccupancyPercent=35  # 提前触发并发标记（从默认45%提前到35%）
-XX:MetaspaceSize=128m
-XX:MaxMetaspaceSize=512m
-XX:ReservedCodeCacheSize=256m

年轻代比例提升的原理：代码优化后，对象分配速率大幅降低，Young GC频率也降低了。可以适当增大年轻代，让对象有更多时间在年轻代被回收（短生命周期对象更多机会在Minor GC中被清理，减少晋升老年代的数量）。

迭代五：关键路径缓存

// 发现商品标签查询还有优化空间：每次都从DB查
// 标签数据变更频率低（平均每分钟0.1次），可以缓存

@Cacheable(value = "productTags", key = "#productId", 
           unless = "#result == null || #result.isEmpty()")
public List<String> getTagNames(Long productId) {
    return tagRepository.findTagNamesByProductId(productId);
}
spring:
  cache:
    type: caffeine
    caffeine:
      spec: maximumSize=10000,expireAfterWrite=60s

效果：DB查询减少约80%，对象分配进一步减少，GC频率进一步降低。

四、最终效果对比

数据对比

指标优化前优化后提升
GC时间占比28%0.9%-96.8%
Young GC频率2.8次/秒0.15次/秒-94.6%
Full GC频率3.2次/分~0次/分-100%
P99延迟180ms（均值），500ms（峰值）35ms-81%
TPS（峰值）48005600+17%
对象分配速率~1.8GB/分钟~120MB/分钟-93.3%

GC日志对比

# 优化前（1分钟内的GC情况）
[GC Young] 14次，总耗时约8.4秒
[Full GC]  3次，总耗时约4.2秒
# GC总时间：约12.6秒/分钟 = 21%

# 优化后（1分钟内的GC情况）
[GC Young] 9次，总耗时约0.5秒
[Full GC]  0次
# GC总时间：约0.5秒/分钟 = 0.8%

五、诊断工具与命令（完整排查脚本）

#!/bin/bash
# performance_analysis.sh - 完整性能分析脚本

PID=$1
DURATION=${2:-60}  # 分析时长，默认60秒
OUTPUT_DIR="/tmp/analysis_$(date +%Y%m%d_%H%M%S)"
mkdir -p $OUTPUT_DIR

echo "=== Starting Performance Analysis for PID $PID ==="
echo "Output directory: $OUTPUT_DIR"
echo ""

# 1. GC统计
echo "=== Collecting GC stats for ${DURATION}s ==="
jstat -gcutil $PID 5000 $(($DURATION / 5)) > $OUTPUT_DIR/gc_stats.txt &
JSTAT_PID=$!

# 2. 内存分配分析（async-profiler）
echo "=== Starting allocation profiling ==="
ASYNC_PROFILER_PATH="/opt/async-profiler/profiler.sh"
if [ -f $ASYNC_PROFILER_PATH ]; then
    $ASYNC_PROFILER_PATH -e alloc -d $DURATION \
        -f $OUTPUT_DIR/alloc_flame.html $PID &
    PROFILER_PID=$!
fi

# 3. 等待分析完成
wait $JSTAT_PID
if [ ! -z "$PROFILER_PID" ]; then
    wait $PROFILER_PID
fi

# 4. 生成对象分布快照
echo "=== Object histogram ==="
jmap -histo:live $PID > $OUTPUT_DIR/histo.txt

# 5. 线程状态快照
echo "=== Thread dump ==="
jstack $PID > $OUTPUT_DIR/jstack.txt

# 6. JVM内存NMT（如果已开启）
echo "=== Native Memory Tracking ==="
jcmd $PID VM.native_memory summary scale=MB > $OUTPUT_DIR/nmt.txt 2>/dev/null

# 7. 分析GC统计，计算GC占比
echo ""
echo "=== GC Analysis Summary ==="
awk 'NR>1 {
    ygc_count += $7; ygct += $8; fgc_count += $9; fgct += $10; gct += $11
    samples++
}
END {
    if (samples > 0) {
        print "Young GC count: " ygc_count/samples " (avg per sample)"
        print "Young GC time: " ygct/samples "s (avg)"
        print "Full GC count: " fgc_count/samples " (avg per sample)"
        print "Full GC time: " fgct/samples "s (avg)"
    }
}' $OUTPUT_DIR/gc_stats.txt

echo ""
echo "=== Analysis Complete ==="
echo "Files saved to: $OUTPUT_DIR"
echo "Next steps:"
echo "1. Open $OUTPUT_DIR/alloc_flame.html in browser for allocation hotspots"
echo "2. Review $OUTPUT_DIR/histo.txt for object distribution"
echo "3. Check $OUTPUT_DIR/gc_stats.txt for GC trends"

六、踩坑实录

坑一：只优化JVM参数，忽略了代码层面的问题

最初我的调优思路是：GC多，那就把堆改大、调G1参数，减少GC触发频率。尝试把堆从8G改成12G，把MaxGCPauseMillis从200改成100，折腾了两天，GC时间占比从28%降到了22%，效果有限。

后来转换思路，先找对象分配热点，从代码层面减少不必要的对象创建，效果是JVM参数调整的10倍以上。

根本规律：GC调优应该先优化代码，再调JVM参数。代码层面的优化是根治，JVM参数调整是缓解。

坑二：缓存引入了另一个问题

引入Caffeine缓存后，标签查询从DB到了本地缓存，减少了大量临时对象的创建。但缓存的Key（productId，Long对象）和Value（List<String>）都长期驻留在老年代，导致老年代增长速度加快，混合GC（Mixed GC）频率上升。

解决方案：合理设置缓存大小（maximumSize=10000），让Caffeine在缓存满时自动淘汰最久未访问的条目，控制缓存对老年代的内存压力。

坑三：P99延迟的尖峰来自GC停顿，但不完全来自GC

优化到GC时间占比0.9%之后，发现P99延迟还有偶发的100-150ms的尖峰，超出了35ms的目标。以为还是GC的问题，但对照GC日志，尖峰出现的时间点并没有GC发生。

排查发现：这些延迟尖峰来自外部依赖（下游商品推荐服务）的偶发慢响应，与JVM完全无关。用Arthas的trace命令追踪了几十个请求，确认了问题来源。

教训：延迟问题不一定是JVM引起的，要先排查外部依赖（RPC调用、数据库、缓存）再考虑JVM。

坑四：优化后的压测与上线前的再验证

代码和JVM参数都优化完之后，在压测环境跑了一小时，数据很好。直接上线发布后，发现生产环境的效果比压测环境差一些——GC时间占比是1.2%而不是0.9%。

排查发现：压测环境的测试数据集只有10万条，而生产环境有几百万条商品数据。生产环境的对象图更复杂，GC扫描的存活对象更多，停顿时间略长于压测。

这个差异在可接受范围内，但提醒了我：压测数据集要尽量接近生产规模，否则优化数据会偏乐观。

六、总结

这次从GC时间28%到0.9%的调优过程，核心经验有以下几点：

第一：数据驱动，不要靠猜。每一步调整都要有数据支撑：现状数据、根因数据、优化后对比数据。async-profiler的内存分配火焰图直接指出了优化方向，没有它，可能折腾一个月也找不到根因。

第二：代码优化优先于JVM参数调整。本次优化90%的收益来自代码层面（DTO精简、消除不必要的字符串操作、修复Metaspace泄漏），JVM参数调整只贡献了约10%。JVM参数是在代码行为基础上的精细化调节，无法解决代码级别的浪费。

第三：对象分配速率是GC性能的关键指标。对象分配速率从1.8GB/分钟降到120MB/分钟，降幅93%，GC频率也相应降低了94%。减少不必要的对象创建（特别是短生命周期的临时对象），是减少GC压力最直接的手段。

第四：Metaspace问题容易被忽视。很多团队只关注堆的调优，忽视了Metaspace。Metaspace频繁扩展会触发Full GC，而Metaspace泄漏（ClassLoader不释放）会导致Metaspace持续增长，是定时炸弹。生产环境务必设置-XX:MaxMetaspaceSize保护上限，并监控Metaspace使用趋势。

第五：系统性能是代码、JVM、外部依赖共同决定的。JVM调优解决了GC问题，但延迟尖峰还有来自外部依赖的部分。完整的性能优化需要全链路视角，不能只盯着JVM。

这20篇JVM深度与性能调优实战文章至此收尾。从内存模型到GC算法，从OOM排查到CPU分析，从字节码工程到容器化部署，每篇都来自真实的生产实践。希望这些踩坑经验能帮你少走弯路，在JVM调优这条路上走得更稳更远。

编辑此页
最近更新:
贡献者: xiaozhangge