记一次性能Debug过程

这两天我一直被一个性能问题困扰着,花了一整天去做调试,最终功夫不负有心人,被我找到原因,而原因居然是由于我不经意的网络配置,这印证了千里之堤毁于蚁穴,但也证明了调试代码需要无比耐心,不放过任何可能性,也不放过任何蛛丝马迹。

问题的开始是这两天我在升级我之前写的一个component,把这个component里面连接其他服务的方式改成了调用另外一个同事新写的Service Discovery的模块。升级的代码我很快就写完了,初步的测试也看上去跑得通。可是我发现有一个奇怪的现象,每次重启server后,第一个发起的request,我的Server居然花了30秒才处理完毕!30秒!!!!什么概念!!这简直是程序员之耻辱!然后就开始我这次调试之旅。

一开始我怀疑是死锁导致,因为我前段时间有fix过一个线程不安全的bug,做了一些同步处理。我就用jstack把thread dump打印出来(jstack -l > file), 注:在windows下,可以按ctrl+break键,直接在控制台打出Thread Dump, 在Linux环境下,可以通过kill -3 命令。我反复仔细查看了Thread dump,发现虽然有等待锁的过程,但并没有死锁,我又仔细推敲了代码,最终排除了死锁。

接着我就开始查看server的log,打开debug模式,看到是执行一个方法的时候直接就用了30秒才返回,我就一路跟着代码debug进去看,由于这个server要连的一个服务是一个第三方的商业软件,叫Sentinel License Server,它提供的client API包不是开源,我只能反编译出来看。

在这个包里面的连接方法里面,我看到了一个DatagramSocket的retry和timeout机制,再仔细看,timeout就是hard code成了30秒,就是说它会反复去连接,知道30秒timeout。得,看到这里,好像是找到了原因。但问题又来了,为什么在我做升级之前并没有这问题呢? 而且都已经到了去连接服务这一步,明显不是service discovery的问题,那我是不是不小心做了哪些配置导致的呢?我先是把代码的版本revert回到我做升级之前的样子,重新跑,发现结果还是一样!

活见鬼了!

于是我又想,除了代码上的改动,还有哪些设置甚至是系统的配置我有做了改动呢? 终于我想到了一个,唯一的一个改动就是我在/etc/hosts文件里把前文中提到的要连的Sentinel License Server的vip指向了127.0.0.1,而以前我是没有设置这个的,我的本意是我的机子上并没有装这个Sentinel License Serer,那我希望它是尝试连本机的时候就直接返回错误了。于是,我就把这个hosts mapping去掉,重新测试,发现问题消失了!!

根据这个结果,我再重新去看那个client包反编译出来的代码,发现了了它的createDatagramPacket的方法里面的实现:

try { DatagramPacket var4 = new DatagramPacket(var16, var16.length, InetAddress.getByName(var1), var2); return var4; } catch (Exception var13) { LStrace.traceMessage(2, "Exception in createPacket(), couldn\'t create datagram:" + var13.getMessage()); return null; }

在以前的时候,我并没有在hosts文件里加上mapping,那它在createDatagramPacket的时候,到调到了InetAddress.getByName(var1)这个方法时,就发生错误了,直接return null跳出,而这次当我加上了host的mapping后,它成功create了DatagramPacket,就尝试去send这个DatagramPacket,send不成功就retry直到timeout!

各位观众,原来凶手就是。。。。。我自己!

经验: 耐心!计算机不会说谎,出错的百分之99.999999%是人,没错,说的就是我自己!

comments powered by Disqus