排查 zk session 超时的异常
zk session 超时
上周四，性能测试童鞋告诉我，说我们后端的大数据应用报错。都是跑了一会儿才报错，刚开始是好的。
那个应用是个 tomcat 应用，提供了几个 web service 接口，主要作用是通过 es 来查询数据，然后通过 spark app 去 hbase 里拉取数据返回给平台。由于任务执行过程可能超过 10s，所以不能马上返回，会把任务结果缓存到本地缓存 ehcache 里，然后平台不断尝试调接口去获取执行结果。每条 hbase 记录都有100多个字段，还算比较大的。
另外，这个应用可能部署多个节点，主节点信息保存在 zk 上，如果当前节点不是主节点，会转发到主节点上去。 而主节点切换时，会把原来主节点上的 spark sc 给干掉，免得浪费 yarn 上的资源。
我听了没放在心上，毕竟功能比较简单。于是慢悠悠听完演讲，才去看这个问题。基本猜测是性能测试，压力过大造成的， 毕竟之前测试的时候没发现这个问题。
回来看了一把，报的错是 zookeeper 的 session 超时，造成主节点切换，结果 sc 被干掉了。问题是，这个环境是单机环境， 主节点只能是当前节点，所以就必须找到为什么会 zookeeper session 超时了。
排除压力大的原因
由于是性能测试中爆出来的问题，所以强烈怀疑是压力大造成的，而且本司的大数据服务器基本都是超负荷跑的。那么就先复现一把吧。
测试童鞋不辞劳苦地又复现了一把，果然，重启后跑了一个小时不到，又复现了。同样的情况，是在全接口测试的最大压力下复现的。 一般 zk session 超时都是压力过大造成的，去年本司还把 zk 安装到了独立的 SSD 盘上，理论上不应该出现呀，难道还有这个问题？
看来得监控一把系统压力了。系统压力监控，我也没有好的办法，同时要监控硬盘/内存/CPU/网络四项，还比较麻烦。 最后决定，硬盘监控用命令：iotop; 内存监控用命令：sar; CPU 监控命令同样是 sar; 网络连接监控用 lsof.
结果辛苦了一天多，唯一发现的价值就是：zk session 超时异常和 CPU 使用率强相关。但理论上讲，后者应该是前者的结果， 而不应该是造成前者的原因呀。
由于本司条件比较差，所有组件都是放在一起，比如 es/hadoop/spark/hbase/kafka 等等，全放一块儿，简单粗爆。之前就发现 es 是 抢占 CPU 资源的神器，会不会是 es 抢占 CPU 造成的 zk session 超时呢？尽管发现用户进程占 CPU 时间的 90% 以上，但CPU是时间片轮询的，再怎么样，10s的时间，怎么样都能完成一次 zk client 和 zk server 的心跳了。 所以个人觉得这个可能性不大。但总得验证一下。
于是把全接口中的查询/检索接口停了，于是CPU压力瞬间就降下来了，而内存使用率也不那么高。
诡异的事情来了，跑了半个多小时，zk session 超时问题又出现了！这说明绝对不可能是压力问题造成的，方向错了！
迷茫
不是压力问题，那会是什么呢？没头绪了。
迷茫了半天多，会不会是某些系统资源比较少，比如网络连接/文件打开数什么的？ 为了能监控更多的东西，我决定找个成熟的系统监控工具。找了半天监控系统的工具，发现网上说 spotlight on unix 挺好用的！ 像发现新大陆一下，搞下来试试。结果人家跑的好好的，在我这儿，估计是系统不兼容的缘故，spotlignt 一直报连不上服务器，说 ssh 密码不对，事实上我拿相同的密码连服务器一点儿问题没有。
快放弃了，继续迷茫。。。
由于只有这个应用报了 zk session 超时问题，其它组件都没有报，说明是这个应用的问题，不是压力问题，不是 zk 的问题。 这时候，同事建议我看下 jvm，会不会是 gc 造成的。但既然不是压力，不应该有 gc 呀。
现在已经没有其它方向了，我决定不抱希望的试下 gc 这个想法。
初步发现原因
配置好 jstatd 的配置文件，在本地跑起来 VisualVM，又把全接口跑起来，结果发现这个应用的 tomcat 的 jvm 堆使用量一直在上升， 从不下降，我也没有太留意，毕竟我不知道这个应用的 jvm 堆大小是多大(汗!)。
大约跑了半个小时后，突然，zk session 超时的异常出现了，看了下此时的 jvm 堆信息，老生代堆 14.5g，全部用掉了，发生 Full gc 时, 完全没有释放任何空间！原因找到了，gc 造成的！！！
突然想来一句国骂(我是文明人，真的!)。
jmap/jhat 踩坑
找到了 gc 的原因，可是我们的 tomcat 启动时，没配置 -XX:+HeapDumpOnOutOfMemoryError 这一项，所以就手动用 jmap 把 jvm 堆信息 导出来，然后用 jhat 分析吧。
重启后导出来 jvm 堆文件, 我的命名是：heap.bin. 导出的有点儿晚，导出来时，已经有 4.1G 了。我传到本地，尝试用 jhat 去分析。 想当然的以为 2048M 就够了，毕竟谁会一次性把 4.1G 全读进来，然后再分析啊。
注意，坑来了！ jhat 分析命令是: jhat -J-Xmx2048M ./heap.bin.
- 命令开始执行后，我 16g 的电脑就开始卡，大约卡了 10 分钟，报错了：Out of heap space. F*ck!
- 换成 4096M，再执行，还错！这次卡了 20分钟。
- 换成 8096M，我就不信了，结果还错！这次卡了半个小时。
- 再换成 10240M，再执行，还错！
想要放弃了。。。我就改个bug，咋就这么难呢。。。
最后拿我司的大数据服务器来分析，命令是：jhat -J-d64 -J-mx50g heap.bin 这次终于搞定了，感谢天，感谢地啊！
定位原因
从本地访问 ip:7000, 发现内存中最大的是类是：[C、java.util.HashMap$Entry、java.lang.String 这三个。这个 [C 是什么鬼。。。 而且，这个应用里，没多少 HashMap 和 String 呀，一脸蒙逼。
翻了半天代码，也没找到原因，又不死心地看看 [C 和 HashMap$Entry，什么发现也没有，最后偶尔点进排第三的 String，奇怪的事情来了， String 里大量的都是数据，这些数据应该都是数据库里的，或缓存里的，难道是代码某个地方没释放？不应该呀！最后怀疑这些东西是缓存 里的数据，问题在 ehcache.
于是修改了一下 ehcache 的配置文件，把 maxElementsInMemory 从 1000 改为 100（之前手贱改成了1000,说多了都是泪呀）。 重启一把再试试，果然这次 tomcat jvm 保持在 3-4g，上不到 5g 了。
总结
一次请求大约有 3000 条记录，每个记录大约 120 个字段；原来内存中保存了 1000 次请求的结果。最后在内存里就要保存近 360000000 个字符串。 这 15g 哪儿放得下啊。。。就是十分之一，也勉强啊！
