Merge pull request #964 from microsoft/fix_quickpulse_counters

counter variables should not be static
microsoft · Jul 6, 2019 · 1cf96aa · 1cf96aa
2 parents 6c2d6e3 + 8f3ce1e
commit 1cf96aa
Show file tree

Hide file tree

Showing 4 changed files with 201 additions and 13 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -9,6 +9,7 @@
 - Added retries to CDSProfileFetcher [#901](https://github.com/microsoft/ApplicationInsights-Java/pull/901)
 - Fix [#919](https://github.com/microsoft/ApplicationInsights-Java/issues/919) - Fixed issue when adding duplicate Windows performance counter.
 - Added caching of sdk version id, reducing number of file IO operations [#896](https://github.com/microsoft/ApplicationInsights-Java/pull/896)
+- Fixed bug with live metrics (QuickPulse) where request/dependency durations were being truncated to the millisecond.
 - Misc stability improvements
 [#932](https://github.com/microsoft/ApplicationInsights-Java/pull/932)
 [#941](https://github.com/microsoft/ApplicationInsights-Java/pull/941)

diff --git a/...n/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollector.java b/...n/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollector.java
@@ -72,19 +72,19 @@ public FinalCounters(Counters currentCounters, MemoryMXBean memory, CpuPerforman
             }
             exceptions = currentCounters.exceptions.get();
 
-            CountAndDuration countAndDuration = currentCounters.decodeCountAndDuration(currentCounters.requestsAndDurations.get());
+            CountAndDuration countAndDuration = Counters.decodeCountAndDuration(currentCounters.requestsAndDurations.get());
             requests = countAndDuration.count;
             this.requestsDuration = countAndDuration.duration;
             this.unsuccessfulRequests = currentCounters.unsuccessfulRequests.get();
 
-            countAndDuration = currentCounters.decodeCountAndDuration(currentCounters.rddsAndDuations.get());
+            countAndDuration = Counters.decodeCountAndDuration(currentCounters.rddsAndDuations.get());
             this.rdds = countAndDuration.count;
             this.rddsDuration = countAndDuration.duration;
             this.unsuccessfulRdds = currentCounters.unsuccessfulRdds.get();
         }
     }
 
-    private static class CountAndDuration {
+    static class CountAndDuration {
         public final long count;
         public final long duration;
 
@@ -94,17 +94,17 @@ private CountAndDuration(long count, long duration) {
         }
     }
 
-    private static class Counters {
+    static class Counters {
         private static final long MAX_COUNT = 524287L;
         private static final long MAX_DURATION = 17592186044415L;
 
-        public static final AtomicInteger exceptions = new AtomicInteger(0);
+        public final AtomicInteger exceptions = new AtomicInteger(0);
 
-        static final AtomicLong requestsAndDurations = new AtomicLong(0);
-        static final AtomicInteger unsuccessfulRequests = new AtomicInteger(0);
+        final AtomicLong requestsAndDurations = new AtomicLong(0);
+        final AtomicInteger unsuccessfulRequests = new AtomicInteger(0);
 
-        static final AtomicLong rddsAndDuations = new AtomicLong(0);
-        static final AtomicInteger unsuccessfulRdds = new AtomicInteger(0);
+        final AtomicLong rddsAndDuations = new AtomicLong(0);
+        final AtomicInteger unsuccessfulRdds = new AtomicInteger(0);
 
         static long encodeCountAndDuration(long  count, long duration) {
             if (count > MAX_COUNT || duration > MAX_DURATION) {
@@ -161,6 +161,15 @@ public synchronized FinalCounters getAndRestart() {
         return null;
     }
 
+    /*@VisibleForTesting*/
+    synchronized FinalCounters peek() {
+        final Counters currentCounters = this.counters.get(); // this should be the only differece
+        if (currentCounters != null) {
+            return new FinalCounters(currentCounters, memory, cpuPerformanceCounterCalculator);
+        }
+        return null;
+    }
+
     public void add(Telemetry telemetry) {
         if (!telemetry.getContext().getInstrumentationKey().equals(ikey)) {
             return;
@@ -182,7 +191,7 @@ private void addDependency(RemoteDependencyTelemetry telemetry) {
             return;
         }
         counters.rddsAndDuations.addAndGet(
-                Counters.encodeCountAndDuration(1, telemetry.getDuration().getMilliseconds()));
+                Counters.encodeCountAndDuration(1, telemetry.getDuration().getTotalMilliseconds()));
         if (!telemetry.getSuccess()) {
             counters.unsuccessfulRdds.incrementAndGet();
         }
@@ -203,7 +212,7 @@ private void addRequest(RequestTelemetry requestTelemetry) {
             return;
         }
 
-        counters.requestsAndDurations.addAndGet(Counters.encodeCountAndDuration(1, requestTelemetry.getDuration().getMilliseconds()));
+        counters.requestsAndDurations.addAndGet(Counters.encodeCountAndDuration(1, requestTelemetry.getDuration().getTotalMilliseconds()));
         if (!requestTelemetry.isSuccess()) {
             counters.unsuccessfulRequests.incrementAndGet();
         }

diff --git a/...a/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollectorTests.java b/...a/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollectorTests.java
@@ -0,0 +1,170 @@
+package com.microsoft.applicationinsights.internal.quickpulse;
+
+import com.microsoft.applicationinsights.internal.quickpulse.QuickPulseDataCollector.CountAndDuration;
+import com.microsoft.applicationinsights.internal.quickpulse.QuickPulseDataCollector.Counters;
+import com.microsoft.applicationinsights.internal.quickpulse.QuickPulseDataCollector.FinalCounters;
+import com.microsoft.applicationinsights.telemetry.Duration;
+import com.microsoft.applicationinsights.telemetry.ExceptionTelemetry;
+import com.microsoft.applicationinsights.telemetry.RemoteDependencyTelemetry;
+import com.microsoft.applicationinsights.telemetry.RequestTelemetry;
+import org.junit.*;
+
+import java.util.Date;
+
+import static org.junit.Assert.*;
+
+public class QuickPulseDataCollectorTests {
+
+    private static final String FAKE_INSTRUMENTATION_KEY = "fake-instrumentation-key";
+
+    @Before
+    public void setup() {
+        QuickPulseDataCollector.INSTANCE.disable();
+    }
+
+    @After
+    public void tearDown() {
+        QuickPulseDataCollector.INSTANCE.disable();
+    }
+
+    @Test
+    public void initialStateIsDisabled() {
+        assertNull(QuickPulseDataCollector.INSTANCE.peek());
+    }
+
+    @Test
+    public void emptyCountsAndDurationsAfterEnable() {
+        QuickPulseDataCollector.INSTANCE.enable(FAKE_INSTRUMENTATION_KEY);
+        final FinalCounters counters = QuickPulseDataCollector.INSTANCE.peek();
+        assertCountersReset(counters);
+    }
+
+    @Test
+    public void nullCountersAfterDisable() {
+        QuickPulseDataCollector.INSTANCE.enable(FAKE_INSTRUMENTATION_KEY);
+        QuickPulseDataCollector.INSTANCE.disable();
+        assertNull(QuickPulseDataCollector.INSTANCE.peek());
+    }
+
+    @Test
+    public void requestTelemetryIsCounted_DurationIsSum() {
+        QuickPulseDataCollector.INSTANCE.enable(FAKE_INSTRUMENTATION_KEY);
+
+        // add a success and peek
+        final long duration = 112233L;
+        RequestTelemetry rt = new RequestTelemetry("request-test", new Date(), duration, "200", true);
+        rt.getContext().setInstrumentationKey(FAKE_INSTRUMENTATION_KEY);
+        QuickPulseDataCollector.INSTANCE.add(rt);
+        FinalCounters counters = QuickPulseDataCollector.INSTANCE.peek();
+        assertEquals(1, counters.requests);
+        assertEquals(0, counters.unsuccessfulRequests);
+        assertEquals((double)duration, counters.requestsDuration, Math.ulp((double)duration));
+
+        // add another success and peek
+        final long duration2 = 65421L;
+        rt = new RequestTelemetry("request-test-2", new Date(), duration2, "200", true);
+        rt.getContext().setInstrumentationKey(FAKE_INSTRUMENTATION_KEY);
+        QuickPulseDataCollector.INSTANCE.add(rt);
+        counters = QuickPulseDataCollector.INSTANCE.peek();
+        double total = duration + duration2;
+        assertEquals(2, counters.requests);
+        assertEquals(0, counters.unsuccessfulRequests);
+        assertEquals(total, counters.requestsDuration, Math.ulp(total));
+
+        // add a failure and get/reset
+        final long duration3 = 9988L;
+        rt = new RequestTelemetry("request-test-3", new Date(), duration3, "400", false);
+        rt.getContext().setInstrumentationKey(FAKE_INSTRUMENTATION_KEY);
+        QuickPulseDataCollector.INSTANCE.add(rt);
+        counters = QuickPulseDataCollector.INSTANCE.getAndRestart();
+        total += duration3;
+        assertEquals(3, counters.requests);
+        assertEquals(1, counters.unsuccessfulRequests);
+        assertEquals(total, counters.requestsDuration, Math.ulp(total));
+
+        assertCountersReset(QuickPulseDataCollector.INSTANCE.peek());
+    }
+
+    @Test
+    public void dependencyTelemetryIsCounted_DurationIsSum() {
+        QuickPulseDataCollector.INSTANCE.enable(FAKE_INSTRUMENTATION_KEY);
+
+        // add a success and peek.
+        final long duration = 112233L;
+        RemoteDependencyTelemetry rdt = new RemoteDependencyTelemetry("dep-test", "dep-test-cmd", new Duration(duration), true);
+        rdt.getContext().setInstrumentationKey(FAKE_INSTRUMENTATION_KEY);
+        QuickPulseDataCollector.INSTANCE.add(rdt);
+        FinalCounters counters = QuickPulseDataCollector.INSTANCE.peek();
+        assertEquals(1, counters.rdds);
+        assertEquals(0, counters.unsuccessfulRdds);
+        assertEquals((double)duration, counters.rddsDuration, Math.ulp((double)duration));
+
+        // add another success and peek.
+        final long duration2 = 334455L;
+        rdt = new RemoteDependencyTelemetry("dep-test-2", "dep-test-cmd-2", new Duration(duration2), true);
+        rdt.getContext().setInstrumentationKey(FAKE_INSTRUMENTATION_KEY);
+        QuickPulseDataCollector.INSTANCE.add(rdt);
+        counters = QuickPulseDataCollector.INSTANCE.peek();
+        assertEquals(2, counters.rdds);
+        assertEquals(0, counters.unsuccessfulRdds);
+        double total = duration + duration2;
+        assertEquals(total, counters.rddsDuration, Math.ulp(total));
+
+        // add a failure and get/reset.
+        final long duration3 = 123456L;
+        rdt = new RemoteDependencyTelemetry("dep-test-3", "dep-test-cmd-3", new Duration(duration3), false);
+        rdt.getContext().setInstrumentationKey(FAKE_INSTRUMENTATION_KEY);
+        QuickPulseDataCollector.INSTANCE.add(rdt);
+        counters = QuickPulseDataCollector.INSTANCE.getAndRestart();
+        assertEquals(3, counters.rdds);
+        assertEquals(1, counters.unsuccessfulRdds);
+        total += duration3;
+        assertEquals(total, counters.rddsDuration, Math.ulp(total));
+
+        assertCountersReset(QuickPulseDataCollector.INSTANCE.peek());
+    }
+
+    @Test
+    public void exceptionTelemetryIsCounted() {
+        QuickPulseDataCollector.INSTANCE.enable(FAKE_INSTRUMENTATION_KEY);
+
+        ExceptionTelemetry et = new ExceptionTelemetry(new Exception());
+        et.getContext().setInstrumentationKey(FAKE_INSTRUMENTATION_KEY);
+        QuickPulseDataCollector.INSTANCE.add(et);
+        FinalCounters counters = QuickPulseDataCollector.INSTANCE.peek();
+        assertEquals(1, counters.exceptions, Math.ulp(1.0));
+
+        et = new ExceptionTelemetry(new Exception());
+        et.getContext().setInstrumentationKey(FAKE_INSTRUMENTATION_KEY);
+        QuickPulseDataCollector.INSTANCE.add(et);
+        counters = QuickPulseDataCollector.INSTANCE.getAndRestart();
+        assertEquals(2, counters.exceptions, Math.ulp(2.0));
+
+        assertCountersReset(QuickPulseDataCollector.INSTANCE.peek());
+    }
+
+    @Test
+    public void encodeDecodeIsIdentity() {
+        final long count = 456L;
+        final long duration = 112233L;
+        final long encoded = Counters.encodeCountAndDuration(count, duration);
+        final CountAndDuration inputs = Counters.decodeCountAndDuration(encoded);
+        assertEquals(count, inputs.count);
+        assertEquals(duration, inputs.duration);
+    }
+
+    private void assertCountersReset(FinalCounters counters) {
+        assertNotNull(counters);
+
+        assertEquals(0, counters.rdds);
+        assertEquals(0.0, counters.rddsDuration, Math.ulp(0.0));
+        assertEquals(0, counters.unsuccessfulRdds);
+
+        assertEquals(0, counters.requests);
+        assertEquals(0.0, counters.requestsDuration, Math.ulp(0.0));
+        assertEquals(0, counters.unsuccessfulRequests);
+
+        // FIXME exceptions is stored as a double but counted as an int; is that correct?
+        assertEquals(0, (int) counters.exceptions);
+    }
+}
diff --git a/...er/src/smokeTest/java/com/microsoft/applicationinsights/smoketest/CoreAndFilterTests.java b/...er/src/smokeTest/java/com/microsoft/applicationinsights/smoketest/CoreAndFilterTests.java
@@ -28,6 +28,7 @@
 import static org.hamcrest.Matchers.*;
 import static org.junit.Assert.*;
 
+import java.util.Comparator;
 import java.util.List;
 
 public class CoreAndFilterTests extends AiSmokeTest {
@@ -65,11 +66,18 @@ public void testTrackEvent() throws Exception {
 				expectedItems, totalItems);
 
 		// TODO get event data envelope and verify value
-		EventData d = getTelemetryDataForType(0, "EventData");
+        final List<EventData> events = mockedIngestion.getTelemetryDataByType("EventData");
+        events.sort(new Comparator<EventData>() {
+            @Override
+            public int compare(EventData o1, EventData o2) {
+                return o1.getName().compareTo(o2.getName());
+            }
+        });
+        EventData d = events.get(1);
 		final String name = "EventDataTest";
 		assertEquals(name, d.getName());
 
-		EventData d2 = getTelemetryDataForType(1, "EventData");
+		EventData d2 = events.get(0);
 
 		final String expectedname = "EventDataPropertyTest";
 		final String expectedProperties = "value";