lowleveldesign.org

ASP.NET Health Monitoring is one of the framework gems that is often forgotten by ASP.NET developers or web server administrators. It provides great monitoring features, often allowing you to rapidly diagnose failing applications or systems. Have you ever wondered why ASP.NET errors appear in the system event log? It’s thanks to the ASP.NET Health Monitoring and its configuration in the master web.config file (the one stored in the framework installation directory):

<healthMonitoring>
    <bufferModes>...</bufferModes>
    <providers>...</providers>
    <eventMappings>...</eventMappings>
    <profiles>...</profiles>
    <rules>
        <add name="All Errors Default" eventName="All Errors" provider="EventLogProvider"
            profile="Default" minInstances="1" maxLimit="Infinite" minInterval="00:01:00"
            custom="" />
        <add name="Failure Audits Default" eventName="Failure Audits"
            provider="EventLogProvider" profile="Default" minInstances="1"
            maxLimit="Infinite" minInterval="00:01:00" custom="" />
    </rules>
</healthMonitoring>

Let’s analyze quickly the above snippet. A rule defines which ASP.NET health events will be logged (eventname) by the chosen provider and at what frequency. The ASP.NET health events hierarchy can be found here. The event name used in the rule definition is the name of the mapping that is defined earlier in the web.config file. An example event mapping looks as follows:

<eventMappings>
    <add name="All Errors" type="System.Web.Management.WebBaseErrorEvent,System.Web,Version=4.0.0.0,Culture=neutral,PublicKeyToken=b03f5f7f11d50a3a"
        startEventCode="0" endEventCode="2147483647" />
</eventMappings>

If you recall the events hierarchy diagram you will notice that WebBaseErrorEvent is a parent for WebErrorEvent and WebRequestErrorEvent. So by using the All Errors mapping in the rule’s eventname attribute’s value we inform ASP.NET framework that we want to log all ASP.NET error events. This is a really nice feature and you may use it to create your own event groupings.

Other events that are performance related include:

    <add name="Heartbeats" type="System.Web.Management.WebHeartbeatEvent,System.Web,Version=4.0.0.0,Culture=neutral,PublicKeyToken=b03f5f7f11d50a3a"
        startEventCode="0" endEventCode="2147483647" />
    <add name="Application Lifetime Events" type="System.Web.Management.WebApplicationLifetimeEvent,System.Web,Version=4.0.0.0,Culture=neutral,PublicKeyToken=b03f5f7f11d50a3a"
        startEventCode="0" endEventCode="2147483647" />
    <add name="Request Processing Events" type="System.Web.Management.WebRequestEvent,System.Web,Version=4.0.0.0,Culture=neutral,PublicKeyToken=b03f5f7f11d50a3a"
        startEventCode="0" endEventCode="2147483647" />

If you are also interested in security auditing check the WebAuditEvent specification. Let’s see how this works with real ASP.NET code. We will start with a simple Default.aspx page:

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

<script runat="server">

  public void Page_Load() {
      Response.Write("OK");
  }
</script>

and a following web.config file:

<?xml version="1.0"?>
<configuration>
  <system.web>
    <compilation debug="true" targetFramework="4.0">
    </compilation>

    <healthMonitoring enabled="true" heartbeatInterval="120">
      <rules>
        <add name="Heartbeats Default" eventName="Heartbeats" provider="EventLogProvider"
              profile="Default" />
        <add name="Application Lifetime Events Default" eventName="Application Lifetime Events" provider="EventLogProvider"
              profile="Default" />
        <add name="Request Processing Events Default" eventName="Request Processing Events" provider="EventLogProvider"
              profile="Default" />
      </rules>
    </healthMonitoring>
  </system.web>
</configuration>

If you deploy this code to a server and call the Default.aspx page new events should appear in the event log. Events with codes 1001 and 1002 provide information about application startup and shutdown. Events with code 1005 issued every 120s (heartbeatInterval="120") reveal the application state:

Look how much information is exposed by this simple event. For instance we can easily say whether our application is consuming too much memory or whether there is any latency in serving user requests (Requests queued). If we find any issue we can further profile the application on a machine where the problem appeared (Machine name, Process ID). For instance, if your application shares an application pool with some other applications you may need to check whether the memory problem is not caused by one of them.

In this paragraph I will pick few events and show you which part of the ASP.NET framework fires them. I found this out by simply placing a breakpoint on a System.Web.Management.EventLogWebEventProvider.ProcessEvent method. Once the breakpoint was hit I collected a managed call stack from the debugger. For instance a call stack for WebApplicationLifetimeEvent shows that it’s the HttpApplicationFactory which pulled the event trigger when the application was awakening to serve the first request:

System.Web.dll!System.Web.Management.EventLogWebEventProvider.ProcessEvent(System.Web.Management.WebBaseEvent eventRaised = {System.Web.Management.WebApplicationLifetimeEvent}) + 0x13 bytes	
System.Web.dll!System.Web.Management.WebBaseEvent.RaiseInternal(System.Web.Management.WebBaseEvent eventRaised = {System.Web.Management.WebApplicationLifetimeEvent}, System.Collections.ArrayList firingRuleInfos = Count = Cannot evaluate expression because the code of the current method is optimized., int index0, int index1) + 0x265 bytes	
System.Web.dll!System.Web.Management.WebBaseEvent.RaiseSystemEventInternal(string message, object source, int eventCode, int eventDetailCode, System.Exception exception, string nameToAuthenticate) + 0xef bytes	
System.Web.dll!System.Web.HttpApplicationFactory.EnsureAppStartCalled(System.Web.HttpContext context = {System.Web.HttpContext}) + 0xaf bytes	
System.Web.dll!System.Web.HttpApplicationFactory.GetApplicationInstance(System.Web.HttpContext context = {System.Web.HttpContext}) + 0x5d bytes	
System.Web.dll!System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest wr = {Microsoft.VisualStudio.WebHost.Request}) + 0x20e bytes	
System.Web.dll!System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest wr) + 0x6e bytes	
System.Web.dll!System.Web.HttpRuntime.ProcessRequest(System.Web.HttpWorkerRequest wr) + 0x47 bytes	

