一次有教益的程序崩溃调试 （上）

在系统上线前夕，我们将所有的子系统部署在预发布环境中做集成测试。集成测试模拟真实的业务场景，不停断地使用真实数据测试组成系统的各个服务（service）。

 预发布环境的Windows系统都启动了自动内存转储（auto memory dump）功能：当程序崩溃（crash）时，Windows会调用Windbg生成该程序的内存转储，以方便事后调试（postmortem debugging）。其技术原理是修改注册表，更改Windows对程序崩溃的默认行为。具体细节请参考“Auto Memory Dump on Crash of an Application”和我制作的注册表文件aedebug.reg。

在某个周五，我发现一个Windows服务程序崩溃，生成了内存转储文件。于是，我用Windbg打开该转储文件，做事后调试。由于这是一个用C#编写的托管程序，我加载了调试扩展项sos和sosex。

初步的调查看似没有提供任何信息。

1. !threads显示这个程序有17个托管线程，但是没有一个线程拥有导致崩溃的异常。
2. 利用!dumpheap搜索托管堆，没有发现导致崩溃的异常。
3. !eestack没有提供有价值的信息。
4. !analyze –v 没有提供有价值的信息。

我感到有些束手无策，不过一个有经验的开发人员帮助了我。他用~*k列出所有线程栈，仔细查看。后来我才意识这其中的道理：托管程序的崩溃可能发生在托管栈帧（managed stack frame）中，也可能发生在非托管栈帧（unmanaged stack frame）中。如果托管代码看上去没问题，那么崩溃很可能发生在非托管代码中。

一段时间后，他发现了导致崩溃的栈。利用!clrstack查看托管栈，一切正常。

0:013> !clrstack
OS Thread Id: 0x2630 (13)
Child-SP         RetAddr          Call Site
000000001d3cd2e0 000007fef48dd8ec System.Data.SqlClient.SqlCachedStream.get_TotalLength()
000000001d3cd330 000007fef723a453 System.Data.SqlTypes.SqlXmlStreamWrapper.get_Length()
000000001d3cd370 000007fef74a12d8 System.Xml.XmlReader.CalcBufferSize(System.IO.Stream)
000000001d3cd3b0 000007fef980d502 System.Xml.XmlReader.CreateSqlReader(System.IO.Stream,
        System.Xml.XmlReaderSettings, System.Xml.XmlParserContext)
000000001d3cdcf0 000007fef892ae46 System.Reflection.RuntimeMethodInfo.Invoke(System.Object,
        System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo, Boolean)
000000001d3cde90 000007fef4704211 System.Reflection.RuntimeMethodInfo.Invoke(System.Object,
        System.Reflection.BindingFlags, System.Reflection.Binder, System.Object[], System.Globalization.CultureInfo)
000000001d3cdee0 000007fef4703fc2 System.Data.SqlTypes.SqlXml.CreateReader()
000000001d3cdf60 000007fef4a010db System.Data.SqlTypes.SqlXml.get_Value()
000000001d3cdfb0 000007fef43fe396 System.Data.SqlClient.SqlBuffer.get_Value()
000000001d3ce080 000007fef43fe5a2 System.Data.SqlClient.SqlDataReader.GetValueInternal(Int32)
000000001d3ce0d0 000007fef4419d37 System.Data.SqlClient.SqlDataReader.GetValues(System.Object[])
000000001d3ce150 000007fef4419c47 System.Data.ProviderBase.DataReaderContainer
        +CommonLanguageSubsetDataReader.GetValues(System.Object[])
000000001d3ce180 000007fef4411883 System.Data.ProviderBase.SchemaMapping.LoadDataRow()
000000001d3ce1d0 000007fef4411727 System.Data.Common.DataAdapter.FillLoadDataRow(System.Data.ProviderBase.SchemaMapping)
000000001d3ce260 000007fef4411584 System.Data.Common.DataAdapter.FillFromReader
        (System.Data.DataSet, System.Data.DataTable, System.String,
        System.Data.ProviderBase.DataReaderContainer, Int32, Int32, System.Data.DataColumn, System.Object)
000000001d3ce330 000007fef441266d System.Data.Common.DataAdapter.Fill(System.Data.DataSet,
        System.String, System.Data.IDataReader, Int32, Int32)
