性能瓶颈诊断：我们是如何揪出 Dubbo 大对象传输这个“幕后黑手”？

本文已收录在Github，关注我，紧跟本系列专栏文章，咱们下篇再续！

• 🚀 魔都架构师 | 全网30W技术追随者
• 🔧 大厂分布式系统/数据中台实战专家
• 🏆 主导交易系统百万级流量调优 & 车联网平台架构
• 🧠 AIGC应用开发先行者 | 区块链落地实践者
• 🌍 以技术驱动创新，我们的征途是改变世界！
• 👉 实战干货：编程严选网

0 确认问题（现象）：接口响应时间飙升

某接口平时响应时间平均在200ms，但是最近飙升到600ms。

1 自顶向下，排除法

1.1 系统层（监控）：查看 CPU, TCP 连接, 网卡, Load 等

查看监控指标，cpu、tcp连接、网卡、load一切正常

1.2 应用运行时层（GC、内存）

分析gc日志：查看 Full GC 情况

2017-01-25T11:02:21.939+0800: 71437.958: [Full GC [PSYoungGen: 53452K->0K(1317888K)] [ParOldGen: 2785135K->264180K(2796544K)] 2838587K->264180K(4114432K) [PSPermGen: 79636K->79636K(524288K)], 0.2832510 secs] [Times: user=0.73 sys=0.00, real=0.29 secs]

2017-01-25T11:06:04.727+0800: 71660.746: [Full GC [PSYoungGen: 49073K->0K(1315840K)] [ParOldGen: 2776419K->262440K(2796544K)] 2825492K->262440K(4112384K) [PSPermGen: 79636K->79636K(524288K)], 0.2960190 secs] [Times: user=0.82 sys=0.00, real=0.29 secs]

2017-01-25T11:09:28.385+0800: 71864.404: [Full GC [PSYoungGen: 70709K->0K(1249280K)] [ParOldGen: 2746009K->276325K(2796544K)] 2816719K->276325K(4045824K) [PSPermGen: 79636K->79636K(524288K)], 0.3055130 secs] [Times: user=0.83 sys=0.00, real=0.31 secs]

2017-01-25T11:13:33.216+0800: 72109.235: [Full GC [PSYoungGen: 34214K->0K(1324544K)] [ParOldGen: 2780255K->233175K(2796544K)] 2814470K->233175K(4121088K) [PSPermGen: 79655K->79655K(524288K)], 0.2411000 secs] [Times: user=0.60 sys=0.00, real=0.24 secs]
2017-01-25T11:17:44.210+0800: 72360.229: [Full GC [PSYoungGen: 62186K->0K(1286144K)] [ParOldGen: 2789886K->265640K(2796544K)] 2852072K->265640K(4082688K) [PSPermGen: 79660K->79660K(524288K)], 0.2892200 secs] [Times: user=0.74 sys=0.00, real=0.29 secs]
2017-01-25T11:21:59.963+0800: 72615.982: [Full GC [PSYoungGen: 36964K->0K(1310720K)] [ParOldGen: 2783609K->245655K(2796544K)] 2820573K->245655K(4107264K) [PSPermGen: 79660K->79660K(524288K)], 0.2480330 secs] [Times: user=0.64 sys=0.00, real=0.25 secs]
2017-01-25T11:25:45.380+0800: 72841.398: [Full GC [PSYoungGen: 73723K->0K(1262592K)] [ParOldGen: 2755454K->284318K(2796544K)] 2829177K->284318K(4059136K) [PSPermGen: 79660K->79660K(524288K)], 0.3346010 secs] [Times: user=0.85 sys=0.00, real=0.34 secs]
2017-01-25T11:29:39.537+0800: 73075.556: [Full GC [PSYoungGen: 25344K->0K(1315840K)] [ParOldGen: 2774960K->240992K(2796544K)] 2800304K->240992K(4112384K) [PSPermGen: 79660K->79660K(524288K)], 0.2763920 secs] [Times: user=0.70 sys=0.00, real=0.28 secs]
2017-01-25T11:33:36.363+0800: 73312.381: [Full GC [PSYoungGen: 57780K->0K(1309184K)] [ParOldGen: 2779442K->264429K(2796544K)] 2837223K->264429K(4105728K) [PSPermGen: 79660K->79660K(524288K)], 0.2834540 secs] [Times: user=0.76 sys=0.00, real=0.29 secs]
2017-01-25T11:37:42.528+0800: 73558.547: [Full GC [PSYoungGen: 38837K->0K(1294336K)] [ParOldGen: 2784118K->262562K(2796544K)] 2822955K->262562K(4090880K) [PSPermGen: 79660K->79660K(524288K)], 0.2769620 secs] [Times: user=0.71 sys=0.00, real=0.28 secs]
2017-01-25T11:41:38.613+0800: 73794.632: [Full GC [PSYoungGen: 60301K->0K(1312256K)] [ParOldGen: 2784889K->280961K(2796544K)] 2845190K->280961K(4108800K) [PSPermGen: 79660K->79660K(524288K)], 0.3233140 secs] [Times: user=0.88 sys=0.00, real=0.32 secs]
2017-01-25T11:45:24.406+0800: 74020.425: [Full GC [PSYoungGen: 24950K->0K(1301504K)] [ParOldGen: 2769860K->254403K(2796544K)] 2794811K->254403K(4098048K) [PSPermGen: 79669K->79669K(524288K)], 0.2702330 secs] [Times: user=0.69 sys=0.00, real=0.27 secs]
2017-01-25T11:49:17.728+0800: 74253.746: [Full GC [PSYoungGen: 77793K->0K(1246720K)] [ParOldGen: 2787986K->325470K(2796544K)] 2865780K->325470K(4043264K) [PSPermGen: 79690K->79690K(524288K)], 0.3316160 secs] [Times: user=0.91 sys=0.00, real=0.34 secs]
2017-01-25T11:53:02.996+0800: 74479.015: [Full GC [PSYoungGen: 40194K->0K(1296896K)] [ParOldGen: 2774411K->263508K(2796544K)] 2814606K->263508K(4093440K) [PSPermGen: 79690K->79690K(524288K)], 0.2693080 secs] [Times: user=0.70 sys=0.00, real=0.27 secs]
2017-01-25T11:56:29.604+0800: 74685.623: [Full GC [PSYoungGen: 91113K->0K(1305088K)] [ParOldGen: 2684520K->609246K(2796544K)] 2775634K->609246K(4101632K) [PSPermGen: 79690K->79690K(524288K)], 0.9831970 secs] [Times: user=3.17 sys=0.00, real=0.98 secs]
2017-01-25T11:59:01.868+0800: 74837.887: [Full GC [PSYoungGen: 104932K->0K(1287680K)] [ParOldGen: 2779540K->433632K(2796544K)] 2884472K->433632K(4084224K) [PSPermGen: 79690K->79690K(524288K)], 0.7554340 secs] [Times: user=2.14 sys=0.00, real=0.76 secs]
2017-01-25T12:01:48.453+0800: 75004.472: [Full GC [PSYoungGen: 36636K->0K(1247744K)] [ParOldGen: 2735083K->266286K(2796544K)] 2771719K->266286K(4044288K) [PSPermGen: 79690K->79690K(524288K)], 0.3109250 secs] [Times: user=0.87 sys=0.00, real=0.32 secs]
2017-01-25T12:04:36.500+0800: 75172.519: [Full GC [PSYoungGen: 31085K->0K(1299456K)] [ParOldGen: 2786949K->232197K(2796544K)] 2818034K->232197K(4096000K) [PSPermGen: 79690K->79690K(524288K)], 0.2387330 secs] [Times: user=0.58 sys=0.00, real=0.24 secs]

