Record experiment outcomes with timers instead of counters.

This commit is contained in:
Jon Chambers 2020-08-18 18:14:57 -04:00 committed by Jon Chambers
parent 7e8974683c
commit 56b27ea785
2 changed files with 78 additions and 66 deletions

View File

@ -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 <T> void compareFutureResult(final T expected, final CompletionStage<T> 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 <T> void compareSupplierResult(final T expected, final Supplier<T> 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 <T> void compareSupplierResultAsync(final T expected, final Supplier<T> 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
<T> void recordResult(final T expected, final T actual) {
<T> 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);
}
}
}

View File

@ -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 }
};
}
}