调试ASP.NET 2.0 HttpException请求超时(Request timed out)

李志强ASP.NETLeave a comment


注：以下步骤适用于ASP.NET 2.0 32bit应用程序

问题描述

超时问题发生时应用程序事件日志会出现以下警告。

通常这种问题发生的原因是由于请求的执行时间超过了服务器端配置的超时时间。在配置文件中可以通过httpRuntime/executionTimeout属性设置此最大超时时间(.Net 2.0中默认为110 秒)。

Event Type: Warning
Event Source: ASP.NET 2.0.50727.0Event Category: Web Event 
Event ID: 1309Event code: 3001 Event message: The request has been aborted. Event sequence: 2 Event occurrence: 1 Event detail code: 0 ... 
Exception information: 
    Exception type: HttpException 
    Exception message: Request timed out.

问题重现

创建一个命名为sleep.aspx的ASPX页面。

  
             ASP.NET Simple Page

创建web.config，并把它放在sleep.aspx相同的文件夹。将最大超时时间设置为5秒。

<?xml version="1.0" encoding="UTF-8"?><configuration>    <system.web>        <httpRuntime executionTimeout="5"/>    </system.web></configuration>

使用浏览器访问sleep.aspx，过一会就是收到页面报错"[HttpException (0x80004005): Request timed out.]"。警告也将纪录在应用程序事件日志中。

注：
你可能会注意到，错误消息并非在5秒钟后马上出现。因为内部 ASP.NET 使用一个计时器(System.Threading.Timer)来调用请求取消该线程执行。计时器触每15秒发一次。因此在现实中请求可能在5秒到20秒之间的任何时候超时。
详细信息可以参考http://blogs.msdn.com/b/pedram/archive/2007/10/02/how-the-execution-timeout-is-managed-in-asp-net.aspx

数据收集

对于该问题的数据收集一个典型的"错误"是配置调试器来监视HttpException。实际上问题发生的时刻抛出的ThreadAbortException而非HttpException，所以尝试捕获到HttpException已经错过了问题发生的时刻。
另外并非所有的ThreadAbortException都于此相关，我们可以通过以下方式来在这种ThreadAbortException触发点上收集数据。

  • 将以下的文本保存为c:aspnet_timeout.cfg

<ADPlus Version='2'>
    <!-- Configuring ADPlus to log all first chance exceptions -->
    <!-- Will still create full dump for any type of second chance exceptions --><KeyWords>
   <keyword Name="loadbysos"> .loadby sos mscorwks </keyword>
   <keyword Name="GetJIT"> !name2ee System.web.dll System.Web.RequestTimeoutManager.CancelTimedOutRequests </keyword>
   <keyword Name="JITAddress"> .foreach /pS 0n12 ( record {!name2ee System.web.dll System.Web.RequestTimeoutManager.CancelTimedOutRequests}) { r $t1= ${record}; bp $t1+0x172 ".dump /ma /u ${AdpDumpDirEsc}\Full Request timed out ${AdpProcName}_.dmp;g"; .printf"*breakpoint list*n"; bl} </keyword></KeyWords><Settings>
   <Option>  NoDumpOnFirst  </Option>
   <RunMode> CRASH </RunMode></Settings><PreCommands>
   <DebugActions> loadbysos; GetJIT; JITAddress </DebugActions></PreCommands></ADPlus>

  • 通过管理员权限打开命令提示符，转到windbg的安装目录(%programfiles%Debugging Tools for Windows (x86))

  • 运行以下命令来获取应用程序池的进程号，

  • %windir%system32inetsrvappcmd list wp

  • 然后运行下面的命令监控进程异常，如有问题发生在output folder中会生成相应的dmp文件，

  • adplus.exe -c c:aspnet_timeout.cfg -o <output folder> -p <pid>

数据分析

使用windbg打开dmp文件。然后加载sos。

0:025> .loadby sos mscorwks

转储当前线程的堆栈中的所有对象。你会发现计数对象：

0:025> !dso
OS Thread Id: 0x444 (25)
ESP/REG  Object   Name
eax      05baf5b0 System.Threading.Threadebx      05baf5b0 System.Threading.Thread
ecx      01c4f300 System.Web.RequestTimeoutManager+RequestTimeoutEntry
esi      01c4f300 System.Web.RequestTimeoutManager+RequestTimeoutEntry
0f1ff03c 05b33ad4 System.Web.Util.DoubleLinkList
0f1ff040 01c4b508 System.Collections.ArrayList
0f1ff044 05b3397c System.Web.RequestTimeoutManager
0f1ff064 01c4aa94 System.Threading.ContextCallback
0f1ff068 05b3397c System.Web.RequestTimeoutManager
0f1ff088 05b33b30 System.Threading._TimerCallback
0f1ff094 01c4b4e4 System.Threading.ExecutionContext
0f1ff0a0 01c4b4e4 System.Threading.ExecutionContext
0f1ff0a4 05b33b30 System.Threading._TimerCallback
0f1ff0b0 05b33b30 System.Threading._TimerCallback
0f1ff1c0 01c4b090 System.Collections.Hashtable+HashtableEnumerator
0f1ff25c 05b33b30 System.Threading._TimerCallback
0f1ff260 05b33b30 System.Threading._TimerCallback

