JVM 的 YGC，这次被它搞惨了！，rabbitmq 实战指南 pdf 最新版
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 = 40MaxHeapFreeRatio = 70MaxHeapSize = 4294967296 (4096.0MB)NewSize = 2147483648 (2048.0MB)MaxNewSize = 2147483648 (2048.0MB)OldSize = 2147483648 (2048.0MB)NewRatio = 2SurvivorRatio = 10MetaspaceSize = 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 性能监控等可视化监控平台帮助真的很大，否则到处去查日志得查的晕头转向了。
评论