This is an automated email from the ASF dual-hosted git repository. upthewaterspout pushed a commit to branch feature/redis-performance-testing in repository https://gitbox.apache.org/repos/asf/geode-benchmarks.git
commit 93c0c9851c764e94a82b51c2506eb67210213d36 Author: Dan Smith <[email protected]> AuthorDate: Tue Mar 16 15:43:10 2021 -0700 Logging progress every 10 seconds in the yardstick task Reporting the throughput and latency every 10 seconds while running a benchmark. Each client currently reports it's own numbers. --- geode-benchmarks/build.gradle | 12 ++++++- .../org/apache/geode/perftest/TestContext.java | 6 +++- .../apache/geode/perftest/jvms/JVMLauncher.java | 1 + .../geode/perftest/jvms/RemoteJVMFactory.java | 1 + .../apache/geode/perftest/jvms/rmi/ChildJVM.java | 3 +- .../apache/geode/perftest/jvms/rmi/Controller.java | 9 ++++++ .../geode/perftest/jvms/rmi/ControllerRemote.java | 2 ++ .../geode/perftest/runner/DefaultTestContext.java | 19 ++++++++++- .../geode/perftest/runner/DefaultTestRunner.java | 2 +- .../geode/perftest/yardstick/TestDoneProbe.java | 5 +-- .../geode/perftest/yardstick/YardstickTask.java | 37 ++++++++++++++++++++-- .../yardstick/hdrhistogram/HdrHistogramProbe.java | 12 +++++-- .../perftest/yardstick/YardstickTaskTest.java | 2 +- 13 files changed, 99 insertions(+), 12 deletions(-) diff --git a/geode-benchmarks/build.gradle b/geode-benchmarks/build.gradle index ee9e188..49b423f 100644 --- a/geode-benchmarks/build.gradle +++ b/geode-benchmarks/build.gradle @@ -70,7 +70,13 @@ compileJava { options.deprecation = true } -test{ useJUnitPlatform() } +test{ + useJUnitPlatform() + systemProperty 'org.slf4j.simpleLogger.showDateTime', 'true' + systemProperty 'org.slf4j.simpleLogger.dateTimeFormat', 'yyyy-MM-dd HH:mm:ss.SSS' + systemProperty 'org.slf4j.simpleLogger.showThreadNam', 'false' + systemProperty 'org.slf4j.simpleLogger.showShortLogName', 'true' +} task benchmark(type: Test) { if (project.hasProperty('testJVM') && !testJVM.trim().isEmpty()) { @@ -90,6 +96,10 @@ task benchmark(type: Test) { forkEvery 1 failFast = true + systemProperty 'org.slf4j.simpleLogger.showDateTime', 'true' + systemProperty 'org.slf4j.simpleLogger.dateTimeFormat', 'yyyy-MM-dd HH:mm:ss.SSS' + systemProperty 'org.slf4j.simpleLogger.showThreadName', 'false' + systemProperty 'org.slf4j.simpleLogger.showShortLogName', 'true' systemProperty 'TEST_HOSTS', project.findProperty('hosts') systemProperty 'TEST_METADATA', project.findProperty('metadata') systemProperty 'OUTPUT_DIR', outputDir diff --git a/harness/src/main/java/org/apache/geode/perftest/TestContext.java b/harness/src/main/java/org/apache/geode/perftest/TestContext.java index d73cd51..576cbfe 100644 --- a/harness/src/main/java/org/apache/geode/perftest/TestContext.java +++ b/harness/src/main/java/org/apache/geode/perftest/TestContext.java @@ -53,5 +53,9 @@ public interface TestContext extends Serializable { Object getAttribute(String key); - + /** + * Print a log message to the terminal about the progress of a test task + * @param progress The progress message to display + */ + void logProgress(String progress); } diff --git a/harness/src/main/java/org/apache/geode/perftest/jvms/JVMLauncher.java b/harness/src/main/java/org/apache/geode/perftest/jvms/JVMLauncher.java index 13c2a44..0d26118 100644 --- a/harness/src/main/java/org/apache/geode/perftest/jvms/JVMLauncher.java +++ b/harness/src/main/java/org/apache/geode/perftest/jvms/JVMLauncher.java @@ -89,6 +89,7 @@ class JVMLauncher { command.add("-D" + RemoteJVMFactory.RMI_HOST + "=" + rmiHost); command.add("-D" + RemoteJVMFactory.RMI_PORT_PROPERTY + "=" + rmiPort); command.add("-D" + RemoteJVMFactory.JVM_ID + "=" + jvmConfig.getId()); + command.add("-D" + RemoteJVMFactory.ROLE + "=" + jvmConfig.getRole()); command.add("-D" + RemoteJVMFactory.OUTPUT_DIR + "=" + jvmConfig.getOutputDir()); if (jvmConfig.getJvmArgs().contains("-DwithSsl=true")) { diff --git a/harness/src/main/java/org/apache/geode/perftest/jvms/RemoteJVMFactory.java b/harness/src/main/java/org/apache/geode/perftest/jvms/RemoteJVMFactory.java index b14817f..7cf1dfa 100644 --- a/harness/src/main/java/org/apache/geode/perftest/jvms/RemoteJVMFactory.java +++ b/harness/src/main/java/org/apache/geode/perftest/jvms/RemoteJVMFactory.java @@ -67,6 +67,7 @@ public class RemoteJVMFactory { public static final String RMI_PORT_PROPERTY = "RMI_PORT"; public static final String CONTROLLER = "CONTROLLER"; public static final String OUTPUT_DIR = "OUTPUT_DIR"; + public static final String ROLE = "ROLE"; public static final String JVM_ID = "JVM_ID"; public static final int RMI_PORT = 33333; private static final String CLASSPATH = System.getProperty("java.class.path"); diff --git a/harness/src/main/java/org/apache/geode/perftest/jvms/rmi/ChildJVM.java b/harness/src/main/java/org/apache/geode/perftest/jvms/rmi/ChildJVM.java index ff3b94e..c8fd512 100644 --- a/harness/src/main/java/org/apache/geode/perftest/jvms/rmi/ChildJVM.java +++ b/harness/src/main/java/org/apache/geode/perftest/jvms/rmi/ChildJVM.java @@ -53,6 +53,7 @@ public class ChildJVM { String RMI_PORT = system.getProperty(RemoteJVMFactory.RMI_PORT_PROPERTY); String OUTPUT_DIR = system.getProperty(RemoteJVMFactory.OUTPUT_DIR); int id = system.getInteger(RemoteJVMFactory.JVM_ID); + String role = system.getProperty(RemoteJVMFactory.ROLE); if (RMI_HOST == null || RMI_PORT == null || OUTPUT_DIR == null) { throw new IllegalStateException( @@ -68,7 +69,7 @@ public class ChildJVM { .lookup("//" + RMI_HOST + ":" + RMI_PORT + "/" + RemoteJVMFactory.CONTROLLER); SharedContext sharedContext = controller.getsharedContext(); - DefaultTestContext context = new DefaultTestContext(sharedContext, outputDir, id); + DefaultTestContext context = new DefaultTestContext(sharedContext, outputDir, id, role, controller); Worker worker = new Worker(context); diff --git a/harness/src/main/java/org/apache/geode/perftest/jvms/rmi/Controller.java b/harness/src/main/java/org/apache/geode/perftest/jvms/rmi/Controller.java index ea4bef2..688d275 100644 --- a/harness/src/main/java/org/apache/geode/perftest/jvms/rmi/Controller.java +++ b/harness/src/main/java/org/apache/geode/perftest/jvms/rmi/Controller.java @@ -29,6 +29,9 @@ import java.util.concurrent.ExecutorService; import java.util.concurrent.Executors; import java.util.concurrent.TimeUnit; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; + import org.apache.geode.perftest.Task; import org.apache.geode.perftest.runner.SharedContext; @@ -36,6 +39,7 @@ import org.apache.geode.perftest.runner.SharedContext; * RMI object that lives on the main controller JVM */ public class Controller extends UnicastRemoteObject implements ControllerRemote { + Logger logger = LoggerFactory.getLogger(Controller.class); private final Registry registry; private final SharedContext context; private final Map<Integer, WorkerRemote> workers = new ConcurrentHashMap<>(); @@ -72,6 +76,11 @@ public class Controller extends UnicastRemoteObject implements ControllerRemote } @Override + public void logProgress(String progress) throws RemoteException { + logger.info(progress); + } + + @Override public SharedContext getsharedContext() throws RemoteException { return context; } diff --git a/harness/src/main/java/org/apache/geode/perftest/jvms/rmi/ControllerRemote.java b/harness/src/main/java/org/apache/geode/perftest/jvms/rmi/ControllerRemote.java index 0a63a0c..606a2af 100644 --- a/harness/src/main/java/org/apache/geode/perftest/jvms/rmi/ControllerRemote.java +++ b/harness/src/main/java/org/apache/geode/perftest/jvms/rmi/ControllerRemote.java @@ -28,5 +28,7 @@ public interface ControllerRemote extends Remote { boolean ping() throws RemoteException; + void logProgress(String progress) throws RemoteException; + SharedContext getsharedContext() throws RemoteException; } diff --git a/harness/src/main/java/org/apache/geode/perftest/runner/DefaultTestContext.java b/harness/src/main/java/org/apache/geode/perftest/runner/DefaultTestContext.java index 1dae065..045fa17 100644 --- a/harness/src/main/java/org/apache/geode/perftest/runner/DefaultTestContext.java +++ b/harness/src/main/java/org/apache/geode/perftest/runner/DefaultTestContext.java @@ -19,21 +19,28 @@ package org.apache.geode.perftest.runner; import java.io.File; import java.net.InetAddress; +import java.rmi.RemoteException; import java.util.Set; import java.util.TreeMap; import org.apache.geode.perftest.TestContext; +import org.apache.geode.perftest.jvms.rmi.ControllerRemote; public class DefaultTestContext implements TestContext { private SharedContext sharedContext; private File outputDir; + private String role; + private ControllerRemote controller; private int jvmID; TreeMap<String, Object> attributeMap; - public DefaultTestContext(SharedContext sharedContext, File outputDir, int jvmID) { + public DefaultTestContext(SharedContext sharedContext, File outputDir, int jvmID, + String role, ControllerRemote controller) { this.sharedContext = sharedContext; this.outputDir = outputDir; + this.role = role; + this.controller = controller; attributeMap = new TreeMap<>(); this.jvmID = jvmID; } @@ -67,4 +74,14 @@ public class DefaultTestContext implements TestContext { public File getOutputDir() { return outputDir; } + + @Override + public void logProgress(String progress) { + try { + controller.logProgress(String.format("%s-%02d: %s", role, jvmID, progress)); + } catch (RemoteException e) { + throw new IllegalStateException("Controller connection lost", e); + } + + } } diff --git a/harness/src/main/java/org/apache/geode/perftest/runner/DefaultTestRunner.java b/harness/src/main/java/org/apache/geode/perftest/runner/DefaultTestRunner.java index a35a460..a71b158 100644 --- a/harness/src/main/java/org/apache/geode/perftest/runner/DefaultTestRunner.java +++ b/harness/src/main/java/org/apache/geode/perftest/runner/DefaultTestRunner.java @@ -132,7 +132,7 @@ public class DefaultTestRunner implements TestRunner { // Close before copy otherwise logs, stats, and profiles are incomplete or missing. remoteJVMs.closeController(); - logger.info("Copying results..."); + logger.info("Copying results to {}", benchmarkOutput); remoteJVMs.copyResults(benchmarkOutput); remoteJVMs.closeInfra(); diff --git a/harness/src/main/java/org/apache/geode/perftest/yardstick/TestDoneProbe.java b/harness/src/main/java/org/apache/geode/perftest/yardstick/TestDoneProbe.java index 2adfafa..47dc277 100644 --- a/harness/src/main/java/org/apache/geode/perftest/yardstick/TestDoneProbe.java +++ b/harness/src/main/java/org/apache/geode/perftest/yardstick/TestDoneProbe.java @@ -20,6 +20,7 @@ package org.apache.geode.perftest.yardstick; import java.util.Collection; import java.util.Collections; import java.util.concurrent.CountDownLatch; +import java.util.concurrent.TimeUnit; import org.yardstickframework.BenchmarkConfiguration; import org.yardstickframework.BenchmarkDriver; @@ -30,8 +31,8 @@ class TestDoneProbe implements BenchmarkProbe { CountDownLatch done = new CountDownLatch(1); - public void await() throws InterruptedException { - done.await(); + public boolean await(long time, TimeUnit unit) throws InterruptedException { + return done.await(time, unit); } @Override diff --git a/harness/src/main/java/org/apache/geode/perftest/yardstick/YardstickTask.java b/harness/src/main/java/org/apache/geode/perftest/yardstick/YardstickTask.java index 763bddd..cf3d23e 100644 --- a/harness/src/main/java/org/apache/geode/perftest/yardstick/YardstickTask.java +++ b/harness/src/main/java/org/apache/geode/perftest/yardstick/YardstickTask.java @@ -20,7 +20,9 @@ package org.apache.geode.perftest.yardstick; import java.util.Arrays; import java.util.Collection; import java.util.List; +import java.util.concurrent.TimeUnit; +import org.HdrHistogram.Histogram; import org.yardstickframework.BenchmarkConfiguration; import org.yardstickframework.BenchmarkDriver; import org.yardstickframework.BenchmarkProbe; @@ -91,8 +93,12 @@ public class YardstickTask implements Task { benchmark.setUp(cfg); TestDoneProbe testDoneProbe = new TestDoneProbe(); + final HdrHistogramProbe + hdrHistogramProbe = + new HdrHistogramProbe(new HdrHistogramWriter(context.getOutputDir())); + Collection<BenchmarkProbe> probes = - Arrays.asList(new HdrHistogramProbe(new HdrHistogramWriter(context.getOutputDir())), + Arrays.asList(hdrHistogramProbe, new ThroughputLatencyProbe(), new PercentileProbe(), new VmStatProbe(), testDoneProbe); @@ -107,6 +113,33 @@ public class YardstickTask implements Task { runner.runBenchmark(); - testDoneProbe.await(); + Histogram lastHistogram = hdrHistogramProbe.getHistogram(); + while(!testDoneProbe.await(10, TimeUnit.SECONDS)) { + boolean warmupFinished = hdrHistogramProbe.isWarmupFinished(); + //Create a histogram for the previous 10 second window + Histogram histogram = hdrHistogramProbe.getHistogram(); + Histogram currentHistogram = histogram.copy(); + if(histogram.getStartTimeStamp() == lastHistogram.getStartTimeStamp()) { + currentHistogram.subtract(lastHistogram); + currentHistogram.setStartTimeStamp(lastHistogram.getEndTimeStamp()); + } + + String prefix = warmupFinished ? "WORK" : "WARMUP"; + + //Log the histogram + logProgress(context, prefix, currentHistogram); + + //Capture the current histogram + lastHistogram = histogram; + } + logProgress(context, "TOTAL", hdrHistogramProbe.getHistogram()); + } + + private void logProgress(TestContext context, String prefix, Histogram histogram) { + double throughput = (((double) histogram.getTotalCount()) + / (histogram.getEndTimeStamp() - histogram.getStartTimeStamp())) * 1000; + double meanLatency = histogram.getMean() / 1_000_000.0; + double percentile_99 = histogram.getValueAtPercentile(99) / 1_000_000.0; + context.logProgress(String.format("%6s ops/sec: %10.2f, latency: %4.3f ms, 99%% latency: %4.3f ms", prefix, throughput, meanLatency, percentile_99)); } } diff --git a/harness/src/main/java/org/apache/geode/perftest/yardstick/hdrhistogram/HdrHistogramProbe.java b/harness/src/main/java/org/apache/geode/perftest/yardstick/hdrhistogram/HdrHistogramProbe.java index d841f67..c1ac53a 100644 --- a/harness/src/main/java/org/apache/geode/perftest/yardstick/hdrhistogram/HdrHistogramProbe.java +++ b/harness/src/main/java/org/apache/geode/perftest/yardstick/hdrhistogram/HdrHistogramProbe.java @@ -24,6 +24,7 @@ import java.util.Arrays; import java.util.Collection; import java.util.Collections; import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicBoolean; import java.util.function.Consumer; import org.HdrHistogram.Histogram; @@ -56,6 +57,7 @@ public class HdrHistogramProbe implements BenchmarkExecutionAwareProbe, Benchmar private final Consumer<Histogram> histogramConsumer; private long[] startTimes; private Histogram[] histograms; + private AtomicBoolean warmUpFinished = new AtomicBoolean(false); public HdrHistogramProbe(Consumer<Histogram> histogramConsumer) { this(1, TimeUnit.HOURS.toNanos(5), 3, () -> System.nanoTime(), histogramConsumer); @@ -116,7 +118,9 @@ public class HdrHistogramProbe implements BenchmarkExecutionAwareProbe, Benchmar @Override public Collection<BenchmarkProbePoint> points() { final Histogram aggregate = getHistogram(); - reset(); + if(warmUpFinished.compareAndSet(false, true)) { + reset(); + } final double mean = aggregate.getMean(); final long percentile99 = aggregate.getValueAtPercentile(99); @@ -146,7 +150,7 @@ public class HdrHistogramProbe implements BenchmarkExecutionAwareProbe, Benchmar } - Histogram getHistogram() { + public Histogram getHistogram() { final Histogram aggregate = new Histogram(lower, upper, numDigits); for (final Histogram histogram : histograms) { aggregate.add(histogram); @@ -154,4 +158,8 @@ public class HdrHistogramProbe implements BenchmarkExecutionAwareProbe, Benchmar aggregate.setEndTimeStamp(System.currentTimeMillis()); return aggregate; } + + public boolean isWarmupFinished() { + return warmUpFinished.get(); + } } diff --git a/harness/src/test/java/org/apache/geode/perftest/yardstick/YardstickTaskTest.java b/harness/src/test/java/org/apache/geode/perftest/yardstick/YardstickTaskTest.java index 1d57fbc..707ca43 100644 --- a/harness/src/test/java/org/apache/geode/perftest/yardstick/YardstickTaskTest.java +++ b/harness/src/test/java/org/apache/geode/perftest/yardstick/YardstickTaskTest.java @@ -45,7 +45,7 @@ public class YardstickTaskTest { workloadConfig.threads(1); Task task = new YardstickTask(benchmark, workloadConfig); File outputDir = folder.toFile(); - TestContext context = new DefaultTestContext(null, outputDir, 1); + TestContext context = new DefaultTestContext(null, outputDir, 1, role, controller); task.run(context); assertTrue(1 <= benchmark.getInvocations());
