Symptoms

========

My customer receives 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.]

 

This issue 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.  

My customer knows it will take 5 minutes to execute his ASP.NET page because the page needs to retrieve large data from database to generate a report. Therefore he has already set the value of executionTimeout attribute of httpRuntime element to 600 seconds in web.config. However he still receives HttpException “Request timed out” error while the ASP.NET page executes for 2 or 3 minutes.

 

 

How to Troubleshoot

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

I used the instructions in my blog article “How to troubleshoot HttpException Request timed out (ASP.NET 2.0 32-bit)” to create a dump file while the error occurs.

 

Use windbg to open the dump file. Then load sos

 0:018> .loadby sos mscorwks

 

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

0:018> !dso

OS Thread Id: 0x1f50 (18)

ESP/REG  Object   Name

eax      028c1a64 System.Threading.Thread

ebx      028c1a64 System.Threading.Thread

ecx      029cab2c System.Web.RequestTimeoutManager+RequestTimeoutEntry

esi      029cab2c System.Web.RequestTimeoutManager+RequestTimeoutEntry

0257f5dc 028fa520 System.Web.Util.DoubleLinkList

0257f5e0 02a67d68 System.Collections.ArrayList

0257f5e4 028fa3c8 System.Web.RequestTimeoutManager

0257f604 02a46294 System.Threading.ContextCallback

0257f608 028fa3c8 System.Web.RequestTimeoutManager

0257f630 028fa2b8 System.Web.HttpRuntime

0257f64c 02a671a0 System.Threading._ThreadPoolWaitCallback

0257f65c 028fa2b8 System.Web.HttpRuntime

0257f674 02a46294 System.Threading.ContextCallback

0257f678 02a671a0 System.Threading._ThreadPoolWaitCallback

0257f688 02a671b8 System.Threading.ExecutionContext

0257f694 02a671a0 System.Threading._ThreadPoolWaitCallback

0257f698 02a671b8 System.Threading.ExecutionContext

0257f6a4 02a671a0 System.Threading._ThreadPoolWaitCallback

0257f6ac 02a671a0 System.Threading._ThreadPoolWaitCallback

 

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

0:018> !do 028c1a64

Name: System.Threading.Thread

MethodTable: 048e1240

EEClass: 0469d994

Size: 56(0x38) bytes

 (C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)

Fields:

      MT    Field   Offset                 Type VT     Attr    Value Name

048d2050  400063f        4 ....Contexts.Context  0 instance 028d3d74 m_Context

048dd960  4000640        8 ....ExecutionContext  0 instance 029b5e74 m_ExecutionContext

048e0c6c  4000641        c        System.String  0 instance 00000000 m_Name

048e10d0  4000642       10      System.Delegate  0 instance 00000000 m_Delegate

048da368  4000643       14    System.Object[][]  0 instance 028f74ec m_ThreadStaticsBuckets

048e2e08  4000644       18       System.Int32[]  0 instance 028f7590 m_ThreadStaticsBits

048e3868  4000645       1c ...ation.CultureInfo  0 instance 028d440c m_CurrentCulture

048e3868  4000646       20 ...ation.CultureInfo  0 instance 028d440c m_CurrentUICulture

048e0888  4000647       24        System.Object  0 instance 00000000 m_ThreadStartArg

048e3534  4000648       28        System.IntPtr  1 instance   159a68 DONT_USE_InternalThread

048e2eb8  4000649       2c         System.Int32  1 instance        2 m_Priority

048e2eb8  400064a       30         System.Int32  1 instance        9 m_ManagedThreadId

048b9888  400064b      16c ...LocalDataStoreMgr  0   shared   static s_LocalDataStoreMgr

    >> Domain:Value  000d7f80:00000000 00106020:00000000 000e1a08:00000000 0015d670:00000000 <<

048e0888  400064c      170        System.Object  0   shared   static s_SyncObject

    >> Domain:Value  000d7f80:02673260 00106020:0268f5e8 000e1a08:027361a8 0015d670:028f74e0 <<

 

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

0:018> !threads

ThreadCount: 11

UnstartedThread: 0

BackgroundThread: 7

