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.

Sign up for GitHub

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

Jump to bottom

Suppress warning when metrics PeriodicExecutor is stopped multiple times (e.g., during tests) #3617

Merged
merged 2 commits into from
Nov 4, 2021
Merged

Suppress warning when metrics PeriodicExecutor is stopped multiple times (e.g., during tests) #3617

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
bd149d2
Change logging for stop-when-stopped to FINE to avoid alarming output…
tjquinno Nov 4, 2021
83d8ec0
Convert synchronized methods to use a semaphore
tjquinno Nov 4, 2021
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
115 changes: 73 additions & 42 deletions metrics/metrics/src/main/java/io/helidon/metrics/PeriodicExecutor.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -21,6 +21,7 @@
import java.util.Set;
import java.util.concurrent.Executors;
import java.util.concurrent.ScheduledExecutorService;
import java.util.concurrent.Semaphore;
import java.util.concurrent.TimeUnit;
import java.util.logging.Level;
import java.util.logging.Logger;
Expand Down Expand Up @@ -48,10 +49,20 @@ static PeriodicExecutor create() {

private static final String STOP_LOG_MESSAGE = "Received stop request in state {0}";

/**
* Current state of the executor.
*
* Normally, the life cycle is DORMANT -> STARTED -> STOPPED & then JVM exit. Particularly in some testing situations, the
* singleton PeriodicExecutor might be reused serially with the life cycle DORMANT -> STARTED -> STOPPED -> STARTED -> ...
*/
enum State {
DORMANT, // never started
STARTED, // started and still running
STOPPED // stopped
STOPPED; // stopped

boolean isStartable() {
return this != STARTED;
}
}

private static class Enrollment {
Expand All @@ -64,12 +75,14 @@ private static class Enrollment {
}
}

private State state = State.DORMANT;
private volatile State state = State.DORMANT;

private ScheduledExecutorService currentTimeUpdaterExecutorService;

private final Collection<Enrollment> deferredEnrollments = new ArrayList<>();

private final Semaphore access = new Semaphore(1, true);

private PeriodicExecutor() {
}

Expand All @@ -89,47 +102,54 @@ static State state() {
return INSTANCE.executorState();
}

synchronized void enrollRunner(Runnable runnable, Duration interval) {

if (state == State.STARTED) {
currentTimeUpdaterExecutorService.scheduleAtFixedRate(
runnable,
interval.toMillis(),
interval.toMillis(),
TimeUnit.MILLISECONDS);
} else if (state == State.DORMANT) {
deferredEnrollments.add(new Enrollment(runnable, interval));
} else {
LOGGER.log(Level.WARNING,
"Attempt to enroll when in unexpected state " + state + "; ignored",
new IllegalStateException());
}
}

synchronized void startExecutor() {
if (state == State.DORMANT) {
LOGGER.log(Level.FINE, "Starting up with " + deferredEnrollments.size() + " deferred enrollments");
state = State.STARTED;
currentTimeUpdaterExecutorService = Executors.newSingleThreadScheduledExecutor();
for (Enrollment deferredEnrollment : deferredEnrollments) {
void enrollRunner(Runnable runnable, Duration interval) {
sync("enroll runner", () -> {
if (state == State.STARTED) {
currentTimeUpdaterExecutorService.scheduleAtFixedRate(
deferredEnrollment.runnable,
deferredEnrollment.interval.toMillis(),
deferredEnrollment.interval.toMillis(),
runnable,
interval.toMillis(),
interval.toMillis(),
TimeUnit.MILLISECONDS);
} else {
deferredEnrollments.add(new Enrollment(runnable, interval));
if (state == State.STOPPED) {
// Unusual during production use, more likely during testing. Keep the logging for diagnosing production
// problems if they occur.
LOGGER.log(Level.FINE,
"Recording deferred enrollment even though in unexpected state " + State.STOPPED,
new IllegalStateException());
}
}
deferredEnrollments.clear();
} else {
LOGGER.log(Level.WARNING, String.format("Attempt to start; the expected state is %s but found %s; ignored",
State.DORMANT,
state),
new IllegalStateException());
}
});
}

synchronized void stopExecutor() {
LOGGER.log(Level.FINE, STOP_LOG_MESSAGE, state);
switch (state) {
void startExecutor() {
sync("start", () -> {
if (state.isStartable()) {
LOGGER.log(Level.FINE, "Starting up with " + deferredEnrollments.size() + " deferred enrollments"
+ (state == State.DORMANT ? "" : " even though in state " + state));
state = State.STARTED;
currentTimeUpdaterExecutorService = Executors.newSingleThreadScheduledExecutor();
for (Enrollment deferredEnrollment : deferredEnrollments) {
currentTimeUpdaterExecutorService.scheduleAtFixedRate(
deferredEnrollment.runnable,
deferredEnrollment.interval.toMillis(),
deferredEnrollment.interval.toMillis(),
TimeUnit.MILLISECONDS);
}
deferredEnrollments.clear();
} else {
LOGGER.log(Level.WARNING, String.format("Attempt to start in unexpected state state %s; ignored",
state),
new IllegalStateException());
}
});
}

void stopExecutor() {
sync("stop", () -> {
LOGGER.log(Level.FINE, STOP_LOG_MESSAGE, state);
switch (state) {
case STARTED:
currentTimeUpdaterExecutorService.shutdownNow();
break;
Expand All @@ -138,16 +158,27 @@ synchronized void stopExecutor() {
break;

default:
LOGGER.log(Level.WARNING, String.format(
LOGGER.log(Level.FINE, String.format(
"Unexpected attempt to stop; the expected states are %s but found %s; ignored",
Set.of(State.DORMANT, State.STARTED),
state),
new IllegalStateException());
}
state = State.STOPPED;
new IllegalStateException());
}
state = State.STOPPED;
});
}

State executorState() {
return state;
}

private void sync(String taskDescription, Runnable task) {
try {
access.acquire();
task.run();
access.release();
} catch (InterruptedException ex) {
LOGGER.log(Level.WARNING, "Attempt to " + taskDescription + " failed", ex);
}
}
}
39 changes: 32 additions & 7 deletions metrics/metrics/src/test/java/io/helidon/metrics/TestPeriodicExecutor.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -125,7 +125,7 @@ void testWithLateEnrollment() throws InterruptedException {
}

@Test
void testWarningOnStopWhenStopped() throws InterruptedException {
void testNoWarningOnStopWhenStopped() throws InterruptedException {

MyHandler handler = new MyHandler();
PERIODIC_EXECUTOR_LOGGER.addHandler(handler);
Expand All @@ -137,14 +137,39 @@ void testWarningOnStopWhenStopped() throws InterruptedException {

executor.stopExecutor();
List<LogRecord> logRecords = handler.logRecords();
assertThat("Expected log records", logRecords.size(), is(1));
assertThat("Log record level", logRecords.get(0)
.getLevel(), is(equalTo(Level.WARNING)));
assertThat("Log record content", logRecords.get(0)
.getMessage(),
containsString("Unexpected attempt to stop"));
assertThat("Expected log records", logRecords.size(), is(0));
} finally {
PERIODIC_EXECUTOR_LOGGER.removeHandler(handler);
}
}

@Test
void testFineMessageOnStopWhenStopped() throws InterruptedException {

MyHandler handler = new MyHandler();
Level originalLevel = PERIODIC_EXECUTOR_LOGGER.getLevel();

PERIODIC_EXECUTOR_LOGGER.addHandler(handler);
try {
PERIODIC_EXECUTOR_LOGGER.setLevel(Level.FINE);
PeriodicExecutor executor = PeriodicExecutor.create();
executor.stopExecutor();
Thread.sleep(SLEEP_TIME_NO_DATA_MS);

executor.stopExecutor();
handler.clear();

executor.stopExecutor();
List<LogRecord> logRecords = handler.logRecords();
assertThat("Expected log records", logRecords.size(), is(2));
assertThat("Log record level", logRecords.get(1)
.getLevel(), is(equalTo(Level.FINE)));
assertThat("Log record content", logRecords.get(1)
.getMessage(),
containsString("Unexpected attempt to stop"));
} finally {
PERIODIC_EXECUTOR_LOGGER.removeHandler(handler);
PERIODIC_EXECUTOR_LOGGER.setLevel(originalLevel);
}
}

Expand Down