The strange case of the Application Pool recycling causing high CPU

Posted On March 12, 2015

 

This case came as a performance issue. Exchange Web Services stopped responding and CPU skyrocketed. The Exchange team captured a manual dump file and tried in vain to recycle the application. The problem was eventually resolved by invoking a full IISRESET. I was added to the case to help identify why the problem was happening. Root cause analysis is not an exact science and there always chance we can never uncover the root cause. Anyway, this case is a good case study of techniques to find why an IIS worker process is hanging.

This case study uses WinDbg with NetExt extension. See this to get started with WinDbg and NetExt:  http://blogs.msdn.com/b/rodneyviana/archive/2015/03/10/getting-started-with-netext.aspx

Finding out how many web applications are running under the worker process

IIS creates a .NET application domain for each web application under the application pool. All .NET processes contain at least 3 domains: System, Shared and the Default Domain. IIS is no different than any .NET application in this aspect and it creates a .NET application domain for each web application. In a nutshell if you enumerate the application domains and subtract by 3 you will know the number of web applications.

0:139> !wdomain
Address          Domain Name                            Modules Base Path & Config
000007fef1525830 System                                      32
000007fef1524f30 Shared                                        
00000000022da5d0 DefaultDomain                               13  c:\windows\system32\inetsrv\ Config: w3wp.exe.config
000000001b8faf90 /LM/W3SVC/1/ROOT/EWS-344-130700513249237468 55 Base Path: D:\…\exchweb\EWS\ Config: web.config
00000000307b7cf0 /LM/W3SVC/1/ROOT/EWS-562-130700529762725531 47 Base Path: D:\…\exchweb\EWS\ Config: web.config
00000000223a9ce0 /LM/W3SVC/1/ROOT/EWS-563-130700529926161985 16 Base Path: D:\…\exchweb\EWS\ Config: web.config
000000001bd40690 /LM/W3SVC/1/ROOT/EWS-347-130700513519079491 61 Base Path: D:\…\exchweb\EWS\ Config: web.config
00000000287a2b20 /LM/W3SVC/1/ROOT/EWS-558-130700528987261744 55 Base Path: D:\…\exchweb\EWS\ Config: web.config
0000000016b3e7b0 /LM/W3SVC/1/ROOT/EWS-114-130700499138390278 57 Base Path: D:\…\exchweb\EWS\ Config: web.config
000000001bd42cd0 /LM/W3SVC/1/ROOT/EWS-557-130700528916324698 55 Base Path: D:\…\exchweb\EWS\ Config: web.config
000000001b81fbc0 /LM/W3SVC/1/ROOT/EWS-406-130700518599046979 59 Base Path: D:\…\exchweb\EWS\ Config: web.config
00000000307b7360 /LM/W3SVC/1/ROOT/EWS-561-130700529146479475 57 Base Path: D:\…\exchweb\EWS\ Config: web.config

So, there are 9 web applications running in this process and as they point to the same Base Path, they have to respond to different URLs (which in this case were set apart via host names).

Finding the running requests ordered by time

Dumping the HttpContext that are still running or waiting to run, we found that there were 364 pending requests waiting to be served. The URLs were modified to protect customer’s privacy.

0:139> !whttp -order -running
HttpContext      Start Time      Thread Time Out Running  Status Verb     Url
000000017ff2b0e0 3/5/2015 5:25:20 PM — 03:14:07 00:51:15    200 POST     http://intra.contoso.com:80/ews/exchange.asmx
000000011ff352b8 3/5/2015 5:25:20 PM — 03:14:07 00:51:15    200 POST     http://intra.contoso.com:80/ews/exchange.asmx
000000013ff08df8 3/5/2015 5:25:20 PM — 03:14:07 00:51:15    200 POST     http://exmail.contoso.com:80/EWS/Exchange.asmx
000000013ff09ff0 3/5/2015 5:25:20 PM — 03:14:07 00:51:15    200 POST     http://exmail.contoso.com:80/EWS/Exchange.asmx
000000015ffc2ac8 3/5/2015 5:25:20 PM — 03:14:07 00:51:15    200 POST     http://intra.contoso.com:80/ews/exchange.asmx
000000017ff2f0e8 3/5/2015 5:25:20 PM — 03:14:07 00:51:15    200 POST     http://exmail.contoso.com:80/EWS/Exchange.asmx
(…. lines removed for brevity …)
00000001836f03d8 3/5/2015 6:16:32 PM — 03:14:07 00:00:03    200 POST     http://exmail.contoso.com:80/EWS/Exchange.asmx
00000001a20df278 3/5/2015 6:16:32 PM — 03:14:07 00:00:03    200 POST     http://intra.contoso.com:80/ews/exchange.asmx
00000001e414e290 3/5/2015 6:16:32 PM — 03:14:07 00:00:03    200 POST     http://exmail.contoso.com:80/ews/Exchange.asmx
00000001e4156290 3/5/2015 6:16:32 PM — 03:14:07 00:00:03    200 POST     http://intra.contoso.com:80/ews/exchange.asmx
00000001e415e290 3/5/2015 6:16:32 PM — 03:14:07 00:00:03    200 POST     http://intra.contoso.com:80/ews/exchange.asmx

