From bd149d245db23ab5ae4cfe48f50f73fd4c12c820 Mon Sep 17 00:00:00 2001 From: "tim.quinn@oracle.com" Date: Thu, 4 Nov 2021 11:10:16 -0500 Subject: [PATCH 1/2] Change logging for stop-when-stopped to FINE to avoid alarming output during tests --- .../io/helidon/metrics/PeriodicExecutor.java | 31 ++++++++++----- .../helidon/metrics/TestPeriodicExecutor.java | 39 +++++++++++++++---- 2 files changed, 54 insertions(+), 16 deletions(-) diff --git a/metrics/metrics/src/main/java/io/helidon/metrics/PeriodicExecutor.java b/metrics/metrics/src/main/java/io/helidon/metrics/PeriodicExecutor.java index d9d22342b96..88658a44671 100644 --- a/metrics/metrics/src/main/java/io/helidon/metrics/PeriodicExecutor.java +++ b/metrics/metrics/src/main/java/io/helidon/metrics/PeriodicExecutor.java @@ -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; @@ -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 { @@ -97,18 +108,20 @@ synchronized void enrollRunner(Runnable runnable, Duration interval) { 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()); + deferredEnrollments.add(new Enrollment(runnable, interval)); + if (state == State.STOPPED) { + LOGGER.log(Level.FINE, + "Recording deferred enrollment even though in unexpected state " + State.STOPPED, + new IllegalStateException()); + } } } synchronized void startExecutor() { - if (state == State.DORMANT) { - LOGGER.log(Level.FINE, "Starting up with " + deferredEnrollments.size() + " deferred enrollments"); + if (state.isStartable()) { + LOGGER.log(Level.FINE, "Starting up with " + deferredEnrollments.size() + " deferred enrollments" + + (state == State.DORMANT ? "" : " even though in state " + State.STOPPED)); state = State.STARTED; currentTimeUpdaterExecutorService = Executors.newSingleThreadScheduledExecutor(); for (Enrollment deferredEnrollment : deferredEnrollments) { @@ -138,7 +151,7 @@ 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), diff --git a/metrics/metrics/src/test/java/io/helidon/metrics/TestPeriodicExecutor.java b/metrics/metrics/src/test/java/io/helidon/metrics/TestPeriodicExecutor.java index 572d7d86e72..28b9168c8eb 100644 --- a/metrics/metrics/src/test/java/io/helidon/metrics/TestPeriodicExecutor.java +++ b/metrics/metrics/src/test/java/io/helidon/metrics/TestPeriodicExecutor.java @@ -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); @@ -137,14 +137,39 @@ void testWarningOnStopWhenStopped() throws InterruptedException { executor.stopExecutor(); List 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 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); } } From 83d8ec08ad303329548d6224c5c942c9c4b7b512 Mon Sep 17 00:00:00 2001 From: "tim.quinn@oracle.com" Date: Thu, 4 Nov 2021 11:16:54 -0500 Subject: [PATCH 2/2] Convert synchronized methods to use a semaphore --- .../io/helidon/metrics/PeriodicExecutor.java | 100 +++++++++++------- 1 file changed, 59 insertions(+), 41 deletions(-) diff --git a/metrics/metrics/src/main/java/io/helidon/metrics/PeriodicExecutor.java b/metrics/metrics/src/main/java/io/helidon/metrics/PeriodicExecutor.java index 88658a44671..3188d4380d0 100644 --- a/metrics/metrics/src/main/java/io/helidon/metrics/PeriodicExecutor.java +++ b/metrics/metrics/src/main/java/io/helidon/metrics/PeriodicExecutor.java @@ -75,12 +75,14 @@ private static class Enrollment { } } - private State state = State.DORMANT; + private volatile State state = State.DORMANT; private ScheduledExecutorService currentTimeUpdaterExecutorService; private final Collection deferredEnrollments = new ArrayList<>(); + private final Semaphore access = new Semaphore(1, true); + private PeriodicExecutor() { } @@ -100,49 +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 { - deferredEnrollments.add(new Enrollment(runnable, interval)); - if (state == State.STOPPED) { - LOGGER.log(Level.FINE, - "Recording deferred enrollment even though in unexpected state " + State.STOPPED, - new IllegalStateException()); + void enrollRunner(Runnable runnable, Duration interval) { + sync("enroll runner", () -> { + if (state == State.STARTED) { + currentTimeUpdaterExecutorService.scheduleAtFixedRate( + 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()); + } } - } + }); } - synchronized void startExecutor() { - if (state.isStartable()) { - LOGGER.log(Level.FINE, "Starting up with " + deferredEnrollments.size() + " deferred enrollments" - + (state == State.DORMANT ? "" : " even though in state " + State.STOPPED)); - state = State.STARTED; - currentTimeUpdaterExecutorService = Executors.newSingleThreadScheduledExecutor(); - for (Enrollment deferredEnrollment : deferredEnrollments) { - currentTimeUpdaterExecutorService.scheduleAtFixedRate( - deferredEnrollment.runnable, - deferredEnrollment.interval.toMillis(), - deferredEnrollment.interval.toMillis(), - TimeUnit.MILLISECONDS); + 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()); } - 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 stopExecutor() { + sync("stop", () -> { + LOGGER.log(Level.FINE, STOP_LOG_MESSAGE, state); + switch (state) { case STARTED: currentTimeUpdaterExecutorService.shutdownNow(); break; @@ -155,12 +162,23 @@ synchronized void stopExecutor() { "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); + } + } }