Event Counter metric support for ingestion response time (#1796)

* Added EventCounter to track breeze response time.

* Removed unused reference.

* Update to Changelog.md

* Resolving merge conflict

* Added EventCounter as non event menthod.

* Fixed test - removed event counter check

* Added test case for Event Counter

* Adding sleep to trace listener.

* Resolving merge conflict

* Fixed EventCounter test

* Fuxed file name

* Added ingestion failure test case.

* Fixed test case

Co-authored-by: Cijo Thomas <cithomas@microsoft.com>

BASE/Test/Microsoft.ApplicationInsights.Test/Microsoft.ApplicationInsights.Tests/Channel/EventCounterListener.cs

@@ -0,0 +1,36 @@
+namespace Microsoft.ApplicationInsights.Channel
+{
+    using System;
+    using System.Collections.Concurrent;
+    using System.Collections.Generic;
+    using System.Diagnostics.Tracing;
+
+    internal class EventCounterListener : EventListener
+    {
+        private const long AllKeywords = -1;
+        public ConcurrentQueue<EventWrittenEventArgs> EventsReceived { get; private set; }
+
+        public EventCounterListener()
+        {
+            this.EventsReceived = new ConcurrentQueue<EventWrittenEventArgs>();
+        }
+
+        protected override void OnEventWritten(EventWrittenEventArgs eventData)
+        {
+            this.EventsReceived.Enqueue(eventData);
+        }
+
+        protected override void OnEventSourceCreated(EventSource eventSource)
+        {
+            if (string.Equals(eventSource.Name, "Microsoft-ApplicationInsights-Core", StringComparison.Ordinal))
+            {
+                var eventCounterArguments = new Dictionary<string, string>
+                {
+                    {"EventCounterIntervalSec", "1"}
+                };
+                EnableEvents(eventSource, EventLevel.LogAlways, (EventKeywords)AllKeywords, eventCounterArguments);
+            }
+        }
+
+    }
+}

BASE/Test/Microsoft.ApplicationInsights.Test/Microsoft.ApplicationInsights.Tests/Channel/TransmissionTest.cs

@@ -15,6 +15,8 @@
     using Microsoft.ApplicationInsights.TestFramework;
     using Microsoft.VisualStudio.TestTools.UnitTesting;
     using System.CodeDom;
+    using Microsoft.ApplicationInsights.Extensibility.Implementation.Tracing;
+    using System.Diagnostics.Tracing;
 
     public class TransmissionTest
     {
@@ -86,6 +88,7 @@ public void SetsTimeoutToSpecifiedValue()
         public class SendAsync
         {
             private readonly Uri testUri = new Uri("https://127.0.0.1/");
+            private const long AllKeywords = -1;
 
             [TestMethod]
             public async Task SendAsyncUsesPostMethodToSpecifiedHttpEndpoint()
@@ -363,6 +366,141 @@ public async Task SendAsyncReturnsCorrectHttpResponseWrapperWithRetryHeaderWhenN
                 }
 
             }
+
+#if NETCOREAPP2_1 || NETCOREAPP3_1
+            [TestMethod]
+            public async Task SendAsyncLogsIngestionReponseTimeEventCounter()
+            {
+                var handler = new HandlerForFakeHttpClient
+                {
+                    InnerHandler = new HttpClientHandler(),
+                    OnSendAsync = (req, cancellationToken) =>
+                    {
+                        Thread.Sleep(TimeSpan.FromMilliseconds(30));
+                        return Task.FromResult<HttpResponseMessage>(new HttpResponseMessage());
+                    }
+                };
+
+                using (var fakeHttpClient = new HttpClient(handler))
+                {
+                    // Instantiate Transmission with the mock HttpClient
+                    Transmission transmission = new Transmission(testUri, new byte[] { 1, 2, 3, 4, 5 }, fakeHttpClient, string.Empty, string.Empty);
+
+                    using (var listener = new EventCounterListener())
+                    {
+                        for (int i = 0; i < 5; i++)
+                        {
+                            HttpWebResponseWrapper result = await transmission.SendAsync();
+                        }
+                        //Sleep for few seconds as the event counter is sampled on a second basis
+                        Thread.Sleep(TimeSpan.FromSeconds(3));
+
+                        // VERIFY
+                        // We validate by checking SDK traces.
+                        var allTraces = listener.EventsReceived.ToList();
+                        var traces = allTraces.Where(item => item.EventName == "EventCounters").ToList();
+                        Assert.IsTrue(traces?.Count >= 1);
+                        var payload = (IDictionary<string, object>)traces[0].Payload[0];
+                        Assert.AreEqual("IngestionEndpoint-ResponseTimeMsec", payload["Name"].ToString());
+                        Assert.IsTrue((int)payload["Count"] >= 5);
+                        // Mean should be more than 30 ms, as we introduced a delay of 30ms in SendAsync.
+#if NETCOREAPP2_1
+                        Assert.IsTrue((float)payload["Mean"] >= 30);
+#endif
+
+#if NETCOREAPP3_1
+                        Assert.IsTrue((double)payload["Mean"] >= 30);
+#endif
+                    }
+                }
+            }
+
+            [TestMethod]
+            public async Task SendAsyncLogsIngestionReponseTimeOnFailureEventCounter()
+            {
+                var handler = new HandlerForFakeHttpClient
+                {
+                    InnerHandler = new HttpClientHandler(),
+                    OnSendAsync = (req, cancellationToken) =>
+                    {
+                        Thread.Sleep(TimeSpan.FromMilliseconds(30));
+                        HttpResponseMessage response = new HttpResponseMessage();
+                        response.StatusCode = HttpStatusCode.ServiceUnavailable;
+                        return Task.FromResult<HttpResponseMessage>(response);
+                    }
+                };
+
+                using (var fakeHttpClient = new HttpClient(handler))
+                {
+                    // Instantiate Transmission with the mock HttpClient
+                    Transmission transmission = new Transmission(testUri, new byte[] { 1, 2, 3, 4, 5 }, fakeHttpClient, string.Empty, string.Empty);
+
+                    using (var listener = new EventCounterListener())
+                    {
+                        for (int i = 0; i < 5; i++)
+                        {
+                            HttpWebResponseWrapper result = await transmission.SendAsync();
+                        }
+                        //Sleep for few seconds as the event counter is sampled on a second basis
+                        Thread.Sleep(TimeSpan.FromSeconds(3));
+
+                        // VERIFY
+                        // We validate by checking SDK traces.
+                        var allTraces = listener.EventsReceived.ToList();
+                        var traces = allTraces.Where(item => item.EventName == "EventCounters").ToList();
+                        Assert.IsTrue(traces?.Count >= 1);
+                        var payload = (IDictionary<string, object>)traces[0].Payload[0];
+                        Assert.AreEqual("IngestionEndpoint-ResponseTimeMsec", payload["Name"].ToString());
+                        Assert.IsTrue((int)payload["Count"] >= 5);
+                        // Mean should be more than 30 ms, as we introduced a delay of 30ms in SendAsync.
+#if NETCOREAPP2_1
+                        Assert.IsTrue((float)payload["Mean"] >= 30);
+#endif
+
+#if NETCOREAPP3_1
+                        Assert.IsTrue((double)payload["Mean"] >= 30);
+#endif
+                    }
+                }
+            }
+#endif
+            [TestMethod]
+            public async Task SendAsyncLogsIngestionReponseTimeAndStatusCode()
+            {
+                var handler = new HandlerForFakeHttpClient
+                {
+                    InnerHandler = new HttpClientHandler(),
+                    OnSendAsync = (req, cancellationToken) =>
+                    {
+                        return Task.FromResult<HttpResponseMessage>(new HttpResponseMessage());
+                    }
+                };
+
+                using (var fakeHttpClient = new HttpClient(handler))
+                {
+                    // Instantiate Transmission with the mock HttpClient
+                    Transmission transmission = new Transmission(testUri, new byte[] { 1, 2, 3, 4, 5 }, fakeHttpClient, string.Empty, string.Empty);
+
+                    using (var listener = new TestEventListener())
+                    {
+                        var eventCounterArguments = new Dictionary<string, string>
+                        {
+                            {"EventCounterIntervalSec", "1"}
+                        };
+
+                        listener.EnableEvents(CoreEventSource.Log, EventLevel.LogAlways, (EventKeywords)AllKeywords, eventCounterArguments);
+
+                        HttpWebResponseWrapper result = await transmission.SendAsync();
+
+                        // VERIFY
+                        // We validate by checking SDK traces.
+                        var allTraces = listener.Messages.ToList();
+                        // Event 67 is logged after response from Ingestion Service.
+                        var traces = allTraces.Where(item => item.EventId == 67).ToList();
+                        Assert.AreEqual(1, traces.Count);
+                    }
+                }
+            }
         }
     }
 