364 HttpContext object(s) found matching criteria
117 HttpContext object(s) skipped by filter

You may also be interested in
================================
Dump HttpRuntime info: !wruntime

Notice that instead of a thread number we see “—“. This mean that a thread could not be created in IIS to server the request. This situation is all across the board. All pending requests are queued and some are this way for almost an hour. Notice that the request time out is very high so it will take a long, long time to kick in. We can also see that there are request as soon as 3 seconds ago, so IIS is still accepting connections.

Listing Http Runtime information

For each web application initiated, there is a corresponding runtime. Below is the runtime list with the number of requests being served. The sum of all active requests is 364, the same number of running requests in !whttp. However we see that all the 9 runtime instances received the request to shutdown the host environment because a config file was changed.

0:139> !wruntime
Runtime Settings per Application Pool

=========================================================================
Address         : 0000000101535B60
First Request   : 3/5/2015 6:15:19 PM
App Pool User   : NT AUTHORITY\SYSTEM
Trust Level     : Full
App Domnain Id  : /LM/W3SVC/1/ROOT/EWS-561-130700529146479475
Debug Enabled   : False
Active Requests : 0n63
Path            : D:\Program Files\Microsoft\Exchange Server\V14\ClientAccess\exchweb\EWS\ (local disk)
Temp Folder     : C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files
Compiling Folder: C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files\ews\2d3834c2\13a11f61
Shutdown Reason : ConfigurationChange at 3/5/2015 6:16:33 PM
CONFIG change
HostingEnvironment initiated shutdown
CONFIG change
   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.Configuration.HttpConfigurationSystem.OnConfigurationChanged(Object sender, InternalConfigEventArgs e)
   at System.Configuration.BaseConfigurationRecord.OnStreamChanged(String streamname)
   at System.Web.Configuration.WebConfigurationHostFileChange.OnFileChanged(Object sender, FileChangeEvent e)
   at System.Web.DirectoryMonitor.FireNotifications()
   at System.Web.Util.WorkItem.CallCallbackWithAssert(WorkItemCallback callback)
   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)

=========================================================================
Address         : 00000001208F1F10
First Request   : 3/5/2015 5:48:53 PM
App Pool User   : NT AUTHORITY\SYSTEM
Trust Level     : Full
App Domnain Id  : /LM/W3SVC/1/ROOT/EWS-344-130700513249237468
Debug Enabled   : False
Active Requests : 0n11
Path            : D:\Program Files\Microsoft\Exchange Server\V14\ClientAccess\exchweb\EWS\ (local disk)
Temp Folder     : C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files
Compiling Folder: C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files\ews\2d3834c2\13a11f61
Shutdown Reason : ConfigurationChange at 3/5/2015 6:16:33 PM

HostingEnvironment initiated shutdown

=========================================================================
Address         : 000000012119E9E8
First Request   : 3/5/2015 5:57:47 PM
App Pool User   : NT AUTHORITY\SYSTEM
Trust Level     : Full
App Domnain Id  : /LM/W3SVC/1/ROOT/EWS-406-130700518599046979
Debug Enabled   : False
Active Requests : 0n34
Path            : D:\Program Files\Microsoft\Exchange Server\V14\ClientAccess\exchweb\EWS\ (local disk)
Temp Folder     : C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files
Compiling Folder: C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files\ews\2d3834c2\13a11f61
Shutdown Reason : ConfigurationChange at 3/5/2015 6:16:33 PM

HostingEnvironment initiated shutdown
CONFIG change
   at System.Environment.get_StackTrace()
   at System.Web.Hosting.HostingEnvironment.Initiat