000000001d3ce3f0 000007fef44124fd System.Data.Common.DbDataAdapter.FillInternal
        (System.Data.DataSet, System.Data.DataTable[], Int32, Int32, System.String, 
        System.Data.IDbCommand, System.Data.CommandBehavior)
000000001d3ce4b0 000007fef4412266 System.Data.Common.DbDataAdapter.Fill(System.Data.DataSet, Int32,
        Int32, System.String, System.Data.IDbCommand, System.Data.CommandBehavior)
000000001d3ce560 000007ff001ab365 System.Data.Common.DbDataAdapter.Fill(System.Data.DataSet)
000000001d3ce5f0 000007ff001aaca3 MyApp.DAL.DatabaseHelper.ExecuteDataSet(System.String, System.Data.CommandType)
000000001d3ce660 000007ff001a99ad MyApp.DAL.ReportDAO.GetPendingAndRunningReportJobs()
000000001d3ce6c0 000007fef88cdd38 MyApp.Report.CheckJobStatus(System.Object)
000000001d3ce930 000007fef980d502 System.Threading.ExecutionContext.runTryCode(System.Object)
000000001d3cf1e0 000007fef890eb56 System.Threading.ExecutionContext.Run
        (System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)
000000001d3cf230 000007fef980d502 System.Threading._TimerCallback.PerformTimerCallback(System.Object)

但是，用k显示非托管栈帧则发现了问题。

