You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@geode.apache.org by up...@apache.org on 2021/03/17 21:22:39 UTC
[geode-benchmarks] 03/03: Logging progress every 10 seconds in the
yardstick task
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 <da...@vmware.com>
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());