private static String getEncodedHistogram(Histogram combined) {
ByteBuffer targetBuffer = ByteBuffer.allocate(combined.getNeededByteBufferCapacity());
int compressedLength =
combined.encodeIntoCompressedByteBuffer(targetBuffer, Deflater.BEST_COMPRESSION);
byte[] compressedArray = Arrays.copyOf(targetBuffer.array(), compressedLength);
return DatatypeConverter.printBase64Binary(compressedArray);
}
private static String createEncodedHistogram() {
Random random = new Random();
Histogram histogram = new Histogram(MAXIMUM_LATENCY, LATENCY_PRECISION);
for (int i = 0; i < 10; i++) {
histogram.recordValue(random.nextInt((int) MAXIMUM_LATENCY));
}
return getEncodedHistogram(histogram);
}
private static void pongHandler(
final DirectBuffer buffer, final int offset, final int length, final Header header) {
final long pingTimestamp = buffer.getLong(offset);
final long rttNs = System.nanoTime() - pingTimestamp;
HISTOGRAM.recordValue(rttNs);
}
private static void runPing(final String embeddedDirName) throws InterruptedException {
final Aeron.Context ctx =
new Aeron.Context()
.availableImageHandler(EmbeddedPingPong::availablePongImageHandler)
.aeronDirectoryName(embeddedDirName);
System.out.println("Publishing Ping at " + PING_CHANNEL + " on stream Id " + PING_STREAM_ID);
System.out.println("Subscribing Pong at " + PONG_CHANNEL + " on stream Id " + PONG_STREAM_ID);
System.out.println("Message size of " + MESSAGE_LENGTH + " bytes");
final FragmentAssembler dataHandler = new FragmentAssembler(EmbeddedPingPong::pongHandler);
try (final Aeron aeron = Aeron.connect(ctx);
final Publication pingPublication = aeron.addPublication(PING_CHANNEL, PING_STREAM_ID);
final Subscription pongSubscription = aeron.addSubscription(PONG_CHANNEL, PONG_STREAM_ID)) {
System.out.println("Waiting for new image from Pong...");
PONG_IMAGE_LATCH.await();
System.out.println(
"Warming up... "
+ WARMUP_NUMBER_OF_ITERATIONS
+ " iterations of "
+ WARMUP_NUMBER_OF_MESSAGES
+ " messages");
for (int i = 0; i < WARMUP_NUMBER_OF_ITERATIONS; i++) {
roundTripMessages(
dataHandler, pingPublication, pongSubscription, WARMUP_NUMBER_OF_MESSAGES);
}
Thread.sleep(100);
final ContinueBarrier barrier = new ContinueBarrier("Execute again?");
do {
HISTOGRAM.reset();
System.out.println("Pinging " + NUMBER_OF_MESSAGES + " messages");
roundTripMessages(dataHandler, pingPublication, pongSubscription, NUMBER_OF_MESSAGES);
System.out.println("Histogram of RTT latencies in microseconds.");
HISTOGRAM.outputPercentileDistribution(System.out, 1000.0);
} while (barrier.await());
}
}
@Override
public Histogram call(Histogram initialDistribution, Histogram distributionToAdd) {
initialDistribution.add(distributionToAdd);
return initialDistribution;
}
@Test
public void testLatencyStats() throws Exception {
SimplePauseDetector pauseDetector =
new SimplePauseDetector(
1000000L /* 1 msec sleep */,
10000000L /* 10 msec reporting threshold */,
3 /* thread count */,
true /* verbose */);
LatencyStats.setDefaultPauseDetector(pauseDetector);
LatencyStats latencyStats = new LatencyStats();
pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + 115 * MSEC);
TimeServices.moveTimeForward(5000L);
TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
TimeServices.moveTimeForward(1000000L);
TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
TimeServices.moveTimeForward(2000000L);
TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
TimeServices.moveTimeForward(110000000L);
TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
try {
TimeUnit.NANOSECONDS.sleep(10 * MSEC); // Make sure things have some time to propagate
long startTime = TimeServices.nanoTime();
System.out.println(
"@ "
+ (TimeServices.nanoTime() - startTime)
+ " nsec after start: startTime = "
+ startTime);
long lastTime = startTime;
for (int i = 0; i < 2000; i++) {
pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + (4 * MSEC));
TimeServices.moveTimeForwardMsec(5);
// TimeUnit.NANOSECONDS.sleep(100000L); // Give things have some time to
// propagate
long now = TimeServices.nanoTime();
latencyStats.recordLatency(now - lastTime);
lastTime = now;
}
TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
// @ 10 sec from start
System.out.println("\nForcing Interval Update:\n");
latencyStats.forceIntervalSample();
System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
System.out.println(
"Estimated interval = "
+ latencyStats.getIntervalEstimator().getEstimatedInterval(lastTime));
Histogram accumulatedHistogram = latencyStats.getAccumulatedHistogram();
Histogram intervalHistogram = latencyStats.getIntervalHistogram();
System.out.println(
"Accumulated Average latency for 5msec sleeps: "
+ accumulatedHistogram.getMean()
+ ", count = "
+ accumulatedHistogram.getTotalCount());
System.out.println(
"Interval Average latency for 5msec sleeps: "
+ intervalHistogram.getMean()
+ ", count = "
+ intervalHistogram.getTotalCount());
Assert.assertEquals(
"Accumulated total count should be 2000", 2000, accumulatedHistogram.getTotalCount());
System.out.println("Pausing detector threads for 5 seconds:");
pauseDetector.stallDetectorThreads(0x7, 5000 * MSEC);
TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
// @ 15 sec from start
// Report without forcing interval measurement update:
System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
System.out.println(
"Estimated interval = "
+ latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
accumulatedHistogram = latencyStats.getAccumulatedHistogram();
intervalHistogram = latencyStats.getIntervalHistogram();
System.out.println(
"Post-pause, pre-observation Accumulated Average latency for 5msec sleeps: "
+ accumulatedHistogram.getMean()
+ ", count = "
+ accumulatedHistogram.getTotalCount());
System.out.println(
"Post-pause, pre-observation Interval Average latency for 5msec sleeps: "
+ intervalHistogram.getMean()
+ ", count = "
+ intervalHistogram.getTotalCount());
Assert.assertEquals(
"Accumulated total count should be 2000", 2000, accumulatedHistogram.getTotalCount());
// Still @ 15 sec from start
System.out.println("\nForcing Interval Update:\n");
latencyStats.forceIntervalSample();
System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
System.out.println(
"Estimated interval = "
+ latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
accumulatedHistogram = latencyStats.getAccumulatedHistogram();
intervalHistogram = latencyStats.getIntervalHistogram();
System.out.println(
"Post-pause, post-observation Accumulated Average latency for 5msec sleeps: "
+ accumulatedHistogram.getMean()
+ ", count = "
+ accumulatedHistogram.getTotalCount());
System.out.println(
"Post-pause, post-observation Interval Average latency for 5msec sleeps: "
+ intervalHistogram.getMean()
+ ", count = "
+ intervalHistogram.getTotalCount());
Assert.assertEquals(
"Accumulated total count should be 2000", 2998, accumulatedHistogram.getTotalCount());
pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + (500 * MSEC));
TimeServices.moveTimeForwardMsec(500);
TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
// @ 15.5 sec from start
System.out.println("\nForcing Interval Update:\n");
latencyStats.forceIntervalSample();
System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
System.out.println(
"Estimated interval = "
+ latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
accumulatedHistogram = latencyStats.getAccumulatedHistogram();
intervalHistogram = latencyStats.getIntervalHistogram();
System.out.println(
"Post-pause Accumulated Average latency for 5msec sleeps: "
+ accumulatedHistogram.getMean()
+ ", count = "
+ accumulatedHistogram.getTotalCount());
System.out.println(
"Post-pause Interval Average latency for 5msec sleeps: "
+ intervalHistogram.getMean()
+ ", count = "
+ intervalHistogram.getTotalCount());
Assert.assertEquals(
"Accumulated total count should be 2000", 2998, accumulatedHistogram.getTotalCount());
pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + (500 * MSEC));
TimeServices.moveTimeForwardMsec(500);
TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
// @ 16 sec from start
System.out.println("\nForcing Interval Update:\n");
latencyStats.forceIntervalSample();
System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
System.out.println(
"Estimated interval = "
+ latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
accumulatedHistogram = latencyStats.getAccumulatedHistogram();
intervalHistogram = latencyStats.getIntervalHistogram();
System.out.println(
"Post-pause Accumulated Average latency for 5msec sleeps: "
+ accumulatedHistogram.getMean()
+ ", count = "
+ accumulatedHistogram.getTotalCount());
System.out.println(
"Post-pause Interval Average latency for 5msec sleeps: "
+ intervalHistogram.getMean()
+ ", count = "
+ intervalHistogram.getTotalCount());
Assert.assertEquals(
"Accumulated total count should be 2999", 2998, accumulatedHistogram.getTotalCount());
pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + (2000 * MSEC));
TimeServices.moveTimeForwardMsec(2000);
TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
// @ 18 sec from start
System.out.println("\nForcing Interval Update:\n");
latencyStats.forceIntervalSample();
System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
System.out.println(
"Estimated interval = "
+ latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
accumulatedHistogram = latencyStats.getAccumulatedHistogram();
intervalHistogram = latencyStats.getIntervalHistogram();
System.out.println(
"Post-pause Accumulated Average latency for 5msec sleeps: "
+ accumulatedHistogram.getMean()
+ ", count = "
+ accumulatedHistogram.getTotalCount());
System.out.println(
"Post-pause Interval Average latency for 5msec sleeps: "
+ intervalHistogram.getMean()
+ ", count = "
+ intervalHistogram.getTotalCount());
Assert.assertEquals(
"Accumulated total count should be 2999", 2998, accumulatedHistogram.getTotalCount());
for (int i = 0; i < 100; i++) {
pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + (5 * MSEC));
TimeServices.moveTimeForwardMsec(5);
long now = TimeServices.nanoTime();
latencyStats.recordLatency(now - lastTime);
lastTime = now;
}
pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + (500 * MSEC));
TimeServices.moveTimeForwardMsec(500);
TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
// @ 19 sec from start
System.out.println("\nForcing Interval Update:\n");
latencyStats.forceIntervalSample();
System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
System.out.println(
"Estimated interval = "
+ latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
accumulatedHistogram = latencyStats.getAccumulatedHistogram();
intervalHistogram = latencyStats.getIntervalHistogram();
System.out.println(
"Post-pause Accumulated Average latency for 5msec sleeps: "
+ accumulatedHistogram.getMean()
+ ", count = "
+ accumulatedHistogram.getTotalCount());
System.out.println(
"Post-pause Interval Average latency for 5msec sleeps: "
+ intervalHistogram.getMean()
+ ", count = "
+ intervalHistogram.getTotalCount());
pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + (500 * MSEC));
TimeServices.moveTimeForwardMsec(500);
TimeUnit.NANOSECONDS.sleep(1 * MSEC); // Make sure things have some time to propagate
// @ 19.5 sec from start
System.out.println("\nForcing Interval Update:\n");
latencyStats.forceIntervalSample();
System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
System.out.println(
"Estimated interval = "
+ latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
accumulatedHistogram = latencyStats.getAccumulatedHistogram();
intervalHistogram = latencyStats.getIntervalHistogram();
System.out.println(
"Post-pause Accumulated Average latency for 5msec sleeps: "
+ accumulatedHistogram.getMean()
+ ", count = "
+ accumulatedHistogram.getTotalCount());
System.out.println(
"Post-pause Interval Average latency for 5msec sleeps: "
+ intervalHistogram.getMean()
+ ", count = "
+ intervalHistogram.getTotalCount());
Assert.assertEquals(
"Accumulated total count should be 2000", 3098, accumulatedHistogram.getTotalCount());
} catch (InterruptedException ex) {
}
latencyStats.stop();
pauseDetector.shutdown();
}