How to troubleshoot HttpException Request timed out (ASP.NET 4.0 64-bit)

Rate This

APGC DSI Team

20 Jun 2012 8:09 PM

Comments 4

NOTE: The following steps apply to ASP.NET 4.0 (64 bit). They have not been tested in other versions of ASP.NET.

(For ASP.NET 2.0 32 bit, please refer to http://blogs.msdn.com/b/asiatech/archive/2011/07/06/how-to-troubleshoot-httpexception-request-timed-out-asp-net-2-0-32-bit.aspx )

Symptoms

========

The user may receive the following response intermittently:

Request timed out.

Description: An unhandled exception occurred during the execution of the current web request. Please review the stack trace for more information about the error and where it originated in the code.

Exception Details: System.Web.HttpException: Request timed out.

Source Error:

An unhandled exception was generated during the execution of the current web request. Information regarding the origin and location of the exception can be identified using the exception stack trace below.

Stack Trace:

[HttpException (0x80004005): Request timed out.]

The following warning may occur in application event logs:

Log Name: Application

Source: ASP.NET 4.0.30319.0

Event ID: 1309

Task Category: Web Event

Level: Warning

Keywords: Classic

User: N/A

Description:

Event code: 3001

Event message: The request has been aborted.

…

Application information:

…

Process information:

…

Process name: w3wp.exe

Account name: IIS APPPOOL\ASP.NET v4.0

Exception information:

Exception type: HttpException

Exception message: Request timed out.

Request information:

…

This kind of issue is typically occurs when the ASP.NET request executes for a period of time longer than the maximum timeout period allowed for server-side code execution.

This maximum timeout period can be set by executionTimeout attribute of httpRuntime element in config file. (The default value is 110 seconds in .Net 4.0)

How to reproduce

===============

Create an ASPX page named as sleep.aspx. It will sleep for 20 seconds:

<%@ Page Language="C#" %>

<%@ import Namespace="System.Diagnostics" %>

protected void Page_Load(object sender, EventArgs e)

{

DateTime time = DateTime.Now;

Response.Write(String.Format("Time: {0}:{1}:{2}", time.Hour, time.Minute, time.Second) +

"\tCurrent process: " + Process.GetCurrentProcess().Id.ToString());

Response.Write("<BR>");

Response.Write(String.Format("This application is running in {0}", System.Environment.Version.ToString()));

System.Threading.Thread.Sleep(20000);

}

</script>

<html>

<head>

<title>ASP.NET Simple Page</title>

</head>

</body>

</html>

Create a web.config and put it in the same folder as sleep.aspx. It sets the maximum timeout period to 5 seconds.

<?xml version="1.0" encoding="UTF-8"?>

<system.web>

</system.web>

</configuration>

Use your browser to access sleep.aspx and you will receive “[HttpException (0x80004005): Request timed out.]” error message after a while. The corresponded warning will also appear in application event log.

NOTE:

You may notice that this “[HttpException (0x80004005): Request timed out.]” error message may not immediately appear in 5 seconds. Internally ASP.NET uses a Timer (an instance of System.Threading.Timer) to invoke the request cancelation process. This timer is fired once every 15 seconds. Therefore in reality the request can timeout at any time between 5 seconds and 20 seconds.

Please refer to http://blogs.msdn.com/b/pedram/archive/2007/10/02/how-the-execution-timeout-is-managed-in-asp-net.aspx

How to Troubleshoot

===============

You can create a Debug Diagnostic 1.2 Performance rule to capture the dump files for the long running requests.

In this article I will introduce the steps to capture the dump file while “[HttpException (0x80004005): Request timed out.]” error occurs.

The typical *mistake* people may make is to configure a debugger to monitor HttpException and generate dump files while HttpException occurs.

In fact ASP.NET will throw ThreadAbortException when the request times out although it shows HttpException to the users.

It is not practicable to generate dump files for all ThreadAbortException. To troubleshoot this issue we have to set a breakpoint just before the ThreadAbortException is thrown. (Use ILSpy to check the code)

To set the breakpoint, we have to find out the offset address of the above breakpoint. (This offset may vary for different version of system.web.dll)

We can use Windbg shipped in Debugging Tools for Windows to attach to w3wp.exe (or open a hang dump file which was collected on that machine). Run the following commands:

0:040> .loadby sos clr

0:040> !name2ee system.web.dll System.Web.RequestTimeoutManager+RequestTimeoutEntry.TimeoutIfNeeded

Module: 000007fed56f1000

Assembly: System.Web.dll

Token: 0000000006002423

MethodDesc: 000007fed57bd248

Name: System.Web.RequestTimeoutManager+RequestTimeoutEntry.TimeoutIfNeeded(System.DateTime)

JITTED Code Address: 000007fed599b220

We can get the JITTED code address. Then disassembly the method and identify the breakpoint we need to set (highlighted):

0:040> !U 000007fed599b220

preJIT generated code

System.Web.RequestTimeoutManager+RequestTimeoutEntry.TimeoutIfNeeded(System.DateTime)

Begin 000007fed599b220, size 28. Cold region begin 000007fed6467e30, size 36

Hot region:

>>> 000007fe`d599b220 53 push rbx

000007fe`d599b221 57 push rdi

000007fe`d599b222 4883ec28 sub rsp,28h

000007fe`d599b226 488bd9 mov rbx,rcx

000007fe`d599b229 488b4b20 mov rcx,qword ptr [rbx+20h]

000007fe`d599b22d 803900 cmp byte ptr [rcx],0

000007fe`d599b230 e8db13f3ff call System.Web.HttpContext.MustTimeout(System.DateTime) (000007fe`d58cc610)

