cat-server不可用导致客户端服务OOM

背景

先解释一下题目。本次问题是公司的某个服务间接依赖了cat-client（后面为了简化，将服务简称为service-X），但是由于服务端cat-server服务挂掉导致客户端的监控信息发不出去，积压在了客户端内部，最终导致service-X OOM，服务不可用。

正文

1 现象

发生问题的时候，是因为客户发现我们的另一个服务一直报错，根绝报错信息和日志排查后发现该服务依赖了service-X的RPC接口，RPC接口调用失败才导致另一个服务报错。查看dubbo监控发现只有消费者，没有提供者了。

也就是说service-X出问题了。

查看grafana监控，可以看到两个pod CPU在一段时间内突然飚很高，内存一直缓慢上涨，直至稳定。

后面检查了一下service-X，由其提供API支持的前端页面也报错。但是看了一下k8s集群，发现service-X的pod还是正常RUNNING，除了CPU、MEMORY占用比较高之外，没有什么明显异常。只有一个pod有一次重启记录，原因是OOMKilled。

也就是说，service-X虽然存活，但是无法对外提供任何服务。

2 问题排查记录

2.1 对比分析 - 正常、异常pod对比

service-X有两个pod，简单看了一下两个pod后，发现没有什么显而易见的问题根因。日志倒是有不少报错，不过短期内无法快速分析定位问题。此外，由于客户在线等着，还要继续推进他们的业务，我们只能暂时先恢复服务，保证服务可用性。具体措施如下：先保留两个pod的所有日志、dump出service-X两个pod的内存（前面看到内存占用较高），然后暂时重启了其中一个pod，先保证服务可用；另一个pod则继续留存，继续看下能不能发现更多线索。

这个时候，用户那边能够继续推进，我们也能够安心排查问题了。

对于service-X，能留存的线索（日志、内存）都已经保留好了。而且刚好两个pod一个正常，一个异常，可以作为对照，先看下两边的异同。

2.2 网络

从日志里发现问题发生之前和期间，有网络相关报错，如ZK timeout。对比了一下两个pod，效果如下。

发现异常pod内一堆的CLOSE_WAIT。暂时没什么思路，只能暂时放弃这个排查方向。

后续

一开始怀疑过网络问题，后面结合内存排查后，觉得CLOSE_WAIT应该是果，因在于内存OOM。

2.3 内存排查

线上排查 - jmap

从上图可以看到pod-rlzhg的老年代已经99%，CPU和内存利用都很高。

当时已经比较晚了，只能让OP先重启服务，保证线上服务的可用性。至此，线上排查过程结束。

补充

这里漏掉了一个线索，当时没有注意去看gc的情况。好在后面测试的时候能复现上述问题，补上了这一环节。也能解释为什么CPU会飙升。

Note

service-X的服务，已经加了auto-heap参数，设定Xmx为pod内存大小的80%。当内存为2G时，Xmx~1600m。

线下排查 - dump内存分析

继续分析dump出来的内存。

查看dump的内存继续分析，可以看到最明显的是CAT相关【com.dianping.cat.message.io.DefaultMessageQueue】。

---

这里有了新的疑问：什么原因导致DefaultMessageQueue占用这么多内存？如果是cat导致的问题，为什么同样环境的其他服务没有问题？为什么其他环境的service-X也没有问题？

---

其实service-X本身是没有依赖cat-client的，是通过lion、dubbo间接依赖。

后面先参考【文章2】快速学习了一下cat-client的原理，例如TcpSocketSender、StatusUpdateTask的功能；参考【文章1】的思路，深入挖掘了dump内存的信息，分析了cat和netty相关问题。

cat目前在公司属于没有开发维护的状态，只能找相关负责人要了cat源码自己分析下。下面描述的cat-client的主要代码逻辑跟开源项目基本一致，也可以参照github上的cat-client源码。

从内存分析~97%的内存都在DefaultMessageQueue类里LinkedBlockingQueue m_queue中，m_count为2894（m_queue内node数量）。其中，cat初始化时会将m_queue设置为固定大小为5000的队列。

这张图转自【文章2】

根据【文章2】中介绍的cat-client的工作原理，会有一些业务线程负责打点，然后Producer处理后将其放入队列m_queue中，这一系列操作是同步的；之后有一个异步上报线程TcpSocketSender，不断从队列m_queue中轮询数据，通过netty建立的tcp channel上报至服务端。

这里可以分析是m_queue内存储的内容太多，导致OOM。

---

但是m_queue中为什么会有太多内容，是因为写入太频繁？还是因为消息发不出去？

---

查看m_queue的node内容，主要可以归为3类

