Add more debugging to the DigestTest

This test sometimes fails, but we don't know what the coefficient of
variation is on the test results. Add this to the debug output so we can
see if there is just some wild swing during testing.

Also add a few rounds of warm-up as well.

Bug: 24011092
Change-Id: Ic58f106f68eb93976e3f030e2f23e0156fe84be8
(cherry picked from commit 5fe1cd001f38fba460ac0ce5c15b85250e400f25)

1 files changed, 21 insertions, 12 deletions

diff --git a/luni/src/test/java/com/android/org/bouncycastle/crypto/digests/DigestTest.java b/luni/src/test/java/com/android/org/bouncycastle/crypto/digests/DigestTest.java
index 8708214..fce8507 100644
--- a/luni/src/test/java/com/android/org/bouncycastle/crypto/digests/DigestTest.java
+++ b/luni/src/test/java/com/android/org/bouncycastle/crypto/digests/DigestTest.java
@@ -19,6 +19,7 @@ package com.android.org.bouncycastle.crypto.digests;
 import junit.framework.TestCase;
 import com.android.org.bouncycastle.crypto.Digest;
 import com.android.org.bouncycastle.crypto.ExtendedDigest;
+import tests.util.SummaryStatistics;
 
 /**
  * Implements unit tests for our JNI wrapper around OpenSSL. We use the
@@ -36,6 +37,7 @@ public class DigestTest extends TestCase {
      * @param newDigest The new digest implementation, provided by OpenSSL
      */
     public void doTestMessageDigest(Digest oldDigest, Digest newDigest) {
+        final int WARMUP = 10;
         final int ITERATIONS = 100;
 
         byte[] data = new byte[1024];
@@ -54,27 +56,31 @@ public class DigestTest extends TestCase {
             data[i] = (byte)i;
         }
 
-        long oldTime = 0;
-        long newTime = 0;
+        SummaryStatistics oldTime = new SummaryStatistics();
+        SummaryStatistics newTime = new SummaryStatistics();
 
-        for (int j = 0; j < ITERATIONS; j++) {
-            long t0 = System.currentTimeMillis();
+        for (int j = 0; j < ITERATIONS + WARMUP; j++) {
+            long t0 = System.nanoTime();
             for (int i = 0; i < 4; i++) {
                 oldDigest.update(data, 0, data.length);
             }
             int oldLength = oldDigest.doFinal(oldHash, 0);
-            long t1 = System.currentTimeMillis();
+            long t1 = System.nanoTime();
 
-            oldTime = oldTime + (t1 - t0);
+            if (j >= WARMUP) {
+                oldTime.add(t1 - t0);
+            }
 
-            long t2 = System.currentTimeMillis();
+            long t2 = System.nanoTime();
             for (int i = 0; i < 4; i++) {
                 newDigest.update(data, 0, data.length);
             }
             int newLength = newDigest.doFinal(newHash, 0);
-            long t3 = System.currentTimeMillis();
+            long t3 = System.nanoTime();
 
-            newTime = newTime + (t3 - t2);
+            if (j >= WARMUP) {
+              newTime.add(t3 - t2);
+            }
 
             assertEquals("Hash sizes must be equal", oldLength, newLength);
 
@@ -83,10 +89,13 @@ public class DigestTest extends TestCase {
             }
         }
 
-        System.out.println("Time for " + ITERATIONS + " x old hash processing: " + oldTime + " ms");
-        System.out.println("Time for " + ITERATIONS + " x new hash processing: " + newTime + " ms");
+        System.out.println("Time for " + ITERATIONS + " x old hash processing: "
+                + oldTime.toString());
+        System.out.println("Time for " + ITERATIONS + " x new hash processing: "
+                + newTime.toString());
 
-        assertTrue("New hash should be faster", newTime < oldTime);
+        assertTrue("New hash should be faster:\nold=" + oldTime.toString() + "\nnew="
+                + newTime.toString(), newTime.mean() < oldTime.mean());
     }
 
     /**