How to tell why an IIS application pool is recycled

Question

Background:

I've deployed an ASP.NET MVC 3 app that works on my machine to a shared hosting provider and am discovering some problems that appear to be related to the application pool being recycled. The host has configured recycling to occur under any of these circumstances:

• Memory usage exceeds 200MB
• CPU usage exceeds 75% (presumably over a sustained period)
• 20 minutes of idle time

The restrictions are more relaxed on my development machine so I wasn't seeing recycling like this during development. I don't have admin access to the shared hosting box (understandably) so I can't read the event log to see why this recycling is occurring.

Question:

Is there a way I can find out why my app was recycled (in Application_End for example) so that I can log it to help my debugging?

Answer 1

Without access to the event logs (because you're in a shared hosting environment) the most information you're going to get is from the Application_End event and by asking the HttpRuntime (via reflection) for the values of one or two private members that are sadly not exposed publicly.

To do this add the following code to your Application_End event:

BindingFlags staticFlags = 
    BindingFlags.NonPublic | BindingFlags.Static | BindingFlags.GetField;
BindingFlags instanceFlags = 
    BindingFlags.NonPublic | BindingFlags.Instance | BindingFlags.GetField;

HttpRuntime runtime = (HttpRuntime)typeof(System.Web.HttpRuntime)
                        .InvokeMember("_theRuntime", staticFlags, null, null, null);
if(runtime != null) 
{
    string shutDownMessage = (string)runtime.GetType()
         .InvokeMember("_shutDownMessage", instanceFlags, null, runtime, null);

    string shutDownStack = (string)runtime.GetType()
         .InvokeMember("_shutDownStack", instanceFlags, null, runtime, null);

    // Log shutDownMessage & shutDownStack somewhere
}

If I shutdown or recycle my app's application pool I see the following:

HostingEnvironment initiated shutdown
HostingEnvironment caused shutdown -    
   at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
   at System.Environment.get_StackTrace()
   at System.Web.Hosting.HostingEnvironment.InitiateShutdownInternal()
   at System.Web.Hosting.HostingEnvironment.InitiateShutdownWithoutDemand()
   at System.Web.Hosting.PipelineRuntime.StopProcessing()

That's probably about as good as it gets.

Update:

I couldn't remember where I found this code but Drew helpfully reminded me it was from a Scott Guthrie blog post.

There are some other private members that could be useful such as:

private ApplicationShutdownReason _shutdownReason;

You can examine these fields in .NET Reflector (if you still have a copy that isn't time-bombed) or one of the alternatives (Open Source Alternatives to Reflector?).

Answer 2

Research - 1

Firstly I tried using System.Web.ProcessModelInfo.GetCurrentProcessInfo() and System.Web.ProcessModelInfo.GetHistory(int). The results of these methods return info such as the PID, start time, age, status, and peak memory usage. Unfortunately these were unavailable in my hosting environment:

HttpException 0x80004005 - Process metrics are available only when the ASP.NET process model is enabled. When running on versions of IIS 6 or newer in worker process isolation mode, this feature is not supported.

This approach might work for others though, so if you're in this situation, give it a shot.

Research - 2

The property System.Web.Hosting.HostingEnvironment.ShutdownReason is an enum with lots of values, but unfortunately all the cases I outline in my question are bundled into a single enum value:

ApplicationShutdownReason.HostingEnvironment: The hosting environment shut down the application domain.

Research - 3

ScottGu has an approach on his blog (which is the same code Kev posted) that uses reflection to access internal state of the HttpApplication. Unfortunately in this case it only reports the same detail as #2 above:

_shutDownMessage =
  HostingEnvironment initiated shutdown
  HostingEnvironment caused shutdown

_shutDownStack =
  at System.Environment.GetStackTrace(Exception e, Boolean needFileInfo)
  at System.Environment.get_StackTrace()
  at System.Web.Hosting.HostingEnvironment.InitiateShutdownInternal()
  at System.Web.Hosting.HostingEnvironment.InitiateShutdownWithoutDemand()
  at System.Web.Hosting.PipelineRuntime.StopProcessing()

Answer 3

Below is good code find from https://mitchelsellers.com/blog/article/logging-asp-net-application-restarts

//  obtain the shutdown reason
System.Web.ApplicationShutdownReason shutdownReason = System.Web.Hosting.HostingEnvironment.ShutdownReason;
string shutdownDetail = "";

//Evaluate which option caused the error
switch (shutdownReason)
{
    case ApplicationShutdownReason.BinDirChangeOrDirectoryRename:
        shutdownDetail = "A change was made to the bin directory or the directory was renamed";
        break;
    case ApplicationShutdownReason.BrowsersDirChangeOrDirectoryRename:
        shutdownDetail = "A change was made to the App_browsers folder or the files contained in it";
        break;
    case ApplicationShutdownReason.ChangeInGlobalAsax:
        shutdownDetail = "A change was made in the global.asax file";
        break;
    case ApplicationShutdownReason.ChangeInSecurityPolicyFile:
        shutdownDetail = "A change was made in the code access security policy file";
        break;
    case ApplicationShutdownReason.CodeDirChangeOrDirectoryRename:
        shutdownDetail = "A change was made in the App_Code folder or the files contained in it";
        break;
    case ApplicationShutdownReason.ConfigurationChange:
        shutdownDetail = "A change was made to the application level configuration";
        break;
    case ApplicationShutdownReason.HostingEnvironment:
        shutdownDetail = "The hosting environment shut down the application";
        break;
    case ApplicationShutdownReason.HttpRuntimeClose:
        shutdownDetail = "A call to Close() was requested";
        break;
    case ApplicationShutdownReason.IdleTimeout:
        shutdownDetail = "The idle time limit was reached";
        break;
    case ApplicationShutdownReason.InitializationError:
        shutdownDetail = "An error in the initialization of the AppDomain";
        break;
    case ApplicationShutdownReason.MaxRecompilationsReached:
        shutdownDetail = "The maximum number of dynamic recompiles of a resource limit was reached";
        break;
    case ApplicationShutdownReason.PhysicalApplicationPathChanged:
        shutdownDetail = "A change was made to the physical path to the application";
        break;
    case ApplicationShutdownReason.ResourcesDirChangeOrDirectoryRename:
        shutdownDetail = "A change was made to the App_GlobalResources foldr or the files contained within it";
        break;
    case ApplicationShutdownReason.UnloadAppDomainCalled:
        shutdownDetail = "A call to UnloadAppDomain() was completed";
        break;
    default:
        shutdownDetail = "Unknown shutdown reason";
        break;
}

Answer 4

This answer can provide extra insight for those having similar problems on IIS 7.x or above.

1. Finding when application pool is starting to shutdown - the following code can be used to find out when the application pool start its shutdown. Actual shutdown occurs in a maximum of Shutdown limit (seconds, default 90) after this event.

public class ApplicationPoolService : IApplicationPoolService
{
    public bool IsShuttingDown()
    {
        return System.Web.Hosting.HostingEnvironment.ShutdownReason != ApplicationShutdownReason.None;
    }

    public ApplicationShutdownReason GetShutdownReason()
    {
        return System.Web.Hosting.HostingEnvironment.ShutdownReason;
    }
}

public class HostingEnvironmentRegisteredObject : IRegisteredObject
{
    public void Stop(bool immediate)
    {
        // second call is done when the Stop is imminent 
        if (immediate)
            return;

        var reason = appPoolService.GetShutdownReason().ToString();
        logger.Log(LogLevel.Info, $"HostingEnvironmentRegisteredObject.stop called with shutdown reason {reason}");
    }
}

// this code should be placed in global.asax.cs
protected void Application_Start()
{
    HostingEnvironment.RegisterObject(new HostingEnvironmentRegisteredObject());
}

This helps to find the general reason and exactly when it was triggered. In your case, I think HostingEnvironment is the value. Unfortunately, the underlying cause is not unique. It can be periodic recycle, recycle due to memory limit (most probable reason in OP's question), recycle due to fixed hour etc.

2. Finding the exact cause - one way to find out the exact cause is to search for it in the EventLog. If this is not accessible, it can be requested from the hosting provider by providing the following details to narrow their search.

• Exact time of shutdown initiation
• Event log filter:
  • Event sources = WAS
  • Event level = Information
  • Logged = custom range including exact time of shutdown +/- 1 minute or so

Event log should return more relevant information like the ones below:

A worker process with process id of 'xxx' serving application pool 'xxx' has requested a recycle because it reached its scheduled recycle time.

A worker process with process id of 'xxx' serving application pool 'xxx' has requested a recycle because it reached its virtual memory limit.