[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 <marc.dumais@ericsson.com>

Author: marcdumais-work

src/test/java/org/eclipse/tracecompass/traceeventlogger/TestLoggerBenchmark.java

@@ -94,6 +94,10 @@ public String format(LogRecord record) {
         List<Long> syncNew = new ArrayList<>();
         List<Long> syncOld = new ArrayList<>();
         List<Long> 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<Long> syncNew = new ArrayList<>();
         List<Long> syncOld = new ArrayList<>();
         List<Long> 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 {