From 40bd03a693385f9fee3764bd388c5e95665ccf20 Mon Sep 17 00:00:00 2001 From: littleaj <1690572+littleaj@users.noreply.github.com> Date: Wed, 3 Jul 2019 12:35:07 -0700 Subject: [PATCH 1/4] counter variables should not be static --- .../quickpulse/QuickPulseDataCollector.java | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/core/src/main/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollector.java b/core/src/main/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollector.java index 068d3ad5981..b327a29e5f4 100644 --- a/core/src/main/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollector.java +++ b/core/src/main/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollector.java @@ -72,12 +72,12 @@ 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(); @@ -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) { From 269ede8e513c4ae9171b506fe8465b0de010700f Mon Sep 17 00:00:00 2001 From: littleaj <1690572+littleaj@users.noreply.github.com> Date: Wed, 3 Jul 2019 15:23:14 -0700 Subject: [PATCH 2/4] add test for data collector. added peek method for easier validation. fixed duration conversion bug. --- CHANGELOG.md | 1 + .../quickpulse/QuickPulseDataCollector.java | 15 +- .../QuickPulseDataCollectorTests.java | 165 ++++++++++++++++++ 3 files changed, 178 insertions(+), 3 deletions(-) create mode 100644 core/src/test/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollectorTests.java diff --git a/CHANGELOG.md b/CHANGELOG.md index 3add0d1c361..84f1ae42a4a 100644 --- 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/core/src/main/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollector.java b/core/src/main/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollector.java index b327a29e5f4..35564faac58 100644 --- a/core/src/main/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollector.java +++ b/core/src/main/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollector.java @@ -84,7 +84,7 @@ public FinalCounters(Counters currentCounters, MemoryMXBean memory, CpuPerforman } } - private static class CountAndDuration { + static class CountAndDuration { public final long count; public final long 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/core/src/test/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollectorTests.java b/core/src/test/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollectorTests.java new file mode 100644 index 00000000000..443d5f9265e --- /dev/null +++ b/core/src/test/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollectorTests.java @@ -0,0 +1,165 @@ +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"; + + @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); + } +} From 3cc135c6a101f4c183bf5cf8aca4c11ffa53ba00 Mon Sep 17 00:00:00 2001 From: littleaj <1690572+littleaj@users.noreply.github.com> Date: Wed, 3 Jul 2019 15:33:48 -0700 Subject: [PATCH 3/4] make sure data collector is disabled --- .../internal/quickpulse/QuickPulseDataCollectorTests.java | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/core/src/test/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollectorTests.java b/core/src/test/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollectorTests.java index 443d5f9265e..c86f8791182 100644 --- a/core/src/test/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollectorTests.java +++ b/core/src/test/java/com/microsoft/applicationinsights/internal/quickpulse/QuickPulseDataCollectorTests.java @@ -17,6 +17,11 @@ 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(); From 8f3ce1ea651304f3f84493ec4be9c8ced8399016 Mon Sep 17 00:00:00 2001 From: littleaj <1690572+littleaj@users.noreply.github.com> Date: Fri, 5 Jul 2019 19:26:51 -0700 Subject: [PATCH 4/4] make event test more predictable --- .../smoketest/CoreAndFilterTests.java | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/test/smoke/testApps/CoreAndFilter/src/smokeTest/java/com/microsoft/applicationinsights/smoketest/CoreAndFilterTests.java b/test/smoke/testApps/CoreAndFilter/src/smokeTest/java/com/microsoft/applicationinsights/smoketest/CoreAndFilterTests.java index dfd33d13c01..24fbd44e22b 100644 --- a/test/smoke/testApps/CoreAndFilter/src/smokeTest/java/com/microsoft/applicationinsights/smoketest/CoreAndFilterTests.java +++ b/test/smoke/testApps/CoreAndFilter/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 events = mockedIngestion.getTelemetryDataByType("EventData"); + events.sort(new Comparator() { + @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";