注:以下步骤适用于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]
希望该示例对你有所帮助。
微软互联网开发支持专家