易坊好文馆

  1. 首页 > 玩科技 >

测试|1个Bug竟修了5天：打log真是门艺术活！

问题 数据 Bug 系统 上线 经验教程 测试 艺术 代码 模块 log 编译器 现网

一、发现Bug
一个程序员在没有成长成为架构师之前 ， 几乎都要跟 Bug为伴 ， 程序员有很多时间都是花在了查找各种 Bug上 。
我印象深刻的一个Bug, 是一个服务器网络框架无锁队列的 Bug。 那个 Bug 连续查找了五天的时间 ， 才最后定位出来 。
当时我们的分布式存储系统出现了性能瓶颈 ， 定位后发现瓶颈是在服务器网络框架上 ， 所以我们决定为此替换一个最新研发的网络框架 。 这个新的网络框架为了追求高的性能 ， 采用了无锁队列的设计 。
第一天编码测试完成后 。 测试环境跑 ， 完全正常 ， 特地搞了一堆 log 来重放请求 ， 程序跑得特别欢快 。 解决了当时的性能瓶颈 ， 感觉特别的开心 ， 但好景不长 ， 服务部署到现网环境 ， 跑不到一个小时 ， 就 coredump 了 。
尝试上线了几次 ， 每次都是跑半个多小时 ， 就 coredump。
当时的第一反应是新网络框架的问题 ， 这是很直觉的反应 ， 但很快就产生了怀疑 ， 因为这个框架也有其它模块在用 ， 也没产生问题 ， 当时觉得诡异了 。
仔细查看了代码的修改记录 ， 特定检查了版本管理系统的 log, 做了代码 diff, 确定确实只有这部分的修改 。 凭着经验 ， 我说服自己 ， 这个时候应该坚信最明确的逻辑 ， 不要走到其他歪路上去 。
第二天 ， 我把这个框架单独拎了出来 ， 特地写了一个测试的模块 ， 并用测试代码生成了一堆的请求数据 ， 发送给测试模块 。 它疯狂的运转起来 ， 跑了一个多小时 ， 跑得很欢快 ， 一切正常 ， 啥 Bug 都没有 。
开大了并发 ， 继续压 ， 依然没有问题 。 懵逼了！不知咋回事 。 再次小心得灰度系统上线 ， 跑不到一个小时还是 coredump 了 ，这个时候 ， 我开始怀疑人生了 ， 这个是咋回事了 ， 都想砸键盘了都 。
然后我冷静了下来 ， 经验告诉我 ， 这时应该按照正常流程完整地跑一遍测试模块 。 于是我把那个测试模块打包成了现网模块 ， 切走了一台现网机器的流量 ， 把测试模块给上线到了一台现网机器 。
之后用工具往现网机器发送数据 ， 不到一个小时 ， coredump 了 。 终于复现了这个 cordedump, 那一刻犹如哥伦布发现了新大陆 ， 简直欣喜若狂啊 。 这个时候已经是第三天了 。
我复现了 Bug ， 但依然没办法定位出具体的原因 。 coredump 出来的栈是全乱的 ， 没有任何价值 ， 接下来 ， 就开始用 log 跟踪法了 。
我依据数据的流转过程 ， 在每个关键点 ， 都打上 log ， log 包含了所在的函数 ， 行数 ， 程序逻辑的编号 ， 全部的关键数据等等 。 我仔细地设计了这个log ， 争取打得不多不少 ， 太多容易看晕头 ， 而且太多无效的信息 ， 会掩盖了真正的问题；太少 ， 信息不足 ， 又不足以判断 ， 所以这种情况下打 log 也是个艺术活 。
通过精心设计的 log, 终于发现数据在一个特定的环节混乱后 ， 程序就一定会 coredump 。 分析log , 发现数据包在最后时刻是完整的 ， 但包似乎出现了乱序和重复 。 这个时候 ， 才开始意识到可能是无锁队列的问题 ， 因为只有队列出问题 ， 包的进出顺序才会乱掉 。
然后又花了半天的时间 ， 专门为无锁队列写了测试用例 ， 用数据疯狂地怼 。 在测试环境 ， 依然一切安好 ， 但上线到正式环境 ， 压测半小后 ， 终于挂了 。 终于看到了胜利的曙光！这个时候已经是第四天了！
到现在已经很明确是无锁队列的问题了 。 但这个数据结构的代码不到 200行 。 我拉了两个同事一起 review ， 都没发现问题 。 但就是 coredump 了 。
奇葩了 ， 又陷入了人生怀疑 ， 开始怀疑内存 ， 怀疑 cpu ， 结果换了机器 ， 还是一样 。
后来 ， 仔细地对比了现网环境和测试环境的区别 ， 机器类型 ， 操作系统版本都一样 。 然后编译器？咦！编译器？上去看了一下 ， 结果发现编译器的版本不一样！这段时间我所使用的现网编译环境升级了新的 gcc 版本 ， 但测试编译环境 ， 还是旧的版本的 。 (这个也比较坑)
当时的直觉是肯定跟编译器相关 ， 但代码都一样 ， 难道是编译器bug？不可能吧 ？！　后来想 ， 不如将它们转换成汇编看看吧 。 于是用两个版本的编译器将C的代码各自转换成了汇编 。 然后diff 汇编代码 ， 哇！发现真的有一行是不同的！
后来自己分析对比 ， 发现是因为我们开启了gcc最高级别的代码性能优化 ， 不同版本的 gcc 在一些没有特定依赖的语句上的优化是不同的 。
说人话 ， 就是有一段代码 ， 如果加了锁 ， 两个版本的编译器下 ， 都会产生一样的汇编 ， 如果没有加锁 ， 代码有一行的顺序被调整了 ， 当然 ， 从编译器优化的角度讲是对的 ， 是我们使用姿势不对 。
但无论怎么样 ， 终于找出了这个问题 。 苍天啊! 找了五天呀! 最后当然是开开心心地上线了 。
查这个bug 确实花费了很多的时间 ， 不过也是没办法 ， 你不解决bug ， 就不能上线 ， 但中间也收获不少 ， 特别是对编译器优化有了很深的印象 ， 也算是为自己的查 Bug 能力 ， 又贡献了一波经验吧 。
对于 Bug , 我分享下自己的一些认识和建议 。
二、面对 Bug 的态度
只要你持续地写代码 ， 就一定会持续的产生 Bug ， 所以第一个事情是要摆正对 Bug 的心态 。 我遇到过两个极端 。
第一个极端 。
遇到过一个leader ， 对系统质量相当重视 ， 对我们写的代码要求很高 ， 每次设计并写完一个新的系统 ， 他喜欢跟你算这次的系统上线 ， 产生了多少次故障 ， 这半年时间产生了多少个 Bug ， 每个 Bug 的影响范围如何 。
我们一堆人被搞得特别累 ， 战战兢兢 ， 到后面 ， 大家都比较排斥去做优化 ， 去重构代码 ， 只求无过 ， 不求有功了 。 所以 ， 我觉得这种方式不好 ， 对 Bug 带着一种比较包容的态度去看待 ， 可以减少不少的心理负担 。
第二个极端 。
后来去了一个新的团队 。 新的团队很重视业务和工程迭代的速度 ， 所以对代码质量和 Bug 的容忍度很高 。 如果是一个新上线的业务 ， 是默许 Bug 存在的 。
这种对质量过于松散的要求 ， 在后面也带来不好的影响 。 大家对 Bug 太免疫了 ， 以至于出现 Bug 和 故障的时候 ， 大家都不够紧张 。 系统质量有一段时间出现比较大的问题 ， 还因此被部门经理特训了一番 ， 后面通过各种措施 ， 才慢慢提高了整体的系统质量 。
上面两种极端都不可取 ， 应该很重视 Bug ， 尽量避免 Bug ， 但也不应该唯 Bug 多少论业绩 。
具体到 Bug 的查找上 ， 我说说我的一些经验 。
三、Bug 的复现
我把 Bug 分为可重现的 Bug 和不可复现的 Bug。
对于可重现的 Bug , 查找起来比较容易 ， 比如可以用”二分查找“的方式 ， 从模块层面开始定位起 ， 每次折半 ， 每次折半地缩小范围 ， 一直到代码层面 。
在代码层面 ， 遵循一些常用的原则：比如看到内存拷贝 ， 直觉上要想到内存越界；看到数组 ， 就要考虑是否索引越界；看到指针 ， 就要考虑是否正确解构；看到多线程 ， 就要考虑是否线程安全；
对于不可重现的 Bug , 第一步就是要把它重现出来 。 有时候特别的难 ， 特别是并发形态下产生的 Bug， 出现的时机和触发条件都不清楚 。 对于这种 Bug， 只能通过各种尝试去复现它 。
比如将多并发调整为单并发的方式 ， 看能否复现 ， 如果可以复现 ， 就可以转化为可复现的 Bug， 用”二分查找“的方式去排查 。
如果不能复现 ， 那极大概率是并发问题 。 这个时候最好先停止排查 ， 仔细分析程序在并发状态下可能出问题的点 。 大部分并发问题的根源 ， 是互斥数据没有被正确读写 ， 或者一些共享状态被错误修改 。
四、静态代码检查
利用coverity等代码检查工具进行代码的静态检查可以发现很多潜在的问题 ， 而且修复的成本很低 。 团队后来引入了这个检查工具 ， 确实带来了不错的效果 。 类似变量未初始化 ， 疑似的内存越界等都有可能被检查出来 。
编译器的 warning 。 有些同学一开始的时候对 warning 不重视 。 我们团队早期也遇到过这个情况 。
那时候产品迭代的速度很快 ， 所以大家写完代码 ， 能够编译通过 ， 就进行各种测试 ， 然后准备上线了 。 一开始的一两个warning, 不太理会 。 后面发现越积越多 ， 到最后终于成为一个不得不解决的问题 。
部门还为此特地立项 ， 来消除warning 。 先是在内部多次强调了这个理念 ， 然后从基础库 ， 基础模块开始实施 ， 基础代码部分统一 fix warning, 然后开启编译器把 warning 当 error 的开关 。 完成之后 ， 再逐步地推业务模块进行修改 。 反正折腾了好一段时间 。
五、工欲善其事必先利其器
代码 Bug 出现的时候 ， 善用一些排查工具可以极大得提升效率 。 比如对于C/C++ 的 gdb 调试 ， 内存泄漏时候 valgrind 的检测 ， linux 下面用 perf top 来析 cpu 的消耗等 。
一开始的时候 ， 我对这些工具不重视 ， 老是觉得真正使用的时候 ， 去查文档就行 。 后面才发现 ， 用工具查着问题时候 ， 遇到不会用的命令或功能 ， 再去查文档 ， 是个痛苦的事情 ， 来回切换的开销也使得效率低下 。
后面就对这些辅助工具的使用重视了起来 ， 专门花时间去学习和练习使用 ， 反而提升了不少的效率
六、打 log 的艺术
很多时候 ， 出现一个 Bug ， 未能定位出来 ， 需要打上更多额外的 log 来辅助排查 。 一开始的时候 ， 是想到一点 ， 打一个 log ， 后面发现这么做没有章法 ， 逻辑不清晰, 排查效率低下 。
后来学会了 ， 遇到 Bug 后 ， 先在脑子里面分析一番 ， 然后花一两个小时详细地设计 log 的格式和打 log 的位置 。 发现这种方式对查问题的效率提升很大 。
所以遇到 Bug 的时候不要急躁 ， 先静下来心来分析 ， 在脑海里尽力重现出完整的运行逻辑 ， 然后仔细地进行 log 设计 ， 包括 log 包含的字段 ， 打 log 的点等 。 这样能极大的提升排查问题的效率 。
七、结语
Bug 是程序员最不愿意用面对 ， 但又经常出现的一个 “诡异生物“ 。 对待Bug 要有正确的心态 ， 最好不要跟业绩强绑定 ， 也不能太过于疏忽 。 Bug 的排查是个很复杂的事情 ， 每个人都有自己的方式和做法 ， 如果你有好的做法和建议 ， 也欢迎在留言区分享给大家！
作者丨大飞码字
来源丨大飞码字（ID：BigFly1024）
【测试|1个Bug竟修了5天：打log真是门艺术活！】欢迎关注公众号dbaplus社群（ID：dbaplus） ， 了解更多原创精选内容 。

    推荐阅读


    上一篇：滨海|集聚相关企业30余家 涵盖细胞全产业链 高新区加速打造“细胞谷”

    下一篇：客户|太平人寿以科技之力，让保险服务更满意