0:013> k
Child-SP          RetAddr           Call Site
00000000`1d3cb648 000007fe`fcf113a6 ntdll!NtWaitForMultipleObjects+0xa
00000000`1d3cb650 00000000`76b3f190 KERNELBASE!WaitForMultipleObjectsEx+0xe8
00000000`1d3cb750 000007fe`f9b303c9 kernel32!WaitForMultipleObjects+0xb0
00000000`1d3cb7e0 000007fe`f9a2c553 mscorwks!Debugger::EnsureDebuggerAttached+0xe9
00000000`1d3cb870 000007fe`f97e0563 mscorwks!`string'+0x842b3
00000000`1d3cb8e0 000007fe`f9c0d9de mscorwks!EEPolicy::LogFatalError+0x1af
00000000`1d3cc060 000007fe`f964fa55 mscorwks!EEPolicy::HandleFatalError+0x6e
00000000`1d3cc0b0 000007fe`f9752cac mscorwks!CLRVectoredExceptionHandlerPhase3+0xcd
00000000`1d3cc0f0 000007fe`f9752c33 mscorwks!CLRVectoredExceptionHandlerPhase2+0x30
00000000`1d3cc160 000007fe`f964f686 mscorwks!CLRVectoredExceptionHandler+0xff
00000000`1d3cc1e0 00000000`76d68a8f mscorwks!CLRVectoredExceptionHandlerShim+0x42
00000000`1d3cc220 00000000`76d659b2 ntdll!RtlpCallVectoredHandlers+0xa8
00000000`1d3cc290 00000000`76d9fe48 ntdll!RtlDispatchException+0x22
00000000`1d3cc970 000007fe`f97a904e ntdll!KiUserExceptionDispatcher+0x2e
00000000`1d3ccf30 000007fe`f96e3401 mscorwks!ArrayClass::GetApproxArrayElementTypeHandle+0x1a
00000000`1d3ccf70 000007fe`f967a908 mscorwks!ArrayBase::GetArrayElementTypeHandle+0x61
00000000`1d3ccfa0 000007fe`f99e3e95 mscorwks!ArrayBase::GetTypeHandle+0x18
00000000`1d3ccff0 000007fe`f967e79d mscorwks!`string'+0x3bbf5
00000000`1d3cd020 000007fe`f9be7936 mscorwks!ObjIsInstanceOf+0x41
00000000`1d3cd0b0 000007fe`f9a2ab9c mscorwks!JITutil_ChkCastAny+0xe6
00000000`1d3cd290 000007fe`f48b2a5e mscorwks!`string'+0x828fc
00000000`1d3cd2e0 000007fe`f48dd8ec System_Data_ni!System.Data.SqlClient.SqlCachedStream.get_TotalLength()+0x4e
00000000`1d3cd330 000007fe`f723a453 System_Data_ni!System.Data.SqlTypes.SqlXmlStreamWrapper.get_Length()+0x3c
...

托管栈的栈顶函数是ADO.NET的SqlCachedStream.get_TotalLength。非托管栈显示它调用即时编译（JIT）相关的函数JITutil_ChkCastAny，似乎在坚持对象的类型转换（cast）。不幸的是，该检查触发了内核异常分派函数KiUserExceptionDispatcher，该函数回调CLR的异常处理函数CLRVectoredExceptionHandler。CLR认为此异常是致命错误（Fatal），程序无法继续运行，于是崩溃。

值得一提的是，sosex提供的调试命令!mk可以同时查看托管栈帧与非托管栈帧，对于调试很有帮助。在如下输出中，M标记了托管栈帧，U标记了非托管栈帧。

0:013> !mk
Thread 13:
     ESP              EIP
00:U 000000001d3cb648 0000000076da046a ntdll!NtWaitForMultipleObjects+0xa
01:U 000000001d3cb650 000007fefcf113a6 KERNELBASE!WaitForMultipleObjectsEx+0xe8
02:U 000000001d3cb750 0000000076b3f190 kernel32!WaitForMultipleObjects+0xb0
03:U 000000001d3cb7e0 000007fef9b303c9 mscorwks!Debugger::EnsureDebuggerAttached+0xe9
04:U 000000001d3cb870 000007fef9a2c553 mscorwks!`string'+0x842b3
05:U 000000001d3cb8e0 000007fef97e0563 mscorwks!EEPolicy::LogFatalError+0x1af
06:U 000000001d3cc060 000007fef9c0d9de mscorwks!EEPolicy::HandleFatalError+0x6e
07:U 000000001d3cc0b0 000007fef964fa55 mscorwks!CLRVectoredExceptionHandlerPhase3+0xcd
08:U 000000001d3cc0f0 000007fef9752cac mscorwks!CLRVectoredExceptionHandlerPhase2+0x30
09:U 000000001d3cc160 000007fef9752c33 mscorwks!CLRVectoredExceptionHandler+0xff
0a:U 000000001d3cc1e0 000007fef964f686 mscorwks!CLRVectoredExceptionHandlerShim+0x42
0b:U 000000001d3cc220 0000000076d68a8f ntdll!RtlpCallVectoredHandlers+0xa8
0c:U 000000001d3cc290 0000000076d659b2 ntdll!RtlDispatchException+0x22
0d:U 000000001d3cc970 0000000076d9fe48 ntdll!KiUserExceptionDispatcher+0x2e
0e:U 000000001d3ccf30 000007fef97a904e mscorwks!ArrayClass::GetApproxArrayElementTypeHandle+0x1a
0f:U 000000001d3ccf70 000007fef96e3401 mscorwks!ArrayBase::GetArrayElementTypeHandle+0x61
10:U 000000001d3ccfa0 000007fef967a908 mscorwks!ArrayBase::GetTypeHandle+0x18
11:U 000000001d3ccff0 000007fef99e3e95 mscorwks!`string'+0x3bbf5
12:U 000000001d3cd020 000007fef967e79d mscorwks!ObjIsInstanceOf+0x41
13:U 000000001d3cd0b0 000007fef9be7936 mscorwks!JITutil_ChkCastAny+0xe6
14:U 000000001d3cd290 000007fef9a2ab9c mscorwks!`string'+0x828fc
15:M 000000001d3cd2e0 000007fef48b2a5e System.Data.SqlClient.SqlCachedStream.get_TotalLength()(+0x2d IL)(+0x4e Native)
16:M 000000001d3cd330 000007fef48dd8ec System.Data.SqlTypes.SqlXmlStreamWrapper.get_Length()(+0x0 IL)(+0x3c Native)
...

基于以上分析，似乎是函数SqlCachedStream.get_TotalLength出了问题。这是ADO.NET的函数，难以获得源代码。但是，可以利用Reflector.exe，用“反编译”的方式查看代码。

