This is an automated email from the ASF dual-hosted git repository. szetszwo pushed a commit to branch branch-2_tmp in repository https://gitbox.apache.org/repos/asf/ratis.git
commit 74830239efd359216406459cc50047d22e2c39f8 Author: Tsz-Wo Nicholas Sze <[email protected]> AuthorDate: Thu Feb 23 00:32:46 2023 -0800 RATIS-1788. Improve the JvmPauseMonitor log messages. (#826) (cherry picked from commit 655db36c68a4c46a59150b548e76f2e92c33bf84) --- .../java/org/apache/ratis/util/JvmPauseMonitor.java | 18 ++++++++---------- .../main/java/org/apache/ratis/util/TimeDuration.java | 18 +++++++++++++++++- .../org/apache/ratis/server/impl/RaftServerProxy.java | 4 ++++ .../java/org/apache/ratis/util/TestTimeDuration.java | 18 ++++++++++-------- 4 files changed, 39 insertions(+), 19 deletions(-) diff --git a/ratis-common/src/main/java/org/apache/ratis/util/JvmPauseMonitor.java b/ratis-common/src/main/java/org/apache/ratis/util/JvmPauseMonitor.java index 1fcfc4d6a..532bd2255 100644 --- a/ratis-common/src/main/java/org/apache/ratis/util/JvmPauseMonitor.java +++ b/ratis-common/src/main/java/org/apache/ratis/util/JvmPauseMonitor.java @@ -65,28 +65,26 @@ public class JvmPauseMonitor { } static String toString(Map<String, GcInfo> beforeSleep, TimeDuration extraSleepTime, Map<String, GcInfo> afterSleep) { - final StringBuilder b = new StringBuilder("Detected pause in JVM or host machine (eg GC): pause of approximately ") - .append(extraSleepTime) - .append('.'); - - boolean detected = false; + final StringBuilder b = new StringBuilder(); + long ms = 0; for(Map.Entry<String, GcInfo> before: beforeSleep.entrySet()) { final String name = before.getKey(); final GcInfo after = afterSleep.get(name); if (after != null) { final GcInfo diff = after.subtract(before.getValue()); if (diff.count != 0) { + ms += diff.timeMs; b.append(System.lineSeparator()).append("GC pool '").append(name) .append("' had collection(s): ").append(diff); - detected = true; } } } - if (!detected) { - b.append(" No GCs detected."); - } - return b.toString(); + final String gc = b.length() == 0? " without any GCs." + : " with " + TimeDuration.valueOf(ms, TimeUnit.MILLISECONDS).toString(TimeUnit.SECONDS, 3) + + " GC time." + b; + return "Detected pause in JVM or host machine approximately " + + extraSleepTime.toString(TimeUnit.SECONDS, 3) + gc; } private static final TimeDuration SLEEP_TIME = TimeDuration.valueOf(500, TimeUnit.MILLISECONDS); diff --git a/ratis-common/src/main/java/org/apache/ratis/util/TimeDuration.java b/ratis-common/src/main/java/org/apache/ratis/util/TimeDuration.java index 58a61cc29..98fb3694e 100644 --- a/ratis-common/src/main/java/org/apache/ratis/util/TimeDuration.java +++ b/ratis-common/src/main/java/org/apache/ratis/util/TimeDuration.java @@ -32,7 +32,7 @@ import java.util.function.LongUnaryOperator; /** * Time duration is represented by a long together with a {@link TimeUnit}. - * + * <p> * This is a value-based class. */ public final class TimeDuration implements Comparable<TimeDuration> { @@ -375,4 +375,20 @@ public final class TimeDuration implements Comparable<TimeDuration> { public String toString() { return duration + Abbreviation.valueOf(unit).getDefault(); } + + /** @return a representation of this object in the given target unit and decimal places. */ + public String toString(TimeUnit targetUnit, int decimalPlaces) { + Objects.requireNonNull(targetUnit, "targetUnit == null"); + if (targetUnit.compareTo(unit) <= 0) { + return to(targetUnit).toString(); + } + final double divisor = unit.convert(1, targetUnit); + if (duration % divisor == 0) { + return to(targetUnit).toString(); + } + final String decimal = StringUtils.format("%." + decimalPlaces + "f", duration/divisor); + final String s = decimal + Abbreviation.valueOf(targetUnit).getDefault(); + LOG.debug("{}.to({}) = {}", this, targetUnit, s); + return s; + } } diff --git a/ratis-server/src/main/java/org/apache/ratis/server/impl/RaftServerProxy.java b/ratis-server/src/main/java/org/apache/ratis/server/impl/RaftServerProxy.java index 54cf15c65..f6f7223da 100644 --- a/ratis-server/src/main/java/org/apache/ratis/server/impl/RaftServerProxy.java +++ b/ratis-server/src/main/java/org/apache/ratis/server/impl/RaftServerProxy.java @@ -226,8 +226,12 @@ class RaftServerProxy implements RaftServer { private void handleJvmPause(TimeDuration extraSleep, TimeDuration closeThreshold, TimeDuration stepDownThreshold) throws IOException { if (extraSleep.compareTo(closeThreshold) > 0) { + LOG.error("{}: JVM pause detected {} longer than the close-threshold {}, shutting down ...", + getId(), extraSleep.toString(TimeUnit.SECONDS, 3), closeThreshold.toString(TimeUnit.SECONDS, 3)); close(); } else if (extraSleep.compareTo(stepDownThreshold) > 0) { + LOG.warn("{}: JVM pause detected {} longer than the step-down-threshold {}", + getId(), extraSleep.toString(TimeUnit.SECONDS, 3), stepDownThreshold.toString(TimeUnit.SECONDS, 3)); getImpls().forEach(RaftServerImpl::stepDownOnJvmPause); } } diff --git a/ratis-test/src/test/java/org/apache/ratis/util/TestTimeDuration.java b/ratis-test/src/test/java/org/apache/ratis/util/TestTimeDuration.java index edb0ad8a2..584c9e811 100644 --- a/ratis-test/src/test/java/org/apache/ratis/util/TestTimeDuration.java +++ b/ratis-test/src/test/java/org/apache/ratis/util/TestTimeDuration.java @@ -27,6 +27,7 @@ import java.util.concurrent.TimeUnit; import java.util.stream.Collectors; import static org.apache.ratis.util.TimeDuration.Abbreviation; +import static org.apache.ratis.util.TimeDuration.LOG; import static org.apache.ratis.util.TimeDuration.parse; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertNotNull; @@ -110,22 +111,23 @@ public class TestTimeDuration { @Test(timeout = 1000) public void testTo() { final TimeDuration oneSecond = TimeDuration.valueOf(1, TimeUnit.SECONDS); - assertTo(1000, oneSecond, TimeUnit.MILLISECONDS); - final TimeDuration nanos = assertTo(1_000_000_000, oneSecond, TimeUnit.NANOSECONDS); - assertTo(1000, nanos, TimeUnit.MILLISECONDS); + assertTo(1000, "1000ms", oneSecond, TimeUnit.MILLISECONDS); + final TimeDuration nanos = assertTo(1_000_000_000, "1000000000ns", oneSecond, TimeUnit.NANOSECONDS); + assertTo(1000, "1000ms", nanos, TimeUnit.MILLISECONDS); - assertTo(0, oneSecond, TimeUnit.MINUTES); - assertTo(0, nanos, TimeUnit.MINUTES); + assertTo(0, "0.0167min", oneSecond, TimeUnit.MINUTES); + assertTo(0, "0.0167min", nanos, TimeUnit.MINUTES); final TimeDuration millis = TimeDuration.valueOf(1_999, TimeUnit.MILLISECONDS); - assertTo(1, millis, TimeUnit.SECONDS); - assertTo(0, millis, TimeUnit.MINUTES); + assertTo(1, "1.9990s", millis, TimeUnit.SECONDS); + assertTo(0, "0.0333min", millis, TimeUnit.MINUTES); } - static TimeDuration assertTo(long expected, TimeDuration timeDuration, TimeUnit toUnit) { + static TimeDuration assertTo(long expected, String expectedString, TimeDuration timeDuration, TimeUnit toUnit) { final TimeDuration computed = timeDuration.to(toUnit); assertEquals(expected, computed.getDuration()); assertEquals(toUnit, computed.getUnit()); + assertEquals(expectedString, timeDuration.toString(toUnit, 4)); return computed; }