整理25号其中一台机器的gc日志，过滤了FullGC的日志，都是STW操作，不过从日志可看出：

• 年轻代完全会被回收
• 老年代也会回收90%，基本每次回收90%

永久代没变化，但永久代在参数配的512M空间是足够的。目前才80M的永久代已足够用。另外老年代回收之后的HEAP空间也回收明显~~90%左右，heap的总容量也是足够的啦。看来JVM也无需优化。

内存分析

查看内存分布图，检查大对象

从分布图可以看出，内存中剩余空间还是很大的。并且没有特别大的对象存活，百分比最高的也仅tomcat的webclassloader，无非请求数太多造成单例比较多，这不会影响接口速度。

1.3 应用自身核心性能层（压测）

之前的步骤排查了系统基础资源和应用 JVM 自身的健康状况。但应用是在复杂的生产环境中运行的，可能受到外部流量、依赖服务、网络等因素的影响。通过将流量隔离到一台机器并进行内网压测，可以测试应用在排除外部干扰、仅自身处理请求时的表现。

使负载均衡不会打到线上机，内网进行压测重现：

从报告可看出，压测一切正常，响应最高也就260ms。压测结果显示，在隔离环境下，应用的响应时间正常。这是一个非常重要的发现！它强力证明：

1. 应用自身的核心处理逻辑在正常负载下是高效的。
2. 问题 不在 应用代码本身的计算效率低下或内存分配问题。
3. 问题 在于 应用在 生产环境 中，与 外部 某些组件或数据交互时出现了瓶颈。 这个结论将排查方向彻底从应用自身代码和 JVM 状态转移到其 依赖项 或 外部接口。

1.4 依赖层（Redis、Dubbo）

查看redis监控

既然问题出在与外部交互，Redis 是一个常见的依赖（缓存或数据存储）。检查 Redis 的监控，特别是 I/O 情况，是排查依赖服务性能的标准步骤。

发现不是redis造成的，io都正常。

Redis 监控正常，排除了 Redis 作为瓶颈的可能性。排查范围进一步缩小。此时需要考虑其他依赖，特别是那些与该接口直接相关的外部通信。

分析Dubbo日志

既然是接口响应慢，而且 Redis 等常见依赖排查过了，那么检查该接口通过 Dubbo 进行的输入/输出通信日志就变得至关重要。特别是要关注 RPC 调用的耗时和传输的数据量。

因为本服务需要给外部提供远程RPC服务。

通过awk统计Dubbo日志发现在请求某些数据的时候返回值过大，基本上达到了8M到12M，导致了dubbo在传输大对象时造成了时间过长，从而影响了Dubbo的接口响应时间飙升至600ms。

Dubbo 日志揭示了在处理某些请求时，返回值异常大（8-12MB）。这个发现与响应时间飙升的现象直接关联了起来。大数据量的网络传输本身就需要时间，而且可能涉及序列化/反序列化开销，完全有可能导致 RPC 调用耗时显著增加，进而拉高接口的整体响应时间。这几乎确定了问题的根源。

2 解决

和调用方沟通，把对方需要的字段留下，其他字段去掉，进行瘦身。发布之后，一切正常。

3 总结

确认问题 (现象)、自顶向下，排除法，并继续结合 ：

• 聚焦与问题相关的关键点：结合接口的特性（提供了 Dubbo 服务），将排查重点放在了 Dubbo 通信上
• 分析具体交互数据：在关键点 (Dubbo) 上，分析具体的数据和调用细节，发现了异常的大数据量
• 连接现象与根源：大数据量传输耗时 -> Dubbo 调用变慢 -> 接口响应变慢。形成完整的因果链条

• 基于根源解决问题：对症下药，通过瘦身数据来解决传输瓶颈

  本文由博客一文多发平台 OpenWrite 发布！