How to troubleshoot HttpException Request timed out (ASP NET 2 0 64-bit)


 

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

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

For ASP.NET 4.0 bit, please refer to http://blogs.msdn.com/b/asiatech/archive/2012/06/21/how-to-troubleshoot-httpexception-request-timed-out-asp-net-4-0-64-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:

 

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 2.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” %>

<script runat=”server”>

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 bgcolor=”#FFFFFF”>

<p><asp:label id=”Message” runat=”server” /></p>

</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″?>

<configuration>

<system.web>

<httpRuntime executionTimeout=”5“/>

</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:039> .loadby sos mscorwks

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

Module: 000007fee0f01000 (System.Web.dll)

Token: 0x00000000060008ef

MethodDesc: 000007fee10257c0

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

JITTED Code Address: 000007fee11e44d0

 

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

 

0:039> !U 000007fee11e44d0

preJIT generated code

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

Begin 000007fee11e44d0, size 29. Cold region begin 000007fee1c46370, size 34

Hot region:

>>> 000007fe`e11e44d0 53              push    rbx

000007fe`e11e44d1 57              push    rdi

000007fe`e11e44d2 4883ec28        sub     rsp,28h

000007fe`e11e44d6 488bd9          mov     rbx,rcx

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

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

000007fe`e11e44e0 e81b13f2ff      call    System.Web.HttpContext.MustTimeout(System.DateTime) (000007fe`e1105800)

000007fe`e11e44e5 488bf8          mov     rdi,rax

000007fe`e11e44e8 4885ff          test    rdi,rdi

000007fe`e11e44eb 0f857f1ea600    jne     System_Web_ni!System.Web.RequestTimeoutManager+RequestTimeoutEntry.TimeoutIfNeeded(System.DateTime)+0xa61ea0 (000007fe`e1c46370)

000007fe`e11e44f1 4883c428        add     rsp,28h

000007fe`e11e44f5 5f              pop     rdi

000007fe`e11e44f6 5b              pop     rbx

000007fe`e11e44f7 f3c3            rep ret

 

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

Therefore we choose the address 000007fe`e11e44eb 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`e11e44e8 4885ff          test    rdi,rdi

 

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

