From 0713da7393971e7fc2329c75c38c8a0897d1deab Mon Sep 17 00:00:00 2001 From: Jon Chambers Date: Tue, 9 Jun 2020 16:35:16 -0400 Subject: [PATCH] Record experiment results with a timer instead of a counter. --- .../textsecuregcm/experiment/Experiment.java | 19 +++++++---- .../experiment/ExperimentTest.java | 34 +++++++++++-------- 2 files changed, 32 insertions(+), 21 deletions(-) diff --git a/service/src/main/java/org/whispersystems/textsecuregcm/experiment/Experiment.java b/service/src/main/java/org/whispersystems/textsecuregcm/experiment/Experiment.java index 9a9306fc3..ce733fbc9 100644 --- a/service/src/main/java/org/whispersystems/textsecuregcm/experiment/Experiment.java +++ b/service/src/main/java/org/whispersystems/textsecuregcm/experiment/Experiment.java @@ -9,13 +9,14 @@ import io.micrometer.core.instrument.Tag; import java.util.List; import java.util.Objects; import java.util.concurrent.CompletionStage; +import java.util.concurrent.TimeUnit; /** * An experiment compares the results of two operations and records metrics to assess how frequently they match. */ public class Experiment { - private final String counterName; + private final String timerName; private final MeterRegistry meterRegistry; static final String OUTCOME_TAG = "outcome"; @@ -35,23 +36,29 @@ public class Experiment { throw new IllegalArgumentException("Experiments must have a name"); } - this.counterName = MetricRegistry.name(getClass(), names); + this.timerName = MetricRegistry.name(getClass(), names); this.meterRegistry = meterRegistry; } public void compareResult(final T expected, final CompletionStage experimentStage) { + // We're assuming that we get the experiment completion stage as soon as possible after it's started, but this + // start time will inescapably have some "wiggle" to it. + final long start = System.nanoTime(); + experimentStage.whenComplete((actual, cause) -> { + final long duration = System.nanoTime() - start; + if (cause != null) { - meterRegistry.counter(counterName, + meterRegistry.timer(timerName, List.of(Tag.of(OUTCOME_TAG, ERROR_OUTCOME), Tag.of(CAUSE_TAG, cause.getClass().getSimpleName()))) - .increment(); + .record(duration, TimeUnit.NANOSECONDS); } else { final boolean shouldIgnore = actual == null && expected != null; if (!shouldIgnore) { - meterRegistry.counter(counterName, + meterRegistry.timer(timerName, List.of(Tag.of(OUTCOME_TAG, Objects.equals(expected, actual) ? MATCH_OUTCOME : MISMATCH_OUTCOME))) - .increment(); + .record(duration, TimeUnit.NANOSECONDS); } } }); diff --git a/service/src/test/java/org/whispersystems/textsecuregcm/experiment/ExperimentTest.java b/service/src/test/java/org/whispersystems/textsecuregcm/experiment/ExperimentTest.java index f22a4e2c6..1b60f2fa6 100644 --- a/service/src/test/java/org/whispersystems/textsecuregcm/experiment/ExperimentTest.java +++ b/service/src/test/java/org/whispersystems/textsecuregcm/experiment/ExperimentTest.java @@ -3,6 +3,7 @@ package org.whispersystems.textsecuregcm.experiment; import io.micrometer.core.instrument.Counter; import io.micrometer.core.instrument.MeterRegistry; import io.micrometer.core.instrument.Tag; +import io.micrometer.core.instrument.Timer; import org.junit.Before; import org.junit.Test; import org.mockito.ArgumentCaptor; @@ -13,11 +14,14 @@ import java.util.HashSet; import java.util.List; import java.util.Set; import java.util.concurrent.CompletableFuture; +import java.util.concurrent.TimeUnit; import static org.junit.Assert.*; import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.anyLong; import static org.mockito.ArgumentMatchers.anyString; import static org.mockito.ArgumentMatchers.anyVararg; +import static org.mockito.ArgumentMatchers.eq; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.never; import static org.mockito.Mockito.verify; @@ -34,63 +38,63 @@ public class ExperimentTest { @Test public void compareResultMatch() { - final Counter counter = mock(Counter.class); - when(meterRegistry.counter(anyString(), ArgumentMatchers.>any())).thenReturn(counter); + final Timer timer = mock(Timer.class); + when(meterRegistry.timer(anyString(), ArgumentMatchers.>any())).thenReturn(timer); new Experiment(meterRegistry, "test").compareResult(12, CompletableFuture.completedFuture(12)); @SuppressWarnings("unchecked") final ArgumentCaptor> tagCaptor = ArgumentCaptor.forClass(Iterable.class); - verify(meterRegistry).counter(anyString(), tagCaptor.capture()); + verify(meterRegistry).timer(anyString(), tagCaptor.capture()); final Set tags = getTagSet(tagCaptor.getValue()); assertEquals(tags, Set.of(Tag.of(Experiment.OUTCOME_TAG, Experiment.MATCH_OUTCOME))); - verify(counter).increment(); + verify(timer).record(anyLong(), eq(TimeUnit.NANOSECONDS)); } @Test public void compareResultMismatch() { - final Counter counter = mock(Counter.class); - when(meterRegistry.counter(anyString(), ArgumentMatchers.>any())).thenReturn(counter); + final Timer timer = mock(Timer.class); + when(meterRegistry.timer(anyString(), ArgumentMatchers.>any())).thenReturn(timer); new Experiment(meterRegistry, "test").compareResult(12, CompletableFuture.completedFuture(77)); @SuppressWarnings("unchecked") final ArgumentCaptor> tagCaptor = ArgumentCaptor.forClass(Iterable.class); - verify(meterRegistry).counter(anyString(), tagCaptor.capture()); + verify(meterRegistry).timer(anyString(), tagCaptor.capture()); final Set tags = getTagSet(tagCaptor.getValue()); assertEquals(tags, Set.of(Tag.of(Experiment.OUTCOME_TAG, Experiment.MISMATCH_OUTCOME))); - verify(counter).increment(); + verify(timer).record(anyLong(), eq(TimeUnit.NANOSECONDS)); } @Test public void compareResultError() { - final Counter counter = mock(Counter.class); - when(meterRegistry.counter(anyString(), ArgumentMatchers.>any())).thenReturn(counter); + final Timer timer = mock(Timer.class); + when(meterRegistry.timer(anyString(), ArgumentMatchers.>any())).thenReturn(timer); new Experiment(meterRegistry, "test").compareResult(12, CompletableFuture.failedFuture(new RuntimeException("OH NO"))); @SuppressWarnings("unchecked") final ArgumentCaptor> tagCaptor = ArgumentCaptor.forClass(Iterable.class); - verify(meterRegistry).counter(anyString(), tagCaptor.capture()); + verify(meterRegistry).timer(anyString(), tagCaptor.capture()); final Set tags = getTagSet(tagCaptor.getValue()); assertEquals(tags, Set.of(Tag.of(Experiment.OUTCOME_TAG, Experiment.ERROR_OUTCOME), Tag.of(Experiment.CAUSE_TAG, "RuntimeException"))); - verify(counter).increment(); + verify(timer).record(anyLong(), eq(TimeUnit.NANOSECONDS)); } @Test public void compareResultNoExperimentData() { - final Counter counter = mock(Counter.class); - when(meterRegistry.counter(anyString(), ArgumentMatchers.>any())).thenReturn(counter); + final Timer timer = mock(Timer.class); + when(meterRegistry.timer(anyString(), ArgumentMatchers.>any())).thenReturn(timer); new Experiment(meterRegistry, "test").compareResult(12, CompletableFuture.completedFuture(null)); - verify(counter, never()).increment(); + verify(timer, never()).record(anyLong(), eq(TimeUnit.NANOSECONDS)); } private static Set getTagSet(final Iterable tags) {