PendingThread: 0

DeadThread: 4

Hosted Runtime: no

                                      PreEmptive   GC Alloc           Lock

       ID OSID ThreadOBJ    State     GC       Context       Domain   Count APT Exception

XXXX    1    0 000dfa78   1808820 Enabled  00000000:00000000 000d7f80     0 MTA (Threadpool Worker)

  13    2 1bf4 000eb758      b220 Enabled  00000000:00000000 000d7f80     0 MTA (Finalizer)

  14    3 1a1c 00102678    80a220 Enabled  00000000:00000000 000d7f80     0 MTA (Threadpool Completion Port)

  15    4 1d38 001058e0      1220 Enabled  00000000:00000000 000d7f80     0 Ukn

  10    5 18cc 00136bb8   880a220 Enabled  00000000:00000000 000d7f80     0 MTA (Threadpool Completion Port)

XXXX    6    0 00137bc8   1801820 Enabled  00000000:00000000 000d7f80     0 Ukn (Threadpool Worker)

XXXX    7    0 001386d0   1801820 Enabled  00000000:00000000 000d7f80     0 Ukn (Threadpool Worker)

XXXX    8    0 00158b08   1801820 Enabled  00000000:00000000 000d7f80     0 Ukn (Threadpool Worker)

  16    9 1db8 00159a68   380b220 Enabled  00000000:00000000 0015d670     1 MTA (Threadpool Worker)

  18    a 1f50 00169f38   180b220 Disabled 00000000:00000000 0015d670     0 MTA (Threadpool Worker)

  19    b 1aec 0016b400   180b220 Enabled  00000000:00000000 000d7f80     0 MTA (Threadpool Worker)

 

Switch to the problematic thread and list the call stack. You will find Default.aspx is waiting in the sleep function:

0:018> ~~[1db8]s

eax=0000000f ebx=00000000 ecx=02419634 edx=02414e14 esi=00000000 edi=00deefc4

eip=7c82845c esp=00deef84 ebp=00deefec iopl=0         nv up ei pl nz na po nc

cs=001b  ss=0023  ds=0023  es=0023  fs=003b  gs=0000             efl=00000202

ntdll!KiFastSystemCallRet:

7c82845c c3              ret

0:016> !clrstack

OS Thread Id: 0x1db8 (16)

ESP       EIP    

00def0d4 7c82845c [HelperMethodFrame: 00def0d4] System.Threading.Thread.SleepInternal(Int32)

00def128 024c03a1 ASP.default_aspx.Page_Load(System.Object, System.EventArgs)

00def164 66f2a7ff System.Web.Util.CalliHelper.EventArgFunctionCaller(IntPtr, System.Object, System.Object, System.EventArgs)

00def174 660b4cc4 System.Web.Util.CalliEventHandlerDelegateProxy.Callback(System.Object, System.EventArgs)

00def188 660ae1c4 System.Web.UI.Control.OnLoad(System.EventArgs)

00def19c 660ae203 System.Web.UI.Control.LoadRecursive()

00def1b4 660aa2b4 System.Web.UI.Page.ProcessRequestMain(Boolean, Boolean)

00def30c 660a9ee4 System.Web.UI.Page.ProcessRequest(Boolean, Boolean)

00def344 660a9e11 System.Web.UI.Page.ProcessRequest()

00def37c 660a9da6 System.Web.UI.Page.ProcessRequestWithNoAssert(System.Web.HttpContext)

00def388 660a9d82 System.Web.UI.Page.ProcessRequest(System.Web.HttpContext)

00def39c 024c0115 ASP.default_aspx.ProcessRequest(System.Web.HttpContext)

00def3a0 660b0256 System.Web.HttpApplication+CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()

00def3d4 6608332c System.Web.HttpApplication.ExecuteStep(IExecutionStep, Boolean ByRef)

00def414 6608eb83 System.Web.HttpApplication+ApplicationStepManager.ResumeSteps(System.Exception)

00def464 660828ac System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext, System.AsyncCallback, System.Object)

00def480 66085e1c System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest)

00def4b4 66085ac3 System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest)