<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+RequestTimeoutEntry.TimeoutIfNeeded </keyword>

    <keyword Name=”JITAddress”> .foreach /pS 0n12 ( 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>

  <Settings>

                 <Option>  NoDumpOnFirst  </Option>

                 <RunMode> CRASH </RunMode>

 </Settings>

 <PreCommands>

        <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 folder> 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:039> .loadby sos mscorwks

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

0:039> !dso

OS Thread Id: 0x16a8 (39)

RSP/REG          Object           Name

rax              000000013ff77030 System.Threading.Thread

rbx              000000013ff78778 System.Web.RequestTimeoutManager+RequestTimeoutEntry

rsi              000000013fe7e880 System.Web.RequestTimeoutManager

rdi              000000013ff77030 System.Threading.Thread

r12              00000001bfe61098 System.Collections.ArrayList

0000000005f4e9b0 000000013ff773e0 System.Web.HttpContext

0000000005f4ea18 00000001bfe61098 System.Collections.ArrayList

0000000005f4ea28 000000013fe7eb20 System.Web.Util.DoubleLinkList

0000000005f4ea48 000000013ff73190 System.Threading.ContextCallback

0000000005f4ea58 000000013fe7ebd0 System.Threading._TimerCallback

0000000005f4ea60 00000001bfe60fe8 System.Threading.ExecutionContext

0000000005f4ea70 000000013fe7e880 System.Web.RequestTimeoutManager

0000000005f4ea98 000000013fe7ebd0 System.Threading._TimerCallback

0000000005f4eab0 00000001bfe60fe8 System.Threading.ExecutionContext

0000000005f4eb10 000000013fe7ebd0 System.Threading._TimerCallback

0000000005f4ed70 000000013fe7ebd0 System.Threading._TimerCallback

0000000005f4ed78 000000013fe7ebd0 System.Threading._TimerCallback

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

0:039> !do 000000013ff77030

Name: System.Threading.Thread

MethodTable: 000007fee0418830

EEClass: 000007fee001ea28

Size: 104(0x68) bytes

 (C:\Windows\assembly\GAC_64\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)

Fields:

              MT    Field   Offset                 Type VT     Attr            Value Name

000007fee0450320  4000691        8 ….Contexts.Context  0 instance 000000013fe609d0 m_Context

000007fee0412d40  4000692       10 ….ExecutionContext  0 instance 000000013ff782f8 m_ExecutionContext

000007fee0417d90  4000693       18        System.String  0 instance 0000000000000000 m_Name

000007fee04185a8  4000694       20      System.Delegate  0 instance 0000000000000000 m_Delegate

000007fee040f150  4000695       28    System.Object[][]  0 instance 0000000000000000 m_ThreadStaticsBuckets

000007fee041eeb0  4000696       30       System.Int32[]  0 instance 0000000000000000 m_ThreadStaticsBits

000007fee0420710  4000697       38 …ation.CultureInfo  0 instance 0000000000000000 m_CurrentCulture

000007fee0420710  4000698       40 …ation.CultureInfo  0 instance 0000000000000000 m_CurrentUICulture

000007fee0417680  4000699       48        System.Object  0 instance 0000000000000000 m_ThreadStartArg

000007fee041a798  400069a       50        System.IntPtr  1 instance          23f7930 DONT_USE_InternalThread

000007fee041f000  400069b       58         System.Int32  1 instance                2 m_Priority

000007fee041f000  400069c       5c         System.Int32  1 instance               10 m_ManagedThreadId

000007fee040ca48  400069d      2d8 …LocalDataStoreMgr  0   shared           static s_LocalDataStoreMgr

                                 >> Domain:Value  0000000002308550:0000000000000000 000000000237d530:0000000000000000 <<

000007fee0417680  400069e      2e0        System.Object  0   shared           static s_SyncObject

                                 >> Domain:Value  0000000002308550:00000000ffe644f8 000000000237d530:000000013fe723a0 <<

 

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

0:039> !threads

ThreadCount: 20

UnstartedThread: 6

BackgroundThread: 14

PendingThread: 6

DeadThread: 0

Hosted Runtime: no

                                              PreEmptive                                                Lock

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

  12    1 1358 000000000232b130      8220 Enabled  000000011fe721a0:000000011fe73008 0000000002308550     0 Ukn

  31    2 1138 0000000002342770      b220 Enabled  0000000000000000:0000000000000000 0000000002308550     0 MTA (Finalizer)

  32    3 1764 0000000002377e00    80a220 Enabled  0000000000000000:0000000000000000 0000000002308550     0 MTA (Threadpool Completion Port)

  33    4 154c 000000000237ca80      1220 Enabled  0000000000000000:0000000000000000 0000000002308550     0 Ukn

  34    5 14e0 00000000023e5430   180b220 Enabled  00000000fff9eee0:00000000fff9f008 0000000002308550     0 MTA (Threadpool Worker)

  35    6 120c 00000000023f31c0   180b220 Enabled  000000013ff73d50:000000013ff74fd0 0000000002308550     0 MTA (Threadpool Worker)

  21    7 1918 00000000023f9a20   880a220 Enabled  0000000000000000:0000000000000000 0000000002308550     0 MTA (Threadpool Completion Port)

   4    8  f94 000000000240ae60       220 Enabled  000000013ff753c8:000000013ff76fd0 0000000002308550     0 Ukn

  37    9 15d4 0000000002409260   180b220 Enabled  000000015fe602f0:000000015fe60fd0 0000000002308550     0 MTA (Threadpool Worker)

  38    a 1bb0 00000000023f7930   380b220 Enabled  000000019fe893c8:000000019fe8b008 000000000237d530     1 MTA (Threadpool Worker)

  39    b 16a8 00000000023f83e0   180b220 Disabled 00000001bfe61288:00000001bfe62fd0 000000000237d530     0 MTA (Threadpool Worker)

  40    c  1e0 00000000022f1640   180b220 Enabled  00000001bfe60238:00000001bfe60fd0 0000000002308550     0 MTA (Threadpool Worker)

  41    d 160c 00000000022f20f0   180b220 Enabled  00000000fff9f700:00000000fffa0fd0 0000000002308550     0 MTA (Threadpool Worker)

  42    e 12f0 00000000022dff20   180b220 Enabled  00000000fffa11b8:00000000fffa2fd0 0000000002308550     0 MTA (Threadpool Worker)

  44    f 1168 00000000023e4cf0      1400 Enabled  0000000000000000:0000000000000000 0000000002308550     0 Ukn

  45   10 17e0 00000000022e0eb0      1400 Enabled  0000000000000000:0000000000000000 0000000002308550     0 Ukn

  46   11 12f8 00000000022eb470      1400 Enabled  0000000000000000:0000000000000000 0000000002308550     0 Ukn

  47   12  dd8 00000000022ebf20      1400 Enabled  0000000000000000:0000000000000000 0000000002308550     0 Ukn

  48   13 17b0 00000000022ec9d0      1400 Enabled  0000000000000000:0000000000000000 0000000002308550     0 Ukn

  49   14 1a88 00000000022ed480      1400 Enabled  0000000000000000:0000000000000000 0000000002308550     0 Ukn

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

0:039> ~~[1bb0]s

ntdll!NtDelayExecution+0xa:

00000000`779115fa c3              ret

0:038> !clrstack

OS Thread Id: 0x1bb0 (38)

Child-SP         RetAddr          Call Site

0000000005dadb70 000007fee59d3ec9 ASP.sleep_aspx.Page_Load(System.Object, System.EventArgs)

0000000005dadc10 000007fee11a9d4a System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)

0000000005dadc40 000007fee11a0504 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)

0000000005dadc70 000007fee11a0562 System.Web.UI.Control.OnLoad(System.EventArgs)

0000000005dadcb0 000007fee119caec System.Web.UI.Control.LoadRecursive()

0000000005dadd00 000007fee119bff0 System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)

0000000005daddd0 000007fee119bf1b System.Web.UI.Page.ProcessRequest(Boolean, Boolean)

0000000005dade30 000007fee119beb0 System.Web.UI.Page.ProcessRequest()

0000000005dade90 000007ff001b0219 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)

0000000005dadef0 000007fee11a3357 ASP.sleep_aspx.ProcessRequest(System.Web.HttpContext)

0000000005dadf20 000007fee116671b System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()

0000000005dadfd0 000007fee1853971 System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)

0000000005dae070 000007fee18443b2 System.Web.HttpApplication+PipelineStepManager.ResumeSteps(System.Exception)

0000000005dae200 000007fee1825df9 System.Web.HttpApplication.BeginProcessRequestNotification(System.Web.HttpContext, System.AsyncCallback)

0000000005dae250 000007fee194dde1 System.Web.HttpRuntime.ProcessRequestNotificationPrivate(System.Web.Hosting.IIS7WorkerRequest, System.Web.HttpContext)

0000000005dae370 000007fee194d9ab System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)

0000000005dae4f0 000007fee194cc14 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)

0000000005dae550 000007fee632afaa DomainNeutralILStubClass.IL_STUB(Int64, Int64, Int64, Int32)

0000000005daed80 000007fee194df10 DomainNeutralILStubClass.IL_STUB(IntPtr, System.Web.RequestNotificationStatus ByRef)

0000000005daee60 000007fee194d9ab System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr, IntPtr, IntPtr, Int32)

0000000005daefe0 000007fee194cc14 System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr, IntPtr, IntPtr, Int32)

0000000005daf040 000007fee632b1fb DomainNeutralILStubClass.IL_STUB(Int64, Int64, Int64, Int32)

 

Regards,

Xin Jin from DSI Team

 

 

 

 

Comments (4)

  1. Jeff says:

    I don't understand how you get the 1b from 000007fe`e11e44eb

    what I see is:

    000007fe`f0216088 4885ff          test    rdi,rdi

    000007fef021608b 0f85cf2ea700 &nbsp; &nbsp;jne &nbsp; &nbsp; System_Web_ni+0xd58f60 (000007fef0c88f60)

    in this case, what is the static offset and why?

    Thanks.

Skip to main content