Fixed bug where jitter was switched with timestamp-diff in log output

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

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) {

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 + ']';
     }
-
 }

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,

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"
         );
     }
 }

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);
     }
 }

src/test/java/org/voltdb/meshmonitor/metrics/HistogramPrinterTest.java

@@ -31,15 +31,15 @@ void setUp() {
     public void shouldPrintBasicHistogram() {
         // Given
         meshMonitorTimings
-                .deltaHistogram()
+                .timestampDeltaHistogram()
                 .recordValueWithExpectedInterval(42L, 42L);
 
         HistogramPrinter printer = new HistogramPrinter("host_name");
         StringBuilder actual = new StringBuilder();
 
         // When
         meshMonitorTimings
-                .deltaHistogram()
+                .timestampDeltaHistogram()
                 .getCumulativeHistogram(histogram ->
                         printer.printHistogram(actual, histogram, REMOTE_ID, "empty_histogram")
                 );
@@ -57,23 +57,23 @@ 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");
         StringBuilder actual = new StringBuilder();
 
         // When
         meshMonitorTimings
-                .deltaHistogram()
+                .timestampDeltaHistogram()
                 .getCumulativeHistogram(histogram ->
                         printer.printHistogram(actual, histogram, REMOTE_ID, "histogram")
                 );

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");
 

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));