00def4c4 66084c5c System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)

 

However in this scenario, ASP.NET page only executes for about 2 minutes before executionTimeout (10 minutes) is reached. Why does HttpException “Request timed out” error still occurs?

Let us go back to check the thread which triggered ThreadAbortException:

0:018> !clrstack

OS Thread Id: 0x1f50 (18)

ESP       EIP    

0257f5dc 660e0732 System.Web.RequestTimeoutManager.CancelTimedOutRequests(System.DateTime)

0257f620 668e8433 System.Web.RequestTimeoutManager.Stop()

0257f63c 6606f756 System.Web.HttpRuntime.Dispose()

0257f65c 6606f635 System.Web.HttpRuntime.ReleaseResourcesAndUnloadAppDomain(System.Object)

0257f688 0487a09f System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(System.Object)

0257f690 0489043f System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)

0257f6a8 0487a603 System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(System.Threading._ThreadPoolWaitCallback)

0257f6bc 0487a499 System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(System.Object)

0257f84c 79e71b4c [GCFrame: 0257f84c]

 

The above call stack seemed to be unloading AppDomain, that is different from the call stack which appears for the real “timed out” issue (see below)

0246f7cc 660e0732 System.Web.RequestTimeoutManager.CancelTimedOutRequests(System.DateTime)

0246f810 66094d4c System.Web.RequestTimeoutManager.TimerCompletionCallback(System.Object)

0246f824 048584bf System.Threading._TimerCallback.TimerCallback_Context(System.Object)

0246f82c 0489043f System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object)

0246f844 0485842b System.Threading._TimerCallback.PerformTimerCallback(System.Object)

 

Use ILSpy to check  System.Web.RequestTimeoutManager.Stop code.  This method will add 1 year to the current time and then pass it to CancelTimedOutRequests method.

// System.Web.RequestTimeoutManager
internal void Stop()
{
    if (this._timer !null)
    {
        ((IDisposable)this._timer).Dispose();
        this._timer = null;
    }
    while (this._inProgressLock !0)
    {
        Thread.Sleep(100);
    }
    if (this._requestCount > 0)
    {
        this.CancelTimedOutRequests(DateTime.UtcNow.AddYears(1));
    }
}

 

Therefore the request appears “timed out” if the current time is “next year”.

Now I need to find out why System.Web.RequestTimeoutManager.Stop was called. Based on the method name System.Web.HttpRuntime.ReleaseResourcesAndUnloadAppDomain, it seems that AppDomain was being unloaded.

I check the System.Web.HttpRuntime object in the stack:

0:018> !do 028fa2b8

Name: System.Web.HttpRuntime

MethodTable: 66149e70

EEClass: 65f4d534

Size: 152(0x98) bytes

 (C:\WINDOWS\assembly\GAC_32\System.Web\2.0.0.0__b03f5f7f11d50a3a\System.Web.dll)

Fields:

      MT    Field   Offset                 Type VT     Attr    Value Name

048cedac  4001106        4 ...amedPermissionSet  0 instance 00000000 _namedPermissionSet

6614a068  4001107        8 ...ileChangesMonitor  0 instance 028fb100 _fcm

6614b4b0  4001108        c ...ing.CacheInternal  0 instance 028fe65c _cacheInternal

6614b5a8  4001109       10 ...Web.Caching.Cache  0 instance 028fe588 _cachePublic

048b4738  400110a       74       System.Boolean  1 instance        0 _isOnUNCShare

66149efc  400110b       14 ...Web.Util.Profiler  0 instance 028fa350 _profiler

66149f44  400110c       18 ...estTimeoutManager  0 instance 028fa3c8 _timeoutManager

66151b78  400110d       1c ....Web.RequestQueue  0 instance 029a1970 _requestQueue

048b4738  400110e       75       System.Boolean  1 instance        0 _apartmentThreading

048b4738  400110f       76       System.Boolean  1 instance        1 _processRequestInApplicationTrust

048b4738  4001110       77       System.Boolean  1 instance        0 _beforeFirstRequest

048b82cc  4001111       84      System.DateTime  1 instance 028fa33c _firstRequestStartTime

