From d34c212718635ede6d8b34fa6552f9bd74ff8c76 Mon Sep 17 00:00:00 2001 From: Marc Dumais Date: Wed, 23 Apr 2025 15:01:48 -0400 Subject: [PATCH] [tests] update benchmark tests, config The benchmarks were showing slow results for AsyncFileHandler,much slower compared to what they were until v0.4.0. The reason is that a couple of bugs were recently fixed in that handler, that resulted in the following configurable property, used for the benchmark tests, to not have the desired effect: org.eclipse.tracecompass.traceeventlogger.AsyncFileHandler.maxSize = 1000 After the bugs were fixed, AsyncFileHandler started to correctly use "maxSize" as the size of its record buffer. However, a buffer of 1000 is not enough for the logging load generated by the benchmark tests, making the new async handler look bad. Setting "bufferSize" to value 100k makes it big enough to "absorb" the logging load of the benchmark tests well, and brings back the previous level of performance for the async handler, such that the benchmark results are comparable to those from until v0.4.0. To detect such a problem in the future, the benchmark tests now compute the relative performance of the async file handler vs the old sync handler and fails the test if the former is not performing above a certain threshold. The threshold may need to be lowered a bit if e.g. it's not met once in a while during CI (there is variation in the results) In the benchmark results printed on STDOUT, the relative performance of the async file handlers now displayed as an extra column in the benchmark result tables. Also, the benchmark results are now printed in two versions: one un- formatted in "csv" format that's suitable to import e.g. in LibreOffice Calc, and another that's formatted for human readability. Signed-off-by: Marc Dumais --- .../traceeventlogger/TestLoggerBenchmark.java | 51 ++++++++++++++++--- .../res/benchmarklogging.properties | 2 +- 2 files changed, 46 insertions(+), 7 deletions(-) diff --git a/src/test/java/org/eclipse/tracecompass/traceeventlogger/TestLoggerBenchmark.java b/src/test/java/org/eclipse/tracecompass/traceeventlogger/TestLoggerBenchmark.java index f65e207..a1b93f1 100644 --- a/src/test/java/org/eclipse/tracecompass/traceeventlogger/TestLoggerBenchmark.java +++ b/src/test/java/org/eclipse/tracecompass/traceeventlogger/TestLoggerBenchmark.java @@ -25,6 +25,7 @@ package org.eclipse.tracecompass.traceeventlogger; import static org.junit.Assert.fail; +import static org.junit.Assert.assertTrue; import java.io.File; import java.io.FileInputStream; @@ -59,6 +60,7 @@ public class TestLoggerBenchmark { private long warmUp = 2000; private long maxRuns = warmUp * 100; private double growth = 2.3; + private final static float newAsyncPerformenceThreshold = 2.5f; /** * Benchmark events with fields @@ -86,6 +88,7 @@ public String format(LogRecord record) { fLogger.addHandler(oldFileHandler); fLogger.setLevel(Level.ALL); Logger logger = fLogger; + List asyncNewVsSyncOld = new ArrayList<>(); List asyncNew = new ArrayList<>(); List asyncOld = new ArrayList<>(); List syncNew = new ArrayList<>(); @@ -212,10 +215,27 @@ public String format(LogRecord record) { long end2 = System.nanoTime(); asyncOld.add(end2 - start2); } - System.out.println("Runs,SyncOld,SyncNew,AsyncOld,AsyncNew"); //$NON-NLS-1$ + System.out.println("\n\"Regular\" Benchmark Results (csv):"); //$NON-NLS-1$ + System.out.println("Runs(#),SyncOld(ns),SyncNew(ns),AsyncOld(ns),AsyncNew(ns),AsyncNewVsSyncOld(rel perf)"); //$NON-NLS-1$ for (int i = 0; i < run.size(); i++) { - System.out.println(String.format("%d,%d,%d,%d,%d", run.get(i), syncOld.get(i), syncNew.get(i), //$NON-NLS-1$ - asyncOld.get(i), asyncNew.get(i))); + float factor = (float)syncOld.get(i) / (float)asyncNew.get(i); + asyncNewVsSyncOld.add(factor); + System.out.println(String.format("%d,%d,%d,%d,%d,%.2f", run.get(i), syncOld.get(i), syncNew.get(i), //$NON-NLS-1$ + asyncOld.get(i), asyncNew.get(i), factor)); + } + System.out.println("\n\"Regular\" Benchmark Results (Human-readable):"); //$NON-NLS-1$ + System.out.println("Runs(#) SyncOld(ms) SyncNew(ms) AsyncOld(ms) AsyncNew(ms) AsyncNewVsSyncOld(rel perf)"); //$NON-NLS-1$ + for (int i = 0; i < run.size(); i++) { + float factor = asyncNewVsSyncOld.get(i); + System.out.println(String.format("%7d %13.2f %13.2f %13.2f %13.2f %27.2fx", run.get(i), syncOld.get(i)*0.000001, syncNew.get(i)*0.000001, //$NON-NLS-1$ + asyncOld.get(i)*0.000001, asyncNew.get(i)*0.000001, factor)); + } + + for (int i = 0; i < run.size(); i++) { + float factor = asyncNewVsSyncOld.get(i); + assertTrue("Runs: " + run.get(i) + " - AsyncNew expected to be much faster vs SyncOld! " + //$NON-NLS-1$//$NON-NLS-2$ + "Expected factor: > " + newAsyncPerformenceThreshold + "x, Actual: " + factor, //$NON-NLS-1$ //$NON-NLS-2$ + (factor > newAsyncPerformenceThreshold)); } } @@ -279,6 +299,7 @@ public void testLeanBench() throws SecurityException, IOException { fLogger.addHandler(oldFileHandler); fLogger.setLevel(Level.ALL); Logger logger = fLogger; + List asyncNewVsSyncOld = new ArrayList<>(); List asyncNew = new ArrayList<>(); List asyncOld = new ArrayList<>(); List syncNew = new ArrayList<>(); @@ -390,10 +411,28 @@ public void testLeanBench() throws SecurityException, IOException { long end2 = System.nanoTime(); asyncOld.add(end2 - start2); } - System.out.println("Runs,SyncOldLean,SyncNewLean,AsyncOldLean,AsyncNewLean"); //$NON-NLS-1$ + System.out.println("\n\"Lean\" Benchmark Results (csv):"); //$NON-NLS-1$ + System.out.println("Runs(#),SyncOld(ns),SyncNew(ns),AsyncOld(ns),AsyncNew(ns),AsyncNewVsSyncOld(rel perf)"); //$NON-NLS-1$ + for (int i = 0; i < run.size(); i++) { + float factor = (float)syncOld.get(i) / (float)asyncNew.get(i); + asyncNewVsSyncOld.add(factor); + System.out.println(String.format("%d,%d,%d,%d,%d,%.2f", run.get(i), syncOld.get(i), syncNew.get(i), //$NON-NLS-1$ + asyncOld.get(i), asyncNew.get(i), factor)); + } + System.out.println("\n\"Lean\" Benchmark Results (Human-readable):"); //$NON-NLS-1$ + System.out.println("Runs(#) SyncOld(ms) SyncNew(ms) AsyncOld(ms) AsyncNew(ms) AsyncNewVsSyncOld(rel perf)"); //$NON-NLS-1$ + for (int i = 0; i < run.size(); i++) { + float factor = asyncNewVsSyncOld.get(i); + asyncNewVsSyncOld.add(factor); + System.out.println(String.format("%7d %13.2f %13.2f %13.2f %13.2f %27.2fx", run.get(i), syncOld.get(i)*0.000001, syncNew.get(i)*0.000001, //$NON-NLS-1$ + asyncOld.get(i)*0.000001, asyncNew.get(i)*0.000001, factor)); + } + System.out.println("-----\n"); //$NON-NLS-1$ for (int i = 0; i < run.size(); i++) { - System.out.println(String.format("%d,%d,%d,%d,%d", run.get(i), syncOld.get(i), syncNew.get(i), //$NON-NLS-1$ - asyncOld.get(i), asyncNew.get(i))); + float factor = asyncNewVsSyncOld.get(i); + assertTrue("Runs: " + run.get(i) + " - AsyncNewLean expected to be much faster vs SyncOldLean! " + //$NON-NLS-1$ //$NON-NLS-2$ + "Expected factor: > " + newAsyncPerformenceThreshold + "x, Actual: " + factor, //$NON-NLS-1$ //$NON-NLS-2$ + (factor > newAsyncPerformenceThreshold)); } } diff --git a/src/test/java/org/eclipse/tracecompass/traceeventlogger/res/benchmarklogging.properties b/src/test/java/org/eclipse/tracecompass/traceeventlogger/res/benchmarklogging.properties index 88877b5..a75df6f 100644 --- a/src/test/java/org/eclipse/tracecompass/traceeventlogger/res/benchmarklogging.properties +++ b/src/test/java/org/eclipse/tracecompass/traceeventlogger/res/benchmarklogging.properties @@ -24,6 +24,6 @@ # used in Benchmarks -org.eclipse.tracecompass.traceeventlogger.AsyncFileHandler.maxSize = 1000 +org.eclipse.tracecompass.traceeventlogger.AsyncFileHandler.maxSize = 100000 org.eclipse.tracecompass.traceeventlogger.AsyncFileHandler.queueDepth = 100 org.eclipse.tracecompass.traceeventlogger.AsyncFileHandler.flushRate = 100