转储计数对象的信息，查找DONT_USE_InternalThread字段：

0:025> !do 05baf5b0
Name: System.Threading.Thread
MethodTable: 0e3c10f8
EEClass: 0e17d994
Size: 56(0x38) bytes
 (C:WindowsassemblyGAC_32mscorlib2.0.0.0__b77a5c561934e089mscorlib.dll)
Fields:
      MT    Field   Offset                 Type VT     Attr    Value Name
0e3b1f08  400063f        4 ....Contexts.Context  0 instance 05b20528 m_Context
0e3bd818  4000640        8 ....ExecutionContext  0 instance 01c4d2c8 m_ExecutionContext
0e3c0b24  4000641        c        System.String  0 instance 00000000 m_Name
0e3c0f88  4000642       10      System.Delegate  0 instance 00000000 m_Delegate
0e3ba220  4000643       14    System.Object[][]  0 instance 00000000 m_ThreadStaticsBuckets
0e3c2cc0  4000644       18       System.Int32[]  0 instance 00000000 m_ThreadStaticsBits
0e3c3720  4000645       1c ...ation.CultureInfo  0 instance 00000000 m_CurrentCulture
0e3c3720  4000646       20 ...ation.CultureInfo  0 instance 00000000 m_CurrentUICulture
0e3c0740  4000647       24        System.Object  0 instance 00000000 m_ThreadStartArg
0e3c33ec  4000648       28        System.IntPtr  1 instance  1915fa8 DONT_USE_InternalThread0e3c2d70  4000649       2c         System.Int32  1 instance        2 m_Priority
0e3c2d70  400064a       30         System.Int32  1 instance        5 m_ManagedThreadId0e399740  400064b      16c ...LocalDataStoreMgr  0   shared   static s_LocalDataStoreMgr

运行!threads命令来列出所有的线程，找到相应的线程(OS thread Id是dd4),

0:025> !threads
ThreadCount: 7UnstartedThread: 0BackgroundThread: 7PendingThread: 0DeadThread: 0Hosted Runtime: no
                                      PreEmptive   GC Alloc           Lock
       ID OSID ThreadOBJ    State     GC       Context       Domain   Count APT Exception   8    1 1400 018ad710      8220 Enabled  05baea40:05baf074 018ac928     0 Ukn  19    2 132c 018b8658      b220 Enabled  00000000:00000000 018ac928     0 MTA (Finalizer)  22    3 16ec 018d7718    80a220 Enabled  00000000:00000000 018ac928     0 MTA (Threadpool Completion Port)  23    4  830 018d7ee8      1220 Enabled  00000000:00000000 018ac928     0 Ukn  24    5  dd4 01915fa8   380b220 Enabled  01c57b44:01c58fe8 018d8590     1 MTA (Threadpool Worker)  25    6  444 01923d00   180b220 Disabled 01c4b604:01c4d008 018d8590     0 MTA (Threadpool Worker)  14    7  180 01933348   880a220 Enabled  00000000:00000000 018ac928     0 MTA (Threadpool Completion Port)

切换到有问题的线程，并列出调用堆栈。

0:025> ~~[dd4]s
eax=0000002d ebx=00000000 ecx=00004e20 edx=00000000 esi=0edced40 edi=00000000eip=777f96f4 esp=0edcecfc ebp=0edced64 iopl=0         nv up ei pl nz na po nc
cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000202ntdll!KiFastSystemCallRet:
777f96f4 c3              ret0:024> !clrstack
OS Thread Id: 0xdd4 (24)
ESP       EIP    
0edcee4c 777f96f4 [HelperMethodFrame: 0edcee4c] System.Threading.Thread.SleepInternal(Int32)0edceea0 015806e1 ASP.sleep_aspx.Page_Load(System.Object, System.EventArgs)
0edceedc 6d59a7ff System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)
0edceeec 62562544 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)
0edcef00 6255ba44 System.Web.UI.Control.OnLoad(System.EventArgs)
0edcef14 6255ba83 System.Web.UI.Control.LoadRecursive()
0edcef2c 62557b34 System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)
0edcf084 62557764 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)
0edcf0bc 62557691 System.Web.UI.Page.ProcessRequest()
0edcf0f4 62557626 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)
0edcf100 62557602 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)
0edcf114 01580455 ASP.sleep_aspx.ProcessRequest(System.Web.HttpContext)
0edcf118 6255dad6 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
0edcf14c 6253132c System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)
0edcf18c 62b2583f System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Exception)
0edcf190 62b1b96c [InlinedCallFrame: 0edcf190]0edcf230 62b06071 System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)
0edcf2a0 62bdb5e6 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
0edcf2a4 62bdb7d7 [InlinedCallFrame: 0edcf2a4]0edcf7f8 005522b4 [NDirectMethodFrameStandalone: 0edcf7f8] System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr, System.Web.RequestNotificationStatus ByRef)
0edcf808 62bdb67d System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)
0edcf88c 62bdb7d7 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)
0edcf98c 005522b4 [ContextTransitionFrame: 0edcf98c]

希望该示例对你有所帮助。

 

微软互联网开发支持专家

Leave a Reply