048b4738  4001112       78       System.Boolean  1 instance        0 _firstRequestCompleted

048b4738  4001113       79       System.Boolean  1 instance        1 _userForcedShutdown

048b4738  4001114       7a       System.Boolean  1 instance        1 _configInited

048b4738  4001115       7b       System.Boolean  1 instance        1 _fusionInited

048e2eb8  4001116       6c         System.Int32  1 instance        1 _activeRequestCount

048b82cc  4001117       8c      System.DateTime  1 instance 028fa344 _lastShutdownAttemptTime

048b4738  4001118       7c       System.Boolean  1 instance        1 _shutdownInProgress

048e0c6c  4001119       20        System.String  0 instance 02a49348 _shutDownStack

048e0c6c  400111a       24        System.String  0 instance 02a67038 _shutDownMessage

6612b95c  400111b       70         System.Int32  1 instance        3 _shutdownReason

048e0c6c  400111c       28        System.String  0 instance 0295e494 _trustLevel

048e0c6c  400111d       2c        System.String  0 instance 028fa9b0 _wpUserId

048b4738  400111e       7d       System.Boolean  1 instance        1 _shutdownWebEventRaised

048b4738  400111f       7e       System.Boolean  1 instance        1 _enableHeaderChecking

048cf9f0  4001120       30 System.AsyncCallback  0 instance 028fa9fc _requestNotificationCompletionCallback

048cf9f0  4001121       34 System.AsyncCallback  0 instance 028faa1c _handlerCompletionCallback

66149fe4  4001122       38 ...fSendNotification  0 instance 028faa3c _asyncEndOfSendCallback

048cebcc  4001123       3c ...ding.WaitCallback  0 instance 028faa5c _appDomainUnloadallback

048e0e00  4001124       40     System.Exception  0 instance 00000000 _initializationError

048b4738  4001125       7f       System.Boolean  1 instance        0 _hostingInitFailed

048c72a8  4001126       44 ...m.Threading.Timer  0 instance 00000000 _appDomainShutdownTimer

048e0c6c  4001127       48        System.String  0 instance 029710fc _tempDir

048e0c6c  4001128       4c        System.String  0 instance 02971fd4 _codegenDir

048e0c6c  4001129       50        System.String  0 instance 028d3354 _appDomainAppId

048e0c6c  400112a       54        System.String  0 instance 028d3398 _appDomainAppPath

6614a32c  400112b       58 ...m.Web.VirtualPath  0 instance 028fb0d8 _appDomainAppVPath

048e0c6c  400112c       5c        System.String  0 instance 028d34e4 _appDomainId

048b4738  400112d       80       System.Boolean  1 instance        0 _debuggingEnabled

048e36dc  400112e       60        System.Byte[]  0 instance 00000000 _appOfflineMessage

048e0c6c  400112f       64        System.String  0 instance 00000000 _clientScriptVirtualPath

048e0c6c  4001130       68        System.String  0 instance 00000000 _clientScriptPhysicalPath

66149e70  40010ff       fc ...m.Web.HttpRuntime  0   shared   static _theRuntime

    >> Domain:Value  000d7f80:02673dfc 00106020:02691b94 000e1a08:0273912c 0015d670:028fa2b8 <<

048e36dc  4001100      100        System.Byte[]  0   shared   static s_autogenKeys

    >> Domain:Value  000d7f80:02673a74 00106020:02691970 000e1a08:02738d2c 0015d670:028f9eb8 <<

048e0c6c  4001101      104        System.String  0   shared   static DirectorySeparatorString

    >> Domain:Value  000d7f80:02673ad8 00106020:02691adc 000e1a08:02738e98 0015d670:028fa024 <<

048e0c6c  4001102      108        System.String  0   shared   static DoubleDirectorySeparatorString

    >> Domain:Value  000d7f80:02673aec 00106020:02691af0 000e1a08:02738eac 0015d670:028fa038 <<

048b4738  4001103      7ec       System.Boolean  1   shared   static s_initialized

    >> Domain:Value  000d7f80:1 00106020:1 000e1a08:1 0015d670:1 <<

