diff --git a/README.md b/README.md index 39a3e41..7b5b802 100644 --- a/README.md +++ b/README.md @@ -94,20 +94,21 @@ pertains to. If a message has no such context then the IP column will be empty: There are 3 kinds of measurements: * ping (delta receive) - delta between receiving heartbeats -* jitter (delta send) - delta between sending heartbeats -* timestamp delta - delta between remotely recorded sent timestamp and locally recorded receive time +* jitter (delta send) - the time that has passed between sending consecutive pings. +* timestamp delta - delta between remotely recorded timestamp when ping + was generated and a locally recorded timestamp when it was received. Meshmonitor will print histograms of each of the three tracked values. All of these values need to be interpreted with the `--ping` interval in mind (default 5ms) that is included in the measurement values. The values that are printed are max, mean, and percentiles: 99th, 99.9th, and 99.99th: ```console -[ ] --------receive-(ms)--------- ---------delta-(ms)---------- ---------send-(ms)----------- -[ ] Max Mean 99 99.9 99.99| Max Mean 99 99.9 99.99| Max Mean 99 99.9 99.99 -[ 172.31.10.72] 5.2 5.1 5.1 5.2 5.2| 0.2 0.0 0.0 0.1 0.2| 5.1 5.1 5.1 5.1 5.1 -[ 172.31.14.3] 5.3 5.1 5.1 5.1 5.3| 0.4 0.2 0.2 0.2 0.4| 5.8 5.1 5.1 5.5 5.8 -[ 172.31.9.146] 5.1 5.1 5.1 5.1 5.1| 5.1 2.6 5.0 5.1 5.1| 5.1 5.1 5.1 5.1 5.1 -[ 172.31.5.177] 5.1 5.1 5.1 5.1 5.1| 5.2 2.8 5.2 5.2 5.2| 5.1 5.1 5.1 5.1 5.1 +09:08:55 [ ] ----------ping-(ms)---------- ---------jitter-(ms)--------- ----timestamp-diff-(ms)------ +09:08:55 [ ] Max Mean 99 99.9 99.99| Max Mean 99 99.9 99.99 | Max Mean 99 99.9 99.99 +09:08:55 [ 172.31.10.72] 5.2 5.1 5.1 5.2 5.2| 5.1 5.1 5.1 5.1 5.1 | 0.2 0.0 0.0 0.1 0.2 +09:08:55 [ 172.31.14.3] 5.3 5.1 5.1 5.1 5.3| 5.8 5.1 5.1 5.5 5.8 | 0.4 0.2 0.2 0.2 0.4 +09:08:55 [ 172.31.9.146] 5.1 5.1 5.1 5.1 5.1| 5.1 5.1 5.1 5.1 5.1 | 5.1 2.6 5.0 5.1 5.1 +09:08:55 [ 172.31.5.177] 5.1 5.1 5.1 5.1 5.1| 5.1 5.1 5.1 5.1 5.1 | 5.2 2.8 5.2 5.2 5.2 ``` Measurements exceeding `--threshold` (default 20ms) will be printed in yellow. Those that exceed 1 second will be printed in diff --git a/src/main/java/org/voltdb/meshmonitor/HistogramLogger.java b/src/main/java/org/voltdb/meshmonitor/HistogramLogger.java index 4d255f4..f175a4c 100644 --- a/src/main/java/org/voltdb/meshmonitor/HistogramLogger.java +++ b/src/main/java/org/voltdb/meshmonitor/HistogramLogger.java @@ -25,11 +25,11 @@ public void printResults(Monitor monitor, long minHiccupSize) { MeshMonitorTimings currentTimings = monitor.getTimings(); InetSocketAddress remoteId = monitor.getRemoteId(); - String receive = printAndReset(currentTimings.receiveHistogram(), minHiccupSize); - String delta = printAndReset(currentTimings.deltaHistogram(), minHiccupSize); - String send = printAndReset(currentTimings.sendHistogram(), minHiccupSize); + String ping = printAndReset(currentTimings.pingHistogram(), minHiccupSize); + String jitter = printAndReset(currentTimings.jitterHistogram(), minHiccupSize); + String timestampDiff = printAndReset(currentTimings.timestampDeltaHistogram(), minHiccupSize); - consoleLogger.log(remoteId, receive + "|" + delta + "|" + send); + consoleLogger.log(remoteId, ping + "|" + jitter + "|" + timestampDiff); } private String printAndReset(HistogramWithDelta histogram, long minHiccupSize) { diff --git a/src/main/java/org/voltdb/meshmonitor/MeshMonitorTimings.java b/src/main/java/org/voltdb/meshmonitor/MeshMonitorTimings.java index 98ca9f2..7adfdd5 100644 --- a/src/main/java/org/voltdb/meshmonitor/MeshMonitorTimings.java +++ b/src/main/java/org/voltdb/meshmonitor/MeshMonitorTimings.java @@ -15,30 +15,31 @@ public final class MeshMonitorTimings { public static final int NUMBER_OF_SIGNIFICANT_VALUE_DIGITS = 3; public static final long HIGHEST_TRACKABLE_VALUE = 24 * 60 * 60 * 1000 * 1000L; - private final HistogramWithDelta receiveHistogram; - private final HistogramWithDelta sendHistogram; - private final HistogramWithDelta deltaHistogram; + + private final HistogramWithDelta pingHistogram; + private final HistogramWithDelta jitterHistogram; + private final HistogramWithDelta timestampDeltaHistogram; public MeshMonitorTimings( - HistogramWithDelta receiveHistogram, - HistogramWithDelta sendHistogram, - HistogramWithDelta deltaHistogram) { - this.receiveHistogram = receiveHistogram; - this.sendHistogram = sendHistogram; - this.deltaHistogram = deltaHistogram; + HistogramWithDelta pingHistogram, + HistogramWithDelta jitterHistogram, + HistogramWithDelta timestampDeltaHistogram) { + this.pingHistogram = pingHistogram; + this.jitterHistogram = jitterHistogram; + this.timestampDeltaHistogram = timestampDeltaHistogram; } public void pingReceived(long now, long lastReceiveTime, long timestampFromRemoteHost, long pingInterval) { long valueToRecord = now - lastReceiveTime; - receiveHistogram.recordValueWithExpectedInterval(valueToRecord, pingInterval); + pingHistogram.recordValueWithExpectedInterval(valueToRecord, pingInterval); // Abs because clocks can be slightly out of sync... valueToRecord = Math.abs(now - timestampFromRemoteHost); - deltaHistogram.recordValueWithExpectedInterval(valueToRecord, pingInterval); + timestampDeltaHistogram.recordValueWithExpectedInterval(valueToRecord, pingInterval); } public void trackWakeupJitter(long observedInterval, long expectedInterval) { - sendHistogram.recordValueWithExpectedInterval(observedInterval, expectedInterval); + jitterHistogram.recordValueWithExpectedInterval(observedInterval, expectedInterval); } private static SynchronizedHistogram defaultHistogram() { @@ -47,22 +48,22 @@ private static SynchronizedHistogram defaultHistogram() { public static MeshMonitorTimings createDefault(ConsoleLogger logger) { return new MeshMonitorTimings( - new HistogramWithDelta(logger, "receive", defaultHistogram()), - new HistogramWithDelta(logger, "send", defaultHistogram()), - new HistogramWithDelta(logger, "delta", defaultHistogram()) + new HistogramWithDelta(logger, "ping", defaultHistogram()), + new HistogramWithDelta(logger, "jitter", defaultHistogram()), + new HistogramWithDelta(logger, "timestamp delta", defaultHistogram()) ); } - public HistogramWithDelta receiveHistogram() { - return receiveHistogram; + public HistogramWithDelta pingHistogram() { + return pingHistogram; } - public HistogramWithDelta sendHistogram() { - return sendHistogram; + public HistogramWithDelta jitterHistogram() { + return jitterHistogram; } - public HistogramWithDelta deltaHistogram() { - return deltaHistogram; + public HistogramWithDelta timestampDeltaHistogram() { + return timestampDeltaHistogram; } @Override @@ -71,22 +72,21 @@ public boolean equals(Object obj) { if (obj == null || obj.getClass() != this.getClass()) return false; MeshMonitorTimings that = (MeshMonitorTimings) obj; - return Objects.equals(this.receiveHistogram, that.receiveHistogram) && - Objects.equals(this.sendHistogram, that.sendHistogram) && - Objects.equals(this.deltaHistogram, that.deltaHistogram); + return Objects.equals(this.pingHistogram, that.pingHistogram) && + Objects.equals(this.jitterHistogram, that.jitterHistogram) && + Objects.equals(this.timestampDeltaHistogram, that.timestampDeltaHistogram); } @Override public int hashCode() { - return Objects.hash(receiveHistogram, sendHistogram, deltaHistogram); + return Objects.hash(pingHistogram, jitterHistogram, timestampDeltaHistogram); } @Override public String toString() { return "MeshMonitorTimings[" + - "receiveHistogram=" + receiveHistogram + ", " + - "sendHistogram=" + sendHistogram + ", " + - "deltaHistogram=" + deltaHistogram + ']'; + "pingHistogram=" + pingHistogram + ", " + + "jitterHistogram=" + jitterHistogram + ", " + + "timestampDeltaHistogram=" + timestampDeltaHistogram + ']'; } - } diff --git a/src/main/java/org/voltdb/meshmonitor/metrics/MonitorStatsPrinter.java b/src/main/java/org/voltdb/meshmonitor/metrics/MonitorStatsPrinter.java index de498d2..801aa14 100644 --- a/src/main/java/org/voltdb/meshmonitor/metrics/MonitorStatsPrinter.java +++ b/src/main/java/org/voltdb/meshmonitor/metrics/MonitorStatsPrinter.java @@ -24,21 +24,21 @@ public void print(StringBuilder output, Monitor monitor) { MeshMonitorTimings timings = monitor.getTimings(); InetSocketAddress remoteId = monitor.getRemoteId(); - timings.receiveHistogram().getCumulativeHistogram(histogram -> + timings.pingHistogram().getCumulativeHistogram(histogram -> histogramPrinter.printHistogram(output, histogram, remoteId, "receive_seconds") ); - timings.deltaHistogram().getCumulativeHistogram(histogram -> + timings.timestampDeltaHistogram().getCumulativeHistogram(histogram -> histogramPrinter.printHistogram(output, histogram, remoteId, "delta_seconds") ); - timings.sendHistogram().getCumulativeHistogram(histogram -> { + timings.jitterHistogram().getCumulativeHistogram(histogram -> { histogramPrinter.printHistogram(output, histogram, remoteId, diff --git a/src/test/java/org/voltdb/meshmonitor/HistogramLoggerTest.java b/src/test/java/org/voltdb/meshmonitor/HistogramLoggerTest.java index 2f42a34..9731645 100644 --- a/src/test/java/org/voltdb/meshmonitor/HistogramLoggerTest.java +++ b/src/test/java/org/voltdb/meshmonitor/HistogramLoggerTest.java @@ -49,14 +49,14 @@ void shouldPrintHistograms() { ConsoleLogger consoleLogger = ConsoleLoggerTest.loggerForTest(logContent); MeshMonitorTimings timings1 = MeshMonitorTimings.createDefault(consoleLogger); - timings1.receiveHistogram().recordValueWithExpectedInterval(TimeUnit.MILLISECONDS.toMicros(10), EXPECTED_INTERVAL); - timings1.deltaHistogram().recordValueWithExpectedInterval(TimeUnit.MILLISECONDS.toMicros(12), EXPECTED_INTERVAL); - timings1.sendHistogram().recordValueWithExpectedInterval(TimeUnit.MILLISECONDS.toMicros(14), EXPECTED_INTERVAL); + timings1.pingHistogram().recordValueWithExpectedInterval(TimeUnit.MILLISECONDS.toMicros(10), EXPECTED_INTERVAL); + timings1.timestampDeltaHistogram().recordValueWithExpectedInterval(TimeUnit.MILLISECONDS.toMicros(12), EXPECTED_INTERVAL); + timings1.jitterHistogram().recordValueWithExpectedInterval(TimeUnit.MILLISECONDS.toMicros(14), EXPECTED_INTERVAL); MeshMonitorTimings timings2 = MeshMonitorTimings.createDefault(consoleLogger); - timings2.receiveHistogram().recordValueWithExpectedInterval(TimeUnit.MILLISECONDS.toMicros(1), EXPECTED_INTERVAL); - timings2.deltaHistogram().recordValueWithExpectedInterval(TimeUnit.MILLISECONDS.toMicros(3), EXPECTED_INTERVAL); - timings2.sendHistogram().recordValueWithExpectedInterval(TimeUnit.MILLISECONDS.toMicros(7), EXPECTED_INTERVAL); + timings2.pingHistogram().recordValueWithExpectedInterval(TimeUnit.MILLISECONDS.toMicros(1), EXPECTED_INTERVAL); + timings2.timestampDeltaHistogram().recordValueWithExpectedInterval(TimeUnit.MILLISECONDS.toMicros(3), EXPECTED_INTERVAL); + timings2.jitterHistogram().recordValueWithExpectedInterval(TimeUnit.MILLISECONDS.toMicros(7), EXPECTED_INTERVAL); Monitor monitor1 = mock(Monitor.class); when(monitor1.getRemoteId()).thenReturn(REMOTE_ID_1); @@ -76,8 +76,8 @@ void shouldPrintHistograms() { assertThat(logContent.toString()).containsIgnoringNewLines( // ----------ping-(ms)---------- ---------jitter-(ms)--------- ----timestamp-diff-(ms)------ // Max Mean 99 99.9 99.99| Max Mean 99 99.9 99.99| Max Mean 99 99.9 99.99 - "[ 10.1.0.2] 10.0 7.5 10.0 10.0 10.0| 12.0 9.5 12.0 12.0 12.0| 14.0 11.5 14.0 14.0 14.0", - "[ 10.1.0.3] 1.0 1.0 1.0 1.0 1.0| 3.0 3.0 3.0 3.0 3.0| 7.0 7.0 7.0 7.0 7.0" + "[ 10.1.0.2] 10.0 7.5 10.0 10.0 10.0| 14.0 11.5 14.0 14.0 14.0| 12.0 9.5 12.0 12.0 12.0", + "[ 10.1.0.3] 1.0 1.0 1.0 1.0 1.0| 7.0 7.0 7.0 7.0 7.0| 3.0 3.0 3.0 3.0 3.0" ); } @@ -88,9 +88,9 @@ void shouldConvertLargeValuesToSecondss() { ConsoleLogger consoleLogger = ConsoleLoggerTest.loggerForTest(logContent); MeshMonitorTimings timings1 = MeshMonitorTimings.createDefault(consoleLogger); - timings1.receiveHistogram().recordValueWithExpectedInterval(TimeUnit.SECONDS.toMicros(10), EXPECTED_INTERVAL); - timings1.deltaHistogram().recordValueWithExpectedInterval(TimeUnit.SECONDS.toMicros(12), EXPECTED_INTERVAL); - timings1.sendHistogram().recordValueWithExpectedInterval(TimeUnit.SECONDS.toMicros(14), EXPECTED_INTERVAL); + timings1.pingHistogram().recordValueWithExpectedInterval(TimeUnit.SECONDS.toMicros(10), EXPECTED_INTERVAL); + timings1.timestampDeltaHistogram().recordValueWithExpectedInterval(TimeUnit.SECONDS.toMicros(12), EXPECTED_INTERVAL); + timings1.jitterHistogram().recordValueWithExpectedInterval(TimeUnit.SECONDS.toMicros(14), EXPECTED_INTERVAL); Monitor monitor1 = mock(Monitor.class); when(monitor1.getRemoteId()).thenReturn(REMOTE_ID_1); @@ -105,7 +105,7 @@ void shouldConvertLargeValuesToSecondss() { assertThat(logContent.toString()).containsIgnoringNewLines( // ----------ping-(ms)---------- ---------jitter-(ms)--------- ----timestamp-diff-(ms)------ // Max Mean 99 99.9 99.99| Max Mean 99 99.9 99.99| Max Mean 99 99.9 99.99 - "[ 10.1.0.2] 10.0s 5.0s 9.9s 10.0s 10.0s|12.0s 6.0s 11.9s 12.0s 12.0s|14.0s 7.0s 13.9s 14.0s 14.0s" + "[ 10.1.0.2] 10.0s 5.0s 9.9s 10.0s 10.0s|14.0s 7.0s 13.9s 14.0s 14.0s|12.0s 6.0s 11.9s 12.0s 12.0s" ); } } diff --git a/src/test/java/org/voltdb/meshmonitor/MeshMonitorTimingsTest.java b/src/test/java/org/voltdb/meshmonitor/MeshMonitorTimingsTest.java index f0b8eeb..b010cf4 100644 --- a/src/test/java/org/voltdb/meshmonitor/MeshMonitorTimingsTest.java +++ b/src/test/java/org/voltdb/meshmonitor/MeshMonitorTimingsTest.java @@ -30,8 +30,8 @@ void shouldRecordPingReceivedProperly() { timings.pingReceived(now, lastReceiveTime, timestampFromRemoteHost, pingInterval); // Then - long receiveSamples = timings.receiveHistogram().getCumulativeHistogram().getCountAtValue(now - lastReceiveTime); - long deltaSamples = timings.deltaHistogram().getCumulativeHistogram().getCountAtValue(now - timestampFromRemoteHost); + long receiveSamples = timings.pingHistogram().getCumulativeHistogram().getCountAtValue(now - lastReceiveTime); + long deltaSamples = timings.timestampDeltaHistogram().getCumulativeHistogram().getCountAtValue(now - timestampFromRemoteHost); assertThat(receiveSamples).isEqualTo(1); assertThat(deltaSamples).isEqualTo(1); @@ -51,8 +51,8 @@ void shouldHandleNegativeDeltaInPingReceived() { timings.pingReceived(now, lastReceiveTime, timestampFromRemoteHost, pingInterval); // Then - long receiveSamples = timings.receiveHistogram().getCumulativeHistogram().getCountAtValue(now - lastReceiveTime); - long deltaSamples = timings.deltaHistogram().getCumulativeHistogram().getCountAtValue(Math.abs(now - timestampFromRemoteHost)); + long receiveSamples = timings.pingHistogram().getCumulativeHistogram().getCountAtValue(now - lastReceiveTime); + long deltaSamples = timings.timestampDeltaHistogram().getCumulativeHistogram().getCountAtValue(Math.abs(now - timestampFromRemoteHost)); assertThat(receiveSamples).isEqualTo(1); assertThat(deltaSamples).isEqualTo(1); @@ -69,7 +69,7 @@ void shouldTrackWakeupJitterProperly() { timings.trackWakeupJitter(expected, expected); // Then - long actual = timings.sendHistogram().getCumulativeHistogram().getCountAtValue(expected); + long actual = timings.jitterHistogram().getCumulativeHistogram().getCountAtValue(expected); assertThat(actual).isEqualTo(1); } } diff --git a/src/test/java/org/voltdb/meshmonitor/metrics/HistogramPrinterTest.java b/src/test/java/org/voltdb/meshmonitor/metrics/HistogramPrinterTest.java index f02e0ce..063ecb1 100644 --- a/src/test/java/org/voltdb/meshmonitor/metrics/HistogramPrinterTest.java +++ b/src/test/java/org/voltdb/meshmonitor/metrics/HistogramPrinterTest.java @@ -31,7 +31,7 @@ void setUp() { public void shouldPrintBasicHistogram() { // Given meshMonitorTimings - .deltaHistogram() + .timestampDeltaHistogram() .recordValueWithExpectedInterval(42L, 42L); HistogramPrinter printer = new HistogramPrinter("host_name"); @@ -39,7 +39,7 @@ public void shouldPrintBasicHistogram() { // When meshMonitorTimings - .deltaHistogram() + .timestampDeltaHistogram() .getCumulativeHistogram(histogram -> printer.printHistogram(actual, histogram, REMOTE_ID, "empty_histogram") ); @@ -57,15 +57,15 @@ public void shouldPrintBasicHistogram() { public void shouldFormatCumulativeBuckets() { // Given meshMonitorTimings - .deltaHistogram() + .timestampDeltaHistogram() .recordValueWithExpectedInterval(42L, 42L); meshMonitorTimings - .deltaHistogram() + .timestampDeltaHistogram() .recordValueWithExpectedInterval(420L, 420L); meshMonitorTimings - .deltaHistogram() + .timestampDeltaHistogram() .recordValueWithExpectedInterval(4200L, 4200L); HistogramPrinter printer = new HistogramPrinter("host_name"); @@ -73,7 +73,7 @@ public void shouldFormatCumulativeBuckets() { // When meshMonitorTimings - .deltaHistogram() + .timestampDeltaHistogram() .getCumulativeHistogram(histogram -> printer.printHistogram(actual, histogram, REMOTE_ID, "histogram") ); diff --git a/src/test/java/org/voltdb/meshmonitor/metrics/MonitorStatsPrinterTest.java b/src/test/java/org/voltdb/meshmonitor/metrics/MonitorStatsPrinterTest.java index 26be55b..5efc99b 100644 --- a/src/test/java/org/voltdb/meshmonitor/metrics/MonitorStatsPrinterTest.java +++ b/src/test/java/org/voltdb/meshmonitor/metrics/MonitorStatsPrinterTest.java @@ -26,9 +26,9 @@ class MonitorStatsPrinterTest { void shouldPrintOutputOfAllHistograms() { // Given MeshMonitorTimings timings = MeshMonitorTimings.createDefault(ConsoleLoggerTest.loggerForTest()); - timings.sendHistogram().recordValueWithExpectedInterval(5, 5); - timings.deltaHistogram().recordValueWithExpectedInterval(15, 15); - timings.receiveHistogram().recordValueWithExpectedInterval(42, 42); + timings.jitterHistogram().recordValueWithExpectedInterval(5, 5); + timings.timestampDeltaHistogram().recordValueWithExpectedInterval(15, 15); + timings.pingHistogram().recordValueWithExpectedInterval(42, 42); MonitorStatsPrinter printer = new MonitorStatsPrinter("host"); diff --git a/src/test/java/org/voltdb/meshmonitor/metrics/SimplePrometheusMetricsServerTest.java b/src/test/java/org/voltdb/meshmonitor/metrics/SimplePrometheusMetricsServerTest.java index ae9630b..13c976b 100644 --- a/src/test/java/org/voltdb/meshmonitor/metrics/SimplePrometheusMetricsServerTest.java +++ b/src/test/java/org/voltdb/meshmonitor/metrics/SimplePrometheusMetricsServerTest.java @@ -141,7 +141,7 @@ void shouldRespondWithMetricsFromManyMonitors() { @NotNull private static Monitor createMonitorWithTimings(String host, long... values) { MeshMonitorTimings timings = MeshMonitorTimings.createDefault(LOGGER); - Arrays.stream(values).forEach(value -> timings.receiveHistogram() + Arrays.stream(values).forEach(value -> timings.pingHistogram() // make it simple to reason for assertions so expectedIntervalBetweenValueSamples is the same as value. .recordValueWithExpectedInterval(value, value));