Skip to content

Commit

Permalink
[4.x] Add some retries because post-request metrics updates occur aft…
Browse files Browse the repository at this point in the history
…er the response is sent (#5122)

* Add some retries because post-request metrics update occur after the response is sent
  • Loading branch information
tjquinno authored Oct 10, 2022
1 parent 9966941 commit 7f6e557
Showing 1 changed file with 10 additions and 14 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -20,7 +20,6 @@
import java.util.SortedMap;
import java.util.concurrent.ExecutionException;
import java.util.concurrent.Future;
import java.util.concurrent.TimeUnit;
import java.util.stream.LongStream;

import io.helidon.microprofile.tests.junit5.AddConfig;
Expand Down Expand Up @@ -124,9 +123,9 @@ public void test() throws Exception {
long explicitDiffNanos = explicitSimpleTimer.getElapsedTime().toNanos() - explicitSimpleTimerDurationBefore.toNanos();
assertThat("Change in elapsed time for explicit SimpleTimer", explicitDiffNanos, is(greaterThan(minDuration.toNanos())));

long syntheticDiffNanos = simpleTimer.getElapsedTime().toNanos() - syntheticaSimpleTimerDurationBefore.toNanos();
assertThat("Change in synthetic SimpleTimer elapsed time", syntheticDiffNanos,
is(greaterThan(minDuration.toNanos())));
assertThatWithRetry("Change in synthetic SimpleTimer elapsed time",
() -> simpleTimer.getElapsedTime().toNanos() - syntheticaSimpleTimerDurationBefore.toNanos(),
is(greaterThan(minDuration.toNanos())));

assertThat("Change in timer count", timer.getCount() - slowMessageTimerCountBefore, is(1L));
assertThat("Timer mean rate", timer.getMeanRate(), is(greaterThan(0.0)));
Expand All @@ -140,10 +139,9 @@ public void testAsyncWithArg() throws InterruptedException {
.request(MediaType.TEXT_PLAIN_TYPE)
.get(String.class));

// Make sure server has a chance to update the metrics, which happens just after it sends the response.
TimeUnit.MILLISECONDS.sleep(500L);
SimpleTimer syntheticSimpleTimer = getSyntheticSimpleTimer();
assertThat("Synthetic SimpleTimer count", syntheticSimpleTimer.getCount(), is(3L));
// Give the server a chance to update the metrics, which happens just after it sends each response.
assertThatWithRetry("Synthetic SimpleTimer count", syntheticSimpleTimer::getCount, is(3L));
}

SimpleTimer getSyntheticSimpleTimer() {
Expand All @@ -158,6 +156,7 @@ SimpleTimer getSyntheticSimpleTimer() {

SortedMap<MetricID, SimpleTimer> simpleTimers = syntheticSimpleTimerRegistry.getSimpleTimers();
SimpleTimer syntheticSimpleTimer = simpleTimers.get(metricID);
// We should not need to retry here. Annotation processing creates the synthetic simple timers long before tests run.
assertThat("Synthetic simple timer "
+ MetricsCdiExtension.SYNTHETIC_SIMPLE_TIMER_METRIC_NAME,
syntheticSimpleTimer, is(notNullValue()));
Expand Down Expand Up @@ -193,16 +192,13 @@ void testInflightRequests() throws InterruptedException, ExecutionException {
// The response might arrive here before the server-side code which updates the inflight metric has run. So wait.
HelloWorldResource.awaitResponseSent();

// Make sure server has a chance to update the metrics, which happens just after it sends the response.
TimeUnit.MILLISECONDS.sleep(500L);

long afterRequest = inflightRequestsCount();

assertThat("Slow response", response, containsString(SLOW_RESPONSE));
assertThat("Change in inflight from before (" + beforeRequest + ") to during (" + duringRequest
+ ") the slow request", duringRequest - beforeRequest, is(1L));
assertThat("Change in inflight from before (" + beforeRequest + ") to after (" + afterRequest
+ ") the slow request", afterRequest - beforeRequest, is(0L));
// The update to the in-flight count occurs after the response completes, so retry a bit until the value returns to 0.
assertThatWithRetry("Change in inflight from before (" + beforeRequest + ") to after the slow request",
() -> inflightRequestsCount() - beforeRequest,
is(0L));
}
}

Expand Down

0 comments on commit 7f6e557

Please sign in to comment.