调试时的常见问题
在分布式 Web 应用程序中最常见的问题有:
ASP 0115—访问冲突
ASP 服务器太忙的错误
100% 的 CPU 问题
在这一节,我们将分析引起这些问题的可能原因,讨论如何调试并鉴别引起每个问题的代码行。
ASP 0115—访问冲突
访问冲突主要是由堆和堆栈故障引起的。
如果您进行这样一些操作,如分配一块内存并试图在该内存块之外执行读写操作,就会引起访问冲突。
例如:
char* pszTemp = (char*) malloc(strlen("BOMB THIS"));
strcpy(pszTemp,"BOMB THIS");
在本例中,用户分配 9 个字节的内存,但没有包含 NULL 的结束符("\0")。当试图向此内存位置复制字符串时,因为函数试图访问所分配的内存段以外的部分,就会产生错误。
另一个方案试图访问一个非法的内存位置。
例如:
FunctionA()
{
m_pAV = NULL;
FunctionB(m_pAV);
}
FunctionB(CAccessViolate* pAV)
{
pAV->BombThis();
}
在本例中,FunctionB 使用传递给它的 pAV 指针而未检查其合法性,从而导致访问冲突。
大多数访问冲突发生在当 ASP 页试图访问一个组件,而这个组件又正在试图做错误的事情时。为简单起见,我们假定您已将某个组件安装为库程序包。当您试图访问使用这个组件的一个 ASP 页时,ASP 页可能返回以下信息:
error 'ASP 0115'
Unexpected error
/<Web Server Name>/<ASP file name>.asp
A trappable error occurred in an external object. The script cannot continue running.
这个错误消息指出在某个特定的 ASP 页中有一个错误,它是由在某个外部对象中产生一个异常引起的。它表明您试图在 ASP 页中访问一个失败的组件。您可以这样来进一步隔离问题,在 ASP 页中删除对任何组件的所有引用,然后再逐个将它们添加进来,直到找到故障原因为止。
如果隔离的过程过于冗长乏味,或者您没有获得一个指明 ASP 页名的清晰错误信息,则可以将 WinDBG、User Mode Process Dump 或 IIS Exception Monitor 连接到 inetinfo,并开始调试。
找出引起访问冲突的代码行
假定您已使用 User Mode Process Dump 工具连接到 inetinfo 进程,并创建了一个转储文件。现在开始在 WinDBG 中检查转储文件,并尽力勾画出所发生的事情。
在 WinDBG 中打开故障转储文件,在 View 菜单中,单击 Call Stack。
图 4. 显示堆栈的 Windows 调试程序对话框
在上图中,即使堆栈中最顶部的函数是 KERNEL32 DLL 中的一个函数,但这并不一定意味着出错的代码就在这个函数中,而且大多数情况都不是这样。下一步是确定列表中是否有非标准的 Windows 系统组件,并确定在出现故障时它们正在做什么。如果您从下到上的读上图中的堆栈,您会发现第 8 行和第 7 行表明 ASP 使用了 Microsoft VBScript 引擎来启动组件,第 6 行和第 5 行表明 VBScript 引擎使用 IDispatch 接口方法调用组件 (CRASHATLAPP) 内部的方法。因为使用了 IDispatch 接口,图中出现 OLEAUT32.dll 便是很自然的了。第 4 行和第 3 行表明了这一点。堆栈中的第 2 行表明调用了 BlowOff 方法,BlowOff 又调用了 KERNEL32 DLL 中的 OutputDebugString API。假定标准 Windows 组件 KERNEL32 dll、OLEAUT32.dll 以及 VBScript 引擎没有问题(从问题隔离的角度看),这是一种安全的假定。接下来要处理的只剩下堆栈中列出的唯一的非 Windows 组件,CRASHATLAPP。
在 CRASHATLAPP 内部的 BlowOff 方法调用了 OutputDebugString API。通过在命令窗口输入 kb,我们可以检查 BlowOff 传递给 OutputDebugString 的参数的值。
在 KERNEL32 DLL 内部,BlowOff 方法将 NULL 作为参数传递给 OutputDebugString 方法。最好查看一下在 BlowOff 方法内部进行了什么操作,使得它传递一个 NULL 值。如果您手头有 CRASHATLAPP 组件的源代码,您可以双击堆栈中的第 2 行。
图 5. 显示堆栈的 Windows 调试程序对话框
这将调出 BlowOff 方法的源代码。
图 6. 显示 BlowOff 方法的源代码的 Windows 调试程序对话框
源代码清楚地显示,NULL 被作为参数传递给 OutputDebugString。
尽管不会在产品代码中遇到这种问题,提供这个示例的意图是,使您对调试和确定访问冲突错误的原因的过程中所涉及的步骤有一个概念。
ASP 服务器太忙的错误
ASP 服务器太忙错误通常是由 ASP 请求队列填满引起的。当 IIS Web 服务器高负荷运转或等待一个阻塞的线程时,就可能产生非常大的队列。当调用 IIS Web 服务器正在等待的某个组件的频率超过该组件所能承受的频率时,通常就会发生这种情况。所有进入的请求都被放在 ASP Request 对列中并按照它们进入的先后顺序进行处理。如果阻塞只持续很短的一段时间,则队列机制最终将解决问题并开始及时响应请求。但是如果阻塞持续很长的时间,队列中的请求就会不断增加,并最终达到 ASPRequestQueueMax 元数据设置中的峰值,默认值为 3000。如果队列大小在 3000 以下,当第 2999 个请求在队列中,并等待要填入的所有其它请求时,发出这个请求的用户就会看到一个沙漏标志。即使在这个时候,如果队列清除得足够快,这个请求仍然会被接收和处理。相反,如果队列大小达到 ASPRequestQueueMax 的值,而又有一个新的请求加进去,则 IIS 服务器返回 ASP 服务器太忙的错误。
ASPProcessorThreadMax 和 ASPRequestQueueMax 的设置
ASPProcessorThreadMax 和 ASPRequestQueueMax 元数据设置对站点的性能有很大的影响。ASPProcessorThreadMax 参数指定处理器能承受的最大线程数。ASPRequestQueueMax 参数指定请求队列的最大值。这两个设置可以通过以下命令更改:
adsutil.vbs set w3svc/AspProcessorThreadMax NewValue
adsutil.vbs set w3svc/AspRequestQueueMax NewValue
对于写得较好的脚本,ASPProcessorThreadMax 值应该低一点。调整 ASPProcessorThreadMax 的主要目的是,使处理器在最大负荷情况下的利用率达到 50% 以上。
由于每一个站点的物理配置有很大的不同,因此很难预测这些参数的最优值。应该使用性能监视器来监视关键的计数器,以作出有关这些参数的一个决策。使用性能监视器的统计数据应该包括:
处理器时间:%Processor time
ASP: Requests per second, Requests rejected, Requests queued
您可以在一个产品站点达到最大负荷时监视这些值。通常,您会在高容量的站点观察到队列中的请求数的起落。如果处理器的利用率很低,并且总的队列长度从不上升,那表明您的站点的容量远大于您的实际需要。如果总的队列长度上下起伏,而处理器利用率在 50% 以下,那就表明有些请求被阻塞,这时您将从增大线程数中获益。如果在增加线程后观察到队列中的请求的数量比以前更糟,而且处理器利用率也降低了,这就说明有严重的阻塞问题。典型的阻塞问题可能是由对数据库进行的、需要执行很长时间的 SQL 查询引起的。增大线程数允许对执行查询的页的更多请求进入;这样会给数据库造成更大的压力,从而使查询的响应时间变得更长。要获得 ASPRequestQueueMax 的一个最优值,请选择一个可接受的最长响应时间,计算在这段时间内可清空的队列的大小,然后将 ASPRequestQueueMax 的值设置为稍小于这个大小。
调试示例
我们已详细讨论了 ASPProcessorThreadMax 参数和 ASPRequestQueueMax 参数,接下来我们将模拟 ASP 服务器太忙的错误,并试着调试哪个组件的线程发生了阻塞,以及为什么会发生阻塞。假定有一个 ASP 页,并且该页正在调用一个发生阻塞的组件。
为了模拟这个问题,我们通过以下命令将 ASPRequestQueueMax 参数设置为 20:
cscript c:\inetpub\AdminScripts\adsutil.vbs SET w3svc/ASPRequestQueueMax 20
要启动性能监视器,请执行以下步骤:
单击开始,指向程序,指向 Adminstrative Tools,然后单击 Administrative。用鼠标右键单击图表,选择 Add Counters。
在 Add Counters 对话框中,从 Performance Object 列表框中选择 Active Server Pages。
在 Select counters from list中,选择 Requests Executing 和 Requests Queued。单击 Add,然后单击 Close。
假定在您的 ASP 代码中调用某个组件,而该组件正在阻塞请求。
添加这些计数器后,观察计数器的值。您会发现,当队列中的请求的计数器达到 ASPRequestQueueMax 的值(20)时,服务器返回 ASP 服务器太忙的错误。
图 7. 显示队列中的请求计数器值的性能监视器
为了调试 inetinfo 进程来确定哪个线程发生阻塞以及为什么发生阻塞,请启动 WinDBG 并连接到 inetinfo 进程。导致线程阻塞的最常见的原因是死锁。您应该试着识别锁定计数大于 0 的那个关键部分,以及该部分拥有的线程 ID。这个线程就是问题所在。一旦获得线程 ID,就可以调试该线程的堆栈,找出是哪个方法发生了阻塞。您可以在命令窗口输入以下命令来完成这一步:
!locks
这时应该列出锁定计数大于零的线程。输出将类似于以下内容:
CritSec ?g_cs@@3U_RTL_CRITICAL_SECTION@@A+0 at 100355A0
LockCount 24
RecursionCount 1
OwningThread 6e8
EntryCount 18
ContentionCount 18
*** Locked
找出锁定计数大于零的那个部分,并注意它拥有的线程 ID。
有时,!locks 命令不提供所需的信息,这通常是因为 ntdll.dll 的符号排列不正确。在这种情况下,您可以使用下面比较原始却行之有效的方法。
在命令窗口中,键入 ~*kb 来显示所有线程的堆栈。查找包含 NTDLL!RtlEnterCriticalSection 的线程堆栈。在您识别出包含此项的线程以后,请注意 NTDLL!RtlEnterCriticalSection 所在行中 param1 的值。这个值就是传送到 EnterCriticalSection API 的有问题的那个对象。使用这个值,在命令窗口中输入以下命令:
!Critsec 100355A0
用上面的任意一种方法,都应该能够识别出锁定计数大于 0 的那个线程 ID。将此线程 ID 从十六进制转换为十进制。
现在请检查这个线程,并识别正在阻塞线程的那个方法。在 Debug 菜单中,单击 Threads。
在 Threads 对话框中,单击从以上步骤中找出的线程 ID,单击 Select。
在 View 菜单中,单击 Call Stack。这时显示此线程的堆栈。就像在上一个示例(访问冲突)中那样开始调试堆栈。
100% 的 CPU 问题
当一个线程占用了处理器的全部时间时,就会出现 100% 的 CPU 问题。一种可能的原因是,某个程序循环独占了 CPU 资源。性能监视器是解决 100% 的 CPU 使用问题的理想工具。首先需要创建一个性能监视器日志。
准备日志
要启动性能监视器,请执行以下步骤:
单击开始菜单,指向程序,指向 Administrative Tools,然后单击 Performance Monitor。
用鼠标右键单击 Counter Logs,然后单击 New Log Settings。输入一个日志名,然后单击确定。
在 General 选项卡上,单击 Add 将计数器添加到日志中。
添加以下的计数器:
ASP:所有计数器
Memory:所有计数器
Process:所有计数器和所有实例
Processor:所有计数器和所有实例
Thread:所有计数器和所有实例
Web service:所有计数器和所有实例
在添加了所有计数器以后,将 Sampling Interval 更改为 every 1 second,然后单击确定。
现在已经设置好所有的内容,可以开始记录数据了。用鼠标右键单击这个日志名,然后单击开始。确保日志捕获了处理器利用率猛增至 100% 的那段时间内的所有数据。启动 WinDBG 并连接到 inetinfo 进程。一旦处理器利用率回到正常水平,您就可以停止记录,方法是用鼠标右键单击该 Log Name ,然后单击 Stop 。
检查日志
现在已经创建了日志,我们可以开始仔细检查它来识别消耗了大部分 CPU 时间的进程,并进一步识别此进程内部的耗尽 CPU 时间的线程,以及它这样做的原因。
第一步是识别哪一个进程消耗了大部分的 CPU 时间。要打开日志文件,请单击控制台根目录下的 System Monitor 文件夹。在详细信息窗格中,用鼠标右键单击图表,然后单击 Properties。在 System Monitor Properties 中,单击 Source 选项卡。选择 Log File,通过浏览选择您刚创建的日志文件。
用鼠标右键单击图表,然后单击 Add Counters。在 Add Counters 对话框中,从 Performance Object列表中选择 Process。选择 Select counters from List,然后从此列表框中选择 %Processor Time。选择 All instances,单击 Add,然后单击 Close。
这将为我们提供所有处理器及其 CPU 使用情况的列表。现在您需要查清哪个进程引起了 100% 的 CPU 问题。
确保选中了 Highlight 工具按钮(有一个球形图标)。现在您可以滚动这些计数器,将除最接近 100% 标记的那个进程之外的所有进程全部删除。确保只选择了那些与您有关系的计数器。例如,如果您正在调试 100% 的 CPU 利用率的问题,您也许应该查找 inetinfo、其它的脱机处理的 COM 程序包/应用程序 (MTX.EXE/DLLHOST.EXE) 或者 IIS 应用程序。
一旦您在进程级将问题隔离出来,您就可以将注意力集中在该进程内部的那些在出现 100% 的 CPU 问题时仍然活动的线程上,并试着隔离引起问题的那个线程。为此,我们添加更多的计数器来显示该进程中所有线程的 CPU 使用情况。对于本例而言,就是为 inetinfo 进程中的所有线程添加计数器。用鼠标右键单击图表,然后单击 Add Counters。在 Add Counters 对话框中,从 Performance Object 列表中选择 Thread。选择 Select counters from list,然后从列表框中选择 %Processor Time。选择 Select instances from list,然后选择以 inetinfo/* 开头的所有实例。单击 Add,然后单击 Close。
这时,图表中显示在 inetinfo 进程中的所有线程的 CPU 使用情况。
现在可以滚动计数器,将除最接近 100% 标记的那个线程以外的所有线程全部删除。这样我们就准确地找到了引起问题的那个线程。
图 8. 显示关于 CPU 使用情况的计数器的性能监视器
我们只保留实例 ID 为 34 的线程,它占用了最长的 CPU 时间。现在必须找出这个线程的线程 ID,然后在 WinDBG 中找到这个线程并对它进行调试。
要找出线程 ID,请用鼠标右键单击图表,然后单击 Add Counters。在 Add Counters 对话框中,从 Performance Object 列表中选择 Thread。选择 Select counters from list,然后从此列表框中选择 ID Thread。选择 Select instances from list,然后选择实例 inetinfo/34。单击 Add,然后单击 Close。
这样我们就得到了引起问题的那个线程的 ID。选择 ID Thread 计数器。记录该计数器的最后一个值、最大值、最小值和平均值。通常这四个数是相同的。记录这个值(本例中为 764),并切换到 WinDBG 应用程序。
图 9. 显示 ID 线程计数器的性能对话框
在 WinDBG 的 View 菜单上,单击 Threads。这将显示在出现 100% 的 CPU 问题时在 inetinfo 进程内部运行的线程的一个列表。查找您在性能监视器中记录的线程 ID 号。如果在列表中找到此 ID 号,则单击它,然后单击 Select。单击 OK。
在 View 菜单上,单击 Call Stack。这时显示引起问题的那个线程的堆栈。该堆栈将有问题的方法隔离出来。一旦我们找到这个方法,我们就可以返回原代码,查看是哪行代码引起这个问题的。
结论
通过使用 IIS Exception Monitor、WinDBG、User Mode Process Dump 工具和性能监视器,可以有效地解决分布式 Web 应用程序中的大多数常见问题。这些工具当然没有问题的所有回答和解决方案,但它们能够为您最终解决问题指出一个方向。
参考资料
方法:对 Internet Information Services 中出现的高 CPU 利用率“挂起”进行调试(英文)
信息:对 Internet Server 产品中的异常进行调试(英文)
其它读物
Web 站点
知识库文章
Q229814, 将 IIS 配置为处理高利用率(英文)
Q150934, 如何为 NT 调试创建一个性能监视器日志(英文)
致谢
我非常感谢 Systems Integration Engineering 集团的技术主管 Aaron Barth。我认为 Aaron 是我的调试老师;他教会我如何进行调试,而且在我写这篇文章的过程中给予了我极大的帮助。