感谢博主 http://book.51cto.com/art/200711/59613.htm
《Windows用户态程序高效排错》第一章从从四个风格迥异的案例谈思考，比工具、技巧和经验都重要。本文是这章内容的梗概。
第1章 比工具、技巧和经验都重要的是你的思考
——从四个风格迥异的案例说起
首先跟大家分享导师Parker给我的一个问题：
镜子里面的像，为什么左右是反的而上下不是？
我问过很多朋友这个问题，很少有人能够在３分钟内给出准确答案。这里列举出一些比较奇特的想法：
1. 因为人的眼睛是左右对称的。（也是某“面试宝典”中的答案）。
2. 如果把镜子横过来，左右不反了，上下却反了。
3. 因为我们在北半球。
从技术层面上说，这里涉及的知识点只有镜面反射，远比Windows内存管理简单。但是要回答清楚，却不是信手拈来那么简单。这个例子只是想说明，除了知识以外，解决问题需要清晰的思路。
1.1.1 问题描述
1.1 绝望的性能问题：ADO.NET 2.0竟然比1.0要慢
1.1.1 问题描述
根据下面一篇文章的介绍，客户决定升级到.NET Framework 2.0来借助ADO.NET 2.0提高性能。
DataSet and DataTable in ADO.NET 2.0 http://msdn.microsoft.com/msdnmag/issues/05/11/DataPoints/default.aspx |
但是根据用户的测试，使用ADO.NET 2.0后，性能反而下降。
拿到用户的代码一看，非常简单：
OracleConnection conn = new OracleConnection();
conn.ConnectionString = "...";
conn.Open();
OracleCommand cmd = new OracleCommand();
cmd.Connection = conn;
OracleDataAdapter dap = new OracleDataAdapter("select * from mytesttable",conn);
DataTable dt = new DataTable();
DateTime start = System.DateTime.Now;
dap.Fill(dt);
TimeSpan span = DateTime.Now - start;
conn.Close();
Console.WriteLine(span.ToString());
Console.WriteLine("The Columns.Count is" + dt.Columns.Count.ToString());
Console.WriteLine("The Rows.Count is"+dt.Rows.Count.ToString()); |
测试用的数据库表也很简单，25万行数据，4个字段。通过检查span.ToString的结果，发现同样的代码，ADO.NET 2.0比1.1多用了近一倍的时间。dap.Fill方法的执行时间从原来的3秒增加到6秒。
1.1.2 悲观和绝望
应该如何着手解决这个问题？
我测试完成，看到这个结果后，我的感觉：悲观。看看我们能够做什么：
1. 后台数据库表格的定义非常简单。4个字段都是int，都是在没有index、primary key、foreign key等约束条件下测试的。也就是说，这个问题跟数据表的Schema定义无关，完全是客户端的问题。
2. 代码已经非常简单。Console工程里Main函数就做这么一件事情。客户端没有任何可以修改和变动的地方。
3. .NET Framework 1.1和.NET Framework 2.0共存在同一个客户端，测试也是在同一个客户端进行的。所以软硬件环境，比如Oracle Client都相同。唯一的区别就是.NET Framework的版本。这也就是客户最关心的地方。
很绝望，找不到任何努力的方向。看来接下来就应该向客户坦白：“我没办法，都怪ADO.NET 2.0的开发人员把Fill方法的性能弄得这么差！”然后推托说MSDN的文章是在.NET Framework 2.0 beta2的时候写的，并不准确。
1.1.3 换位思考
还好没有立刻放弃尝试其他的努力。仔细阅读并且测试了MSDN上关于ADO.NET 2.0性能的文章后，我发现：
1. 事实证明，MSDN上给出的例子的确证明了ADO.NET 2.0的性能更好。不过MSDN例子中的表格Schema比较复杂，而客户使用的Schema非常简单。
2. 虽然在客户的情况中，ADO.NET 2.0的性能下降，但是也可以找出一些客户没有测试的情况，在那样的情况下，ADO.NET 2.0可以把性能提高两个数量级。
同时，当跟同事讨论这个问题的时候，他们最感兴趣的不是性能下降了多少百分比，而是关心客户为什么要一次操作25万行数据。仔细讨论后，提出了下面一些疑点:
1. 客户的测试表明25万行数据总共慢了3秒钟，平均下来每一行慢8微秒。从开发的角度来思考，读取数据库的操作首先把请求从应用程序发送到数据库引擎，然后通过网络到数据库服务器取回数据，最后把数据填充到DataTable中。这么一连串复杂的操作中，任何一点小的改动都可能通过蝴蝶效应扩大。换句话说，如果看百分比，性能的确下降了。但是如果看绝对值3秒钟，跟数据量一比较，对性能下降的看法就会有更多的思路。
2. 用户的代码是把25万行的表格一次读到程序中来。这样的代码会运行在性能敏感的情况下吗？比如Web服务器。计算一下，250000行*4字段*每个字段开销20字节=19MB数据。如果每一个请求都要带来3秒（ADO.NET 1.1的性能数据）的延迟，20MB的内存开销，数据库服务器和Web服务器大量的CPU操作，以及频繁的网络传输，这样的设计肯定是有问题的。所以，正常情况下，这样的代码应该是初始化某一个全局的数据，程序启动后可能一共就运行这样的代码一次。也就是说，虽然这里性能损耗的百分比很明显，但是给最终用户带来的影响，有那么明显吗？
3. 我们并没有考查数据的所有操作。这里客户考察的性能是获取数据的开销，并没有考虑后面使用数据的性能。如果ADO.NET 2.0牺牲获取时间来改进使用数据的性能，使得从DataSet中每使用一行收获1微妙的收益，如果每行数据都被使用了8次以上，从整体来看，性能是有回报的。
有了上面的分析后，我决定首先问问客户真实环境是怎么样的，到底是在怎么样的情况下使用这段代码。同时，用下面的方法来寻求性能下降的根源。
1.1.4 排错
首先，用Reflector反编译分析DataAdapter.Fill方法的实现。
Reflector for .NET http://www.aisto.com/roeder/dotnet/ |
发现DataAdapter.Fill方法可以分解成下面两个部分：
1. 用DataReader读取数据。
2. 构造DataTable，填入数据。
也就是说，DataAdapter.Fill的实现，其实是把ADO.NET中的DataReader.Read和DataTable. Insert合并在一起。于是，可以用这两个函数来代替DataAdapter.Fill方法测试性能：
static void TestReader()
{
OracleConnection conn = new OracleConnection();
conn.ConnectionString = "…";
conn.Open();
OracleCommand cmd = new OracleCommand();
cmd.Connection = conn;
cmd.CommandText = " select * from mytesttable ";
OracleDataReader reader = cmd.ExecuteReader();
object[] objs=new object[4];
DateTime start = System.DateTime.Now;
while (reader.Read())
{
reader.GetValues(objs); |
根据测试，性能的损失主要是由于DataReader.Read方法带来的。如果要再进一步分析Read方法的性能损失，使用Reflector就太困难了。这里采用的工具是企业版本VS2005里面自带的Profiler。通过Tools→Performance Tools→Performance Wizard菜单激活。（关于VS 2005中Profiler的详细案例分析，在最后一章介绍性能调优的时候有详细说明。）
这个工具可以显示出每一个方法（包括子方法）调用所花费的时间，以及占整体运行时间的比例。为了让问题更加明显，这里把数据库的行数增加了10万来方便观察。沿着花费时间比例最多的函数一路走下去，发现DataReader.Read的方法实现分成两部分：自身的托管代码调用和非托管代码调用，分别占用了35%左右的时间和65%左右的时间。有了这个信息后，再通过Reflector分析ADO.NET1.1中的对应函数的实现（VS2005自带的Profiler无法分析.NET Framework 1.1的程序，不然直接分析两者时间比例就可以方便地看出问题），发现非托管代码部分的调用几乎没什么差别，都是调入数据库的客户端非托管DLL。主要差别在托管代码部分。其中引起注意的是ADO.NET 2.0增加了SafeHandle.Dangerous- AddRef/DangerousRelease调用。每一对这样的调用就要花费7%的时间。而每读取一行数据，需要用大约3对这样的调用。经过比较分析，认为问题就是在这里。
由于对数据库的操作和数据填充最终通过调用非托管的数据库引擎来完成，所以需要向非托管的DLL传入托管代码管理的缓存空间，而SafeHandle就是管理这种资源的。在.NET Framework 1.1中，由于缺少SafeHandle类，高负载环境下程序存在表现不稳定的危险，没有完美的解决方法。.NET Framework 2.0增加了SafeHandle来保证程序的可靠性。然而，代价就是25万行数据发生3秒钟的时间损失。（后来经开发人员确认，这3秒钟的损失，在下一版本的Framework也可以想办法优化掉！）
1.1.5 结论和收获
在跟客户作进一步的交流后，这个问题的结论如下：
1. MSDN文章的介绍是正确的。如果用文章里面的例子，的确可以看到性能有数量级上的提升。
2. 在客户的真实环境中，损失的3秒时间其实不会对最终用户和整个程序造成影响。
3. 3秒钟不是白白损失的，换来的是程序的可靠性。
到最后，我们还是没有能够找回这3秒钟，但是找到了3秒钟背后更多的东西。收获是：
1. 至关重要的是思考，不要迷失在问题中，而是要全方位考虑客户和开发人员真正关心的是什么。
2. 把问题放到真实环境中去考虑，通过不同的角度分析理解这个问题，看看问题背后是否有更多可以发掘的地方。这一点帮助我们发现了100%的性能损失在客户的实际环境下是微不足道的。
3. 采取合适的工具。这里使用了reflector和profiler。
4. 必要的时候把问题扩大，方便分析。这里通过增加数据量来让结果更明显。这个思路在解决内存泄漏的时候也是非常重要的。因为泄漏1G内存的程序检查起来肯定比只泄漏1K内存的程序容易。
5. 任何问题都必有因果。某一方面的损失并不代表整体就有问题。合理取舍（Tradeoff）是必要的。
1.1.6 题外话和相关讨论
Safehandle的更多讨论
关于Safehandle更多的一些讨论：
SafeHandle: A Reliability Case Study [Brian Grunkemeyer]
http://blogs.msdn.com/bclteam/archive/2005/03/16/396900.aspx
CLR SafeHandle Consideration [grapef]
http://eparg.spaces.msn.com/blog/cns!59BFC22C0E7E1A76!576.entry
平衡、取舍、双赢和RFC 1925
关于平衡、取舍、双赢的一个有趣问题和权威的文档是RFC1925：
RFC 1925 (RFC1925)
http://www.faqs.org/rfcs/rfc1925.html
关于Tradeoff的另一个案例是要不要使用/3GB。关于/3GB的信息可以参考：
Large memory support is available in Windows Server 2003 and in Windows 2000
http://support.microsoft.com/kb/283037/en-us
问题是这样的，用户有一个大型的ASP.NET站点，压力大的时候常常在跟数据库通信时发生Invalid Operation的异常。经过网络工程师和数据库工程师的排查，该问题是由于使用了/3GB导致的。/3GB增加了用户态内存地址空间，代价是内核可用内存减少。由于网络IO操作在内核完成，内核内存减少导致了这个问题。
但是，我们却不能够建议用户去掉/3GB开关，因为这个开关是半年前为了解决ASP.NET用户态内存空间不够的时候加上去的。（由于客户程序页面很多，默认的2GB用户态空间无法满足需求，继而导致OutOfMemory的异常）。所以，如果要从根源上同时解决ASP.NET内存空间和数据库访问的问题，使用64位系统是最好的方案。不过最后还是在系统工程师的帮助下，通过下面这篇文章找到了2GB和3GB之间的一个平衡点，平衡了内核和用户态空间的分配：
How to use the /userva switch with the /3GB switch to tune the User-mode space to a value between 2 GB and 3 GB
http://support.microsoft.com/kb/316739/en-us
Profiler的下载地址和相关资源
CLR Profiler for the .NET Framework 2.0
http://www.microsoft.com/downloads/details.aspx?FamilyID=a362781c-3870-43be-8926-862b40aa0cd0&DisplayLang=en
No Code Can Hide from the Profiling API in the .NET Framework 2.0
http://msdn.microsoft.com/msdnmag/issues/05/01/CLRProfiler/default.aspx
CLR Debugging vs. CLR Profiling
http://blogs.msdn.com/jmstall/archive/2004/10/22/246151.aspx
1.2 不可思议：一个API同时打开了两个文件
1.2.1 问题描述
有一天，一个电话打进来，客户非常气愤地抱怨，调用ShellExecute这个API，传入本地的一个文本文件的路径，有时候会在打开这个TXT的同时，还打开另一个不相干的文件！客户非常明确地告诉我，所有的参数肯定没有传错，而且ShellExecute的返回值也正确。
1.2.2 第一印象
我仔细思考了两分钟后，告诉客户，不可能发生上述问题。如果参数正确，API的行为肯定是唯一的。（在往下面阅读以前，请您花两分钟思考，这有可能吗？）
我的第一感觉是用户的参数传递错了。比如打开的是一个BAT文件，或者打开方式被用户修改过。这样才有可能同时打开两个文件。但如果真的是这样，程序的行为也应该是唯一的，而不会有时候才出现。
事实是我错了。在查看了用户的截图，并且用客户的代码在本地重现了一次问题后，我不得不相信一次ShellExecute调用会偶尔打开两个文件。
在下面的分析中，你会看到该问题是如何发生的。但是，请先记住第一点，相信事实，不要相信经验。如果我胸有成竹地告诉客户，这种问题肯定跟代码不相关，唯一的可能性是出自一些防病毒之类的程序（防病毒程序的确是很多问题的根源，但是有时也是挡箭牌），那么就失去了找到真相的机会。
1.2.3 深入分析
背景是这样。客户用MFC开发了一个Dialog Application, 上面放了一个HTMLView Control，这个Control会显示本地的一个HTML文件。这个HTML文件会显示一个GIF图片。当用户在这个GIF图片上点鼠标右键，默认的IE右键菜单被用户自定义的菜单代替。当用户点击其中一个菜单命令后，在客户的消息响应函数中调用ShellExecute打开本地的一个TXT文件。TXT文件类型跟UltraEdit绑定，所以文件会被UltraEdit打开。当问题发生的时候，UltraEdit会在打开TXT的同时，打开另外一个二进制的文件。经过分析，这个二进制的文件就是那个 HTML中显示的GIF文件。
客户在PreTranslateMessage函数中用下面的代码弹出自定义菜单代替IE默认菜单：
if(pMsg->message==WM_RBUTTONDOWN)
{CMenu menu;
menu.LoadMenu(IDR_MENU_MSG_OPEN);
CMenu *pMenu = menu.GetSubMenu(0);
if (pMenu)
{
CPoint pt;
GetCursorPos(&pt);
pMenu->TrackPopupMenu(TPM_LEFTALIGN, pt.x, pt.y, this);
}
return FALSE;} |
有了这样的背景，问题跟用户的代码就联系起来了。额外打开的文件（GIF）的确是跟这个程序（HTMLView Control）相关的。那下一步我们该做什么呢？
当时我的思路是这样的。ShellExecue能打开这个GIF文件，肯定在某种程度上，这个GIF跟ShellExecue的调用有联系, 至少ShellExecute要知道这个GIF的路径才可以打开它。为了进一步分析，可以选择的步骤是：
1. 打开Windbg（和Visual Studio Debugger类似的调试工具，后面有详细介绍），在ShellExecute上设断点，然后开始调试，一步一步走下去看这个GIF文件是如何打开的。
2. 通过阅读客户的代码和做进一步的测试来缩小问题的范围。
仔细思考后，我放弃了第一种。原因是，首先，打开文件的操作不是在ShellExecute中完成的，而是在UltraEdit中完成的。目标和范围都太大，操作起来很难。其次，问题是偶尔发生的，所以无法保证每次调试都能够重现问题。
整理后的思路如下。
首先，ShellExecute是在菜单处理函数中调用的，菜单处理函数是用户点击菜单项触发的。可以尝试隔离检查ShellExecute跟两者的关联。所以写了一个Timer，定时地直接调用菜单处理函数。结果发现，通过这样调用菜单处理函数，问题没有出现过。从这个测试中，基本上可以确定问题跟弹出的菜单相关。所以，下一步就是检查替换IE默认菜单相关的代码，也就是PreTranslateMessage。
用户是通过在PreTranslateMessage函数中截获鼠标的WM_RBUTTONDOWN消息，然后显示菜单。注意，返回值是False！MSDN中对这个函数的描述在：
CWnd::PreTranslateMessage
http://msdn.microsoft.com/library/default.asp?url=/library/en-us/vclib/html/_mfc_cwnd.3a3a.pretranslatemessage.asp
这里客户返回False，表示消息没有被处理，需要继续发送给后继的消息处理链。然而事实上，客户的代码已经截获这个消息，并且显示了菜单，所以，我建议客户这里修改成True测试。这个建议避免了问题的继续发生。
这里说明了分析问题一定要有理有据，不要放过问题中的任何一个线索，应该尽可能分析出可能的因果关系，然后决定下一步的操作。一旦确认线索后，要仔细彻底地分析，不要错过细节。
1.2.4 革命尚未成功
通过上面的分析和测试，没有花费太多的精力就找到了解决问题的方法。但是，这个时候就开始高兴，未免太早。这里把False修改成True给客户带来了新问题，上面的分析也不足以揭示为什么简单的True/False就给ShellExecute带来这么大的影响。让我们继续走下去。
首先解释一下带来的新问题是什么。在菜单的消息响应函数中，客户除了用ShellExecute打开文本文件外，还需要用HTMLDocument的一些属性和操作来获取当前用户是在HTML页面中的哪一个tag上点的鼠标，比如是在<img>标签呢还是<div>标签。如果修改成True，上面的功能就无法正常工作。这个问题很好解释，由于HTMLView无法继续处理鼠标消息，当然得不到用户的操作信息。
问题的另一方面还是在于为何会打开两个文件。PreTranslateMessage的返回值带来两种不同的表现，所以我考虑分析ShellExecute在两种情况下表现的差异。首先反汇编ShellExecute，发现里面的实现非常复杂，不可能首先读懂代码后再进行调试。一个高效的办法是通过Windbg的wt命令（这里不详细介绍这些命令的用法，留到下一章），观察ShellExecute内部的调用栈（callstack）。研究后发现ShellExecute是通过DDE的方法来打开目标文件的。在研究了MSDN的说明以后，了解到DDE其实内部是依靠WindowsMessage来完成进程之间通信的。于是，又在PostMessageW/SendMessageW上设定条件断点，每次调用这两个函数的时候，就把WindowsMessage的详细信息和callstack在windbg中打印出来，以便比较不同情况下的差异。最后看到发生问题时候的callstack是这样的，您能想清楚原因吗？
USER32!PostMessageW ole32!CDropTarget::Drop ole32!CDragOperation::CompleteDrop ole32!DoDragDrop mshtml!CLayout::DoDrag mshtml!CElement::DragElement mshtml!CImgElement::HandleCaptureMessageForImage mshtml!CElementCapture::CallCaptureFunction mshtml!CDoc::PumpMessage mshtml!CDoc::OnMouseMessage mshtml!CDoc::OnWindowMessage mshtml!CServer::WndProc USER32!InternalCallWinProc USER32!UserCallWinProcCheckWow USER32!DispatchMessageWorker USER32!DispatchMessageW SHELL32!SHProcessMessagesUntilEventEx SHELL32!CShellExecute::_PostDDEExecute SHELL32!CShellExecute::_DDEExecute SHELL32!CShellExecute::_TryExecDDE SHELL32!CShellExecute::_TryInvokeApplication SHELL32!CShellExecute::ExecuteNormal SHELL32!ShellExecuteNormal SHELL32!ShellExecuteExW SHELL32!ShellExecuteExA SHELL32!ShellExecuteA |
从CDropTarget::Drop这个函数可以猜到gif是怎么被打开的，但奇怪的地方是ShellExecute居然把mshtml牵涉进来了。如果仔细回想一下问题重现的步骤，会发现遗漏了一个重要的地方，那就是：
既然在PreTranslateMessage中返回了False，那么这个消息就相当于没有处理过，那么，IE的默认菜单为什么没有弹出来呢？
根据这个callstack，问题发生的经过是：
1. 用户在HTMLView上面的GIF文件上点下鼠标右键（注意，这个时候点下去，还没有放开），系统发送WM_RBUTTONDOWN消息。
2. 在PreTranslateMessage里面，判断WM_RBUTTONDOWN消息，用TrackPopMenu API显示菜单，并且代码堵塞在TrackPopMenu API上。
3. TrackPopMenu显示出菜单。
4. 用户放开鼠标右键，并且移动鼠标，点击菜单项。
5. 点击菜单后，TrackPopMenu API返回，同时系统向应用程序发送对应菜单项点击后的WM_COMMAND消息到Posted Message队列中。
6. PreTranslateMessage函数返回False，于是WM_RBUTTONDOWN的消息继续发送到后面的消息处理函数。同时系统还会发送（Post, in Posted MessageQueue）额外的一个WM_MOUSEMOVE消息到消息队列中。
7. WM_RBUTTONDOWN的消息传播到后面消息处理函数，导致的结果是在HTML的GIF上点下了鼠标。由于WM_RBUTTONUP的消息在显示菜单的时候被菜单吃掉了，所以，对于HTMLView来说，点下去的鼠标就一直没有放开。因为IE是在WM_RBUTTONUP的时候显示自身的弹出菜单，所以IE自身的菜单也因为缺少WM_RBUTTONUP消息而没有显示。
8. 程序回到消息循环，由于SentMessage有优先权，所以WM_COMMAND先得到处理，于是ShellExecute得到了调用。
9. ShellExecute通过DDE给UltraEdit发送打开文件的消息，于是UltraEdit就打开了TXT文件，同时，UltraEdit的窗口切换到了前台。
10. 由于ShellExecute需要检查UltraEdit返回的DDE消息来判断打开是否成功，所以ShellExecute需要维持自己的消息循环，这也就是callstack中SHProcessMessagesUntil- EventEx函数做的事情。
11. ShellExecute维护的消息处理函数继续分发消息队列中的消息，第6步生成的WM_MOUSEMOVE得到处理，从callstack可以看到，这些消息到达了HTMLView。
12. 根据第7步，HTMLView得到的消息是鼠标在GIF落下，HTMLView会把GIF设定成Captured状态，然而接下来的鼠标抬起，消息丢失，导致HTMLView执行了跟普通点击（鼠标一下一上）不一样的顺序。 由于GIF是Captured的状态，加上前台窗口是UltraEdit，同时还有WM_MOUSEMOVE消息，这些非常规的状态和后继消息导致了HTMLView认为当前发生了落下鼠标紧接移动鼠标的行为，类似用鼠标右键把这个GIF文件从HTMLView上拖动到了UltraEdit上。GIF就这样被打开了。
当然这里还有一个问题。拖动的3个步骤是鼠标落下、鼠标移动和鼠标松开。但是这里我们并没有看到鼠标松开消息的来源。在WebControl的拖动实现中，是否有其他的消息可以代理鼠标松开，就需要研究复杂的HTML实现了。我只能猜测，正是因为这一点的不确定性，导致了问题的随机性。希望您有机会把整个问题完全弄清楚。
在第6步中，我通过自己写的一个例子程序发现点击菜单后还会有一个WM_MOUSE- MOVE的消息。至于为何要这样设计，请参考:
Why do I get spurious WM_MOUSEMOVE messages?
http://blogs.msdn.com/oldnewthing/archive/2003/10/01/55108.aspx
另外这个问题在IE7上面可能无法重现，因为IE7做了一些改变。
通过比较分析正常情况（return TRUE）和异常情况（return FALSE）下wt命令和PostMessageW/SendMessageW函数的调试输出，问题基本上找到原因了。整体的思路是先隔离问题，然后比较不同情况的差异。当然，获取这些差异的时候要聪明一点，选用正确的方法和工具。
不知道你有什么感想，总之，当时我的感觉就像一个状态机，是一个Windows+MFC Framework，根据用户的操作，严格地响应消息，执行对应的代码，哪怕这些状态是非常规的。不要迷信，尊重CPU和代码运行法则，用CPU的节奏和方法来考虑问题，才可以看到问题的来龙去脉。
从程序设计的角度来看，细节是非常重要的。到底应该返回True还是False，到底是在WM_BUTTONDOWN还是WM_BUTTONUP的时候处理消息，都是需要仔细推敲的问题。
这一个ShellExecute的案例就到此为止了，找到问题根源后，正确做法就很明了了：
How to disable the default pop-up menu for CHtmlView in Visual C++
http://support.microsoft.com/?id=236312
1.2.5 结论
通过这个案例我的收获是：
1. 尊重事实，而不是经验。
2. 详细观察问题发生的过程，对任何线索保持敏感。
3. 用对比的方法来寻求问题的根源。
4. 用CPU的节奏和方法来理解整个系统。
1.2.6 题外话和相关讨论
MSDN是最值得信赖的吗
不仅仅是经验不可信，就算MSDN，也没有事实证明其确凿可信。下面这篇知识库文章，是详细测试了用户的代码后，确认MSDN有一个bug，然后申请了一篇知识库文章（Knowledge Base）来作专门的解释：
Description of a documentation error in the "Assembly.Load Method (Byte[])" topic in the .NET Framework Class Library online documentation
http://support.microsoft.com/kb/915589/en-us
里面的第一句话就是：
The "Assembly.Load Method (Byte[])" topic in the Microsoft .NET Framework Class Library online documentation contains an error
你敢说CPU坏了
这个案例是美国工程师处理的。客户有两台负载均衡的小型机，每一台机器有64颗CPU，从硬件到软件环境都完全一样。其中一台机器一直正常，另一台机器的MSDTC偶尔会崩溃。那位工程师根据调试器的输出，对客户说：“我怀疑问题是CPU导致的，你换一块CPU试试看。”将信将疑的客户立刻把Intel的工程师叫过来，热插拔换了一块CPU，问题果然就搞定了。我在想，如果某一天，当我从调试器上看到xor eax，eax执行后，eax不等于0，我敢跟客户说这是CPU的问题吗？
There's an awful lot of overclocking out there
http://blogs.msdn.com/oldnewthing/archive/2005/04/12/407562.aspx
同时，现在有的rootkit和加壳程序已经能够欺骗调试器了。但有的时候，一些新加入的系统功能也会导致一些有趣的现象：
VS2003在push edi的时候AV
http://eparg.spaces.msn.com/Blog/cns!1pnPgEC6RF6WtiSBWIHdc5qQ!379.entry
SEH,DEP, Compiler,FS:[0], LOAD_CONFIG and PE format
http://eparg.spaces.msn.com/blog/cns!59BFC22C0E7E1A76!712.entry
要区分事实和谎言，不是那么容易……
DWORD和文件长度
对某些数字保持敏感有助于找到线索。客户写了一个文件类，但是发现操作长度大于4GB文件的时候，就会有一些莫名其妙的问题发生。你能一下子猜出原因吗？
4GB表示DWORD的上限。如果用一个DWORD指针来获取文件大小，当文件大小超过4GB，问题就会发生。所以，客户很可能使用了错误的API。
解决这个问题，应该用GetFileSizeEx API而不是GetFileSize。其实，不单单是客户会犯这样的错误，.NET Runtime也有类似的bug，由于没有使用正确的方法来获取物理内存数量，导致物理内存超过4GB后性能反而下降：
FIX: Generation 1 garbage collections and generation 2 garbage collections occur much more frequently on computers that have 4 GB or more of physical memory in the .NET Framework 1.1
http://support.microsoft.com/kb/893360/en-us
所以，常常会有人用下面的智力题来面试开发人员：让工人为你工作7天，工人得到的回报是一根金条。每天你都必须支付给工人一天的费用，每天的费用为七分之一根金条，但这根金条不能被平分成7段，只允许你把金条弄断两次，你如何给工人付费？
在网上找一下就可以看到答案。如果对二进制比较敏感，你会发现答案跟2的n次方是相同的，当然，这绝对不是偶然。
程序输出0xcdcdcdcd,想到了什么
关于数字敏感的另一个例子：一段加密解密程序，首先由用户输入16个字节的原文，然后程序用固定的密钥加密生成密文，接着再对密文解密得到原来的原文，并且打印。问题的现象是，无论用户输入怎么样的原文，经过加密解密后，打印出来的原文的二进制都是一连串的0xcdcdcdcd。
仔细回忆一下， VC在debug模式下，对CRT（C Runtime）分配的堆（Heap）内存，都会初始化填充成0xcdcdcdcd。目的就是为了方便程序员debug，一旦看到0xcdcdcdcd，就表示访问了没有初始化的内存。所以，这个问题显然是开发人员忘记把用户的输入拷贝到对应的缓冲区，导致缓冲区里面的值都是分配内存时有CRT初始化填入的0xcdcdcd。
1.3 简单的问题最棘手：稀疏平常的ASP.NET Session Lost问题
1.3.1 问题描述
客户抱怨，刚刚开发完成的大型ASP.NET站点测试阶段一切正常，但是放到生产环境上，运行压力一大，就会发生Session Lost现象。问题的表现是一个NullReferenceException异常。分析代码后发现，该NullReferenceException是试图访问一个SessionObject时候发生的。该SessionObject应该在前面就已经设置过。问题半年来一共就发生过3次，而且是在3个不同的页面发生。
1.3.2 制定策略
这个问题困难的地方在于重现的几率很小，没有多少详细观察的机会。所以，必须制订非常周全的计划，以便问题再次发生的时候，获取足够多的信息。如何制订周密的计划呢？
思路非常直观，了解Session实现的细节，总结出导致问题的所有可能性，获取信息的时候排查所有的可能性。
关于ASP.NET Session的细节，可以参考：
Underpinnings of the Session State Implementation in ASP.NET
http://msdn.microsoft.com/library/default.asp?url=/library/en-us/dnaspp/html/ASPNetSessionState.asp
有了对Session的理解后，把这个问题分成了下面几种情况：
1. 客户使用了负载均衡的环境，但是没有正确配置基于数据库或者服务的Session模式。或者是几台服务器的Machine key没有配置成一致。跟客户确认后排除了这种情况，因为客户只有一个服务器，使用的In-Proc。
2. 最简单的情况就是所有的用户，所有的session都丢了。这种情况一般发生在In-Proc的session mode上。原因就是appdomain重启或者IIS进程崩溃。可以通过性能日志或系统日志来排查。
3. 稍微麻烦一点的就是某一个用户的session丢了，而没有影响到所有用户。观察方法是，首先在session start里面做log， 把每一个session的创建时间以及session id都记录到本地的一个log里面，同时往session里面添加一个测试用的session value。问题发生的时候，在ASP.NET的全局错误处理函数中当前的session id读出来，比较log中的记录看看这个session是不是刚刚建立的。如果是，很有可能是客户端的原因导致session id丢了，比如IE crash导致cookie丢失。
4. 如果不是，那就看看测试用的session value是不是丢了。如果这个也丢了，应该是代码中掉了Session.Clear。
5. 如果测试用的session value没有丢，情况就变成一个用户的session里面的一部分value丢了。很可能是由于用户的代码逻辑导致的。解决方法就是通过更详细的log来定位问题，然后阅读代码来检查。
可以看到，问题的特征跟潜在的根源是对应的。目的在于区分出这3种情况：
1. 所有用户的所有Session全没有了。
2. 一个用户的Session没有了。
3. 一个用户的部分Session没有了。
针对每种情况，采取的log策略是：
对于第1类情况，可以在Application_Start/End函数中记录下时间来检查Appdomain是不是重新启动过。
对于第2类情况，log文件应该记录下session id和session创建的时间。以便判断问题是否是cookie id lost导致的。如果是cookie id lost，那问题就出在客户端，或者是网络原因。
对于第3类情况，可以在工程中搜索所有Session Clear的调用，每次调用前写log文件来记录。如果工程很大，无法逐一添加，可以加载调试器，在Session Clear函数中设定条件断点来记录。
1.3.3 具体操作和结论
总结下来，具体的实现是：
1. 在global.asax文件的session_start中把这个session的创建时间记录到session里面。这个创建时间也同时充当测试用的session value。
2. 代码中对session操作的地方，写log到以sessionid为文件名的文件中去。
3. 用log文件记录每次session的操作，发生在什么函数，发生的时间，session内容的变化。
4. 当Exception发生的时候，在Exception handler中记录发生问题的session id和残留下来的Session value。
这样，问题发生的时候，根据Exception handler记录的session id找到log文件，就可以很清楚地得到所需要的信息。
在做了上述部署之后，等了大约一个星期问题重现了。在log文件中，发现这样的信息：
1. 某一个用户的部分Session丢失。
2. 从Session创建时间看，该Session已经维持很长时间了。
3. 通过检查Session Clear的调用纪录，发现丢失的Session的确是由用户自己的代码清除的。同时发现这些代码的运行次序跟设计不吻合。根据设计初衷，在清除Session后，页面会重定向到一个专门的页面并重新添加Session，然后继续操作。但是log表明这个专门的页面并没有得到执行。
检查用户的重定向代码后发现，重定向是通过客户端JavaScript来实现的。用JavaScript来维护事务逻辑，犯了web开发的大忌。因为JavaScript的行为对客户端浏览器的依赖非常大。重定向最好用http 302来实现（Response.redirect就是这样实现的），同时需要在服务器端添加检测代码来确保业务逻辑的正确顺序：
HTTP Status code definition
http://www.w3.org/Protocols/rfc2616/rfc2616-sec10.html
在做了上面的改动后，问题得到了解决。Session lost不是一个很有趣的例子，但它却非常具有代表性。
问题现象简单而且明确，但是很难重现。问题的原因是在早期积累下来的，如果只观察问题暴露出来后的现象，为时已晚。对付这类问题，关键在于根据问题的特点，在适当的地方主动抓取信息。
1.3.4 题外话和相关讨论
排查session lost的经验
除了上面的步骤外，遇上session lost还应该注意。
1. 如果用户开两个IE进程（注意，不是用Ctrl+N开两个IE窗口） 访问同一个url, 这两个进程分别对应两个独立的session。
2. 最容易忽视的情况是session timeout。可以观察Session id是否变化，或者在session end里面加log进行排查。
1.4 本可以做得更好：SharePoint中文界面变英文
1.4.1 问题描述
Windows SharePoint Portal 是运行在.NET Framework上的一个web应用程序。管理员可以设定使用英文界面或者中文界面。某天一个客户抱怨SharePoint无法显示中文界面，所有的页面都用英文显示。经过仔细观察，发现下面的现象:
1. 管理员的设定值是中文界面。
2. 该程序在过去的一年中都运行正常。
3. 大多数情况下，中文界面工作正常。
4. 偶然有几次，中文界面会变成英文界面。
5. 变成英文界面后，过一段时间后会自动变回中文界面。
6. 变成英文界面后，如果重新启动IIS, 有可能解决问题。
1.4.2 排错步骤
经过观察，发现客户的安装和配置是没有问题的。大致调试后发现:
1. 客户程序工作线程的UI Culture的确是zh-cn, 跟客户的设定一致。
2. 界面显示资源是通过ResourceManager.GetString系统方法来加载的。
ResourceManager.GetString
http://msdn2.microsoft.com/en-us/system.resources.resourcemanager.getstring.aspx
3. 该客户的中文资源卫星文件安装正确。
根据这3个信息，GetString应该返回对应的中文资源，但是在问题发生的时候，返回的却是英文资源。所以，需要解释的是这个.NET系统方法为何表现异常。面临的难点是：
1. 无法简单重现问题，需要反复重新启动IIS多次后，问题才会偶然发生。
2. 问题只有在客户机器上才能重现，需要远程调试，操作起来不是很方便。
3. 由于出问题的代码是.NET Framework的函数，不是客户的代码，没办法用第3个例子的方法来添加log分析。
当时欧洲很多客户也有类似问题发生，比如西班牙语的站点变成了英语。日本更是严重，有十几个站点都有这个问题，但是几个星期来一直都没有找到问题的根源。
由于问题的线索是GetString方法的异常表现，所以排错计划也非常直接：跟踪GetString的执行过程。在做远程调试以前，首先在本地跟踪GetString的执行过程来理解逻辑。大致的逻辑是：
1. 资源符号从卫星加载起来后会放到内存的HashTable中。
2. GetString检查HashTable中是否有请求的资源，如果有，跳到第5步。
3. 如果没有，GetString会让ResourceManager根据当前线程的UI Culture寻找对应卫星目录来加载。
4. ResourceManager加载卫星Assembly到内存，同时把所有的资源符号都写入HashTable。
5. GetString返回这个HashTable中对应的资源。
6. 如果有问题发生，比如ResourceManager没有找到对应的卫星目录，或者资源文件不存在，就用中立语言（英语）资源代替。
7. 一旦HashTable填充完成，GetString的后继执行就不需要使用ResourceManager了，直接返回HashTable的内容。
根据上面的逻辑，客户那里的问题很可能是ResourceManager没有找到资源文件，于是就用英语初始化HashTable。根据这个信息，决定用Filemon来检视资源文件的访问。可惜的是，Filemon的结果表明每次对资源文件的访问都是成功的。同时，再次检查了资源文件的安装，也没有发现异常。
走投无路的时候，只有通过远程调试来检查了。跟客户交流后，客户同意在把晚上10点到早上8点的时间段留给我们来排错。为了排除干扰，用下面的步骤来检查：
1. 在IIS上限制只有测试用客户端IP才能访问。
2. 把IIS和ASP.NET的超时时间都设定到无限长。
3. 每次调试前重新启动IIS。
4. 在客户端刷新一次页面，然后在调试器中检查GetString和ResourceManager的执行过程。
限制IP的目的是为了控制重现问题的时机，防止有其他用户来访问页面。重新启动IIS是必须的。因为要观察HashTable的初始化过程。设定超时时间是为了防止超时异常干扰调试。在连续几天的努力后，发现下面的线索：
1. 加载卫星文件的时候失败了。
2. 加载过程中，有两次first chance CLR exception。
3. 问题发生的时候执行了一些异常的codepath。这个codepath上很多函数的名字比较新颖，在本地测试的时候，没看到类似的函数。
根据上面的结果，重新在本地检查对应的代码，然后结合wt命令和异常发生的时机，抓取某些codepath的执行过程。分析后发现一个比较重要的线索，客户那里部署了.NET Framework 1.1 SP1，一些SP1中新加入的codepath被执行到了。
经过最后的整理和分析，发现了问题是这样的：在.NET Framework 1.1上，ResourceManager判断当前线程的UI Culture后就开始寻找对应的卫星文件。但是SP1中添加了某一个额外的配置选项，使得寻找的过程可以通过web.config来配置。由于web.config配置文件很重要，普通的web用户是没有权限访问的，在访问web.config过程中，一旦发生了Access Denied，就会导致CLR exception。异常发生后，ResourceManager认为某些地方出了问题，于是ResourceManager停止加载卫星文件，用中立资源代替，于是英文就代替了中文。
换句话说，设计者没有考虑到web程序中，没有权限去访问CLR程序配置文件（web程序中是web.config）的情况是很常见的。这种情况没有被特殊处理，因而导致了问题。
在客户重新启动IIS后，如果程序第一个使用者权限比较高，能够访问web.config的话，中文资源就可以加载起来。如果第一个使用者权限比较低，问题就发生了，而且会一直保留到下一次IIS重新启动再次加载资源的时候。暂时的解决方法是把web.config设定为Everyone Access Allow。这个workaround在一个星期内迅速帮助了全球范围内很多SPS站点的显示正常起来。
当然，修改web.config的权限是非常危险的，所以申请一个hotfix才是最终的解决方案：
FIX: Your application cannot load resources from a satellite assembly if the impersonated user account does not have permissions to access the application .config file in the .NET Framework 1.1 Service Pack 1
http://support.microsoft.com/?id=894092
1.4.3 错过的线索
如果仔细分析这个案例的解决过程, 会发现排错初期距离胜利就只有一步之遥。已经想到了用Filemon去观察卫星文件的访问情况，但是就没想到用Filemon观察里面是否有Access Denied。事后拿出当时的Filemon结果，查找Access Denied，一共发现了30几处。同时，当观察到该问题以前一直没有，现在突然像洪水一样全球泛滥时，就应该意识到最近一段时间发布的一些重要补丁很可疑。
所以，如果想做得更好一点，不在于使用了多少工具，用了多么深奥的调试技术，而在于能够比经验主义多想到一点什么。开拓一下思路，可以很简单地四两拔千斤。
这一章不在于演示出一套分析问题的模版，而是想说明解决问题的核心武器是思考，知识和工具只是辅助。在遇上问题的时候能够多想一分钟再动手，本章的目的就达到了。
扫一扫
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
