周末“捉虫”记

七月 18, 2009

周六，对于上班族来说是多么好的日子，能在家里享受自由的无拘无束的生活而且不用担心第二天的工作，应该说是一周中最没有压力的一天。六点半起床，慢慢喝下一杯225ml左右的凉白开（保健医生说20-25摄氏度的凉白开比较适宜作为起床后的第一杯水），套上运动短裤和上衣，打开MP3播放器，塞上耳机，出门在园区内慢跑。昨晚下了一场雨，所以园区早上的空气很好。耳畔酷玩乐队的“Viva La Vida”让我跑起来很轻松，30分钟的有氧慢跑能让我的大脑和心脏获得足够的氧气，心情也变得更好。最后绕着园区走上一圈结束锻炼。

回房间后，舒舒服服的冲了个热水澡。简单的吃过早饭后就回到了本本前，本来计划解决一下本周五发现的一个GB2312转Unicode码的问题。但此时远在南方某省的技术支持人员打来电话，说我们的产品又出现问题了。这个问题早有端倪，曾先后引起客户总部的投诉、当地一些客户的投诉以及计费部门的投诉。前些时间在查这个问题时一直很迷惑，同样的机器和配置在其他省就没有问题，为什么唯独在该省问题严重。而且从业务量上来说，该省虽然业务量上比其他省高出一些，但按照目前我们产品的处理能力来看，还是完全可以满足要求的。在没有找到根本问题前，本周一直在做一些程序部署上的优化以及参数调整，希望能通过这些手段来缓解问题的严重程度。

本周五刚刚完成了一些I/O上优化，周六却又出现了问题，而且这次是客户集团总部的投诉。前方的技术人员已经是火急火燎，但是查问题也不是一蹴而就的事情，还是需要细心、耐心和稳定的心理的，不能头脑发热。

所有问题的查找都只能从已出现的问题现象着手。今天问题的现象是：我们的产品作为Server端时无法及时收消息并回应答，导致客户端异步发送窗口中的消息超时并重发该消息，而这条重发的消息因与前一条消息有着同样的消息ID而被我们的产品拒绝。还有一个现象就是：我们的产品作为Client端向一内部的鉴权子系统发鉴权请求，因未能及时收到应答而导致我们自己的异步发送窗口中的消息过期而直接进行了下一个环节的处理，这样一来这些消息在用户体验和计费上都会出现问题而导致投诉。

试着调整一下两端通信的参数以及一些队列的缓存参数，生效后也仅仅缓解了一段时间就再次出现了类似的问题，严重时双方居然因为socket阻塞而导致链接断开。这时技术支持同事提到主机I/O特别高。I/O高倒是很好的解释了socket未能及时被读取的问题，但是本周明明做了些I/O优化，为什么I/O还是这么高，而且此时该省的业务量相当的小，基本排除因业务量过大而导致I/O高的可能了。但是又是什么导致阵列I/O高呢？甚是疑惑！

究竟是什么问题导致大量磁盘操作呢？无意间在产品运行环境里发现一个Core文件，如果只发现一个core文件倒不足意外，但是发现这个core文件有上G的容量，而且一直在不断被刷新。难道就是这个core的不断刷新导致了I/O特高？遂尝试写了个脚本每个2秒尝试rm一次该core文件。果然经过这一处理，I/O降了下来，上面的问题也不再出现了。停掉脚本，I/O又攀升了上来，上面的问题就又出现了。“罪魁祸首”终于找到了！

虽然使用脚本可以临时解决问题，但是这样解决问题显然是不负责任的。到底是什么导致Core的出现呢? 停掉脚本，让程序产生core，对core文件进行分析。通过pstack和gdb打开core文件，core文件输出的信息很少，很多信息都成了“???”，似乎栈被破坏了。不过可以获得出core文件的进程号以及dump core的接口函数名字。通过进程号和程序日志共同定位，发现出core的进程都是在处理同一个客户端提交的消息。让技术支持同事封掉该客户端的IP，果然再没有Core产生，看来是我们的程序在处理这家客户端提交的消息时出了问题。

到目前为止已经大有收获了。继续！利用snoop工具获得了该客户端提交的消息包的信息。经过对比分析发现，该客户端提交的包信息与协议中定义的格式不符合。但是我们的程序居然没有发现这样的非法格式包，进一步结合代码、包信息和core信息进行分析，终于定位到了问题所在。原来是我们的程序的一个函数实现逻辑有误，而这种错误在处理正常格式包时是不会发生的，但是处理这种非法格式包时，会导致严重的栈上缓冲区溢出，直至进程运行混乱，dump core并退出。

这时想起周五同事发来的一封邮件，说的是我们的另一个产品在另外一个省也遇到了类似情况，core的输出与今天处理的情况几乎相同。想必是一个问题。因为出问题的函数是很久以前的代码了，而且是复用库中的一处代码。估计所有复用了该库的产品都要做一次升级了。

解决完问题已是日落时分，虽然身体感觉一丝疲乏，但是心情还是不错的，一天的努力终于有了成果，程序员的成就感就是由此而来的。