How dependency calls are tracked by the Application Insights?


Application Insights is a performance monitoring service, created by Microsoft and available on Azure. It gives you space to store the performance metrics and logs of your application (1GB for free!), as well as functionalities to search and manage them. In this post I am not going to present you the whole platform – Microsoft already did it in the Azure documentation, but rather focus on an element of the log collection, named dependency calls tracking. I did some analysis on the Application Insights libraries, and decided to publish my findings, in the hope that the results might interest some of you too.

Dependency calls are requests, which your application makes to the external services (such as databases or REST services). When this telemetry type is enabled, all the dependent actions form a timeline within the scope of the parent action. Using this timeline we may easily verify whether the delay in our application is caused by an external service, or the application itself. Let’s analyze in detail how this data is collected.

Application Insights setup

Before your application logs enter the Azure servers, you need to make some adjustments in the source code or/and install an agent on the application server. Modifying the application code is called in the official documentation the instrumentation at build time, whilst the agent installation is the instrumentation at run time (you may use both simultaneously). The table below (copied from https://docs.microsoft.com/en-us/azure/application-insights/app-insights-monitor-performance-live-website-now) lists the differences in capabilities between these two approaches:

appinsights-runtime-buildtime

The “Dependency diagnostics” row is the one we will investigate further. As you can see the official docs state that the run time dependency diagnostics provides more details about the calls, and it works for all versions of .NET, whereas the build time dependency diagnostics is supported only on .NET 4.6+ and lacks some details. If you are surprised, don’t worry – I was too, but everything will be clear soon.

Instrumentation at build time

If your project is an ASP.NET MVC/Forms/WebApi application, adding the Application Insights instrumentation is as simple as right clicking on the project name and choosing “Add Application Insights Telemetry” from the context menu:

appinsights-enable-webapp

Visual Studio will then run a wizard, in which you will need to sign in the Azure portal, and configure the Application Insights account. Next, a number of Nuget packages will be installed, a new ApplicationInsights.config file will be added to the root folder of your project, and the web.config file will be slightly modified. The table below describes some of the Nuget packages, and their role in the log collection process:

Nuget package Required Main purpose
Microsoft.ApplicationInsights YES Main library, containing all the classes required for the communication with the AppInsights account in Azure
Microsoft.ApplicationInsights
.WindowsServer
YES Exception tracking, environment settings collection, support for telemetry tracking while debugging
Microsoft.ApplicationInsights
.Web
YES Tracking request times, collecting exception info (through an HTTP module)
Microsoft.ApplicationInsights
.Agent.Intercept
NO Interaction with the AppInsights agent (if it is installed and running on the server)
Microsoft.ApplicationInsights
.DependencyCollector
NO Dependency diagnostics – the subject of this post

The list of telemetry modules used by the Application Insights component can be found in the ApplicationInsights.config file. The Application Insights settings are read by the ApplicationInsightsHttpModule, which is configured in the web.config file:

<httpModules>
      <add name="ApplicationInsightsWebTracking" type="Microsoft.ApplicationInsights.Web.ApplicationInsightsHttpModule, Microsoft.AI.Web" />
</httpModules>

On initialization, the Application Insights component loads all the telemetry modules, including the DependencyTrackingTelemetryModule, by calling their Initialize methods. The dependency tracking module checks whether a profiler is attached to the application (we will talk about it soon), and if it is not, the InitializeForFrameworkEventSource method is called. The main purpose of this method is to initialize two fields: httpEventListener of type FrameworkHttpEventListener and sqlEventListener of type FrameworkSqlEventListener. Both those types inherit from the System.Diagnostics.Tracing.EventListener and override the OnEventSourceCreated method. This method is called for all the event sources existing in the application, as well as new event sources attached to a given listener. The first call happens while the class is being instantiated (have a look at the call stack below), which is a great moment to attach the listener to the interesting event sources:

Microsoft.AI.DependencyCollector.dll!Microsoft.ApplicationInsights.DependencyCollector.Implementation.FrameworkHttpEventListener.OnEventSourceCreated
mscorlib.dll!System.Diagnostics.Tracing.EventSource.AddListener
mscorlib.dll! System.Diagnostics.Tracing.EventListener..ctor
Microsoft.AI.DependencyCollector.dll!Microsoft.ApplicationInsights.DependencyCollector.Implementation.FrameworkHttpEventListener..ctor
…

And this is exactly what our two listeners are doing. The FrameworkHttpEventListener attaches to the events with a keyword 0x4 sent by the FrameworkEventSource (we may verify in the .NET source code that this keyword is assigned to the NetClient events):

if (eventSource != null && eventSource.Name == "System.Diagnostics.Eventing.FrameworkEventSource")
{
    base.EnableEvents(eventSource, EventLevel.Informational, (EventKeywords)4L);
    DependencyCollectorEventSource.Log.RemoteDependencyModuleVerbose(
        "HttpEventListener initialized for event source:System.Diagnostics.Eventing.FrameworkEventSource", "Incorrect");
}

The FrameworkSqlEventListener is using the Microsoft-AdoNet-SystemData event source, which has only one keyword available:

if (eventSource != null && eventSource.Name == "Microsoft-AdoNet-SystemData")
{
    base.EnableEvents(eventSource, EventLevel.Informational, (EventKeywords)1L);
    DependencyCollectorEventSource.Log.RemoteDependencyModuleVerbose(
        "SqlEventListener initialized for event source:Microsoft-AdoNet-SystemData", "Incorrect");
}

You may later check the OnEventWritten methods in both those listeners to see how the received events are processed. As you see, the dependency calls instrumentation at build time is based on ETW events. Let’s analyze what happens at run time.

Instrumentation at run time

Instrumentation at run time does not require any changes in the application code. You simply install an Application Insights agent, and choose which IIS application you would like to instrument. After finishing the wizard, the agent will drop AppInsights libraries in the application bin folder, and will add the ApplicationInsights.config file to the root folder of the application. The list of DLLs is almost the same as for the build time instrumentation, except for one additional assembly: Microsoft.AI.HttpModule. You may be wondering why this additional assembly is required. Everything becomes clear when you check its assembly attributes:

…
[assembly: PreApplicationStartMethod(typeof(WebRequestTrackingModuleRegister), "Register")]
[assembly: TargetFramework(".NETFramework,Version=v4.0", FrameworkDisplayName = ".NET Framework 4")]
[assembly: AssemblyFileVersion("2.1.1.196")]
…

As we are no longer in control of the web.config file, we need to find a different way to inject our HttpModule. The PreApplicationStartMethod attribute comes with help here, as it allows an easy and straightforward way to register an HttpModule dynamically on application start. With the HttpModule registered, all the predefined telemetry modules should be loaded into our application AppDomain. One of them would be the DependencyTrackingTelemetryModule. As you recall, in its Initialize method body, there is a check whether a profiler is attached to the application. And this time it is! That’s the biggest difference between instrumentation at build time and at run time. It took me a moment to figure this out, but as you will soon see the configuration is quite simple. After enabling the Application Insights telemetry for any of your ASP.NET applications, and restarting the IIS, you should see three new environment variables in the svchost.exe process hosting the IIS service:

  • COR_ENABLE_PROFILING=1
  • COR_PROFILER={324F817A-7420-4E6D-B3C1-143FBED6D855}
  • MicrosoftInstrumentationEngine_Host={CA487940-57D2-10BF-11B2-A3AD5A13CBC0}

If you are wondering how they got there, check the Environment value under the HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\W3SVC key. Consequently, these variables will appear in w3wp processes (application pool processes are created by the svchost.exe and inherit the environment settings). Let’s move back to the DependencyTrackingTelemetryModule initialization process. As the profiler was found, the next called method would be InitializeForRuntimeProfiler, which at the end calls the DecorateProfilerForHttp and DecorateProfilerForSql methods of the ProfilerRuntimeInstrumentation class. Both these methods use the Functions static class (from the Microsoft.AI.Agent.Intercept assembly) to inject callbacks into the interesting framework methods. Instead of analyzing the decompiled code, let’s use the profiling engine in our own application, in which we will measure the HttpWebRequest.GetResponse method execution:

using System;
using System.Diagnostics;
using System.Net;
using Microsoft.ApplicationInsights.Extensibility;
using Microsoft.Diagnostics.Instrumentation.Extensions.Intercept;

public static class Program
{
    public static void Main(string[] args) {
        InitializeProfiler();

        var req = WebRequest.Create("https://lowleveldesign.wordpress.com");
        using (var resp = req.GetResponse()) {
            Console.WriteLine("Content type: {0}", resp.ContentType);
        }
    }

    internal static void InitializeProfiler()
    {
        Decorator.InitializeExtension();
        Functions.Decorate("System", "System.dll", "System.Net.HttpWebRequest.GetResponse",
                new Func<object, object>(Program.BeginGetResponse),
                new Func<object, object, object, object>(Program.EndGetResponse),
                null, false, true);
    }

    private static readonly Stopwatch stopwatch = new Stopwatch();

    private static object BeginGetResponse(object thisobj) {
        Console.WriteLine("Begin GetResponse");
        stopwatch.Start();
        return null;
    }

    private static object EndGetResponse(object context, object returnValue, object thisobj) {
        stopwatch.Stop();
        Console.WriteLine("End GetResponse: {0:0.###}ms", stopwatch.ElapsedMilliseconds);
        return returnValue;
    }
}

Before running the application, we need to set the required environment variables:

set COR_ENABLE_PROFILING=1
set "COR_PROFILER={324F817A-7420-4E6D-B3C1-143FBED6D855}"
set "MicrosoftInstrumentationEngine_Host={CA487940-57D2-10BF-11B2-A3AD5A13CBC0}"
 

And as a result we should receive:

Begin GetResponse
End GetResponse: 1094ms
Content type: text/html; charset=UTF-8

As you can see, we’ve just written a small profiler using the Application Insights engine 🙂

Summary

You may be now wondering which instrumentation type you should use in your app. If your app runs on .NET older than 4.6 and you want to use dependency diagnostics, you don’t have a choice, but to install the agent on the server. If your app uses .NET 4.6+ you may configure only the build time instrumentation. The profiler way (run time instrumentation) generates more overhead compared to the ETW way (build time instrumentation). Thus, I would recommend starting with the build time instrumentation, and enable the run time instrumentation only if you need more details. Finally, if you have both types of instrumentation enabled, the profiler way will take precedence.

3 thoughts on “How dependency calls are tracked by the Application Insights?

  1. Pingback: dotnetomaniak.pl

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s