use of org.HdrHistogram.Histogram in project pulsar by yahoo.
the class PerformanceProducer method printAggregatedStats.
private static void printAggregatedStats() {
Histogram reportHistogram = cumulativeRecorder.getIntervalHistogram();
log.info("Aggregated latency stats --- Latency: mean: {} ms - med: {} - 95pct: {} - 99pct: {} - 99.9pct: {} - 99.99pct: {} - 99.999pct: {} - Max: {}", dec.format(reportHistogram.getMean() / 1000.0), dec.format(reportHistogram.getValueAtPercentile(50) / 1000.0), dec.format(reportHistogram.getValueAtPercentile(95) / 1000.0), dec.format(reportHistogram.getValueAtPercentile(99) / 1000.0), dec.format(reportHistogram.getValueAtPercentile(99.9) / 1000.0), dec.format(reportHistogram.getValueAtPercentile(99.99) / 1000.0), dec.format(reportHistogram.getValueAtPercentile(99.999) / 1000.0), dec.format(reportHistogram.getMaxValue() / 1000.0));
}
use of org.HdrHistogram.Histogram in project LatencyUtils by LatencyUtils.
the class LatencyStatsTest method testLatencyStats.
@Test
public void testLatencyStats() throws Exception {
SimplePauseDetector pauseDetector = new SimplePauseDetector(1000000L, /* 1 msec sleep */
10000000L, /* 10 msec reporting threshold */
3, /* thread count */
true);
LatencyStats.setDefaultPauseDetector(pauseDetector);
LatencyStats latencyStats = new LatencyStats();
Histogram accumulatedHistogram = new Histogram(latencyStats.getIntervalHistogram());
try {
Thread.sleep(100);
pauseDetector.skipConsensusTimeTo(TimeServices.nanoTime() + 115 * MSEC);
TimeServices.moveTimeForward(5000L);
// Make sure things have some time to propagate
TimeUnit.NANOSECONDS.sleep(1 * MSEC);
TimeServices.moveTimeForward(1000000L);
// Make sure things have some time to propagate
TimeUnit.NANOSECONDS.sleep(1 * MSEC);
TimeServices.moveTimeForward(2000000L);
// Make sure things have some time to propagate
TimeUnit.NANOSECONDS.sleep(1 * MSEC);
TimeServices.moveTimeForward(110000000L);
// Make sure things have some time to propagate
TimeUnit.NANOSECONDS.sleep(1 * MSEC);
// Make sure things have some time to propagate
TimeUnit.NANOSECONDS.sleep(10 * MSEC);
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;
}
// Make sure things have some time to propagate
TimeUnit.NANOSECONDS.sleep(1 * MSEC);
// @ 10 sec from start
System.out.println("\nForcing Interval Update:\n");
Histogram intervalHistogram = latencyStats.getIntervalHistogram();
accumulatedHistogram.add(intervalHistogram);
System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
System.out.println("Estimated interval = " + latencyStats.getIntervalEstimator().getEstimatedInterval(lastTime));
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);
// Make sure things have some time to propagate
TimeUnit.NANOSECONDS.sleep(1 * MSEC);
// @ 15 sec from start
// Report without doing an interval measurement update:
System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
System.out.println("Estimated interval = " + latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
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");
System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
System.out.println("Estimated interval = " + latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
intervalHistogram = latencyStats.getIntervalHistogram();
accumulatedHistogram.add(intervalHistogram);
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);
// Make sure things have some time to propagate
TimeUnit.NANOSECONDS.sleep(1 * MSEC);
// @ 15.5 sec from start
System.out.println("\nForcing Interval Update:\n");
System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
System.out.println("Estimated interval = " + latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
intervalHistogram = latencyStats.getIntervalHistogram();
accumulatedHistogram.add(intervalHistogram);
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);
// Make sure things have some time to propagate
TimeUnit.NANOSECONDS.sleep(1 * MSEC);
// @ 16 sec from start
System.out.println("\nForcing Interval Update:\n");
System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
System.out.println("Estimated interval = " + latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
intervalHistogram = latencyStats.getIntervalHistogram();
accumulatedHistogram.add(intervalHistogram);
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);
// Make sure things have some time to propagate
TimeUnit.NANOSECONDS.sleep(1 * MSEC);
// @ 18 sec from start
System.out.println("\nForcing Interval Update:\n");
System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
System.out.println("Estimated interval = " + latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
intervalHistogram = latencyStats.getIntervalHistogram();
accumulatedHistogram.add(intervalHistogram);
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);
// Make sure things have some time to propagate
TimeUnit.NANOSECONDS.sleep(1 * MSEC);
// @ 19 sec from start
System.out.println("\nForcing Interval Update:\n");
System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
System.out.println("Estimated interval = " + latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
intervalHistogram = latencyStats.getIntervalHistogram();
accumulatedHistogram.add(intervalHistogram);
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);
// Make sure things have some time to propagate
TimeUnit.NANOSECONDS.sleep(1 * MSEC);
// @ 19.5 sec from start
System.out.println("\nForcing Interval Update:\n");
System.out.println("@ " + (TimeServices.nanoTime() - startTime) + " nsec after start:");
System.out.println("Estimated interval = " + latencyStats.getIntervalEstimator().getEstimatedInterval(TimeServices.nanoTime()));
intervalHistogram = latencyStats.getIntervalHistogram();
accumulatedHistogram.add(intervalHistogram);
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();
}
use of org.HdrHistogram.Histogram in project LatencyUtils by LatencyUtils.
the class LatencyStats method getLatestUncorrectedIntervalHistogram.
/**
* Get a copy of the uncorrected latest interval latency histogram. Values will not include
* corrections for detected pauses. The interval histogram copies will include all values points
* captured up to the latest call to call to one of {@link #getIntervalHistogram},
* {@link #getIntervalHistogramInto}, or {@link #addIntervalHistogramTo}.
*
* @return a copy of the latest uncorrected interval latency histogram
*/
public synchronized Histogram getLatestUncorrectedIntervalHistogram() {
try {
recordingPhaser.readerLock();
Histogram intervalHistogram = new Histogram(lowestTrackableLatency, highestTrackableLatency, numberOfSignificantValueDigits);
getLatestUncorrectedIntervalHistogramInto(intervalHistogram);
return intervalHistogram;
} finally {
recordingPhaser.readerUnlock();
}
}
use of org.HdrHistogram.Histogram in project logging-log4j2 by apache.
the class ResponseTimeTest method createResultHistogram.
private static Histogram createResultHistogram(final List<Histogram> list, final long start, final long end) {
final Histogram result = new Histogram(TimeUnit.SECONDS.toNanos(10), 3);
result.setStartTimeStamp(start);
result.setEndTimeStamp(end);
for (final Histogram hist : list) {
result.add(hist);
}
return result;
}
use of org.HdrHistogram.Histogram in project logging-log4j2 by apache.
the class ResponseTimeTest method main.
public static void main(final String[] args) throws Exception {
if (args.length < 2) {
System.out.println("Please specify thread count, target throughput (msg/sec) " + "and logger library (Log4j1, Log4j2, Logback, JUL)");
return;
}
final int threadCount = Integer.parseInt(args[0]);
final double loadMessagesPerSec = Double.parseDouble(args[1]);
final String loggerLib = args.length > 2 ? args[2] : "Log4j2";
// print to console if ringbuffer is full
System.setProperty("log4j2.AsyncQueueFullPolicy", PrintingAsyncQueueFullPolicy.class.getName());
System.setProperty("AsyncLogger.RingBufferSize", String.valueOf(256 * 1024));
//System.setProperty("log4j.configurationFile", "perf3PlainNoLoc.xml");
if (System.getProperty("AsyncLogger.WaitStrategy") == null) {
System.setProperty("AsyncLogger.WaitStrategy", "Yield");
}
//for (Object key : System.getProperties().keySet()) {
// System.out.println(key + "=" + System.getProperty((String) key));
//}
// initialize the logger
final String wrapper = loggerLib.startsWith("Run") ? loggerLib : "Run" + loggerLib;
final String loggerWrapperClass = "org.apache.logging.log4j.core.async.perftest." + wrapper;
final IPerfTestRunner logger = Loader.newCheckedInstanceOf(loggerWrapperClass, IPerfTestRunner.class);
// ensure initialized
logger.log("Starting...");
Thread.sleep(100);
// producers + 1 consumer + 1 for OS
final int requiredProcessors = threadCount + 1 + 1;
final IdleStrategy idleStrategy = Runtime.getRuntime().availableProcessors() > requiredProcessors ? new NoOpIdleStrategy() : new YieldIdleStrategy();
System.out.printf("%s: %d threads, load is %,f msg/sec, using %s%n", loggerLib, threadCount, loadMessagesPerSec, idleStrategy.getClass().getSimpleName());
// Warmup: run as many iterations of 50,000 calls to logger.log as we can in 1 minute
final long WARMUP_DURATION_MILLIS = TimeUnit.MINUTES.toMillis(1);
final List<Histogram> warmupServiceTmHistograms = new ArrayList<>(threadCount);
final List<Histogram> warmupResponseTmHistograms = new ArrayList<>(threadCount);
final int WARMUP_COUNT = 50000 / threadCount;
runLatencyTest(logger, WARMUP_DURATION_MILLIS, WARMUP_COUNT, loadMessagesPerSec, idleStrategy, warmupServiceTmHistograms, warmupResponseTmHistograms, threadCount);
System.out.println("-----------------Warmup done. load=" + loadMessagesPerSec);
if (!Constants.ENABLE_DIRECT_ENCODERS || !Constants.ENABLE_THREADLOCALS) {
//System.gc();
//Thread.sleep(5000);
}
System.out.println("-----------------Starting measured run. load=" + loadMessagesPerSec);
final long start = System.currentTimeMillis();
final List<Histogram> serviceTmHistograms = new ArrayList<>(threadCount);
final List<Histogram> responseTmHistograms = new ArrayList<>(threadCount);
PrintingAsyncQueueFullPolicy.ringbufferFull.set(0);
// Actual test: run as many iterations of 1,000,000 calls to logger.log as we can in 4 minutes.
final long TEST_DURATION_MILLIS = TimeUnit.MINUTES.toMillis(4);
final int COUNT = (1000 * 1000) / threadCount;
runLatencyTest(logger, TEST_DURATION_MILLIS, COUNT, loadMessagesPerSec, idleStrategy, serviceTmHistograms, responseTmHistograms, threadCount);
logger.shutdown();
final long end = System.currentTimeMillis();
// ... and report the results
final Histogram resultServiceTm = createResultHistogram(serviceTmHistograms, start, end);
resultServiceTm.outputPercentileDistribution(System.out, 1000.0);
writeToFile("s", resultServiceTm, (int) (loadMessagesPerSec / 1000), 1000.0);
final Histogram resultResponseTm = createResultHistogram(responseTmHistograms, start, end);
resultResponseTm.outputPercentileDistribution(System.out, 1000.0);
writeToFile("r", resultResponseTm, (int) (loadMessagesPerSec / 1000), 1000.0);
System.out.printf("%n%s: %d threads, load %,f msg/sec, ringbuffer full=%d%n", loggerLib, threadCount, loadMessagesPerSec, PrintingAsyncQueueFullPolicy.ringbufferFull.get());
System.out.println("Test duration: " + (end - start) / 1000.0 + " seconds");
}
Aggregations