• cat heartbeat，cat-client定期产生的统计信息，如CPU%，MEM%，连接池状态，系统负载等；
• rpc调用：例如Class::method；
• 内存OOM上报Event，有点类似于heartbeat。

上面的截图看着简洁，可能无法真实反映m_queue的node里存储信息的大小。

换另一个视角看的话，m_queue中单个node的完整信息如下。

其中第一种情况单条数据最大，仅m_data约229KB。

具体内容为：

关于heartbeat等概念，可以详细阅读下【文章2】。

2.4 内存 - cat-client发送

service-X不会主动打点，打点基本都是dubbo、cat自己打的。这种基础组件已经被很多人用了很长时间，不太可能出现疯狂打点这类异常情况。所以目光转向消息写入后发不出去。

根据cat-client代码可以知道可以知道TcpSocketSender实现了Task interface，类内也持有对象m_queue，线程的作用就是从m_queue中不断poll消息，然后通过netty channel发送至服务端。根据【文章1】的思路，排查后发现是channel还存在，但是非open状态，所以checkWritable()=false，不可写。

关于server端cat，发生问题的当天没有排查，春节后跟OP翻阅监控记录，发现cat服务在2月7日~2月20日之间挂掉了。所以cat客户端与服务端的连接肯定不可用，无法将数据发出去。

2.5 内存 - cat-client打点

后面主要排查cat-client打点部分，以及什么情况下会导致上述问题。

最后代码分析+测试后发现只要当前环境的cat不可用（服务端中途挂掉、cat没有部署），都会导致上述问题。

---

在排查过程中，另一个环境在QA测试过程中，也发生了service-X的问题。排查后发现另一个服务service-Y内存也比较高，但是仍然可以提供rpc服务。

又一个迷惑？为什么还可以正常提供服务？

从新环境dump service-X和service-Y的内存后分析，service-Y的m_queue size=5000，已经满了，两个pod内存使用量分别为1.31G、1.47G；service-X类似，两个pod都是1.6G左右（两个pod一个size已经5000，一个4000+）。

这里可以得出结论：不同环境的service-X、同样环境的其他服务也会出现类似问题。

两个环境的共同原因都是cat服务不可用：最开始的环境是cat服务挂了，新环境是cat服务没有部署。

而m_queue满了后，两个服务一个可用，一个OOM不可用的区别在于m_queue内存储的数据量大小：如果heartbeat比例较高，则内存占用较多；如果rpc调用打点的比例较高，则内存占用就算达到上限，也不会OOM。后者相当于从pod总内存中吃掉了一小块，服务不可回收这部分内存，也由于服务还有其他内存可用，不至于OOM死掉。

简单算一下heartbeat占用的内存：

• 230KB * 5000 = 1.1GB
• 230KB * 2894 = 650MB，实际老年代大小约1092MB。

这里算出来的内存不一定准确，只是提供一种数量上的概念。

2.6 本地复现

在本地采取一些措施，尝试复现上述问题。具体如下：

• 在cat-client的源码中加了一些日志，将heartbeat频率从原来的1min提高至1s，重新编译cat-client源码生成jar包。
• 本地启动service-X，设置Xmx=400MB，使用jvisualVM监控。
• 防火墙禁用cat通信的2280端口，模拟cat服务不可用的情况。

具体效果如下：

小结：

整体效果跟线上问题一致。

OOM问题复现后，FGC次数以每秒10+次的频率往上涨，CPU load飙升。跟最开始看到的grafana监控一致。

而且即使OOM自动dump出内存后，服务依然没有挂掉，还是存活状态。也跟线上问题一致。

3 Q&A及解决方案

Q：如果cat服务一开始就不可用，是不是就不会因为channel open=false而出现问题？

A：不会，依然会出问题。另一个环境出现的问题已经说明。而且，如果cat一开始不可用，可能现象会是channel为null，最终还是发不出去。

Q：m_queue size=5000能不能调整，使用方自主调整，从而降低出问题时的内存负担？

A：不能修改，size=5000是硬编码写死了，无法修改。

Q：发生问题后，能不能自行恢复？

A：只要pod没有彻底OOM不可用，当cat-client和服务端的通信恢复后，还是可以把m_queue中积压的数据发出去的。所以短暂性的cat服务不可用是可以自行恢复的。

Q：怎么解决上述问题？

A：根据测试和cat源码分析，总结了4种解决方案。其中某些方案纯粹为理论分析，不具有可行性。请自行识别。

1 最稳妥的方案：确保cat服务正常。

2 败家浪费内存方案：加大服务内存，即使m_queue全满时占用掉一些内存，也有足够的空余内存可用；

3 影响最小方案：移除/data/apps/config/cat/client.xml文件（是否有其他风险，暂时未知）；