From the WebHeartbeatEvent call stack we can read that it’s fired by a timer (on a dedicated system thread):

System.Web.dll!System.Web.Management.EventLogWebEventProvider.ProcessEvent(System.Web.Management.WebBaseEvent eventRaised = {System.Web.Management.WebHeartbeatEvent}) + 0x13 bytes
System.Web.dll!System.Web.Management.WebBaseEvent.RaiseInternal(System.Web.Management.WebBaseEvent eventRaised = {System.Web.Management.WebHeartbeatEvent}, System.Collections.ArrayList firingRuleInfos = Count = Cannot evaluate expression because the code of the current method is optimized., int index0, int index1) + 0x265 bytes
System.Web.dll!System.Web.Management.WebBaseEvent.RaiseSystemEventInternal(string message, object source, int eventCode, int eventDetailCode, System.Exception exception, string nameToAuthenticate) + 0xef bytes
System.Web.dll!System.Web.Management.HealthMonitoringManager.HeartbeatCallback(object state) + 0x27 bytes
mscorlib.dll!System.Threading.TimerQueueTimer.CallCallbackInContext(object state) + 0x2c bytes
mscorlib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool preserveSyncCtx) + 0xa7 bytes
mscorlib.dll!System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state, bool preserveSyncCtx) + 0x16 bytes
mscorlib.dll!System.Threading.TimerQueueTimer.CallCallback() + 0x71 bytes
mscorlib.dll!System.Threading.TimerQueueTimer.Fire() + 0xc0 bytes
mscorlib.dll!System.Threading.TimerQueue.FireNextTimers() + 0x131 bytes
mscorlib.dll!System.Threading.TimerQueue.AppDomainTimerCallback() + 0x1c bytes

Finally WebRequestErrorEvent is fired by the HttpRuntime after the request processing is finished:

System.Web.dll!System.Web.Management.EventLogWebEventProvider.ProcessEvent(System.Web.Management.WebBaseEvent eventRaised = {System.Web.Management.WebRequestErrorEvent}) + 0x13 bytes	
System.Web.dll!System.Web.Management.WebBaseEvent.RaiseInternal(System.Web.Management.WebBaseEvent eventRaised = {System.Web.Management.WebRequestErrorEvent}, System.Collections.ArrayList firingRuleInfos = Count = Cannot evaluate expression because the code of the current method is optimized., int index0, int index1) + 0x265 bytes	
System.Web.dll!System.Web.Management.WebBaseEvent.RaiseSystemEventInternal(string message, object source, int eventCode, int eventDetailCode, System.Exception exception, string nameToAuthenticate) + 0xef bytes	
System.Web.dll!System.Web.Management.WebBaseEvent.RaiseRuntimeError(System.Exception e, object source) + 0xa3 bytes	
System.Web.dll!System.Web.HttpResponse.ReportRuntimeError(System.Exception e = {Cannot evaluate expression because the code of the current method is optimized.}, bool canThrow = true, bool localExecute = false) + 0x58 bytes	
System.Web.dll!System.Web.HttpRuntime.FinishRequest(System.Web.HttpWorkerRequest wr = {Microsoft.VisualStudio.WebHost.Request}, System.Web.HttpContext context = {System.Web.HttpContext}, System.Exception e) + 0x16e bytes	
System.Web.dll!System.Web.HttpRuntime.OnHandlerCompletion(System.IAsyncResult ar) + 0x9c bytes	
System.Web.dll!System.Web.HttpAsyncResult.Complete(bool synchronous, object result, System.Exception error, System.Web.RequestNotificationStatus status) + 0x3a bytes	
System.Web.dll!System.Web.HttpApplication.ApplicationStepManager.ResumeSteps(System.Exception error) + 0x288 bytes	
System.Web.dll!System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(System.Web.HttpContext context, System.AsyncCallback cb, object extraData) + 0xf8 bytes	
System.Web.dll!System.Web.HttpRuntime.ProcessRequestInternal(System.Web.HttpWorkerRequest wr = {Microsoft.VisualStudio.WebHost.Request}) + 0x284 bytes	
System.Web.dll!System.Web.HttpRuntime.ProcessRequestNoDemand(System.Web.HttpWorkerRequest wr) + 0x6e bytes	
System.Web.dll!System.Web.HttpRuntime.ProcessRequest(System.Web.HttpWorkerRequest wr) + 0x47 bytes	

You may now ask yourself how such monitoring impacts your application performance. Unfortunately I can’t give you the exact numbers, but I assure you Microsoft did best to make it as invisible as possible:) I think the most important performance related decision is the choice of provider which will collect health events. There are few providers available out of the box, including: EventLogWebEventProvider, IisTraceWebEventProvider, TraceWebEventProvider or SqlWebEventProvider. For example, I would recommend using SqlWebEventProvider for storing infrequent events, such as audit, error or application lifetime events – having them saved in a SQL Server table might help you generate some performance-related reports in the future. For more frequent events (such as heart beats or web request events) you should look for providers that can consume large amount of data with insignificant delays – I suppose that TraceWebEventProvider, IisTraceWebEventProvider or even EventLogWebEventProvider will lead the field here.

To conclude, health monitoring events provide great insight into the application’s lifetime. By processing them correctly you may easily monitor your server web farms and spot any anomalies before they become a major issue. If you would like to play with this technology I invite you to go and grab my sample app and adapt it to your needs.