MirrorMirror
/
Signal-Server
mirror of https://github.com/signalapp/Signal-Server.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

Record distributions of timer values; stop recording error causes.

This commit is contained in:
Jon Chambers 2020-06-10 12:05:01 -04:00 committed by Jon Chambers
parent 4c623ca3c5
commit f701e3d834
2 changed files with 54 additions and 124 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

46
service/src/main/java/org/whispersystems/textsecuregcm/experiment/Experiment.java
View File

@ -2,11 +2,9 @@ package org.whispersystems.textsecuregcm.experiment;
import com.codahale.metrics.MetricRegistry; import com.codahale.metrics.MetricRegistry;
import com.google.common.annotations.VisibleForTesting; import com.google.common.annotations.VisibleForTesting;
import io.micrometer.core.instrument.MeterRegistry;
import io.micrometer.core.instrument.Metrics; import io.micrometer.core.instrument.Metrics;
import io.micrometer.core.instrument.Tag; import io.micrometer.core.instrument.Timer;
import java.util.List;
import java.util.Objects; import java.util.Objects;
import java.util.concurrent.CompletionStage; import java.util.concurrent.CompletionStage;
import java.util.concurrent.TimeUnit; import java.util.concurrent.TimeUnit;
@ -17,28 +15,35 @@ import java.util.function.Supplier;
*/ */
public class Experiment { public class Experiment {
private final String timerName; private final Timer matchTimer;
private final MeterRegistry meterRegistry; private final Timer mismatchTimer;
private final Timer errorTimer;
static final String OUTCOME_TAG = "outcome";
static final String CAUSE_TAG = "cause";
static final String OUTCOME_TAG = "outcome";
static final String MATCH_OUTCOME = "match"; static final String MATCH_OUTCOME = "match";
static final String MISMATCH_OUTCOME = "mismatch"; static final String MISMATCH_OUTCOME = "mismatch";
static final String ERROR_OUTCOME = "error"; static final String ERROR_OUTCOME = "error";
public Experiment(final String... names) { public Experiment(final String... names) {
this(Metrics.globalRegistry, names); this(buildTimer(MATCH_OUTCOME, names), buildTimer(MISMATCH_OUTCOME, names), buildTimer(ERROR_OUTCOME, names));
} }
@VisibleForTesting private static Timer buildTimer(final String outcome, final String... names) {
Experiment(final MeterRegistry meterRegistry, final String... names) {
if (names == null || names.length == 0) { if (names == null || names.length == 0) {
throw new IllegalArgumentException("Experiments must have a name"); throw new IllegalArgumentException("Experiments must have a name");
} }
this.timerName = MetricRegistry.name(getClass(), names); return Timer.builder(MetricRegistry.name(Experiment.class, names))
this.meterRegistry = meterRegistry; .tag(OUTCOME_TAG, outcome)
.publishPercentileHistogram()
.register(Metrics.globalRegistry);
}
@VisibleForTesting
Experiment(final Timer matchTimer, final Timer mismatchTimer, final Timer errorTimer) {
this.matchTimer = matchTimer;
this.mismatchTimer = mismatchTimer;
this.errorTimer = errorTimer;
} }
public <T> void compareFutureResult(final T expected, final CompletionStage<T> experimentStage) { public <T> void compareFutureResult(final T expected, final CompletionStage<T> experimentStage) {
@ -50,7 +55,7 @@ public class Experiment {
final long duration = System.nanoTime() - start; final long duration = System.nanoTime() - start;
if (cause != null) { if (cause != null) {
recordError(duration, cause); recordError(duration);
} else { } else {
recordResult(duration, expected, actual); recordResult(duration, expected, actual);
} }
@ -64,23 +69,20 @@ public class Experiment {
final T result = experimentSupplier.get(); final T result = experimentSupplier.get();
recordResult(System.nanoTime() - start, expected, result); recordResult(System.nanoTime() - start, expected, result);
} catch (final Exception e) { } catch (final Exception e) {
recordError(System.nanoTime() - start, e); recordError(System.nanoTime() - start);
} }
} }
private void recordError(final long durationNanos, final Throwable cause) { private void recordError(final long durationNanos) {
meterRegistry.timer(timerName, errorTimer.record(durationNanos, TimeUnit.NANOSECONDS);
List.of(Tag.of(OUTCOME_TAG, ERROR_OUTCOME), Tag.of(CAUSE_TAG, cause.getClass().getSimpleName())))
.record(durationNanos, TimeUnit.NANOSECONDS);
} }
private <T> void recordResult(final long durationNanos, final T expected, final T actual) { private <T> void recordResult(final long durationNanos, final T expected, final T actual) {
final boolean shouldIgnore = actual == null && expected != null; final boolean shouldIgnore = actual == null && expected != null;
if (!shouldIgnore) { if (!shouldIgnore) {
meterRegistry.timer(timerName, final Timer timer = Objects.equals(expected, actual) ? matchTimer : mismatchTimer;
List.of(Tag.of(OUTCOME_TAG, Objects.equals(expected, actual) ? MATCH_OUTCOME : MISMATCH_OUTCOME))) timer.record(durationNanos, TimeUnit.NANOSECONDS);
.record(durationNanos, TimeUnit.NANOSECONDS);
} }
} }
} }

