调试Bug的神兵利器:通过WinDbg条件断点收集Log
前段时间花了几天一直在用WinDbg调试一个比较棘手的Bug。这个Bug是C# Team那边发现的,他们的Testcase跑大概10分钟左右会出一个在CLR内部的ASSERT。比较难调试的主要原因在于ASSERT表明一个全局的数据结构出现了问题,本来不应该用完的数组却已经用完了(因为按照设计,这个数组是边使用边清理的,是不会用完的)。初步想到的有下面几种方案来调试:
1. 设置数据断点
2. 一步一步调试
3. 添加Log代码
设置数据断点的主要问题是不太好确定到底是因为什么原因导致的数据结构问题,而且因为是数组被用完,很难将是到底是哪一个数组元素的加入导致了数组被全部占用,因此无法通过设置数据断点的方法来调试。一步一步的调试显然也没法解决问题,因为这个Testcase本身要跑十分钟,可以想象单步调试运行十分钟的程序会花费多长时间。因此两个方案都被我否决。添加Log代码其实是可以的,只是需要修改代码,每次修改之后需要重新编译代码,然后需要在目标机器上安装,而且C#使用的CLR的Branch并非我们正在开发的Branch,需要重新下载源代码,相对比较麻烦。最后为了解决这个问题,我采取的方法是使用WinDbg的条件断点+Log的方式。大致的方法如下:
第一步:在一个或者多个可疑处设置断点
bu address “command”
bu是WinDbg中的设置Unresolved Breakpoints命令,用起来比较方便,我比较喜欢用。address就是你所要断的代码地址,可以是函数开始,也可以是某一行。Command非常重要,它表示了WinDbg在每次断到address的时候都要执行的命令,不同命令用分号隔开,如:
.echo [Function A]; dv this; kb; g
这几条命令意思是:打印[Function A],打印this指针的值,打印当前调用栈,然后继续执行。大家可以根据实际情况添加一些其他命令打印一些自己所需要的信息。通过上面这套命令打印的内容大致如下:
[FunctionA]
this = 0xABCDEFG
module!FuncA
module!FuncB
module!FuncC
…
可以看出,这条断点如果反复被断,那么在WinDbg的命令窗口中便会把每次断点被Hit的相关信息通过刚才定义的命令打印出来。如果定义了很多这样的断点,那么在命令窗口中就会把整个程序执行的情况打印出来,起到Log的作用,而且可以显示调用栈等信息,比一般的Log要强大许多。
第二步:设置Log
缺省情况下,WinDbg的Buffer大小是有限的,如果程序运行时间比较长,那么Buffer可能会不够,我们通过条件断点打出的信息会被截断。幸好,WinDbg提供了将命令窗口的内容输出到Log中的功能。选择Edit->Open/Close Log File菜单项,WinDbg会显示如下对话框:
在这个对话框里面输入你想要保存的Log文件名即可。如果是添加新的内容而不是覆盖原有的,则勾上Append。
第三步:分析Log
当获得了Log信息之后,下一步就需要分析Log的内容了,这是一件需要耐心、对数据的敏感、以及一点点运气的事情。分析的时候可能发现Log的信息不足,这时就需要添加新的断点或者修改打印的信息,重新收集Log,再加以分析,直到Log信息足够为止。这时WinDbg设置条件断点的优势就出来了,因为不需要修改代码,编译代码,部署代码这样的一个过程,而是只需要键入不同的命令而已。经过几次调整断点位置和打印的信息并重新收集Log,我最终通过分析发现这个Bug是只有可能在特定情况下RCW没有被GC,并且创建线程退出的时候才会出现,具体的内容因为涉及到.NET 4.0中还没有发布的新功能,这里就不多说了。可以看到,如果采用常规的方法,对于这种在特定的条件下才会重现的问题是很难发现的。
总之,使用WinDbg来设置条件断点,打印相关信息,并且输出到Log文件是一种非常强大的调试方法,可以调试一些非常复杂的Bug,而且具有不需要修改代码的灵活性,可以自由定义自己想需要打印的信息和断点设置的位置,主要的缺点是方法稍显复杂,不过如果适应了之后还是很方便的。我强烈推荐大家在遇到比较复杂的Bug的时候,可以尝试使用一下这种方法,可能具有意想不到的效果哦。