由源代码可知，该函数对this._catchedBytes的每一个元素做类型转换。于是进一步调查this._catchedBytes的内容。先用!dso在栈上找到SqlCachedStream对象，然后用!do查看其成员。

0:013> !dso
OS Thread Id: 0x2630 (13)
RSP/REG          Object           Name
000000001d3cba20 00000000399675d8 System.Threading.ExecutionContext
000000001d3cbd50 0000000039abd0b0 System.Data.SqlTypes.SqlXmlStreamWrapper
000000001d3cbd60 0000000039abd0f8 System.Xml.XmlReaderSettings
...
000000001d3cd1d8 0000000039abd0b0 System.Data.SqlTypes.SqlXmlStreamWrapper
000000001d3cd1f8 0000000001c29d58 System.String
000000001d3cd260 0000000039abd0b0 System.Data.SqlTypes.SqlXmlStreamWrapper
000000001d3cd270 0000000002aae5f8 <unknown type>
000000001d3cd2e0 0000000039ab9960 System.Data.SqlClient.SqlCachedStream
...

0:013> !do 0000000039ab9960
Name: System.Data.SqlClient.SqlCachedStream
MethodTable: 000007fef4977ce0
EEClass: 000007fef4301f70
Size: 80(0x50) bytes
(C:\Windows\assembly\GAC_64\System.Data\2.0.0.0__b77a5c561934e089\System.Data.dll)
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
000007fef89ee580  400018a        8        System.Object  0 instance 0000000000000000 __identity
000007fef91ec3a8  4001bbe       10 ...ream+ReadDelegate  0 instance 0000000000000000 _readDelegate
000007fef91ec4b0  4001bbf       18 ...eam+WriteDelegate  0 instance 0000000000000000 _writeDelegate
000007fef8a32d68  4001bc0       20 ...ng.AutoResetEvent  0 instance 0000000000000000
    _asyncActiveEvent
000007fef89f5f00  4001bc1       28         System.Int32  1 instance                1
    _asyncActiveCount
000007fef89f1c40  4001bbd      ae8     System.IO.Stream  0   shared           static Null
000007fef89f5f00  400196a       2c         System.Int32  1 instance                0
    _currentPosition
000007fef89f5f00  400196b       40         System.Int32  1 instance                0
    _currentArrayIndex
000007fef89f5b78  400196c       30 ...ections.ArrayList  0 instance 0000000002cd40a0 _cachedBytes
000007fef89f21b0  400196d       38         System.Int64  1 instance 0 _totalLength

0:013> !do 0000000002cd40a0
Name: System.Collections.ArrayList
MethodTable: 000007fef89f5b78
EEClass: 000007fef85fe9e8
Size: 40(0x28) bytes
(C:\Windows\assembly\GAC_64\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)
Fields:
              MT    Field   Offset                 Type VT     Attr            Value Name
000007fef89e4748  400094c        8      System.Object[]  0 instance  00000000111c9830 _items
000007fef89f5f00  400094d       18         System.Int32  1 instance            19523 _size
000007fef89f5f00  400094e       1c         System.Int32  1 instance            19523 _version
000007fef89ee580  400094f       10        System.Object  0 instance 0000000000000000 _syncRoot
000007fef89e4748  4000950      388      System.Object[]  0   shared           static emptyArray

由Windbg的输出可知，this._catchedBytes是一个ArraryList，其元素都保持在数组变量_items中。于是查看该数组。

0:013> !do 00000000111c9830
Name: System.Object[]
MethodTable: 000007fef89e4748
EEClass: 000007fef85fb660
Size: 262176(0x40020) bytes
Array: Rank 1, Number of elements 32768, Type CLASS
Element Type: System.Object
Fields:
None

该数组可容纳32768个元素，当前已容纳26217个元素。那么是哪个元素的类型转换触发了异常呢？用!dumparray查看数组内容。

0:013> !DumpArray -details 00000000111c9830

输出的内容很长，可用.logopen将其保持在文本日志中。我删除了日志开始处的一些文本，获得一个5M大小的文本文件，其内容如下。

然后，我编写了一个Python脚本对该文本文件进行分析，以发现有问题的元素。

