How dependency calls are tracked by the application insights?

 In We blog it!

This article has been originally published on Low Level Design blog by Sebastian Solnica. Follow him on Twitter to get more fantastic news and content!

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:

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:




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:


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

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

Sebastian Solnica
I’m a System Engineer, working in the DevOps team in KMD. The DevOps term is still pretty fresh in IT world, and covers a lot of areas such as: Continuous Delivery, code quality assurance, test automation, as well as application monitoring. For more than 10 years I worked as a .NET developer, which gives me a good understanding of the necessity of automation in the development process. My another area of interest (which I could even call a hobby) involves application/system diagnostics and security. In my constant need to understand how things work, I debug and trace whatever runs on my machine. You may reach out to me on twitter: @lowleveldesign or through my personal site: http://www.lowleveldesign.org/.
Recommended Posts
Showing 4 comments
  • Paritosh Gupta
    Reply

    Issue. Incoming Request in Live Stream Telemetry is not showing graphs. Refer below snapshot:
    https://uploads.disquscdn.com/images/622e7af3c2651ae415c6217c8ef6ff996b60855e60e42d48e03fb21a26c6799d.png

    We are trying to get live stream telemetry dynamically from code. We are not using Appinsight.config and Web.Config.

    While referencing Microsoft.ApplicationInsight.Web from Nu-get package for fetching Live Stream, an entry(mentioned below) is automatically added in in Web.Config which helps in fetching incoming request for live-stream.

    After removing this entry from web.config, Incoming Request in Live Stream are stopped working. We are trying to make above code entry dynamically with C# code.

    Sample Code is given below:

    private void LiveMetricStream()
    {
    bool enableDependencyTracking = true;
    bool _telemetryModulesInitialized = false;

    // Telemetry modules can be only instantiated and initialized once per app domain.
    if (!_telemetryModulesInitialized)
    {
    var telemetryModules = new List();
    var httpModule = new List();
    httpModule.Add(new ApplicationInsightsHttpModule());

    if (enableDependencyTracking)
    {
    telemetryModules.Add(new DependencyTrackingTelemetryModule());
    }

    telemetryModules.Add(new PerformanceCollectorModule());
    telemetryModules.Add(new QuickPulseTelemetryModule());

    var reqTrackingModule = new RequestTrackingTelemetryModule();
    reqTrackingModule.Handlers.Add(“System.Web.Handlers.TransferRequestHandler”);
    reqTrackingModule.Handlers.Add(“Microsoft.VisualStudio.Web.PageInspector.Runtime.Tracing.RequestDataHttpHandler”);
    reqTrackingModule.Handlers.Add(“System.Web.StaticFileHandler”);
    reqTrackingModule.Handlers.Add(“System.Web.Handlers.AssemblyResourceLoader”);
    reqTrackingModule.Handlers.Add(“System.Web.Optimization.BundleHandler”);
    reqTrackingModule.Handlers.Add(“System.Web.Script.Services.ScriptHandlerFactory”);
    reqTrackingModule.Handlers.Add(“System.Web.Handlers.TraceHandler”);
    reqTrackingModule.Handlers.Add(“System.Web.Services.Discovery.DiscoveryRequestHandler”);
    reqTrackingModule.Handlers.Add(“System.Web.HttpDebugHandler”);
    telemetryModules.Add(reqTrackingModule);

    telemetryModules.Add(new UnhandledExceptionTelemetryModule());
    telemetryModules.Add(new ExceptionTrackingTelemetryModule());

    TelemetryConfiguration telemetryConfiguration = new TelemetryConfiguration();

    telemetryConfiguration.TelemetryInitializers.Add(new HttpDependenciesParsingTelemetryInitializer());
    telemetryConfiguration.TelemetryInitializers.Add(new AzureRoleEnvironmentTelemetryInitializer());
    telemetryConfiguration.TelemetryInitializers.Add(new AzureWebAppRoleEnvironmentTelemetryInitializer());
    telemetryConfiguration.TelemetryInitializers.Add(new BuildInfoConfigComponentVersionTelemetryInitializer());
    telemetryConfiguration.TelemetryInitializers.Add(new WebTestTelemetryInitializer());

    var syntheticAgentIntializer = new SyntheticUserAgentTelemetryInitializer();
    syntheticAgentIntializer.Filters = “search|spider|crawl|Bot|Monitor|BrowserMob|BingPreview|PagePeeker|WebThumb|URL2PNG|ZooShot|GomezA|Google SketchUp|Read Later|KTXN|KHTE|Keynote|Pingdom|AlwaysOn|zao|borg|oegp|silk|Xenu|zeal|NING|htdig|lycos|slurp|teoma|voila|yahoo|Sogou|CiBra|Nutch|Java|JNLP|Daumoa|Genieo|ichiro|larbin|pompos|Scrapy|snappy|speedy|vortex|favicon|indexer|Riddler|scooter|scraper|scrubby|WhatWeb|WinHTTP|voyager|archiver|Icarus6j|mogimogi|Netvibes|altavista|charlotte|findlinks|Retreiver|TLSProber|WordPress|wsr-agent|http client|Python-urllib|AppEngine-Google|semanticdiscovery|facebookexternalhit|web/snippet|Google-HTTP-Java-Client”;

    telemetryConfiguration.TelemetryInitializers.Add(syntheticAgentIntializer);
    telemetryConfiguration.TelemetryInitializers.Add(new ClientIpHeaderTelemetryInitializer());
    telemetryConfiguration.TelemetryInitializers.Add(new OperationNameTelemetryInitializer());
    telemetryConfiguration.TelemetryInitializers.Add(new Microsoft.ApplicationInsights.Web.OperationCorrelationTelemetryInitializer());
    telemetryConfiguration.TelemetryInitializers.Add(new UserTelemetryInitializer());
    telemetryConfiguration.TelemetryInitializers.Add(new AuthenticatedUserIdTelemetryInitializer());
    telemetryConfiguration.TelemetryInitializers.Add(new AccountIdTelemetryInitializer());
    telemetryConfiguration.TelemetryInitializers.Add(new SessionTelemetryInitializer());
    telemetryConfiguration.TelemetryChannel = new ServerTelemetryChannel();
    var quickPulseProcessor = telemetryConfiguration.TelemetryProcessors
    .FirstOrDefault(processor => processor is QuickPulseTelemetryProcessor);
    if (quickPulseProcessor != null)
    {
    var quickPulseModule = new QuickPulseTelemetryModule();
    quickPulseModule.RegisterTelemetryProcessor(quickPulseProcessor);
    telemetryModules.Add(quickPulseModule);
    }
    _telemetryModulesInitialized = true;
    TelemetryConfiguration.Active.TelemetryProcessorChainBuilder.Use(next => new QuickPulseTelemetryProcessor(next));
    TelemetryConfiguration.Active.TelemetryProcessorChainBuilder.Use(next => new AdaptiveSamplingTelemetryProcessor(next));
    TelemetryConfiguration.Active.TelemetryProcessorChainBuilder.Build();
    TelemetryConfiguration.Active.InstrumentationKey = “Your Instrumentation Key Here”;

    foreach (var telemetryModule in telemetryModules)
    {
    telemetryModule.Initialize(telemetryConfiguration);
    }

    }
    }

    What else can we add or remove in above code to make it workable.

  • Sebastian Solnica
    Reply

    In your code I don’t see a place where you register the httpModule in the IIS pipeline, so I guess that’s the problem here. You may use PreApplicationStartCode (instead of using the web.config file) to do that – later answers in this question might help: http://stackoverflow.com/questions/239802/programmatically-register-httpmodules-at-runtime. Having said that, I would recommend using the httpModules section to add ApplicationInsightsHttpModule – it is just more convenient.

  • Ted
    Reply

    great article!
    Can I use Functions.Decorate() in other project to hijack the code? What’s the usage of thos environment variables?

Leave a Comment