From 86b2a9cab4010ed62e03aede4cac3b152445a014 Mon Sep 17 00:00:00 2001 From: Marc Dumais Date: Wed, 21 May 2025 10:04:13 -0400 Subject: [PATCH] [benchmark test] use average when asserting against performance threshold The recently added assertions in the benchmark test, that confirm that the new async handler is much more performant vs the old sync handler, were failing the test once in a while. Originally the assertions were against each test run - those runs with fewer iterations were very sensitive to interference by e.g. GC. e.g. imagine that a 10-20 ms GC occurs while doing one of the runs below, while performing logging using "AsyncNew" - it could easily make "AsyncNew" look much less performant vs "SyncOld", once in a while making the AsyncNewVsSyncOld ratio look too low and failing the test : Runs(#) SyncOld(ms) AsyncNew(ms) AsyncNewVsSyncOld(rel perf) 2000 75.48 8.56 8.81x 4600 243.99 4.24 57.59x 10580 239.99 9.82 24.43x 24333 404.66 46.39 8.72x After this commit, the performance is asserted against the average performance of AsyncNew vs SyncOld, over the totals of all runs (separately for the Regular vs Lean benchmarks). The totals are also printed-out on stdout in human-readable form. Signed-off-by: Marc Dumais --- .../traceeventlogger/TestLoggerBenchmark.java | 44 ++++++++++++++----- 1 file changed, 32 insertions(+), 12 deletions(-) diff --git a/src/test/java/org/eclipse/tracecompass/traceeventlogger/TestLoggerBenchmark.java b/src/test/java/org/eclipse/tracecompass/traceeventlogger/TestLoggerBenchmark.java index a1b93f1..9df58ea 100644 --- a/src/test/java/org/eclipse/tracecompass/traceeventlogger/TestLoggerBenchmark.java +++ b/src/test/java/org/eclipse/tracecompass/traceeventlogger/TestLoggerBenchmark.java @@ -94,6 +94,10 @@ public String format(LogRecord record) { List syncNew = new ArrayList<>(); List syncOld = new ArrayList<>(); List run = new ArrayList<>(); + long totalRuns = 0; + long totalAsyncNew = 0; + long totalSyncOld = 0; + for (long runs = warmUp; runs < maxRuns; runs *= growth) { for (long i = 0; i < warmUp; i++) { try (LogUtils.ScopeLog log = new LogUtils.ScopeLog(logger, Level.FINE, "foo")) { //$NON-NLS-1$ @@ -220,6 +224,10 @@ public String format(LogRecord record) { for (int i = 0; i < run.size(); i++) { float factor = (float)syncOld.get(i) / (float)asyncNew.get(i); asyncNewVsSyncOld.add(factor); + totalRuns += run.get(i); + totalAsyncNew += asyncNew.get(i); + totalSyncOld += syncOld.get(i); + 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)); } @@ -230,13 +238,14 @@ public String format(LogRecord record) { 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)); } + float avgFactor = (float)totalSyncOld / (float)totalAsyncNew; + System.out.println("\n\"Regular\" Benchmark Results - Total/Average"); //$NON-NLS-1$ + System.out.println("Runs(#) SyncOld(ms) AsyncNew(ms) AsyncNewVsSyncOld(rel perf)"); //$NON-NLS-1$ + System.out.println(String.format("%7d %13.2f %13.2f %27.2fx", totalRuns, totalSyncOld*0.000001, totalAsyncNew*0.000001, avgFactor));//$NON-NLS-1$ - 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)); - } + assertTrue("(Regular) On average AsyncNew is expected to be much faster vs SyncOld! " + //$NON-NLS-1$ + "Expected factor: > " + newAsyncPerformenceThreshold + "x, Actual: " + avgFactor, //$NON-NLS-1$ //$NON-NLS-2$ + (avgFactor > newAsyncPerformenceThreshold)); } private static long linecount(Path path) throws IOException { @@ -305,6 +314,9 @@ public void testLeanBench() throws SecurityException, IOException { List syncNew = new ArrayList<>(); List syncOld = new ArrayList<>(); List run = new ArrayList<>(); + long totalRuns = 0; + long totalAsyncNew = 0; + long totalSyncOld = 0; for (long runs = warmUp; runs < maxRuns; runs *= growth) { for (long i = 0; i < warmUp; i++) { try (LogUtils.ScopeLog log = new LogUtils.ScopeLog(logger, Level.FINE, "foo")) { //$NON-NLS-1$ @@ -416,6 +428,9 @@ public void testLeanBench() throws SecurityException, IOException { for (int i = 0; i < run.size(); i++) { float factor = (float)syncOld.get(i) / (float)asyncNew.get(i); asyncNewVsSyncOld.add(factor); + totalRuns += run.get(i); + totalAsyncNew += asyncNew.get(i); + totalSyncOld += syncOld.get(i); 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)); } @@ -427,13 +442,18 @@ public void testLeanBench() throws SecurityException, IOException { 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)); } + + float avgFactor = (float)totalSyncOld / (float)totalAsyncNew; + System.out.println("\n\"Lean\" Benchmark Results - Total/Average"); //$NON-NLS-1$ + System.out.println("Runs(#) SyncOld(ms) AsyncNew(ms) AsyncNewVsSyncOld(rel perf)"); //$NON-NLS-1$ + System.out.println(String.format("%7d %13.2f %13.2f %27.2fx", totalRuns, totalSyncOld*0.000001, totalAsyncNew*0.000001, avgFactor));//$NON-NLS-1$ + + assertTrue("(Lean) On average AsyncNew is expected to be much faster vs SyncOld! " + //$NON-NLS-1$ + "Expected factor: > " + newAsyncPerformenceThreshold + "x, Actual: " + avgFactor, //$NON-NLS-1$ //$NON-NLS-2$ + (avgFactor > newAsyncPerformenceThreshold)); + + System.out.println("-----\n"); //$NON-NLS-1$ - for (int i = 0; i < run.size(); 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)); - } } private static Handler makeAsyncFileHandler(String path) throws IOException {