Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[3.x] Various metrics test improvements to avoid intermittent failures #5621

Merged
merged 2 commits into from
Dec 12, 2022
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,8 @@
import org.hamcrest.Matcher;
import org.hamcrest.StringDescription;

import static org.junit.jupiter.api.Assertions.fail;

/**
* Hamcrest matcher capable of configured retries before failing the assertion, plus more generic retry processing.
*/
Expand All @@ -41,18 +43,20 @@ private MatcherWithRetry() {
* @param matcher Hamcrest matcher which evaluates the supplied value
* @return the supplied value
* @param <T> type of the supplied value
* @throws InterruptedException if the sleep is interrupted
*/
public static <T> T assertThatWithRetry(String reason, Supplier<T> actualSupplier, Matcher<? super T> matcher)
throws InterruptedException {
public static <T> T assertThatWithRetry(String reason, Supplier<T> actualSupplier, Matcher<? super T> matcher) {

T actual = null;
for (int i = 0; i < RETRY_COUNT; i++) {
actual = actualSupplier.get();
if (matcher.matches(actual)) {
return actual;
}
Thread.sleep(RETRY_DELAY_MS);
try {
Thread.sleep(RETRY_DELAY_MS);
} catch (InterruptedException e) {
fail("Error sleeping during assertThatWithRetry", e);
}
}

Description description = new StringDescription();
Expand Down
5 changes: 5 additions & 0 deletions integrations/micrometer/cdi/pom.xml
Original file line number Diff line number Diff line change
Expand Up @@ -115,6 +115,11 @@
<artifactId>helidon-microprofile-tests-junit5</artifactId>
<scope>test</scope>
</dependency>
<dependency>
<groupId>io.helidon.config</groupId>
<artifactId>helidon-config-testing</artifactId>
<scope>test</scope>
</dependency>
</dependencies>

<build>
Expand Down
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
/*
* Copyright (c) 2018, 2021 Oracle and/or its affiliates.
* Copyright (c) 2018, 2022 Oracle and/or its affiliates.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
Expand Down Expand Up @@ -31,6 +31,8 @@
import jakarta.ws.rs.core.MediaType;
import org.junit.jupiter.api.Test;

import static io.helidon.config.testing.MatcherWithRetry.assertThatWithRetry;

import static org.hamcrest.MatcherAssert.assertThat;
import static org.hamcrest.Matchers.is;
import static org.hamcrest.Matchers.notNullValue;
Expand Down Expand Up @@ -95,7 +97,7 @@ public void testSlowTimer() {
assertThat("Returned from HTTP request", result.get(), is(HelloWorldResource.SLOW_RESPONSE));
Timer slowTimer = registry.timer(HelloWorldResource.SLOW_MESSAGE_TIMER);
assertThat("Slow message timer", slowTimer, is(notNullValue()));
assertThat("Slow message timer count", slowTimer.count(), is((long) exp));
assertThatWithRetry("Slow message timer count", slowTimer::count, is((long) exp));
}

@Test
Expand All @@ -116,7 +118,7 @@ public void testFastFailCounter() {

Counter counter = registry.counter(HelloWorldResource.FAST_MESSAGE_COUNTER);
assertThat("Failed message counter", counter, is(notNullValue()));
assertThat("Failed message counter count", counter.count(), is((double) exp / 2));
assertThatWithRetry("Failed message counter count", counter::count, is((double) exp / 2));
}

@Test
Expand Down Expand Up @@ -151,7 +153,7 @@ public void testSlowFailCounter() {

Counter counter = registry.counter(HelloWorldResource.SLOW_MESSAGE_FAIL_COUNTER);
assertThat("Failed message counter", counter, is(notNullValue()));
assertThat("Failed message counter count", counter.count(), is((double) 3));
assertThatWithRetry("Failed message counter count", counter::count, is((double) 3));
}

void checkMicrometerURL(int iterations) {
Expand Down
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
/*
* Copyright (c) 2021 Oracle and/or its affiliates.
* Copyright (c) 2021, 2022 Oracle and/or its affiliates.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
Expand All @@ -24,6 +24,8 @@
import jakarta.inject.Inject;
import org.junit.jupiter.api.Test;

import static io.helidon.config.testing.MatcherWithRetry.assertThatWithRetry;

import static org.hamcrest.MatcherAssert.assertThat;
import static org.hamcrest.Matchers.is;
import static org.junit.jupiter.api.Assertions.assertThrows;
Expand All @@ -42,22 +44,26 @@ public class MeteredBeanTest {
public void testSimpleCounted() {
int exp = 3;
IntStream.range(0, exp).forEach(i -> meteredBean.count());
assertThat("Value from simple counted meter", registry.counter(MeteredBean.COUNTED).count(), is((double) exp));
assertThatWithRetry("Value from simple counted meter", () -> registry.counter(MeteredBean.COUNTED).count(),
is((double) exp));
}

@Test
public void testSinglyTimed() {
int exp = 4;
IntStream.range(0, exp).forEach(i -> meteredBean.timed());
assertThat("Count from singly-timed meter", registry.timer(MeteredBean.TIMED_1).count(), is((long) exp));
assertThatWithRetry("Count from singly-timed meter", () -> registry.timer(MeteredBean.TIMED_1).count(),
is((long) exp));
}

@Test
public void testDoublyTimed() {
int exp = 5;
IntStream.range(0, exp).forEach(i -> meteredBean.timedA());
assertThat("Count from doubly-timed meter (A)", registry.timer(MeteredBean.TIMED_A).count(), is((long) exp));
assertThat("Count from doubly-timed meter (B)", registry.timer(MeteredBean.TIMED_B).count(), is((long) exp));
assertThatWithRetry("Count from doubly-timed meter (A)", () -> registry.timer(MeteredBean.TIMED_A).count(),
is((long) exp));
assertThatWithRetry("Count from doubly-timed meter (B)", () -> registry.timer(MeteredBean.TIMED_B).count(),
is((long) exp));
}

@Test
Expand Down
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
/*
* Copyright (c) 2021 Oracle and/or its affiliates.
* Copyright (c) 2021, 2022 Oracle and/or its affiliates.
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
Expand All @@ -18,6 +18,8 @@
import java.time.Duration;
import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicInteger;
import java.util.logging.Handler;
import java.util.logging.Level;
Expand All @@ -33,20 +35,20 @@
import static org.hamcrest.Matchers.containsString;
import static org.hamcrest.Matchers.equalTo;
import static org.hamcrest.Matchers.greaterThan;
import static org.hamcrest.Matchers.greaterThanOrEqualTo;
import static org.hamcrest.Matchers.is;
import static org.junit.jupiter.api.Assertions.fail;

class TestPeriodicExecutor {

private static final int SLEEP_TIME_MS = 1500;
private static final int SLEEP_TIME_NO_DATA_MS = 100;
private static final int APPROX_TEST_DURATION_MS = 1500;
private static final int MAX_TEST_WAIT_TIME_MS = APPROX_TEST_DURATION_MS * 15 / 10; // 1.5 * approx test duration

private static final int FAST_INTERVAL = 250;
private static final int SLOW_INTERVAL = 400;

private static final double SLOWDOWN_FACTOR = 0.80; // for slow pipelines!

private static final double MIN_FAST_COUNT = 1500 / FAST_INTERVAL * SLOWDOWN_FACTOR;
private static final double MIN_SLOW_COUNT = 1500 / SLOW_INTERVAL * SLOWDOWN_FACTOR;
private static final int MIN_FAST_COUNT = APPROX_TEST_DURATION_MS / FAST_INTERVAL;
private static final int MIN_SLOW_COUNT = APPROX_TEST_DURATION_MS / SLOW_INTERVAL;

private static final Logger PERIODIC_EXECUTOR_LOGGER = Logger.getLogger(PeriodicExecutor.class.getName());

Expand All @@ -59,13 +61,28 @@ void testWithNoDeferrals() throws InterruptedException {
AtomicInteger countA = new AtomicInteger();
AtomicInteger countB = new AtomicInteger();

exec.enrollRunner(() -> countA.incrementAndGet(), Duration.ofMillis(FAST_INTERVAL));
exec.enrollRunner(() -> countB.incrementAndGet(), Duration.ofMillis(SLOW_INTERVAL));
CountDownLatch latchA = new CountDownLatch(MIN_FAST_COUNT);
CountDownLatch latchB = new CountDownLatch(MIN_SLOW_COUNT);

long startTime = System.nanoTime();
exec.enrollRunner(() -> {
countA.incrementAndGet();
latchA.countDown();
}, Duration.ofMillis(FAST_INTERVAL));

exec.enrollRunner(() -> {
countB.incrementAndGet();
latchB.countDown();
}, Duration.ofMillis(SLOW_INTERVAL));

Thread.sleep(SLEEP_TIME_MS);
assertThat("Wait latch for fast interval", latchA.await(MAX_TEST_WAIT_TIME_MS, TimeUnit.MILLISECONDS), is(true));
assertThat("Wait latch for slow interval", latchB.await(MAX_TEST_WAIT_TIME_MS, TimeUnit.MILLISECONDS), is(true));

assertThat("CountA", (double) countA.get(), is(greaterThan(MIN_FAST_COUNT)));
assertThat("CountB", (double) countB.get(), is(greaterThan(MIN_SLOW_COUNT)));
Duration elapsedTime = Duration.ofNanos(System.nanoTime() - startTime);

assertThat("CountA", countA.get(), is(greaterThanOrEqualTo(MIN_FAST_COUNT)));
assertThat("CountB", countB.get(), is(greaterThanOrEqualTo(MIN_SLOW_COUNT)));
assertThat("Wait duration", elapsedTime, greaterThanOrEqualTo(Duration.ofMillis(1500)));
} finally {
if (exec.executorState() == PeriodicExecutor.State.STARTED) {
exec.stopExecutor();
Expand All @@ -80,16 +97,23 @@ void testWithDeferredEnrollments() throws InterruptedException {
AtomicInteger countA = new AtomicInteger();
AtomicInteger countB = new AtomicInteger();

exec.enrollRunner(() -> countA.incrementAndGet(), Duration.ofMillis(FAST_INTERVAL));
CountDownLatch latchA = new CountDownLatch(MIN_FAST_COUNT);
CountDownLatch latchB = new CountDownLatch(MIN_SLOW_COUNT);

exec.startExecutor();
exec.enrollRunner(() -> {
countA.incrementAndGet();
latchA.countDown();
}, Duration.ofMillis(FAST_INTERVAL));

exec.enrollRunner(() -> countB.incrementAndGet(), Duration.ofMillis(SLOW_INTERVAL));
exec.startExecutor();

Thread.sleep(SLEEP_TIME_MS);
exec.enrollRunner(() -> {
countB.incrementAndGet();
latchB.countDown();
}, Duration.ofMillis(SLOW_INTERVAL));

assertThat("CountA", (double) countA.get(), is(greaterThan(MIN_FAST_COUNT)));
assertThat("CountB", (double) countB.get(), is(greaterThan(MIN_SLOW_COUNT)));
assertThat("Wait latch for fast interval", latchA.await(MAX_TEST_WAIT_TIME_MS, TimeUnit.MILLISECONDS), is(true));
assertThat("Wait latch for slow interval", latchB.await(MAX_TEST_WAIT_TIME_MS, TimeUnit.MILLISECONDS), is(true));
} finally {
if (exec.executorState() == PeriodicExecutor.State.STARTED) {
exec.stopExecutor();
Expand All @@ -104,17 +128,25 @@ void testWithLateEnrollment() throws InterruptedException {
AtomicInteger countA = new AtomicInteger();
AtomicInteger countB = new AtomicInteger();

exec.enrollRunner(() -> countA.incrementAndGet(), Duration.ofMillis(FAST_INTERVAL));
CountDownLatch latchA = new CountDownLatch(MIN_FAST_COUNT);

exec.enrollRunner(() -> {
countA.incrementAndGet();
latchA.countDown();
}, Duration.ofMillis(FAST_INTERVAL));

exec.startExecutor();
Thread.sleep(SLEEP_TIME_MS);
assertThat("Wait latch", latchA.await(MAX_TEST_WAIT_TIME_MS, TimeUnit.MILLISECONDS), is(true));

exec.stopExecutor();

exec.enrollRunner(() -> countB.incrementAndGet(), Duration.ofMillis(SLOW_INTERVAL));

assertThat("CountA", (double) countA.get(), is(greaterThan(MIN_FAST_COUNT))); // should be 8
assertThat("CountB", (double) countB.get(), is(0.0));
// The executor is no longer running, so we cannot use a countdown latch to know when to check countB. Use time.
Thread.sleep(MAX_TEST_WAIT_TIME_MS);

assertThat("CountA", countA.get(), is(greaterThanOrEqualTo(MIN_FAST_COUNT))); // should be 8
assertThat("CountB", countB.get(), is(0));
} finally {
if (exec.executorState() == PeriodicExecutor.State.STARTED) {
exec.stopExecutor();
Expand All @@ -130,7 +162,8 @@ void testNoWarningOnStopWhenStopped() throws InterruptedException {
try {
PeriodicExecutor executor = PeriodicExecutor.create();
executor.stopExecutor();
Thread.sleep(SLEEP_TIME_NO_DATA_MS);

waitForExecutorState(executor, PeriodicExecutor.State.STOPPED);
handler.clear();

executor.stopExecutor();
Expand All @@ -152,7 +185,7 @@ void testFineMessageOnStopWhenStopped() throws InterruptedException {
PERIODIC_EXECUTOR_LOGGER.setLevel(Level.FINE);
PeriodicExecutor executor = PeriodicExecutor.create();
executor.stopExecutor();
Thread.sleep(SLEEP_TIME_NO_DATA_MS);
waitForExecutorState(executor, PeriodicExecutor.State.STOPPED);

executor.stopExecutor();
handler.clear();
Expand Down Expand Up @@ -184,7 +217,7 @@ void testFineLoggingOnExpectedStop(PeriodicExecutor.State testState) throws Inte

if (testState == PeriodicExecutor.State.STARTED) {
executor.startExecutor();
Thread.sleep(SLEEP_TIME_NO_DATA_MS);
waitForExecutorState(executor, PeriodicExecutor.State.STARTED);
}

handler.clear();
Expand All @@ -205,6 +238,15 @@ void testFineLoggingOnExpectedStop(PeriodicExecutor.State testState) throws Inte
}
}

private void waitForExecutorState(PeriodicExecutor executor, PeriodicExecutor.State expectedState) {
for (int i = MAX_TEST_WAIT_TIME_MS; i > 0; i -= 500) {
if (executor.executorState() == expectedState) {
return;
}
}
fail("Timed out waiting for executor in state " + executor.executorState() + " to enter state " + expectedState.name());
}

private static class MyHandler extends Handler {

private List<LogRecord> logRecords = new ArrayList<>();
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -133,7 +133,7 @@ public void test() throws Exception {
}

@Test
public void testAsyncWithArg() throws InterruptedException {
public void testAsyncWithArg() {
LongStream.range(0, 3).forEach(
i -> webTarget
.path("helloworld/slowWithArg/Johan")
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -88,28 +88,23 @@ void checkForAsyncMethodRESTRequestMetric() throws NoSuchMethodException {

AtomicReference<JsonObject> nextRestRequest = new AtomicReference<>();

try {
// With async endpoints, metrics updates can occur after the server sends the response.
// Retry as needed (including fetching the metrics again) for a little while for the count to change.
assertThatWithRetry("getAsync count value after invocation",
() -> JsonNumber.class.cast(getRESTRequestValueForGetAsyncMethod(
// Set the reference using fresh metrics and get that newly-set JSON object, then
// extract the 'count' field cast as a number.
nextRestRequest.updateAndGet(old -> getRESTRequestJSON()),
"count",
false))
.longValue(),
is(1L));

// Reuse (no need to update the atomic reference again) the freshly-fetched metrics JSON.
getAsyncTime = JsonNumber.class.cast(getRESTRequestValueForGetAsyncMethod(nextRestRequest.get(),
"elapsedTime",
false));
assertThat("getAsync elapsedTime value after invocation", getAsyncTime.longValue(), is(greaterThan(0L)));
} catch (Exception e) {
throw new RuntimeException("Dump of REST.request metrics due to following assertion failure\n"
+ restRequest, e);
}
// With async endpoints, metrics updates can occur after the server sends the response.
// Retry as needed (including fetching the metrics again) for a little while for the count to change.
assertThatWithRetry("getAsync count value after invocation",
() -> JsonNumber.class.cast(getRESTRequestValueForGetAsyncMethod(
// Set the reference using fresh metrics and get that newly-set JSON object, then
// extract the 'count' field cast as a number.
nextRestRequest.updateAndGet(old -> getRESTRequestJSON()),
"count",
false))
.longValue(),
is(1L));

// Reuse (no need to update the atomic reference again) the freshly-fetched metrics JSON.
getAsyncTime = JsonNumber.class.cast(getRESTRequestValueForGetAsyncMethod(nextRestRequest.get(),
"elapsedTime",
false));
assertThat("getAsync elapsedTime value after invocation", getAsyncTime.longValue(), is(greaterThan(0L)));
}

private JsonObject getRESTRequestJSON() {
Expand Down
Loading