000007fe`d599b235 488bf8 mov rdi,rax

000007fe`d599b238 4885ff test rdi,rdi

000007fe`d599b23b 0f85efcbac00 jne System_Web_ni!System.Web.RequestTimeoutManager+RequestTimeoutEntry.TimeoutIfNeeded(System.DateTime)+0xaccc10 (000007fe`d6467e30)

000007fe`d599b241 4883c428 add rsp,28h

000007fe`d599b245 5f pop rdi

000007fe`d599b246 5b pop rbx

000007fe`d599b247 c3 ret

At first we want to set the breakpoint at the address 000007fe`d6467e30. However this address may vary in different process.

Therefore we choose the address 000007fe`d599b23b which has a static offset 1b from the method System.Web.RequestTimeoutManager+RequestTimeoutEntry.TimeoutIfNeeded(System.DateTime). But we only need to generate the dump file when the value of the register rdi is not null according to the following instruction:

000007fe`d599b238 4885ff test rdi,rdi

Save the following text as aspnet_timeout.cfg and put it under c:\.

<keyword Name="loadbysos"> .loadby sos clr</keyword>

<keyword Name="GetJIT"> !name2ee System.web.dll System.Web.RequestTimeoutManager+RequestTimeoutEntry.TimeoutIfNeeded </keyword>

<keyword Name="JITAddress"> .foreach /pS 0n13 ( record {!name2ee System.web.dll System.Web.RequestTimeoutManager+RequestTimeoutEntry.TimeoutIfNeeded}) { r $t1= ${record}; bp $t1+0x1b ".if @rdi {.dump /ma /u ${AdpDumpDirEsc}\\Full Request timed out ${AdpProcName}_.dmp;g} .else {g}"; .printf"*breakpoint list*\n"; bl} </keyword>

</KeyWords>

<Option> NoDumpOnFirst </Option>

<RunMode> CRASH </RunMode>

</Settings>

<DebugActions> loadbysos; GetJIT; JITAddress </DebugActions>

</PreCommands>

</ADPlus>

Open a command prompt with *elevated administrator privileges* and change the current directory to the folder where Debugging Tools for Windows is installed (The default location is %programfiles%\Debugging Tools for Windows (x64)

Run the command:

%windir%\system32\inetsrv\appcmd list wp

You will get the PID of the worker process for the problematic application pool.

Then run the following command:

adplus.exe -c c:\aspnet_timeout.cfg -o <output folder> -p <pid of problematic apppool>

Where <output foder> is the existing folder where you want to save the dump files

There will be one cdb.exe window popped up. Please keep this window running because it is monitoring the problematic application pool. If “Request timed out” occurs, it will automatically generate the dump files.

How to find out which operation causes “Request timed out” from dump files

=======================================================

Use windbg to open the dump file. Then load sos

0:036> .loadby sos clr

Dump all objects in the stack of the current thread. You will find System.Threading.Thread object:

0:036> !dso

OS Thread Id: 0x824 (36)

RSP/REG Object Name

rax 00000000ffbbd030 System.Threading.Thread

rbx 00000000ffbc42a8 System.Web.RequestTimeoutManager+RequestTimeoutEntry

rcx 00000000ffbbd700 System.Web.HttpContext

rsi 000000013fd14660 System.Web.RequestTimeoutManager

rdi 00000000ffbbd030 System.Threading.Thread

r12 00000000ffbb7630 System.Collections.ArrayList

0000000005B6E660 00000000ffbbd700 System.Web.HttpContext

0000000005B6E6C8 000000013fd14900 System.Web.Util.DoubleLinkList

0000000005B6E6D8 00000000ffbb7630 System.Collections.ArrayList

0000000005B6E708 00000000ffbb0248 System.Threading.ContextCallback

0000000005B6E710 000000013fd149b0 System.Threading._TimerCallback

0000000005B6E720 000000013fd14660 System.Web.RequestTimeoutManager

0000000005B6E730 000000013fd14660 System.Web.RequestTimeoutManager

0000000005B6E758 00000000ffbb0248 System.Threading.ContextCallback

0000000005B6E760 00000000ffbb75e8 System.Threading.ExecutionContext

0000000005B6E7C0 000000013fd149b0 System.Threading._TimerCallback

0000000005B6E7D0 000000013fd149b0 System.Threading._TimerCallback

0000000005B6E800 00000000ffbb75e8 System.Threading.ExecutionContext

0000000005B6E830 000000013fd149b0 System.Threading._TimerCallback

0000000005B6E848 000000013fd10e28 System.Threading.TimerBase

0000000005B6E9B8 00000000ffbb74d8 System.Collections.Hashtable+HashtableEnumerator

0000000005B6EA90 000000013fd149b0 System.Threading._TimerCallback

0000000005B6EA98 000000013fd149b0 System.Threading._TimerCallback

0000000005B6EB08 00000000ffbb00b0 System.Threading.ContextCallback

0000000005B6EB90 000000013fbca9f8 System.Threading._TimerCallback

Dump the information of System.Threading.Thread object and you will find the field DONT_USE_InternalThread:

0:036> !do 00000000ffbbd030

Name: System.Threading.Thread

MethodTable: 000007fef6e87208

EEClass: 000007fef6a0f050

Size: 88(0x58) bytes

File: C:\Windows\Microsoft.Net\assembly\GAC_64\mscorlib\v4.0_4.0.0.0__b77a5c561934e089\mscorlib.dll

Fields:

MT Field Offset Type VT Attr Value Name

000007fef6ed5bb0 400079a 8 ....Contexts.Context 0 instance 000000013fcb4758 m_Context

000007fef6ea9a28 400079b 10 ....ExecutionContext 0 instance 00000000ffbbe1b8 m_ExecutionContext

000007fef6e86738 400079c 18 System.String 0 instance 0000000000000000 m_Name

000007fef6e86f78 400079d 20 System.Delegate 0 instance 0000000000000000 m_Delegate

000007fef6e93c20 400079e 28 ...ation.CultureInfo 0 instance 0000000000000000 m_CurrentCulture

000007fef6e93c20 400079f 30 ...ation.CultureInfo 0 instance 0000000000000000 m_CurrentUICulture

000007fef6e85890 40007a0 38 System.Object 0 instance 0000000000000000 m_ThreadStartArg

000007fef6e93318 40007a1 40 System.IntPtr 1 instance 250e430 DONT_USE_InternalThread

000007fef6e8c620 40007a2 48 System.Int32 1 instance 2 m_Priority

000007fef6e8c620 40007a3 4c System.Int32 1 instance 10 m_ManagedThreadId

000007fef6eb6330 40007a4 318 ...LocalDataStoreMgr 0 shared static s_LocalDataStoreMgr

>> Domain:Value 000000000241e680:NotInit 00000000024d19c0:NotInit <<

000007fef6eaf4f8 40007a5 10 ...alDataStoreHolder 0 shared TLstatic s_LocalDataStore

>> Thread:Value <<

Run !threads command to list all threads and you will find the corresponded thread (whose OS thread Id is dd4) which causes “Request timed out”:

0:036> !threads

ThreadCount: 18

UnstartedThread: 0

BackgroundThread: 17

PendingThread: 0

DeadThread: 1

Hosted Runtime: no

PreEmptive Lock

ID OSID ThreadOBJ State GC GC Alloc Context Domain Count APT Exception

13 1 1158 000000000244d810 8220 Enabled 000000013fed0fb0:000000013fed1040 000000000241e680 0 Ukn

27 2 1e4 000000000246dc80 b220 Enabled 0000000000000000:0000000000000000 000000000241e680 0 MTA (Finalizer)

29 3 570 00000000024c10a0 100a220 Enabled 0000000000000000:0000000000000000 000000000241e680 0 MTA (Threadpool Worker)

30 4 1694 00000000024d2620 1220 Enabled 0000000000000000:0000000000000000 000000000241e680 0 Ukn

31 7 1b54 000000000251c460 8009220 Enabled 0000000000000000:0000000000000000 000000000241e680 0 MTA (Threadpool Completion Port)

17 6 d3c 0000000002515900 8008220 Enabled 0000000000000000:0000000000000000 000000000241e680 0 MTA (Threadpool Completion Port)

32 8 1574 0000000002523660 1009220 Enabled 000000017fc89968:000000017fc8afd0 000000000241e680 0 MTA (Threadpool Worker)

XXXX 9 000000000257b150 1019820 Enabled 0000000000000000:0000000000000000 000000000241e680 0 MTA (Threadpool Worker)

33 5 1428 000000000259b620 1009220 Enabled 00000000ffbb3910:00000000ffbb4fd0 000000000241e680 0 MTA (Threadpool Worker)

34 a 1108 000000000250e430 3009220 Enabled 000000015fbbbbc8:000000015fbbcfd0 00000000024d19c0 1 MTA (Threadpool Worker)

35 b 374 0000000002589260 1009220 Enabled 00000000ffbb5650:00000000ffbb6fd0 000000000241e680 0 MTA (Threadpool Worker)

36 c 824 00000000025603d0 1009220 Disabled 00000000ffbb7820:00000000ffbb8fd0 00000000024d19c0 0 MTA (Threadpool Worker)

37 d 14ac 000000000147e170 1009220 Enabled 00000000ffbb97b0:00000000ffbbafd0 000000000241e680 0 MTA (Threadpool Worker)

38 e 928 000000000147e880 1009220 Enabled 00000000ffbbb238:00000000ffbbcfd0 000000000241e680 0 MTA (Threadpool Worker)

5 f 1abc 0000000002412080 220 Enabled 00000000ffbb1988:00000000ffbb2fd0 000000000241e680 0 Ukn

39 10 1118 0000000002413b90 1009220 Enabled 00000000ffbc1478:00000000ffbc2fd0 000000000241e680 0 MTA (Threadpool Worker)

2 11 1a34 0000000001480a40 220 Enabled 00000000ffbbf158:00000000ffbc0fd0 000000000241e680 0 Ukn

40 12 1870 00000000025a0e60 1009220 Enabled 0000000000000000:0000000000000000 000000000241e680 0 MTA (Threadpool Worker)

Switch to the problematic thread and list the call stack. You will find the sleep function:

0:036> ~~[1108]s

ntdll!NtDelayExecution+0xa:

00000000`7720165a c3 ret