=========================================================================
Address         : 0000000142469ED0
First Request   : 3/5/2015 6:16:32 PM
App Pool User   : NT AUTHORITY\SYSTEM
Trust Level     : Full
App Domnain Id  : /LM/W3SVC/1/ROOT/EWS-563-130700529926161985
Debug Enabled   : False
Active Requests : 0n0
Path            : D:\Program Files\Microsoft\Exchange Server\V14\ClientAccess\exchweb\EWS\ (local disk)
Temp Folder     : C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files
Compiling Folder: C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files\ews\2d3834c2\13a11f61
Shutdown Reason : ConfigurationChange at #INVALIDDATE#

CONFIG change

=========================================================================
Address         : 000000015FF2C628
First Request   : 3/5/2015 5:25:20 PM
App Pool User   : NT AUTHORITY\SYSTEM
Trust Level     : Full
App Domnain Id  : /LM/W3SVC/1/ROOT/EWS-114-130700499138390278
Debug Enabled   : False
Active Requests : 0n22
Path            : D:\Program Files\Microsoft\Exchange Server\V14\ClientAccess\exchweb\EWS\ (local disk)
Temp Folder     : C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files
Compiling Folder: C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files\ews\2d3834c2\13a11f61
Shutdown Reason : ConfigurationChange at 3/5/2015 6:16:33 PM

HostingEnvironment initiated shutdown
HostingEnvironment caused shutdown

CONFIG change

=========================================================================
Address         : 0000000160D1A720
First Request   : 3/5/2015 6:14:58 PM
App Pool User   : NT AUTHORITY\SYSTEM
Trust Level     : Full
App Domnain Id  : /LM/W3SVC/1/ROOT/EWS-557-130700528916324698
Debug Enabled   : False
Active Requests : 0n0
Path            : D:\Program Files\Microsoft\Exchange Server\V14\ClientAccess\exchweb\EWS\ (local disk)
Temp Folder     : C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files
Compiling Folder: C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files\ews\2d3834c2\13a11f61
Shutdown Reason : ConfigurationChange at 3/5/2015 6:15:29 PM

HostingEnvironment initiated shutdown
CONFIG change
HostingEnvironment caused shutdown
   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.Configuration.HttpConfigurationSystem.OnConfigurationChanged(Object sender, InternalConfigEventArgs e)
   at System.Configuration.BaseConfigurationRecord.OnStreamChanged(String streamname)
   at System.Web.Configuration.WebConfigurationHostFileChange.OnFileChanged(Object sender, FileChangeEvent e)
   at System.Web.DirectoryMonitor.FireNotifications()
   at System.Web.Util.WorkItem.CallCallbackWithAssert(WorkItemCallback callback)
   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)

=========================================================================
Address         : 00000001A0327ED8
First Request   : 3/5/2015 5:49:15 PM
App Pool User   : NT AUTHORITY\SYSTEM
Trust Level     : Full
App Domnain Id  : /LM/W3SVC/1/ROOT/EWS-347-130700513519079491
Debug Enabled   : False
Active Requests : 0n181
Path            : D:\Program Files\Microsoft\Exchange Server\V14\ClientAccess\exchweb\EWS\ (local disk)
Temp Folder     : C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files
Compiling Folder: C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files\ews\2d3834c2\13a11f61
Shutdown Reason : ConfigurationChange at 3/5/2015 6:16:33 PM

CONFIG change
HostingEnvironment initiated shutdown
HostingEnvironment caused shutdown

=========================================================================
Address         : 00000001E1102D58
First Request   : 3/5/2015 6:15:04 PM
App Pool User   : NT AUTHORITY\SYSTEM
Trust Level     : Full
App Domnain Id  : /LM/W3SVC/1/ROOT/EWS-558-130700528987261744
Debug Enabled   : False
Active Requests : 0n0
Path            : D:\Program Files\Microsoft\Exchange Server\V14\ClientAccess\exchweb\EWS\ (local disk)
Temp Folder     : C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files
Compiling Folder: C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files\ews\2d3834c2\13a11f61
Shutdown Reason : ConfigurationChange at 3/5/2015 6:15:35 PM

CONFIG change
HostingEnvironment initiated shutdown
HostingEnvironment caused shutdown
CONFIG change
   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.Configuration.HttpConfigurationSystem.OnConfigurationChanged(Object sender, InternalConfigEventArgs e)
   at System.Configuration.BaseConfigurationRecord.OnStreamChanged(String streamname)
   at System.Web.Configuration.WebConfigurationHostFileChange.OnFileChanged(Object sender, FileChangeEvent e)
   at System.Web.DirectoryMonitor.FireNotifications()
   at System.Web.Util.WorkItem.CallCallbackWithAssert(WorkItemCallback callback)
   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)

