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

[4.x] Various metrics test improvements to avoid intermittent failures #5611

Merged
merged 6 commits into from
Dec 7, 2022
Merged
Show file tree
Hide file tree
Changes from 4 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
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.common.testing</groupId>
<artifactId>helidon-common-testing-junit5</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,8 +31,11 @@
import jakarta.ws.rs.core.MediaType;
import org.junit.jupiter.api.Test;

import static io.helidon.common.testing.junit5.MatcherWithRetry.assertThatWithRetry;

import static org.hamcrest.MatcherAssert.assertThat;
import static org.hamcrest.Matchers.is;
import static org.hamcrest.Matchers.not;
import static org.hamcrest.Matchers.notNullValue;

/**
Expand Down Expand Up @@ -83,7 +86,7 @@ void testTimer() {
}

@Test
public void testSlowTimer() {
public void testSlowTimer() throws InterruptedException {
int exp = 3;
AtomicReference<String> result = new AtomicReference<>();
IntStream.range(0, exp).forEach(
Expand All @@ -95,11 +98,11 @@ 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
public void testFastFailCounter() {
public void testFastFailCounter() throws InterruptedException {
int exp = 8;
IntStream.range(0, exp).forEach(
i -> {
Expand All @@ -116,7 +119,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 All @@ -134,7 +137,7 @@ public void testSlowFailNoCounter() {
}

@Test
public void testSlowFailCounter() {
public void testSlowFailCounter() throws InterruptedException {
int exp = 6;
IntStream.range(0, exp).forEach(
i -> {
Expand All @@ -151,7 +154,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,7 +24,8 @@
import jakarta.inject.Inject;
import org.junit.jupiter.api.Test;

import static org.hamcrest.MatcherAssert.assertThat;
import static io.helidon.common.testing.junit5.MatcherWithRetry.assertThatWithRetry;

import static org.hamcrest.Matchers.is;
import static org.junit.jupiter.api.Assertions.assertThrows;

Expand All @@ -39,35 +40,40 @@ public class MeteredBeanTest {
MeterRegistry registry;

@Test
public void testSimpleCounted() {
public void testSimpleCounted() throws InterruptedException {
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() {
public void testSinglyTimed() throws InterruptedException {
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() {
public void testDoublyTimed() throws InterruptedException {
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
public void testFailable() {
public void testFailable() throws InterruptedException {
int OKCalls = 2;
int expFailed = 3;
IntStream.range(0, OKCalls).forEach(i -> meteredBean.failable(false));
IntStream.range(0, expFailed).forEach(i -> assertThrows(RuntimeException.class,
() -> meteredBean.failable(true)));
assertThat("Count from failed calls", registry.counter(MeteredBean.COUNTED_ONLY_FOR_FAILURE).count(),
is((double) expFailed));
assertThatWithRetry("Count from failed calls",
() -> registry.counter(MeteredBean.COUNTED_ONLY_FOR_FAILURE).count(),
is((double) expFailed));
}
}
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 @@ -32,21 +34,20 @@
import static org.hamcrest.Matchers.arrayContaining;
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 +60,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 +96,26 @@ 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.enrollRunner(() -> {
countA.incrementAndGet();
latchA.countDown();
}, Duration.ofMillis(FAST_INTERVAL));

exec.startExecutor();

exec.enrollRunner(() -> countB.incrementAndGet(), Duration.ofMillis(SLOW_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)));
assertThat("CountA", countA.get(), is(greaterThanOrEqualTo(MIN_FAST_COUNT)));
assertThat("CountB", countB.get(), is(greaterThanOrEqualTo(MIN_SLOW_COUNT)));
} finally {
if (exec.executorState() == PeriodicExecutor.State.STARTED) {
exec.stopExecutor();
Expand All @@ -104,17 +130,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 +164,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 +187,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 +219,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 +240,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
@@ -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 All @@ -16,11 +16,13 @@

package io.helidon.microprofile.metrics;

import io.helidon.microprofile.tests.junit5.AddConfig;
import io.helidon.microprofile.tests.junit5.HelidonTest;

import jakarta.inject.Inject;
import org.eclipse.microprofile.metrics.MetricRegistry;
import org.eclipse.microprofile.metrics.annotation.RegistryType;
import org.junit.jupiter.api.BeforeAll;
import org.junit.jupiter.api.Test;

import static org.hamcrest.CoreMatchers.is;
Expand All @@ -31,15 +33,21 @@
* the config disables that feature.
*/
@HelidonTest
@AddConfig(key = "metrics." + MetricsCdiExtension.REST_ENDPOINTS_METRIC_ENABLED_PROPERTY_NAME, value = "false")
public class HelloWorldRestEndpointSimpleTimerDisabledTest {

@BeforeAll
static void init() {
MetricsMpServiceTest.cleanUpSyntheticSimpleTimerRegistry();
}

@Inject
@RegistryType(type = MetricRegistry.Type.BASE)
MetricRegistry syntheticSimpleTimerRegistry;

boolean isSyntheticSimpleTimerPresent() {
return !syntheticSimpleTimerRegistry.getSimpleTimers((metricID, metric) ->
metricID.equals(MetricsCdiExtension.SYNTHETIC_SIMPLE_TIMER_METRIC_NAME))
metricID.getName().equals(MetricsCdiExtension.SYNTHETIC_SIMPLE_TIMER_METRIC_NAME))
.isEmpty();
}

Expand Down
Loading