lines = open('windbg.log').readlines()
start = 1
step = 9
for i in range(26217):
    lineno = start + step * i
    if 'Name: System.Byte[]' not in lines[lineno]:
        print 'error (index:%i, line:%i): %s' % (i, lineno, lines[lineno])
        break

该Python脚本发现第7736号元素有问题。

[7735] 0000000002aadde0
    Name: System.Byte[]
    MethodTable: 000007fef89f6cd0
    EEClass: 000007fef85ff188
    Size: 2072(0x818) bytes
    Array: Rank 1, Number of elements 2048, Type Byte
    Element Type: System.Byte
    Fields:
    None
[7736] 0000000002aae5f8
    Free Object
    Size 8088(0x1f98) bytes
[7737] 0000000002aaed48
    Name: System.Byte[]
    MethodTable: 000007fef89f6cd0
    EEClass: 000007fef85ff188
    Size: 2072(0x818) bytes
    Array: Rank 1, Number of elements 2048, Type Byte
    Element Type: System.Byte
    Fields:
    None

用dc查看第7735号和第7737号对象所在内存，可知它们都是字符串片段。也就是说_catchedBytes是一个字符串缓存。但是缓冲区的第7736号对象已经被垃圾回收，成为自由对象（Free Object）。当程序依次处理缓冲区的对象时，该自由对象导致了程序崩溃。

0:013> dc 0000000002aadde0
00000000`02aadde0  f89f6cd0 000007fe 00000800 00000000  .l..............
00000000`02aaddf0  0066002c 00630061 00730074 00730020  ,.f.a.c.t.s. .s.
00000000`02aade00  00610070 00650063 0066002c 00630061  p.a.c.e.,.f.a.c.
00000000`02aade10  00730074 00730020 00610074 00690074  t.s. .s.t.a.t.i.
00000000`02aade20  00740073 00630069 002c0073 00610066  s.t.i.c.s.,.f.a.
00000000`02aade30  00740063 00200073 00740073 00610072  c.t.s. .s.t.r.a.
00000000`02aade40  0067006e 002c0065 00610066 00740063  n.g.e.,.f.a.c.t.
00000000`02aade50  00200073 00790073 00740073 006d0065  s. .s.y.s.t.e.m.

0:013> dc 0000000002aaed48
00000000`02aaed48  f89f6cd0 000007fe 00000800 00000000  .l..............
00000000`02aaed58  00610066 00720069 00700020 006f0068  f.a.i.r. .p.h.o.
00000000`02aaed68  006f0074 002c0073 00610066 00720069  t.o.s.,.f.a.i.r.
00000000`02aaed78  00700020 006f0072 0065006a 00740063   .p.r.o.j.e.c.t.
00000000`02aaed88  0066002c 00690061 00200072 00720070  ,.f.a.i.r. .p.r.
00000000`02aaed98  006a006f 00630065 00200074 00640069  o.j.e.c.t. .i.d.
00000000`02aaeda8  00610065 002c0073 00610066 00720069  e.a.s.,.f.a.i.r.
00000000`02aaedb8  00700020 006f0072 0065006a 00740063   .p.r.o.j.e.c.t.

为什么在一个缓存区中会存在被释放的对象？我们推测，这很可能是垃圾回收漏洞（GC hole），是垃圾回收器错误地释放了被使用的内存。于是我们向CLR支持团队（CLR Support Team）发邮件，描述了我们遇到的问题。对方的答复是：我们知道在垃圾回收过程中存在缺陷，但是我们尚未修复。没有修复的原因之一是该问题极难复现（repro）。

经过漫长的分析，终于找到错误的根源。暂且打住，总结一下收获。

1. 托管程序的错误可能发生在托管栈帧中（利用!clrstack查看），也可能发生在非托管栈帧中（利用k查看）。
2. 调试时，如果托管栈（帧）和托管内存看上去没有问题，那么问题很可能在非托管栈（帧）和非托管内存中。
3. sosex的!mk可以同时查看托管栈帧和非托管栈帧，对调试很有帮助。
4. Reflector.exe可以查看.NET Framework Library的代码，有助于检查.NET程序的底层代码。
5. 有时需要对Windbg的输出进行自动解析，以快速发现调试线索。
6. CLR和.NET Framework Library都可能存在缺陷。