0:034> !clrstack

OS Thread Id: 0x1108 (34)

Child SP IP Call Site

00000000059cdf48 000000007720165a [HelperMethodFrame: 00000000059cdf48] System.Threading.Thread.SleepInternal(Int32)

00000000059ce070 000007ff001d064a ASP.sleep_aspx.Page_Load(System.Object, System.EventArgs)

00000000059ce0e0 000007fee1499c09 System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)

00000000059ce110 000007fedf018f57 System.Web.UI.Control.LoadRecursive()

00000000059ce160 000007fedf014a78 System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)

00000000059ce230 000007fedf013d51 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)

00000000059ce2a0 000007fedf013bfd System.Web.UI.Page.ProcessRequest()

00000000059ce330 000007fedf0129f7 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)

00000000059ce380 000007fedf01c4e1 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()

00000000059ce460 000007fedefe8f1e System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)

00000000059ce530 000007fedf779915 System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Exception)

00000000059ce5f0 000007fedf6a7455 System.Web.HttpApplication.BeginProcessRequestNotification(System.Web.HttpContext, System.AsyncCallback)

00000000059ce640 000007fedf687c76 System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)

00000000059ce6e0 000007fedf76b0af System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)

00000000059ce880 000007fedf76b962 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)

00000000059ce8d0 000007fedf7699e1 DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)

00000000059cf188 000007fef7f09c97 [NDirectMethodFrameStandalone: 00000000059cf188] System.Web.Hosting.UnsafeIISMethods.MgdIndicateCompletion(IntPtr, System.Web.RequestNotificationStatus ByRef)

00000000059cf150 000007fedf71c467 DomainNeutralILStubClass.IL_STUB_PInvoke(IntPtr, System.Web.RequestNotificationStatus ByRef)

00000000059cf220 000007fedf76b1e4 System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)

00000000059cf3c0 000007fedf76b962 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)

00000000059cf410 000007fedf7699e1 DomainNeutralILStubClass.IL_STUB_ReversePInvoke(Int64, Int64, Int64, Int32)

00000000059cf678 000007fef7f09efb [ContextTransitionFrame: 00000000059cf678]

Regards,

Xin Jin From APGC DSI Team