132
service/src/test/java/org/whispersystems/textsecuregcm/experiment/ExperimentTest.java
View File

@ -1,8 +1,11 @@
package org.whispersystems.textsecuregcm.experiment; package org.whispersystems.textsecuregcm.experiment;
import io.micrometer.core.instrument.Meter;
import io.micrometer.core.instrument.MeterRegistry; import io.micrometer.core.instrument.MeterRegistry;
import io.micrometer.core.instrument.Tag; import io.micrometer.core.instrument.Tag;
import io.micrometer.core.instrument.Timer; import io.micrometer.core.instrument.Timer;
import io.micrometer.core.instrument.distribution.DistributionStatisticConfig;
import org.LatencyUtils.PauseDetector;
import org.junit.Before; import org.junit.Before;
import org.junit.Test; import org.junit.Test;
import org.mockito.ArgumentCaptor; import org.mockito.ArgumentCaptor;
@ -21,146 +24,71 @@ import static org.mockito.ArgumentMatchers.eq;
import static org.mockito.Mockito.mock; import static org.mockito.Mockito.mock;
import static org.mockito.Mockito.never; import static org.mockito.Mockito.never;
import static org.mockito.Mockito.verify; import static org.mockito.Mockito.verify;
import static org.mockito.Mockito.verifyNoMoreInteractions;
import static org.mockito.Mockito.when; import static org.mockito.Mockito.when;
public class ExperimentTest { public class ExperimentTest {
private MeterRegistry meterRegistry; private Timer matchTimer;
private Timer mismatchTimer;
private Timer errorTimer;
private Experiment experiment;
@Before @Before
public void setUp() { public void setUp() {
meterRegistry = mock(MeterRegistry.class); matchTimer = mock(Timer.class);
mismatchTimer = mock(Timer.class);
errorTimer = mock(Timer.class);
experiment = new Experiment(matchTimer, mismatchTimer, errorTimer);
} }
@Test @Test
public void compareFutureResultMatch() { public void compareFutureResultMatch() {
final Timer timer = mock(Timer.class); experiment.compareFutureResult(12, CompletableFuture.completedFuture(12));
when(meterRegistry.timer(anyString(), ArgumentMatchers.<Iterable<Tag>>any())).thenReturn(timer); verify(matchTimer).record(anyLong(), eq(TimeUnit.NANOSECONDS));
new Experiment(meterRegistry, "test").compareFutureResult(12, CompletableFuture.completedFuture(12));
@SuppressWarnings("unchecked") final ArgumentCaptor<Iterable<Tag>> tagCaptor = ArgumentCaptor.forClass(Iterable.class);
verify(meterRegistry).timer(anyString(), tagCaptor.capture());
final Set<Tag> tags = getTagSet(tagCaptor.getValue());
assertEquals(tags, Set.of(Tag.of(Experiment.OUTCOME_TAG, Experiment.MATCH_OUTCOME)));
verify(timer).record(anyLong(), eq(TimeUnit.NANOSECONDS));
} }
@Test @Test
public void compareFutureResultMismatch() { public void compareFutureResultMismatch() {
final Timer timer = mock(Timer.class); experiment.compareFutureResult(12, CompletableFuture.completedFuture(77));
when(meterRegistry.timer(anyString(), ArgumentMatchers.<Iterable<Tag>>any())).thenReturn(timer); verify(mismatchTimer).record(anyLong(), eq(TimeUnit.NANOSECONDS));
new Experiment(meterRegistry, "test").compareFutureResult(12, CompletableFuture.completedFuture(77));
@SuppressWarnings("unchecked") final ArgumentCaptor<Iterable<Tag>> tagCaptor = ArgumentCaptor.forClass(Iterable.class);
verify(meterRegistry).timer(anyString(), tagCaptor.capture());
final Set<Tag> tags = getTagSet(tagCaptor.getValue());
assertEquals(tags, Set.of(Tag.of(Experiment.OUTCOME_TAG, Experiment.MISMATCH_OUTCOME)));
verify(timer).record(anyLong(), eq(TimeUnit.NANOSECONDS));
} }
@Test @Test
public void compareFutureResultError() { public void compareFutureResultError() {
final Timer timer = mock(Timer.class); experiment.compareFutureResult(12, CompletableFuture.failedFuture(new RuntimeException("OH NO")));
when(meterRegistry.timer(anyString(), ArgumentMatchers.<Iterable<Tag>>any())).thenReturn(timer); verify(errorTimer).record(anyLong(), eq(TimeUnit.NANOSECONDS));
new Experiment(meterRegistry, "test").compareFutureResult(12, CompletableFuture.failedFuture(new RuntimeException("OH NO")));
@SuppressWarnings("unchecked") final ArgumentCaptor<Iterable<Tag>> tagCaptor = ArgumentCaptor.forClass(Iterable.class);
verify(meterRegistry).timer(anyString(), tagCaptor.capture());
final Set<Tag> tags = getTagSet(tagCaptor.getValue());
assertEquals(tags, Set.of(Tag.of(Experiment.OUTCOME_TAG, Experiment.ERROR_OUTCOME), Tag.of(Experiment.CAUSE_TAG, "RuntimeException")));
verify(timer).record(anyLong(), eq(TimeUnit.NANOSECONDS));
} }
@Test @Test
public void compareFutureResultNoExperimentData() { public void compareFutureResultNoExperimentData() {
final Timer timer = mock(Timer.class); experiment.compareFutureResult(12, CompletableFuture.completedFuture(null));
when(meterRegistry.timer(anyString(), ArgumentMatchers.<Iterable<Tag>>any())).thenReturn(timer); verifyNoMoreInteractions(matchTimer, mismatchTimer, errorTimer);
new Experiment(meterRegistry, "test").compareFutureResult(12, CompletableFuture.completedFuture(null));
verify(timer, never()).record(anyLong(), eq(TimeUnit.NANOSECONDS));
} }
@Test @Test
public void compareSupplierResultMatch() { public void compareSupplierResultMatch() {
final Timer timer = mock(Timer.class); experiment.compareSupplierResult(12, () -> 12);
when(meterRegistry.timer(anyString(), ArgumentMatchers.<Iterable<Tag>>any())).thenReturn(timer); verify(matchTimer).record(anyLong(), eq(TimeUnit.NANOSECONDS));
new Experiment(meterRegistry, "test").compareSupplierResult(12, () -> 12);
@SuppressWarnings("unchecked") final ArgumentCaptor<Iterable<Tag>> tagCaptor = ArgumentCaptor.forClass(Iterable.class);
verify(meterRegistry).timer(anyString(), tagCaptor.capture());
final Set<Tag> tags = getTagSet(tagCaptor.getValue());
assertEquals(tags, Set.of(Tag.of(Experiment.OUTCOME_TAG, Experiment.MATCH_OUTCOME)));
verify(timer).record(anyLong(), eq(TimeUnit.NANOSECONDS));
} }
@Test @Test
public void compareSupplierResultMismatch() { public void compareSupplierResultMismatch() {
final Timer timer = mock(Timer.class); experiment.compareSupplierResult(12, () -> 77);
when(meterRegistry.timer(anyString(), ArgumentMatchers.<Iterable<Tag>>any())).thenReturn(timer); verify(mismatchTimer).record(anyLong(), eq(TimeUnit.NANOSECONDS));
new Experiment(meterRegistry, "test").compareSupplierResult(12, () -> 77);
@SuppressWarnings("unchecked") final ArgumentCaptor<Iterable<Tag>> tagCaptor = ArgumentCaptor.forClass(Iterable.class);
verify(meterRegistry).timer(anyString(), tagCaptor.capture());
final Set<Tag> tags = getTagSet(tagCaptor.getValue());
assertEquals(tags, Set.of(Tag.of(Experiment.OUTCOME_TAG, Experiment.MISMATCH_OUTCOME)));
verify(timer).record(anyLong(), eq(TimeUnit.NANOSECONDS));
} }
@Test @Test
public void compareSupplierResultError() { public void compareSupplierResultError() {
final Timer timer = mock(Timer.class); experiment.compareSupplierResult(12, () -> { throw new RuntimeException("OH NO"); });
when(meterRegistry.timer(anyString(), ArgumentMatchers.<Iterable<Tag>>any())).thenReturn(timer); verify(errorTimer).record(anyLong(), eq(TimeUnit.NANOSECONDS));
new Experiment(meterRegistry, "test").compareSupplierResult(12, () -> { throw new RuntimeException("OH NO"); });
@SuppressWarnings("unchecked") final ArgumentCaptor<Iterable<Tag>> tagCaptor = ArgumentCaptor.forClass(Iterable.class);
verify(meterRegistry).timer(anyString(), tagCaptor.capture());
final Set<Tag> tags = getTagSet(tagCaptor.getValue());
assertEquals(tags, Set.of(Tag.of(Experiment.OUTCOME_TAG, Experiment.ERROR_OUTCOME), Tag.of(Experiment.CAUSE_TAG, "RuntimeException")));
verify(timer).record(anyLong(), eq(TimeUnit.NANOSECONDS));
} }
@Test @Test
public void compareSupplierResultNoExperimentData() { public void compareSupplierResultNoExperimentData() {
final Timer timer = mock(Timer.class); experiment.compareSupplierResult(12, () -> null);
when(meterRegistry.timer(anyString(), ArgumentMatchers.<Iterable<Tag>>any())).thenReturn(timer); verifyNoMoreInteractions(mismatchTimer, mismatchTimer, errorTimer);
new Experiment(meterRegistry, "test").compareSupplierResult(12, () -> null);
verify(timer, never()).record(anyLong(), eq(TimeUnit.NANOSECONDS));
}
private static Set<Tag> getTagSet(final Iterable<Tag> tags) {
final Set<Tag> tagSet = new HashSet<>();
for (final Tag tag : tags) {
tagSet.add(tag);
}
return tagSet;
} }
} }