048e0c6c  4001104      10c        System.String  0   shared   static s_installDirectory

    >> Domain:Value  000d7f80:02673d68 00106020:02691b14 000e1a08:02738ee8 0015d670:028fa074 <<

048b4738  4001105      7f0       System.Boolean  1   shared   static s_isEngineLoaded

    >> Domain:Value  000d7f80:1 00106020:1 000e1a08:1 0015d670:1 <<

048b4738  4001131      7f4       System.Boolean  1   shared   static _useIntegratedPipeline

    >> Domain:Value  000d7f80:0 00106020:0 000e1a08:0 0015d670:0 <<

6614772c  4001132      110 ...nloadEventHandler  0   shared   static AppDomainShutdown

    >> Domain:Value  000d7f80:00000000 00106020:00000000 000e1a08:00000000 0015d670:00000000 <<

66113ca4  4001133      114 ....FactoryGenerator  0   shared   static s_factoryGenerator

    >> Domain:Value  000d7f80:00000000 00106020:00000000 000e1a08:00000000 0015d670:00000000 <<

048e32c0  4001134      118 ...ections.Hashtable  0   shared   static s_factoryCache

    >> Domain:Value  000d7f80:00000000 00106020:00000000 000e1a08:00000000 0015d670:00000000 <<

048b4738  4001135      7f8       System.Boolean  1   shared   static s_initializedFactory

    >> Domain:Value  000d7f80:0 00106020:0 000e1a08:0 0015d670:0 <<

048e0888  4001136      11c        System.Object  0   shared   static s_factoryLock

    >> Domain:Value  000d7f80:02673b04 00106020:02691b08 000e1a08:02738ec4 0015d670:028fa050 <<

 

Based on the field _shutdownInProgress I get to know that AppDomain was being shut down. The shutdown message is:

0:018> !do -nofields 02a67038

Name: System.String

MethodTable: 048e0c6c

EEClass: 0469d65c

Size: 194(0xc2) bytes

 (C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)

String: Directory rename change notification for 'C:\Inetpub\wwwroot\Test'.

Test dir change or directory rename

Directory rename change notification for 'C:\Inetpub\wwwroot\Test'.

Test dir change or directory rename

HostingEnvironment initiated shutdown

HostingEnvironment caused shutdown

Directory rename change notification for 'C:\Inetpub\wwwroot\Test'.

Test dir change or directory rename

 

The call stack is:

0:018> !do -nofields 02a49348

Name: System.String

MethodTable: 048e0c6c

EEClass: 0469d65c

Size: 4098(0x1002) bytes

 (C:\WINDOWS\assembly\GAC_32\mscorlib\2.0.0.0__b77a5c561934e089\mscorlib.dll)

String:    at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)

   at System.Environment.get_StackTrace()

   at System.Web.Hosting.HostingEnvironment.InitiateShutdownInternal()

   at System.Web.Hosting.HostingEnvironment.InitiateShutdown()

   at System.Web.HttpRuntime.ShutdownAppDomain(String stackTrace)

   at System.Web.HttpRuntime.OnCriticalDirectoryChange(Object sender, FileChangeEvent e)

   at System.Web.FileChangesMonitor.OnSubdirChange(Object sender, FileChangeEvent e)

   at System.Web.DirectoryMonitor.FireNotifications()

   at System.Web.Util.WorkItem.CallCallbackWithAssert(WorkItemCallback callback)

   at System.Web.Util.WorkItem.OnQueueUserWorkItemCompletion(Object state)

   at System.Threading._ThreadPoolWaitCallback.WaitCallback_Context(Object state)

   at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)

   at System.Threading._ThreadPoolWaitCallback.PerformWaitCallbackInternal(_ThreadPoolWaitCallback tpWaitCallBack)

   at System.Threading._ThreadPoolWaitCallback.PerformWaitCallback(Object state)

 

The application sub-directories were being deleted (see Todd’s blog for more info), that caused ASP.NET to shutdown AppDomain, that in turn “timed out” the executing requests.

In my real case the customer’s application created and deleted temporary folders under the application directory.

 

Regards,

 

Xinjin from APAC DSI Team