实战：结合Dr.Watson系统日志和Vc6来定位多线程环境下程序异常退出的错误

来源：百度文库 编辑：神马文学网 时间：2024/04/28 11:07:06

实战：结合Dr.Watson系统日志和Vc6来定位多线程环境下程序异常退出的错误

    当开发的软件发布以后，在客户那运行时可能会因为各种原因导致程序退出。这种情况很尴尬，很明显我们无法在客户机器上装个VisualStudio调试，所以必须有机制来收集出错的信息。软件本身的运行日志能提供部分信息，但是可能还不够。Windows系统为此提供了解决方案：Dr.Watson工具。Dr.Watson也算是一个小巧的调试器，32位的版本名字是drwtsn32.exe。可用于当系统中有进程发生异常崩溃时采集信息。下面结合一个例子看一下其用法。

 

先把测试代码贴一下：

  1. /********************************************************************/
  2. /* 程序：lesson_2, 结合Dr.Watson与工程map文件定位错误                                  */
  3. /* 功能：多线程环境中利用除0错误使程序产生异常，被Dr.Watson捕获之       */
  4. /* 作者：coding (http://blog.csdn.net/coding_hello)                                                     */
  5. /* 日期：2008-09-29                                                                                                    */
  6. /********************************************************************/
  8. #include 
  9. #include 
  10. #include 
  12. const int cnThreadnum = 4;
  14. UINT WINAPI Worker(LPVOID lpParam)
  15. {
  16.     srand((DWORD)lpParam);
  18.     DWORD dwTid = GetCurrentThreadId();
  19.     int k=100;
  20.     while(k--)
  21.     {
  22.         printf("tid[%u] tmp = %d\n", dwTid, RAND_MAX/(rand()%cnThreadnum));
  23.         Sleep(10);
  24.     }
  25.     return 0;
  26. }
  28. int main(int argc, char* argv[])
  29. {
  30.     HANDLE hThd[cnThreadnum] = {0};
  31.     for(DWORD i=0; i
  32.     {
  33.         hThd[i] = (HANDLE)_beginthreadex(NULL, 0, Worker, (LPVOID)i, 0, NULL);
  34.     }
  36.     printf("Wait...\n");
  37.     WaitForMultipleObjects(cnThreadnum, hThd, TRUE, INFINITE);
  39.     for(int k=0; k
  40.     {
  41.         CloseHandle(hThd[k]);
  42.     }
  44.     printf("Finish!\n");
  45.     system("pause");
  46.     return 0;
  47. }

程序已开始就启动了4个线程，然后主线程等待所有的线程结束。线程函数中可能会因为RAND_MAX/(rand()%10)导致出现除0的错误。这里注意，编译的时候选择Link页，把"Generate mapfile"前面勾上。一般来说我就这样用了。但是还可以让map信息更详细一些，在最下面的"ProjectOptions"的最后面手工敲入："/mapinfo:lines"，注意，跟前面内容要用空格隔开。然后再编译。

 

因为是要演示Dr.Waston，所以我们在命令行先用drwtsn32 -i的命令注册Dr.Watson为默认调试器（下次启动VC6的时候，在菜单option-->debug里面确认just-in-time debugging选中，就会把VC6恢复为默认调试器的）。注册完以后，我们看看注册表是否满足需要了。

 

 

看看注册表中HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\WindowsNT\CurrentVersion\AeDebug，其中的Auto键的值如果是0的话，程序出错后还会弹出错误提示。我们需要的是出错后安静的处理掉，客户知道了多不好~所以，改成1。下面的Debugger已经是drwtsn32了，很好。最后的UserDebuggerHotKey是调试器的热键，我们不需要。接下来，还是在命令行敲Drwtsn32，回车，终于看到Drwtsn32的庐山真面目了：

 

 

上面是日志文件和dump文件的保存路径。这次我们要看的是日志，dump文件下次再说。符号表我一般都勾上了，有的话就更好不是~重点是下面的应用程序错误(&R)这里，如果日志中有信息，就会在下面一条一条以纪录的形式显示出来。如果你的Drwatson中确实有日志的话，可以点清除把以前的都删掉。既然已经见过面了，那就把它关掉吧，需要时再打开，反正它自己也不会实施刷新。

 

好，现在一切就绪了！运行一下程序~ 只见嗖的一下，程序就停了。赶紧再把Dr.Watson请出来看看~

 

这次我们看到应用程序错误那里有了一条记录，把它选中变蓝后点上面的查看按钮。于是又出来一个对话框，显示“发生应用程序意外错误:”云云，内容很长，信息相当多。嗯，很好，很强大，这就是我们要的。考虑到这个框小了点，可以Ctrl+Shift+END全选后copy出来，用记事本看哈。在记事本中查找"错误 ->"，然后就会看到个这：

 

错误 ->00401087 f7f9            idiv    eax,ecx

 

没错，这就是错误的位置。仔细看看上下文，分析分析。由于是一个多线程的程序，所以这里把出错的线程单独剥离出来。如下所示，每个线程的信息分为几个部分：一开始是错误发生时寄存器的信息；然后是当前发生错误的指令的前后各10条指令(什么是10条，不是20条或者2条？因为Dr.Watson里面默认设置的就是10条呀~，你刚才又没改)；接下来是堆栈反向跟踪信息，也就是函数的逆向调用序列；最后是原始堆栈信息，可以获得参数，返回地址，局部变量之类的信息。

 

 

  1. *----> 线程 ID 0x2714 的状态转储 <----*
  3. eax=00007fff ebx=003724b8 ecx=00000000 edx=00000000 esi=0063ff2c edi=0063ff80
  4. eip=00401087 esp=0063ff2c ebp=0063ff80 iopl=0         nv up ei pl zr na pe nc
  5. cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00010246
  7. 函数: lesson_2!Worker
  8.         0040106b 7441                   je      lesson_2!Worker+0x8e (004010ae)
  9.         0040106d e86e020000       call    lesson_2!rand (004012e0)
  10.         00401072 8bc8                   mov     ecx,eax
  11.         00401074 81e103000080   and     ecx,80000003h
  12.         0040107a 7905                   jns     lesson_2!Worker+0x61 (00401081)
  13.         0040107c 49                       dec     ecx
  14.         0040107d 83c9fc                or      ecx,0FFFFFFFCh
  15.         00401080 41                      inc     ecx
  16.         00401081 b8ff7f0000        mov     eax,7FFFh
  17.         00401086 99                      cdq
  18. 错误 ->00401087 f7f9               idiv    eax,ecx
  19.         00401089 50                      push    eax
  20.         0040108a 8b55fc               mov     edx,dword ptr [ebp-4]
  21.         0040108d 52                      push    edx
  22.         0040108e 681cd04200       push    offset lesson_2!`string' (0042d01c)
  23.         00401093 e898010000       call    lesson_2!printf (00401230)
  24.         00401098 83c40c               add     esp,0Ch
  25.         0040109b 8bf4                   mov     esi,esp
  26.         0040109d 6a0a                   push    0Ah
  27.         0040109f ff15d8714300    call    dword ptr [lesson_2!_imp__Sleep (004371d8)]
  28.         004010a5 3bf4                   cmp     esi,esp
  30. *----> 堆栈反向跟踪 <---*
  31. ChildEBP   RetAddr   Args to Child              
  32. 0063ff80   004015e2   00000001  00000000  00000000  lesson_2!Worker+0x67
  33. 0063ffb8   7c824829   003724b8  00000000  00000000  lesson_2!_threadstartex+0xb2
  34. WARNING: Stack unwind information not available. Following frames may be wrong.
  35. 0063ffec    00000000  00401530  003724b8  00000000  kernel32!GetModuleHandleA+0xdf
  37. *----> 原始堆栈转储 <----*
  38. 000000000063ff2c   00 00 00 00 00 00 00 00 - b8 24 37 00  cc  cc  cc  cc  .........$7.....
  39. 000000000063ff3c   cc  cc cc  cc  cc  cc cc  cc - cc  cc  cc  cc  cc  cc  cc  cc  ................
  40. 000000000063ff4c   cc  cc cc  cc  cc  cc cc  cc - cc  cc  cc  cc  cc  cc  cc  cc  ................
  41. 000000000063ff5c   cc  cc cc  cc  cc  cc  cc cc - cc  cc  cc  cc  cc  cc  cc  cc  ................
  42. 000000000063ff6c   cc  cc cc  cc  cc  cc  cc cc - cc  cc  cc  cc  06 00 00  00  ................
  43. 000000000063ff7c   14 27 00 00 b8 ff  63 00 - e2 15 40  00  01 00 00  00  .'....c...@.....
  44. 000000000063ff8c   00 00 00 00 00 00 00 00 - b8 24 37 00  94 00  00 c0  .........$7.....
  45. 000000000063ff9c   00 00 00 00 8c ff   63 00 - 60 fb 63 00  dc  ff   63 00  ......c.`.c...c.
  46. 000000000063ffac    b4 65 40 00 b0 d1 42 00 - 00 00 00 00 ec  ff   63 00  .e@...B.......c.
  47. 000000000063ffbc   29 48  82 7c b8 24 37 00 - 00 00 00 00 00 00  00 00  )H.|.$7.........
  48. 000000000063ffcc    b8 24 37 00 94 00 00 c0 - c4  ff  63 00 60 fb  63  00  .$7.......c.`.c.
  49. 000000000063ffdc    ff   ff  ff  ff  60 1a  82 7c - 30 48 82 7c 00 00 00  00  ....`..|0H.|....
  50. 000000000063ffec    00 00 00 00 00 00 00 00 - 30 15 40 00 b8 24 37  00  ........0.@..$7.
  51. 000000000063fffc    00 00 00 00 00 00 00 00 - 00 00 00 00 00  00 00 00  ................
  52. 000000000064000c  00 00 00 00 00 00 00 00 - 00 00 00 00 00  00 00 00  ................
  53. 000000000064001c  00 00 00 00 00 00 00 00 - 00 00 00 00 00  00 00 00  ................
  54. 000000000064002c  00 00 00 00 00 00 00 00 - 00 00 00 00 00  00 00 00  ................
  55. 000000000064003c  00 00 00 00 00 00 00 00 - 00 00 00 00 00  00 00 00  ................
  56. 000000000064004c  00 00 00 00 00 00 00 00 - 00 00 00 00 00  00 00 00  ................
  57. 000000000064005c  00 00 00 00 00 00 00 00 - 00 00 00 00 00  00 00 00  ................

尽管这里可以简单的利用错误处指出的地址0x401087直接定位，那是因为这是很简单的情况。所以我决定还是简单讲一下在实际的复杂得多的环境中如何分析这些数据。

 

1.定位出错的模块。

我们看到错误的地址是0x401087，应该先确认这个地址是在哪个模块中。在错误日志中查找“模块清单”，能找到以下内容：

  1. *----> 模块清单 <----*
  2. 0000000000400000 - 000000000043a000: D:\DebugEasy\lesson_2\Debug\lesson_2.exe
  3. 0000000074ae0000 - 0000000074b45000: C:\windows\system32\USP10.dll
  4. 0000000076180000 - 000000007619d000: C:\windows\system32\IMM32.DLL
  5. 0000000076eb0000 - 0000000076ec3000: C:\windows\system32\Secur32.dll
  6. 0000000077bd0000 - 0000000077c18000: C:\windows\system32\GDI32.dll
  7. 0000000077c20000 - 0000000077cbf000: C:\windows\system32\RPCRT4.dll
  8. 0000000077e10000 - 0000000077ea0000: C:\windows\system32\USER32.dll
  9. 0000000077f30000 - 0000000077fdb000: C:\windows\system32\ADVAPI32.dll
  10. 000000007c800000 - 000000007c92b000: C:\windows\system32\kernel32.dll
  11. 000000007c930000 - 000000007ca00000: C:\windows\system32\ntdll.dll
  12. 000000007f000000 - 000000007f009000: C:\windows\system32\LPK.DLL

这里清楚的指出0000000000400000 -0000000000439000这个范围的地址是系统分配给lesson_2.exe的。我们得到的错误地址是0x401087，所以可以确定错误就是发生的lesson_2.exe模块。实际上很多应用都还有些自己的动态库之类的，定位到具体的模块后才能更具体的结合代码分析。有时候出错的地址是属于kernel32,ntdll.dll之类的系统函数，这种情况下需要分析堆栈信息来确定错误模块。

 

2.分析当前发生错误的直接原因

我们看到错误的指令是:idiveax,ecx。基本上访问eax和ecx都不会有问题，不然就是cpu有问题了。所以应该是除法指令出错。看看前面的寄存器的信息，eax=00007fff，也就是RAND_MAX，ecx=00000000，除0错误。对于我们这个例子，有了这个信息就足够定位到问题了。不过还是看看我们还能收集到些什么信息，毕竟实际环境可不会这么简单。

 

3.分析当前线程的调用堆栈。

ChildEBP   RetAddr    Args to Child             
0063ff80    004015e2    00000001  00000000 00000000 lesson_2!Worker+0x67
0063ffb8    7c824829    003724b8  00000000 00000000 lesson_2!_threadstartex+0xb2

 

在堆栈反向跟踪部分，这个信息很清晰。_threadstartex系统函数调用了我们的线程函数Worker。当前函数的返回地址是0x4015e2，接着是3个参数（注意：不一定都有效，显然不是所有的函数都有3个参数。实际上通过分析其dump文件能看到我们的例子中只有第一个参数有效，即1，是作为线程参数传入的lpParam）。这里我们结合map文件看看是不是跟这里记录的一样。在工程的debug目录里，有个扩展名为map的文件，用一般的文本编辑器就能打开。这文件太长了，节选一部分看看：

  1.  lesson_2
  3.  Timestamp is 48e0197a (Mon Sep 29 06:50:11 2008)
  5.  Preferred load address is 00400000
  7.  Start                      Length     Name                   Class
  8.  0001:00000000 0001bae7H .text                    CODE
  9.  0001:0001bae7 00010009H .textbss               CODE
  10.  0002:00000000 00002207H .rdata                  DATA
  11.  0002:00002207 00000000H .edata                  DATA
  12.  0003:00000000 00000104H .CRT$XCA        DATA
  13.  0003:00000104 00000104H .CRT$XCZ        DATA
  14.  0003:00000208 00000104H .CRT$XIA         DATA
  15.  0003:0000030c 00000109H .CRT$XIC          DATA
  16.  0003:00000418 00000104H .CRT$XIZ          DATA
  17.  0003:0000051c 00000104H .CRT$XPA         DATA
  18.  0003:00000620 00000104H .CRT$XPX         DATA
  19.  0003:00000724 00000104H .CRT$XPZ         DATA
  20.  0003:00000828 00000104H .CRT$XTA        DATA
  21.  0003:0000092c 00000104H .CRT$XTZ         DATA
  22.  0003:00000a30 0000407cH .data                     DATA
  23.  0003:00004ab0 00001b94H .bss                      DATA
  24.  0004:00000000 00000014H .idata$2                DATA
  25.  0004:00000014 00000014H .idata$3                DATA
  26.  0004:00000028 000001b0H .idata$4                DATA
  27.  0004:000001d8 000001b0H .idata$5                DATA
  28.  0004:00000388 0000076bH .idata$6                DATA
  30.   Address         Publics by Value              Rva+Base     Lib:Object
  32.  0001:00000020       ?Worker@@YGIPAX@Z          00401020 f   lesson_2.obj
  33.  0001:000000f0       _main                                            004010f0 f   lesson_2.obj
  34.  0001:00000212       _Sleep@4                                     00401212 f   kernel32:KERNEL32.dll
  35.  0001:00000218       _GetCurrentThreadId@0             00401218 f   kernel32:KERNEL32.dll
  36.  0001:0000021e       _CloseHandle@4                          0040121e f   kernel32:KERNEL32.dll
  37.  0001:00000224       _WaitForMultipleObjects@16    00401224 f   kernel32:KERNEL32.dll
  38.  0001:00000230       _printf                                          00401230 f   LIBCMTD:printf.obj
  39.  0001:000002d0       _srand                                           004012d0 f   LIBCMTD:rand.obj
  40.  0001:000002e0       _rand                                             004012e0 f   LIBCMTD:rand.obj
  41.  0001:00000320       __chkesp                                      00401320 f   LIBCMTD:chkesp.obj
  42.  0001:00000360       _system                                        00401360 f   LIBCMTD:system.obj
  43.  0001:00000470       __beginthreadex                            00401470 f   LIBCMTD:threadex.obj
  44.  0001:00000630       __endthreadex                               00401630 f   LIBCMTD:threadex.obj
  45.  0001:00000680       _mainCRTStartup                        00401680 f   LIBCMTD:crt0.obj
  46.  0001:000007d0       __amsg_exit                                  004017d0 f   LIBCMTD:crt0.obj
  48. 。。。。。。省略若干。。。。。
  50. Line numbers for .\Debug\lesson_2.obj(d:\debugeasy\lesson_2\lesson_2.cpp) segment .text
  52.     18 0001:00000020    19 0001:00000038    21 0001:00000044    22 0001:00000056
  53.     23 0001:0000005d    25 0001:0000006d    26 0001:0000009b    27 0001:000000ac
  54.     28 0001:000000ae    29 0001:000000b0    32 0001:000000f0    33 0001:00000108
  55.     34 0001:0000011a    36 0001:00000132    37 0001:00000152    39 0001:00000154
  56.     40 0001:00000161    42 0001:0000017a    44 0001:00000192    45 0001:000001a9
  57.     47 0001:000001ab    48 0001:000001b8    49 0001:000001c5    50 0001:000001c7

其中显示了程序名，程序的时间戳，程序中的代码分布，预定的加载地址，各个函数的起始地址，包括相对虚拟地址(RVA)以及文件行与RVA的对应关系等信息。我们看到预定的加载地址和我们在模块清单中看到的加载地址相同。很好，省得计算相对位置。一般来说Exe总是加载到0x400000，并且总是能得到这个位置的。而动态库的话，墨认是0x10000000，显然如果有2个动态库就没法都加载到同一个地址，需要计算RVA。

 

刚才从堆栈反向跟踪信息中我们看到当前Worker函数的返回地址为0x401e52，在map文件中找找。很快就能看到__beginthreadex函数是从0x401470开始，到0x401630结束。那就说明地址0x401e52就在__beginthreadex函数中。这就对了，因为我们就是用__beginthreadex函数启动的线程函数Worker，是吧~。顺手看一下刚才出错的地址0x401087，看看是在哪。再看看map文件，第一个函数就是?Worker@@YGIPAX@Z，地址是0x00401020至0x4010f0(main函数），所以0x401087就是在执行Worker函数中的指令。那么具体在哪一行呢？因为出错的函数Worker在文件lesson_2.cpp中，所以我们查找lesson_2.cpp,就找到了下面的信息：

  1. Line numbers for .\Debug\lesson_2.obj(d:\debugeasy\lesson_2\lesson_2.cpp) segment .text
  3.     15 0001:00000020    16 0001:00000038    18 0001:00000044    19 0001:00000056
  4.     20 0001:0000005d    22 0001:0000006d    23 0001:0000009b    24 0001:000000ac
  5.     25 0001:000000ae    26 0001:000000b0    29 0001:000000f0    30 0001:00000108
  6.     31 0001:0000011a    33 0001:00000132    34 0001:00000152    46 0001:00000154
  7.     37 0001:00000161    39 0001:0000017a    41 0001:00000192    42 0001:000001a9
  8.     44 0001:000001ab    45 0001:000001b8    46 0001:000001c5    47 0001:000001c7

    我们看到前面是个数字，18、19、21啥的，后面是0001:00000020之类。前面的就是cpp文件中的行号，后面是相对虚拟地址，我们的 0x401087在哪呢？又回到刚才说的默认加载地址了。map中看到默认加载地址是0x400000，而我们的exe在内存中也是加载到 0x400000,所以相对位置就是RVA = 0x401087(错误地址) - 0x400000(模块在内存中实际加载的地址) = 0x1067。不对啊，这里最大才到0x1c7，这是怎~么个情况？因为每个PE模块之前都有0x1000字节的dos stub和PE格式信息。所以0x1087还要减掉0x1000，就剩下0x87了。再看看，大于0x5d,小于0x6d，所以就是第22行。看看代码中 的22行，printf("tid[%u] tmp = %d\n", dwTid, RAND_MAX/(rand()%cnThreadnum));没错，就是在这里RAND_MAX/0了~。说明前面根据Dr.Watson的日志分析的结果都是正确的，没骗你噢~

 

       有时候堆栈反向跟踪的信息并不准确，多半是因为函数中的局部变量在memcpy,strcpy之类的函数复制的数据过长，导致堆栈访问越界。这种情况下，要仔细分析原始堆栈转储，以后再说。

 

       在实际工作中，利用Dr.Watson辅助生成错误日志，对于开发人员确实是很有帮助的。有需要的朋友，可以考虑这么试试。

 

       那今天就写到这吧~ 天亮啦，饭去~

实战：结合Dr.Watson系统日志和Vc6来定位多线程环境下程序异常退出的错误 C#多线程退出程序 - longkai178的日志 - 网易博客 实时多线程系统中程序日志的实现 - 程序设计 - IXPUB技术社区 Linux系统下的多线程编程入门 Linux系统下的多线程编程入门 QNX环境下多线程编程 QNX环境下多线程编程 了解精子和卵子结合环境 创造生男生女的环境 - 妹妹的日志 - 网易博客 实时多线程系统的日志实现 如何收集FAStT的系统信息错误和错误日志 多线程错误的思考 详解.NET多线程异常的处理方法 Linux多线程编程和Linux 2.6下的NPTL 多线程错误 VC6.0下看不到的字符 Linux下的多线程编程 结合romimage来分析WINCE下的PE文件特点 C程序的运行环境 - rocky的日志 - 网易博客 一个下雪的小程序 c++ vc6.0 vc6能用的SDK和库列表 系统本身的注册表来限制特定程序运行 教你自制XP系统下的垃圾清理程序！ 教你自制XP系统下的垃圾清理程序！ 自制XP系统下的垃圾清理程序！