年轻代频繁 ParNew GC，导致 http 服务 rt 飙高

背景介绍

某日下午大约四点多，接到合作方消息，线上环境，我这边维护的某 http 服务突然大量超时（对方超时时间设置为 300ms），我迅速到鹰眼平台开启采样，发现该服务平均 QPS 到了 120 左右，平均 RT 在 2 秒多到 3 秒，部分毛刺高达 5 到 6 秒（正常时候在 60ms 左右）。

qps 情况：

rt 情况

问题解决

该服务是一个对内的运营平台服务（只部署了两台 docker）预期 qps 个位数，近期没做过任何的线上发布，核心操作是整合查询数据库，一次请求最多涉及 40 次左右的 DB 查询，最终查询结果为一个多层树形结构，一个响应体大约 50K。之前口头跟调用方约定要做缓存，现在看到 QPS 在 120 左右，（QPS 证明没有做缓存），遂要求对方做缓存，降低 QPS。后 QPS 降到 80 以内，rt 恢复正常（平均 60ms），最终 QPS 一直降到 40（后续需要推动调用方上缓存，保证 QPS 在个位数）。

问题定位

由于该服务核心操作是查询数据库，且一次请求有 40 次 DB query，遂首先排查是否慢 sql 导致，查看 db 性能监控，发现 db 平均 rt 在 0.3ms 以内，可以算出来 DB 整体耗时在 12ms 左右，排除慢 sql 导致 RT 变高。

开始怀疑，是否 DB 连接池在高并发下出现排队，tddl 默认的连接池大小是 10.一查监控，整个占用的连接数从来没有超过 7 个，排除连接池不足的问题。

至此，造成 RT 高的原因，在数据库层面被排除。

接着开始查采样到的服务调用链上的每一个执行点，看看到底是调用链上的那部分耗时最多。发现里面很多执行点都有一个特点，就是本地调用耗时特别长（几百毫秒），但是真正的服务调用（比如 db 查询动作）时间却很短，(0ms 代表执行时间小于 1ms，也间接印证之前 db 的平均 RT 在 0.3ms 以内)

本地调用耗时: 267ms

客户端发送请求: 0ms

服务端处理请求: 0ms

客户端收到响应: 1ms

总耗时: 1ms

这时候问题逐渐清晰，问题出现在本地方法执行的耗时过长，可是再次检查该服务所有代码，并没有需要长耗时的本地执行逻辑，那么继续看 CPU 的 load 情况。

load 长时间在 4 左右徘徊，我们的 docker 部署在 4c8G 的宿主机上，但是我们不能独占这个 4C 的，持续这么高的 load 已经不正常了。

继续追查 cpu load 飙高的原因，接着去看 GC 日志，发现大量的 Allocation Failure，然后 ParNew 次数在每分钟 100 次以上，明显异常，见下 GC 日志例子

2020-03-25T16:16:18.390+0800: 1294233.934: [GC (Allocation Failure) 2020-03-25T16:16:18.391+0800: 1294233.935: [ParNew: 1770060K->25950K(1922432K), 0.0317141 secs] 2105763K->361653K(4019584K), 0.0323010 secs] [Times: user=0.12 sys=0.00, real=0.04 secs]复制代码

每次占用 cpu 的时间在 0.04s 左右，但是由于 ParNew GC 太过频繁，每分钟最高 100 次以上，整体占用 cpu 时间还是很可观。

看了下 jvm 内存参数

Heap Configuration:   MinHeapFreeRatio         = 40   MaxHeapFreeRatio         = 70   MaxHeapSize              = 4294967296 (4096.0MB)   NewSize                  = 2147483648 (2048.0MB)   MaxNewSize               = 2147483648 (2048.0MB)   OldSize                  = 2147483648 (2048.0MB)   NewRatio                 = 2   SurvivorRatio            = 10   MetaspaceSize            = 268435456 (256.0MB)   CompressedClassSpaceSize = 1073741824 (1024.0MB)   MaxMetaspaceSize         = 536870912 (512.0MB)   G1HeapRegionSize         = 0 (0.0MB)复制代码

年轻代分配了 2G 内存，其中 eden 区约 1.7G

使用 jmap 查看年轻代对象占用空间情况,排名靠前的有多个 org.apache.tomcat.util.buf 包下的对象，比如 ByteChunk、CharChunk、MessageBytes 等，以及响应涉及的一些临时对象列表。其中 ByteChunk 等即 tomcat 响应输出相关类

至此问题明确，超大响应包（50K）在发送到网卡的过程中，需要经过从用户态 user space 拷贝到内核态 kernel space，然后在拷贝到网卡进行发送（像 netty 等的零拷贝针对的就是这种拷贝），加上响应体查询过程中，涉及的大量临时对象 list，在高并发场景下，就导致年轻代内存占满，然后频繁 gc（后续在合适的时间会压测该接口），这里还有一个点，很多人以为 ParNewGC 不会 stop the world，其实是会的。频繁 ParNewGC 造成用户线程进入阻塞状态，让出 CPU 时间片，最终导致连接处理等待，接口的 RT 变高。整个排查过程，鹰眼，idb 性能监控等可视化监控平台帮助真的很大，否则到处去查日志得查的晕头转向了。

经验总结

1. 接口设计，需要避免超大响应体出现，分而治之，将一个大接口拆分为多个小接口。

2. 缓存设计，像这个服务一样，一个请求带来将近 40 次 DB 查询的，需要考虑在服务端进行缓存（当时偷懒了，要求调用方去做缓存）。

3. 性能设计，要对自己负责系统的性能了如指掌，可以通过压测等手段得到自己系统的天花板，否则，某一个接口 hang 住，会导致整个应用的可用性出现问题。

4. 流量隔离，内部应用和外部流量之间，需要进行流量隔离，即使通过缓存，也有缓存击穿的问题。

5. 口头说的东西都不靠谱，要落在文档上，还需要检查执行情况。

看完三件事❤️

如果你觉得这篇内容对你还蛮有帮助，我想邀请你帮我三个小忙：

1. 点赞，转发，有你们的 『点赞和评论』，才是我创造的动力。

2. 关注公众号 『 java 烂猪皮 』，不定期分享原创知识。

3. 同时可以期待后续文章 ing🚀

作者：edenbaby

出处：club.perfma.com/article/184…