环境:java8 dubbo2.8.4
现象:a服务调用b服务，设置调用超时10s，偶尔会出现调用超时，但是非常奇怪的是，b服务收到请求是延迟的，比如a服务1点发送请求，超时，b服务接收请求就打印日志，但打印日志的时间却是1点40多秒。b服务在超时的那段时间没有什么日志。1分钟左右会恢复正常，非常奇怪。
排查过程:
这个现象困扰了我很长时间，一直找不到原因。
刚开始怀疑docker网络问题，做了节点切换，问题依旧。
后来发现超时的那个时间点有zk心跳断开的日志，开始怀疑是zk的问题，并且我们使用的zkclient版本与zk server的版本也不一致，然后升级a、b服务的zkclient版本后问题依然存在。zk问题排查无果。
继续排查，偶然发现b服务的日志使用log4j2，但日志却在console中也同步输出了，这有可能会把docker搞死，会不会因为这个问题？修改后重新部署，问题依旧。
后来怀疑环境问题，因为服务部署在docker里，做过一次docker环境迁移，迁移之前没有出现过问题，迁移后才出现的，但是别的服务却没有问题，苦于没有证据，只能作罢。
再后来偶然在网上看到gc问题导致应用停顿时间过长，恍然大悟，赶紧去生产查看，通过jstat -gc ，jstat -gcutil命令，发现fullgc平均耗时20多s，我们使用的是cms算法，也就是说一次fullgc耗时了40多s，这也就印证了b服务打印日志的时间就晚的问题已经zk心跳断开的问题。因为fullgc期间会将应用停住。但是为什么唯独b服务耗时长呢？另外还发现了另外一个问题metaspace居然占用了1g多。
接着开始分析b服务与其他服务的差异，b服务除了基本的dubbo以外还运行着定时任务，会不会定时任务导致？排查无果。
后来在网上看到可能跟使用了swap空间有关，按照https://blog.csdn.net/xiangliangyu/article/details/8213127 发现进程确实使用了swap，同时通过iostat命令跟踪fullgc前后swap空间使用情况，发现fullgc时占用了大量的swap空间，那应该是此问题导致fullgc耗时长了。
原因终于查到，怎么进行优化呢，swap是不可能去掉的，会不会是metaspace占用大导致的呢。测试环境增加jvm参数，打印fullgc时的详细信息，发现fullgc时unclassloading占用一多办的时间，参考https://blogs.oracle.com/poonam/long-class-unloading-pauses-with-jdk8 增加UseLargePagesInMetaspace参数后，继续测试发现fullgc耗时降到了5s以下。至此问题已基本解决。
但是还是有一个问题困扰着我，metaspace为什么会占用这么大呢？抓jvm快照、线程信息、堆栈信息，分析后也没有发现什么蛛丝马迹，查了一下metaspace的原理，怀疑还是classload或使用了aop 反射导致，但是spring本身就用了大量的反射，整个去掉是不可能的。
继续jvm增加参数gcverbose，没有发现什么特别，继续加-XX:+TraceClassUnloading –XX:+TraceClassLoading参数，发现一直加载groovyclassload，至此恍然大悟: 原来是groovy使用方式不对导致，查找使用groovy的地方，发现有段代码:每隔一秒创建一个classload并加载groovy，非常隐蔽，但总算找到根本原因了，优化代码，至此问题终于根本解决了。
网友评论