=========================================================================
Address         : 00000001E2605398
First Request   : 3/5/2015 6:16:32 PM
App Pool User   : NT AUTHORITY\SYSTEM
Trust Level     : Full
App Domnain Id  : /LM/W3SVC/1/ROOT/EWS-562-130700529762725531
Debug Enabled   : False
Active Requests : 0n53
Path            : D:\Program Files\Microsoft\Exchange Server\V14\ClientAccess\exchweb\EWS\ (local disk)
Temp Folder     : C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files
Compiling Folder: C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Temporary ASP.NET Files\ews\2d3834c2\13a11f61
Shutdown Reason : ConfigurationChange at 3/5/2015 6:16:33 PM

HostingEnvironment initiated shutdown
CONFIG change

Deadlock of sorts

As the application pool is set to allow only one worker process for this application pool, a new worker process is not created before the requests are served. There was lock preventing the application pools to recycle as well, but this is not part of this case study.

Discovering which configuration file changed

There are levels of config files being applied to a .NET application: machine, .NET runtime and local. In order to find out which file was modified we can prevent this deadlock to happen in the future. The query command below does the trick (FileMonitor is the class that implements the file change notification delegation):

0:139> !wfrom -type System.Web.FileMonitor where ($enumname(_lastAction) == “Modified”)  $addr(),_fileNameLong,$enumname(_lastAction),$tickstodatetime(_utcLastCompletion.dateData),DirectoryMonitor.Directory

calculated: 0000000120687860
_fileNameLong: web.config
calculated: Modified
calculated: 3/6/2015 12:05:36 PM
DirectoryMonitor.Directory: C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Config
calculated: 0000000181A27398
_fileNameLong: web.config
calculated: Modified
calculated: 3/6/2015 12:05:36 PM
DirectoryMonitor.Directory: C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Config
calculated: 00000001A03279D0
_fileNameLong: web.config
calculated: Modified
calculated: 3/6/2015 12:05:32 PM
DirectoryMonitor.Directory: C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Config
calculated: 00000001A0FCA008
_fileNameLong: web.config
calculated: Modified
calculated: 3/6/2015 12:05:36 PM
DirectoryMonitor.Directory: C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Config
calculated: 00000001BFFACAB8
_fileNameLong: web.config
calculated: Modified
calculated: 3/6/2015 12:05:36 PM
DirectoryMonitor.Directory: C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Config
 
5 Object(s) listed
71 Object(s) skipped by filter

So, putting all together the file modified was C:\Windows\Microsoft.NET\Framework64\v2.0.50727\Config\web.config.

Verifying the date of last change

When looking at the all fields of FileMonitor to identify the modified date, we see this:

0:139> !wselect * from 0000000120687860
[System.Web.FileMonitor]
System.Web.DirectoryMonitor DirectoryMonitor = 000000015FF3B9B8
System.Collections.Specialized.HybridDictionary Aliases = 000000015FF4C790
(string)System.String _fileNameLong = web.config
(string)System.String _fileNameShort = WEB~1.CON
System.Collections.Specialized.HybridDictionary _targets = 000000015FF4C768
System.Web.Util.FileAttributesData _fad = 0000000182782A20
System.Byte[] _dacl = 000000015FF4C650
(int32)System.Web.FileAction _lastAction = 3 (0n3) Modified
(bool)System.Boolean _exists = 1 (True)
System.DateTime _utcLastCompletion = -mt 000007FEF01E82D0 000000015FF4C758 3/6/2015 12:05:36 PM

Clicking on field _fad (FileAttributesData) we see the last modified was a while back:

0:139> !wselect * from 0000000182782a20
[System.Web.Util.FileAttributesData]
(int64)System.Int64 FileSize = 8014 (0n32788)
(int32)System.IO.FileAttributes FileAttributes = 80 (0n128) Normal
System.DateTime UtcCreationTime = -mt 000007FEF01E82D0 0000000182782A38 7/14/2009 2:36:14 AM
System.DateTime UtcLastAccessTime = -mt 000007FEF01E82D0 0000000182782A40 7/14/2009 2:36:14 AM
System.DateTime UtcLastWriteTime = -mt 000007FEF01E82D0 0000000182782A48 1/24/2012 2:53:39 PM

There are more to attributes than date

The file monitor event will be triggered by any attribute change. Most antivirus and backup applications change the file attributes without changing the date of last update. This trigger an unexpected and unwanted application pool recycling. The solution is to exclude those files of the backup and/or antivirus list.