BASE/src/Microsoft.ApplicationInsights/Channel/Transmission.cs

@@ -2,6 +2,7 @@
 {
     using System;
     using System.Collections.Generic;
+    using System.Diagnostics;
     using System.IO;
     using System.Net;
     using System.Net.Http;
@@ -159,9 +160,16 @@ public virtual async Task<HttpWebResponseWrapper> SendAsync()
                             // "The request failed due to an underlying issue such as network connectivity, DNS failure, server certificate validation or timeout."
                             // i.e for Server errors (500 status code), no exception is thrown. Hence this method should read the response and status code,
                             // and return correct HttpWebResponseWrapper to give any Retry policies a chance to retry as needed.
+                            var stopwatch = new Stopwatch();
+                            stopwatch.Start();
 
                             using (var response = await client.SendAsync(request, ct.Token).ConfigureAwait(false))
                             {
+                                stopwatch.Stop();
+                                CoreEventSource.Log.IngestionResponseTime(response != null ? (int)response.StatusCode : -1, stopwatch.ElapsedMilliseconds);
+                                // Log ingestion respose time as event counter metric.
+                                CoreEventSource.Log.IngestionResponseTimeEventCounter(stopwatch.ElapsedMilliseconds);
+
                                 if (response != null)
                                 {
                                     wrapper = new HttpWebResponseWrapper

BASE/src/Microsoft.ApplicationInsights/Extensibility/Implementation/Tracing/CoreEventSource.cs

@@ -9,8 +9,19 @@ internal sealed class CoreEventSource : EventSource
     {
         public static readonly CoreEventSource Log = new CoreEventSource();
 
+#if NETSTANDARD2_0
+        public EventCounter IngestionResponseTimeCounter;
+#endif
+
         private readonly ApplicationNameProvider nameProvider = new ApplicationNameProvider();
 
+#if NETSTANDARD2_0
+        private CoreEventSource()
+        {
+            this.IngestionResponseTimeCounter = new EventCounter("IngestionEndpoint-ResponseTimeMsec", this);
+        }
+#endif
+
         public static bool IsVerboseEnabled
         {
             [NonEvent]
@@ -620,6 +631,17 @@ public void InitializationIsSkippedForSampledItem(string appDomainName = "Incorr
 
         #endregion
 
+        [Event(67, Message = "Backend has responded with {0} status code in {1}ms.", Level = EventLevel.Informational)]
+        public void IngestionResponseTime(int responseCode, float responseDurationInMs, string appDomainName = "Incorrect") => this.WriteEvent(67, responseCode, responseDurationInMs, this.nameProvider.Name);
+
+        [NonEvent]
+        public void IngestionResponseTimeEventCounter(float responseDurationInMs)
+        {
+#if NETSTANDARD2_0
+            this.IngestionResponseTimeCounter.WriteMetric(responseDurationInMs);
+#endif
+        }
+
         /// <summary>
         /// Keywords for the PlatformEventSource.
         /// </summary>

CHANGELOG.md

@@ -3,6 +3,7 @@
 ## VNext
 - [WorkerService package is modified to depend on 2.1.1 on Microsoft.Extensions.DependencyInjection so that it can be used in .NET Core 2.1 projects without nuget errors.](https://github.com/microsoft/ApplicationInsights-dotnet/issues/1677)
 - [Adding a flag to EventCounterCollector to enable/disable storing the EventSource name in the MetricNamespace and simplify the metric name](https://github.com/microsoft/ApplicationInsights-dotnet/issues/1341)
+- [New: EventCounter to track Ingestion Endpoint Response Time] (https://github.com/microsoft/ApplicationInsights-dotnet/pull/1796)
 
 ## Version 2.14.0
 - no changes since beta.