如果client.xml文件不存在，cat-client会在初始化时认为被禁用，而不会初始化m_queue及相关线程。

[03-02 17:17:03.018] [WARN] [DefaultModuleContext] Global config file(\data\apps\config\cat\client.xml) not found, IGNORED.
[03-02 17:17:03.030] [INFO] [DefaultModuleContext] Current working directory is D:\x\y\z\service-X
[03-02 17:17:03.043] [INFO] [DefaultClientConfigManager] external_properties: /data/apps//config/app.properties
[03-02 17:17:03.051] [INFO] [DefaultClientConfigManager] prop: {"deployEnv":"beta","lionZkServer":"1.xxx.6:2181,1.xxx.7:2181,1.xxx.8:2181","arch.zk.address":"zookeeper://1.xxx.6:2181?backup\u003d1.xxx.7:2181,1.xxx.8:2181"}
[03-02 17:17:03.052] [WARN] [DefaultClientConfigManager] Global config file(\data\apps\config\cat\client.xml) not found, IGNORED.
[03-02 17:17:03.059] [INFO] [DefaultClientConfigManager] Find domain name service-X from app.properties.
[03-02 17:17:03.064] [INFO] [DefaultClientConfigManager] clientConfig: <?xml version="1.0" encoding="utf-8"?>
<config enabled="true">
   <domain id="service-X" max-message-size="1000"/>
</config>
 
[03-02 17:17:03.908] [INFO] [DefaultClientConfigManager] m_config: null
[03-02 17:17:03.909] [INFO] [DefaultClientConfigManager] localMode： true
[03-02 17:17:03.910] [INFO] [DefaultClientConfigManager] m_config.isEnable(): false
[03-02 17:17:03.928] [WARN] [DefaultTransportManager] CAT was DISABLED due to not initialized yet!

注意上面最后一行（CAT was DISABLED）。

如果确定cat服务端可以下线，这种方案是影响范围最小的。对cat开发和OP，直接下线cat，并禁用client.xml即可；对用户，不需要改动代码，也不会出现内存浪费。

但是该方案没有充分测试，不确定是否有其他风险。

4 理论方案，实际不可行：修改*/data/apps/config/app.properties文件里的deployEnv=local*

理论可行，但是基本不具有可操作性。会导致无法连接zk，无法读取lion配置等一系列问题。

总结

从上面的分析可以知道，不管主动与否，但凡依赖了cat-client，代码中有了打点的操作，一旦cat-client初始化（例如service-X，调用别人的rpc接口、或者提供的RPC接口被别人调用），都会遇到上面的问题，有可能出现OOM问题。

个人感受

1 cat相关知识

【文章2】对cat的介绍非常棒，在排查问题的过程中帮助很大，非常感谢作者的分享。

2 JVM相关知识

之前也排查过内存问题，当时小白一个，第一次听说MAT，对JVM了解有限，排查这种问题无异于赶鸭子上架。但是没办法，面对问题总不能退缩吧，只能打起精神、硬着头皮往前推进。

当时花了几天的时间排查问题后，对MAT、jvisualvm等工具的功能大致有了个面上的概念，知道怎么回事，怎么用起来了。

这次问题排查中，往下更深入了一点，能够主动使用jvisualvm；对MAT的使用更细致、深入了。特别是【文章1】中展示的找出dump内存中变量value、结合代码逐步推进的思路，很有启发性，bingo，原来MAT还可以这么用。

综上，参照【文章2】，学习了cat-client理论知识；参照【文章1】，学习了如何细致分析dump内存，抽丝剥茧。

非常感谢无私分享的同行前辈。

3 抓重点

排查过程中，也涉及到了网络、ZooKeeper、Netty等，如果全面来看，这些都是技术发展路线上不可或缺的部分。但是如果因为我还不会、需要等到把所有知识都掌握后再来看问题，可能黄花菜都凉了。而且看到这么多技术点要攻克，很容易产生畏难情绪。

与其畏首畏尾，不如先干再说。

一定要注意去繁就简，抓住重点。不重要的部分不要求全，暂时只涉略跟当前主线相关的一部分即可，有兴趣的话后面再慢慢把其他知识补起来。

过程中花了点时间看了篇介绍ZooKeeper的类似于【文章2】的文章，准备深入追查网络、ZooKeeper的日志报错问题，最后看完发现确实对ZK大概有印象了，但是回头来看，这部分知识确实不在问题主路径上，帮助有限。而且由于没有实践辅助，虽然看过了文章，但掌握不算深刻。

参考文章

【文章1】 曹工改bug：cpu狂飆，old gc頻繁……

【文章1】 大众点评CAT开源监控系统剖析 - 沙漏哟 - 博客园