From 56b27ea785c3f1edc80c5452a93c4a25962d1f73 Mon Sep 17 00:00:00 2001 From: Jon Chambers Date: Tue, 18 Aug 2020 18:14:57 -0400 Subject: [PATCH] Record experiment outcomes with timers instead of counters. --- .../textsecuregcm/experiment/Experiment.java | 76 +++++++++++-------- .../experiment/ExperimentTest.java | 68 +++++++++-------- 2 files changed, 78 insertions(+), 66 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 a808c61d5..c00012182 100644 --- a/service/src/main/java/org/whispersystems/textsecuregcm/experiment/Experiment.java +++ b/service/src/main/java/org/whispersystems/textsecuregcm/experiment/Experiment.java @@ -1,8 +1,8 @@ package org.whispersystems.textsecuregcm.experiment; import com.google.common.annotations.VisibleForTesting; -import io.micrometer.core.instrument.Counter; import io.micrometer.core.instrument.Metrics; +import io.micrometer.core.instrument.Timer; import org.slf4j.Logger; import org.slf4j.LoggerFactory; @@ -11,7 +11,7 @@ import java.util.Optional; import java.util.concurrent.CompletableFuture; import java.util.concurrent.CompletionStage; import java.util.concurrent.Executor; -import java.util.concurrent.ExecutorService; +import java.util.concurrent.TimeUnit; import java.util.function.Supplier; import static com.codahale.metrics.MetricRegistry.name; @@ -23,12 +23,12 @@ public class Experiment { private final String name; - private final Counter matchCounter; - private final Counter errorCounter; + private final Timer matchTimer; + private final Timer errorTimer; - private final Counter bothPresentMismatchCounter; - private final Counter controlNullMismatchCounter; - private final Counter experimentNullMismatchCounter; + private final Timer bothPresentMismatchTimer; + private final Timer controlNullMismatchTimer; + private final Timer experimentNullMismatchTimer; private static final String OUTCOME_TAG = "outcome"; private static final String MATCH_OUTCOME = "match"; @@ -44,74 +44,84 @@ public class Experiment { public Experiment(final String... names) { this(name(Experiment.class, names), - Metrics.counter(name(Experiment.class, names), OUTCOME_TAG, MATCH_OUTCOME), - Metrics.counter(name(Experiment.class, names), OUTCOME_TAG, ERROR_OUTCOME), - Metrics.counter(name(Experiment.class, names), OUTCOME_TAG, MISMATCH_OUTCOME, MISMATCH_TYPE_TAG, BOTH_PRESENT_MISMATCH), - Metrics.counter(name(Experiment.class, names), OUTCOME_TAG, MISMATCH_OUTCOME, MISMATCH_TYPE_TAG, CONTROL_NULL_MISMATCH), - Metrics.counter(name(Experiment.class, names), OUTCOME_TAG, MISMATCH_OUTCOME, MISMATCH_TYPE_TAG, EXPERIMENT_NULL_MISMATCH)); + Metrics.timer(name(Experiment.class, names), OUTCOME_TAG, MATCH_OUTCOME), + Metrics.timer(name(Experiment.class, names), OUTCOME_TAG, ERROR_OUTCOME), + Metrics.timer(name(Experiment.class, names), OUTCOME_TAG, MISMATCH_OUTCOME, MISMATCH_TYPE_TAG, BOTH_PRESENT_MISMATCH), + Metrics.timer(name(Experiment.class, names), OUTCOME_TAG, MISMATCH_OUTCOME, MISMATCH_TYPE_TAG, CONTROL_NULL_MISMATCH), + Metrics.timer(name(Experiment.class, names), OUTCOME_TAG, MISMATCH_OUTCOME, MISMATCH_TYPE_TAG, EXPERIMENT_NULL_MISMATCH)); } @VisibleForTesting - Experiment(final String name, final Counter matchCounter, final Counter errorCounter, final Counter bothPresentMismatchCounter, final Counter controlNullMismatchCounter, final Counter experimentNullMismatchCounter) { + Experiment(final String name, final Timer matchTimer, final Timer errorTimer, final Timer bothPresentMismatchTimer, final Timer controlNullMismatchTimer, final Timer experimentNullMismatchTimer) { this.name = name; - this.matchCounter = matchCounter; - this.errorCounter = errorCounter; + this.matchTimer = matchTimer; + this.errorTimer = errorTimer; - this.bothPresentMismatchCounter = bothPresentMismatchCounter; - this.controlNullMismatchCounter = controlNullMismatchCounter; - this.experimentNullMismatchCounter = experimentNullMismatchCounter; + this.bothPresentMismatchTimer = bothPresentMismatchTimer; + this.controlNullMismatchTimer = controlNullMismatchTimer; + this.experimentNullMismatchTimer = experimentNullMismatchTimer; } public void compareFutureResult(final T expected, final CompletionStage experimentStage) { + final long startNanos = System.nanoTime(); + experimentStage.whenComplete((actual, cause) -> { + final long durationNanos = System.nanoTime() - startNanos; + if (cause != null) { - recordError(cause); + recordError(cause, durationNanos); } else { - recordResult(expected, actual); + recordResult(expected, actual, durationNanos); } }); } public void compareSupplierResult(final T expected, final Supplier experimentSupplier) { + final long startNanos = System.nanoTime(); + try { - recordResult(expected, experimentSupplier.get()); + final T result = experimentSupplier.get(); + + recordResult(expected, result, System.nanoTime() - startNanos); } catch (final Exception e) { - recordError(e); + recordError(e, System.nanoTime() - startNanos); } } public void compareSupplierResultAsync(final T expected, final Supplier experimentSupplier, final Executor executor) { + final long startNanos = System.nanoTime(); + try { compareFutureResult(expected, CompletableFuture.supplyAsync(experimentSupplier, executor)); } catch (final Exception e) { - recordError(e); + recordError(e, System.nanoTime() - startNanos); } } - private void recordError(final Throwable cause) { + private void recordError(final Throwable cause, final long durationNanos) { log.warn("Experiment {} threw an exception.", name, cause); - errorCounter.increment(); + errorTimer.record(durationNanos, TimeUnit.NANOSECONDS); } @VisibleForTesting - void recordResult(final T expected, final T actual) { + void recordResult(final T expected, final T actual, final long durationNanos) { if (expected instanceof Optional && actual instanceof Optional) { - recordResult(((Optional)expected).orElse(null), ((Optional)actual).orElse(null)); + recordResult(((Optional)expected).orElse(null), ((Optional)actual).orElse(null), durationNanos); } else { - final Counter counter; + final Timer Timer; if (Objects.equals(expected, actual)) { - counter = matchCounter; + Timer = matchTimer; } else if (expected == null) { - counter = controlNullMismatchCounter; + Timer = controlNullMismatchTimer; } else if (actual == null) { - counter = experimentNullMismatchCounter; + Timer = experimentNullMismatchTimer; } else { - counter = bothPresentMismatchCounter; + Timer = bothPresentMismatchTimer; } - counter.increment(); + Timer.record(durationNanos, 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 c939f5ca2..e654ac11d 100644 --- a/service/src/test/java/org/whispersystems/textsecuregcm/experiment/ExperimentTest.java +++ b/service/src/test/java/org/whispersystems/textsecuregcm/experiment/ExperimentTest.java @@ -1,13 +1,12 @@ package org.whispersystems.textsecuregcm.experiment; -import io.micrometer.core.instrument.Counter; +import io.micrometer.core.instrument.Timer; import junitparams.JUnitParamsRunner; import junitparams.Parameters; import org.junit.Before; import org.junit.Test; import org.junit.runner.RunWith; -import java.util.List; import java.util.Optional; import java.util.concurrent.CompletableFuture; import java.util.concurrent.ExecutorService; @@ -16,50 +15,51 @@ import java.util.concurrent.RejectedExecutionException; import java.util.concurrent.TimeUnit; import static org.mockito.ArgumentMatchers.any; +import static org.mockito.ArgumentMatchers.anyLong; +import static org.mockito.ArgumentMatchers.eq; import static org.mockito.Mockito.doThrow; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.reset; import static org.mockito.Mockito.verify; -import static org.mockito.Mockito.when; @RunWith(JUnitParamsRunner.class) public class ExperimentTest { - private Counter matchCounter; - private Counter errorCounter; + private Timer matchTimer; + private Timer errorTimer; private Experiment experiment; @Before public void setUp() { - matchCounter = mock(Counter.class); - errorCounter = mock(Counter.class); + matchTimer = mock(Timer.class); + errorTimer = mock(Timer.class); - experiment = new Experiment("test", matchCounter, errorCounter, mock(Counter.class), mock(Counter.class), mock(Counter.class)); + experiment = new Experiment("test", matchTimer, errorTimer, mock(Timer.class), mock(Timer.class), mock(Timer.class)); } @Test public void compareFutureResult() { experiment.compareFutureResult(12, CompletableFuture.completedFuture(12)); - verify(matchCounter).increment(); + verify(matchTimer).record(anyLong(), eq(TimeUnit.NANOSECONDS)); } @Test public void compareFutureResultError() { experiment.compareFutureResult(12, CompletableFuture.failedFuture(new RuntimeException("OH NO"))); - verify(errorCounter).increment(); + verify(errorTimer).record(anyLong(), eq(TimeUnit.NANOSECONDS)); } @Test public void compareSupplierResultMatch() { experiment.compareSupplierResult(12, () -> 12); - verify(matchCounter).increment(); + verify(matchTimer).record(anyLong(), eq(TimeUnit.NANOSECONDS)); } @Test public void compareSupplierResultError() { experiment.compareSupplierResult(12, () -> { throw new RuntimeException("OH NO"); }); - verify(errorCounter).increment(); + verify(errorTimer).record(anyLong(), eq(TimeUnit.NANOSECONDS)); } @Test @@ -70,7 +70,7 @@ public class ExperimentTest { experimentExecutor.shutdown(); experimentExecutor.awaitTermination(1, TimeUnit.SECONDS); - verify(matchCounter).increment(); + verify(matchTimer).record(anyLong(), eq(TimeUnit.NANOSECONDS)); } @Test @@ -81,7 +81,7 @@ public class ExperimentTest { experimentExecutor.shutdown(); experimentExecutor.awaitTermination(1, TimeUnit.SECONDS); - verify(errorCounter).increment(); + verify(errorTimer).record(anyLong(), eq(TimeUnit.NANOSECONDS)); } @Test @@ -90,38 +90,40 @@ public class ExperimentTest { doThrow(new RejectedExecutionException()).when(executorService).execute(any(Runnable.class)); experiment.compareSupplierResultAsync(12, () -> 12, executorService); - verify(errorCounter).increment(); + verify(errorTimer).record(anyLong(), eq(TimeUnit.NANOSECONDS)); } @Test @Parameters(method = "argumentsForTestRecordResult") - public void testRecordResult(final Object expected, final Object actual, final Experiment experiment, final Counter expectedCounter) { - reset(expectedCounter); + public void testRecordResult(final Object expected, final Object actual, final Experiment experiment, final Timer expectedTimer) { + reset(expectedTimer); - experiment.recordResult(expected, actual); - verify(expectedCounter).increment(); + final long durationNanos = 123; + + experiment.recordResult(expected, actual, durationNanos); + verify(expectedTimer).record(durationNanos, TimeUnit.NANOSECONDS); } @SuppressWarnings("unused") private Object argumentsForTestRecordResult() { // Hack: parameters are set before the @Before method gets called - final Counter matchCounter = mock(Counter.class); - final Counter errorCounter = mock(Counter.class); - final Counter bothPresentMismatchCounter = mock(Counter.class); - final Counter controlNullMismatchCounter = mock(Counter.class); - final Counter experimentNullMismatchCounter = mock(Counter.class); + final Timer matchTimer = mock(Timer.class); + final Timer errorTimer = mock(Timer.class); + final Timer bothPresentMismatchTimer = mock(Timer.class); + final Timer controlNullMismatchTimer = mock(Timer.class); + final Timer experimentNullMismatchTimer = mock(Timer.class); - final Experiment experiment = new Experiment("test", matchCounter, errorCounter, bothPresentMismatchCounter, controlNullMismatchCounter, experimentNullMismatchCounter); + final Experiment experiment = new Experiment("test", matchTimer, errorTimer, bothPresentMismatchTimer, controlNullMismatchTimer, experimentNullMismatchTimer); return new Object[] { - new Object[] { 12, 12, experiment, matchCounter }, - new Object[] { null, 12, experiment, controlNullMismatchCounter }, - new Object[] { 12, null, experiment, experimentNullMismatchCounter }, - new Object[] { 12, 17, experiment, bothPresentMismatchCounter }, - new Object[] { Optional.of(12), Optional.of(12), experiment, matchCounter }, - new Object[] { Optional.empty(), Optional.of(12), experiment, controlNullMismatchCounter }, - new Object[] { Optional.of(12), Optional.empty(), experiment, experimentNullMismatchCounter }, - new Object[] { Optional.of(12), Optional.of(17), experiment, bothPresentMismatchCounter } + new Object[] { 12, 12, experiment, matchTimer }, + new Object[] { null, 12, experiment, controlNullMismatchTimer }, + new Object[] { 12, null, experiment, experimentNullMismatchTimer }, + new Object[] { 12, 17, experiment, bothPresentMismatchTimer }, + new Object[] { Optional.of(12), Optional.of(12), experiment, matchTimer }, + new Object[] { Optional.empty(), Optional.of(12), experiment, controlNullMismatchTimer }, + new Object[] { Optional.of(12), Optional.empty(), experiment, experimentNullMismatchTimer }, + new Object[] { Optional.of(12), Optional.of(17), experiment, bothPresentMismatchTimer } }; } }