QPID-2425 : Augmented JUnit-Toolkit to emit latency information already gathed by the PingAsyncTestPerf for each batch.

Merged from 0.5.x-dev r 917464

git-svn-id: https://svn.apache.org/repos/asf/qpid/trunk/qpid@933283 13f79535-47bb-0310-9956-ffa450edef68

6 files changed, 138 insertions, 16 deletions

diff --git a/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/TKTestResult.java b/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/TKTestResult.java
index ae497c671b..5ce56a690e 100644
--- a/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/TKTestResult.java
+++ b/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/TKTestResult.java
@@ -557,18 +557,7 @@ public class TKTestResult extends TestResult
          */
         public void completeTest(boolean testPassed, int param) throws InterruptedException
         {
-            /*log.debug("public long completeTest(boolean testPassed = " + testPassed + ", int param = " + param
-                + "): called");*/
-
-            // Calculate the test run time.
-            long endTime = System.nanoTime();
-            long runTime = endTime - startTime;
-            // log.debug("runTime = " + runTime);
-
-            // Reset the test start time to now, to reset the timer for the next result.
-            startTime = endTime;
-
-            completeTest(testPassed, param, runTime);
+            completeTest(testPassed, param, null, null);
         }
 
         /**
@@ -579,14 +568,53 @@ public class TKTestResult extends TestResult
          * @param param      The test parameter size for parameterized tests.
          * @param timeNanos  The time in nano-seconds to log the test result with.
          *
+         * A null value for timeNanos is a request to this method that it should
+         * calculate the time for the given test run.
+         *
          * @throws InterruptedException If the test runner decides that testing should stop it throws this exception to
          *                              indicate to the test method that it should stop immediately.
          */
-        public void completeTest(boolean testPassed, int param, long timeNanos) throws InterruptedException
+        public void completeTest(boolean testPassed, int param, Long timeNanos) throws InterruptedException
+        {
+            completeTest(testPassed, param, timeNanos, null);
+        }
+
+        /**
+         * Register an additional pass/fail for the current test. The test result is applies to a test of the specified
+         * 'size' parmeter and allows the caller to sepecify the timing to log.
+         *
+         * @param testPassed Whether or not this timing is for a test pass or fail.
+         * @param param      The test parameter size for parameterized tests.
+         * @param timeNanos  The time in nano seconds to log the test result with.
+         *
+         * A null value for timeNanos is a request to this method that it should
+         * calculate the time for the given test run.
+         * A null value for timeNanos2 means this test does not provide a second
+         * timing value so a '-' is printed in the log.
+         *
+         *
+         * @throws InterruptedException If the test runner decides that testing should stop it throws this exception to
+         *                              indicate to the test method that it should stop immediately.
+         */
+        public void completeTest(boolean testPassed, int param, Long timeNanos, Long time2Nanos) throws InterruptedException
         {
             log.debug("public void completeTest(boolean testPassed, int param, long timeNanos): called");
             log.debug("testResult = " + testResult);
 
+            /*log.debug("public long completeTest(boolean testPassed = " + testPassed + ", int param = " + param
+                + "): called");*/
+
+            // Calculate the test run time.
+            long endTime = System.nanoTime();
+            long runTime = endTime - startTime;
+            startTime = endTime;
+
+            //
+            if (timeNanos != null)
+            {
+                runTime = timeNanos;
+            }
+
             // Tell the test result that completeTest has been used, so to not register end test events for the whole
             // test method.
             testResult.completeTestUsed = true;
@@ -598,7 +626,8 @@ public class TKTestResult extends TestResult
                 for (TKTestListener listener : testResult.tkListeners)
                 {
                     listener.reset(test, threadId);
-                    listener.timing(test, timeNanos, threadId);
+                    listener.timing(test, runTime, threadId);
+                    listener.timing2(test, time2Nanos, threadId);
                     listener.parameterValue(test, param, threadId);
                     listener.concurrencyLevel(test, testResult.concurrencyLevel, threadId);
 
diff --git a/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/TimingController.java b/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/TimingController.java
index b69df84045..27e43a10a4 100644
--- a/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/TimingController.java
+++ b/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/TimingController.java
@@ -168,8 +168,31 @@ public interface TimingController
      * @param param      The test parameter size for parameterized tests.
      * @param timeNanos  The time in nano seconds to log the test result with.
      *
+     * A null value for timeNanos is a request to this method that it should
+     * calculate the time for the given test run.
+     *
+     *
+     * @throws InterruptedException If the test runner decides that testing should stop it throws this exception to
+     *                              indicate to the test method that it should stop immediately.
+     */
+    public void completeTest(boolean testPassed, int param, Long timeNanos) throws InterruptedException;
+
+    /**
+     * Register an additional pass/fail for the current test. The test result is applies to a test of the specified
+     * 'size' parmeter and allows the caller to sepecify the timing to log.
+     *
+     * @param testPassed Whether or not this timing is for a test pass or fail.
+     * @param param      The test parameter size for parameterized tests.
+     * @param timeNanos  The time in nano seconds to log the test result with.
+     *
+     * A null value for timeNanos is a request to this method that it should
+     * calculate the time for the given test run.
+     * A null value for timeNanos2 means this test does not provide a second
+     * timing value so a '-' is printed in the log.
+     *
+     *
      * @throws InterruptedException If the test runner decides that testing should stop it throws this exception to
      *                              indicate to the test method that it should stop immediately.
      */
-    public void completeTest(boolean testPassed, int param, long timeNanos) throws InterruptedException;
+    public void completeTest(boolean testPassed, int param, Long timeNanos, Long time2Nanos) throws InterruptedException;
 }
diff --git a/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/listeners/CSVTestListener.java b/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/listeners/CSVTestListener.java
index f93212e0c5..40841189a3 100644
--- a/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/listeners/CSVTestListener.java
+++ b/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/listeners/CSVTestListener.java
@@ -96,7 +96,7 @@ public class CSVTestListener implements TestListener, TKTestListener, ShutdownHo
     private int totalSize;
 
     /**
-     * Used to record the summation of all of the individual test timgings. Note that total time and summed time
+     * Used to record the summation of all of the individual test timings. Note that total time and summed time
      * are unlikely to be in agreement, exception for a single threaded test (with no setup time). Total time is
      * the time taken to run all the tests, summed time is the added up time that each individual test took. So if
      * two tests run in parallel and take one second each, total time will be one seconds, summed time will be two
@@ -104,6 +104,12 @@ public class CSVTestListener implements TestListener, TKTestListener, ShutdownHo
      */
     private long summedTime;
 
+    /**
+     * Used to record the summation of all of the second test timing information.
+     * One use of the second timing would be to provide latency as well as test timing. 
+     */
+    private long summedTime2;
+
     /** Flag to indicate when batch has been started but not ended to ensure end batch stats are output only once. */
     private boolean batchStarted = false;
 
@@ -134,6 +140,7 @@ public class CSVTestListener implements TestListener, TKTestListener, ShutdownHo
             (threadId == null) ? threadLocalResults.get(Thread.currentThread().getId()) : threadLocalResults.get(threadId);
 
         r.testTime = 0L;
+        r.testTime2 = null;
         r.testStartMem = 0L;
         r.testEndMem = 0L;
         r.testState = "Pass";
@@ -236,6 +243,26 @@ public class CSVTestListener implements TestListener, TKTestListener, ShutdownHo
     }
 
     /**
+     * Optionally called every time a test completes with the second timing test.
+     *
+     * @param test    The name of the test.
+     * @param nanos   The second timing information of the test in nanoseconds.
+     * @param threadId Optional thread id if not calling from thread that started the test method. May be null.
+     */
+    public void timing2(Test test, Long nanos, Long threadId)
+    {
+        TestResult r =
+            (threadId == null) ? threadLocalResults.get(Thread.currentThread().getId()) : threadLocalResults.get(threadId);
+
+
+        if (nanos != null)
+        {
+            r.testTime2 = nanos;
+            summedTime2 += nanos;
+        }
+    }
+
+    /**
      * Should be called every time a test completed with the amount of memory used before and after the test was run.
      *
      * @param test     The test which memory was measured for.
@@ -322,6 +349,7 @@ public class CSVTestListener implements TestListener, TKTestListener, ShutdownHo
         totalSize = 0;
         batchStartTime = System.nanoTime();
         summedTime = 0;
+        summedTime2 = 0;
         batchStarted = true;
 
         // Write out the column headers for the batch.
@@ -344,6 +372,8 @@ public class CSVTestListener implements TestListener, TKTestListener, ShutdownHo
             long batchEndTime = System.nanoTime();
             float totalTimeMillis = ((float) (batchEndTime - batchStartTime)) / 1000000f;
             float summedTimeMillis = ((float) summedTime) / 1000000f;
+            float summedTime2Millis = ((float) summedTime2) / 1000000f;
+
 
             // Write the stats for the batch out.
             try
@@ -356,8 +386,10 @@ public class CSVTestListener implements TestListener, TKTestListener, ShutdownHo
                     timingsWriter.write("Total Error:, " + numError + ", ");
                     timingsWriter.write("Total Size:, " + totalSize + ", ");
                     timingsWriter.write("Summed Time:, " + summedTimeMillis + ", ");
+                    timingsWriter.write("Summed Custom Time:, " + summedTime2Millis + ", ");
                     timingsWriter.write("Concurrency Level:, " + concurrencyLevel + ", ");
                     timingsWriter.write("Total Time:, " + totalTimeMillis + ", ");
+                    timingsWriter.write("Average Custom Time:, " + ((summedTime2Millis/ (float) totalTests)) + ", ");
                     timingsWriter.write("Test Throughput:, " + (((float) totalTests) / totalTimeMillis) + ", ");
                     timingsWriter.write("Test * Size Throughput:, " + (((float) totalSize) / totalTimeMillis)
                         + (noParams ? "\n\n" : ", "));
@@ -430,6 +462,7 @@ public class CSVTestListener implements TestListener, TKTestListener, ShutdownHo
             timingsWriter.write("Thread, ");
             timingsWriter.write("Test Outcome, ");
             timingsWriter.write("Time (milliseconds), ");
+            timingsWriter.write("Custom Time (milliseconds), ");
             timingsWriter.write("Memory Used (bytes), ");
             timingsWriter.write("Concurrency level, ");
             timingsWriter.write("Test Size\n");
@@ -477,6 +510,9 @@ public class CSVTestListener implements TestListener, TKTestListener, ShutdownHo
                 timingsWriter.write(Thread.currentThread().getName() + ", ");
                 timingsWriter.write(r.testState + ", ");
                 timingsWriter.write((((float) r.testTime) / 1000000f) + ", ");
+
+                timingsWriter.write(r.testTime2 == null ? "- , " :
+                                    (((float) r.testTime2) / 1000000f) + ", ");
                 timingsWriter.write((r.testEndMem - r.testStartMem) + ", ");
                 timingsWriter.write(r.testConcurrency + ", ");
                 timingsWriter.write(r.testParam + "\n");
@@ -514,6 +550,9 @@ public class CSVTestListener implements TestListener, TKTestListener, ShutdownHo
         /** Used to hold the test timing. */
         public long testTime;
 
+        /** Use to hold the second timing information. */
+        public Long testTime2;
+
         /** Used to hold the test start memory usage. */
         public long testStartMem;
 
@@ -528,5 +567,6 @@ public class CSVTestListener implements TestListener, TKTestListener, ShutdownHo
 
         /** Used to hold the concurrency level under which the test was run. */
         public int testConcurrency;
+
     }
 }
diff --git a/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/listeners/ConsoleTestListener.java b/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/listeners/ConsoleTestListener.java
index 2955fba2bd..276fec328e 100644
--- a/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/listeners/ConsoleTestListener.java
+++ b/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/listeners/ConsoleTestListener.java
@@ -185,6 +185,16 @@ public class ConsoleTestListener implements TestListener, TKTestListener
     { }
 
     /**
+     * Optionally called every time a test completes with the second timing test.
+     *
+     * @param test    The name of the test.
+     * @param nanos   The second timing information of the test in nanoseconds.
+     * @param threadId Optional thread id if not calling from thread that started the test method. May be null.
+     */
+    public void timing2(Test test, Long nanos, Long threadId)
+    { }
+
+    /**
      * Should be called every time a test completed with the amount of memory used before and after the test was run.
      *
      * @param test     The test which memory was measured for.
diff --git a/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/listeners/TKTestListener.java b/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/listeners/TKTestListener.java
index 11fc6a7451..63b042db10 100644
--- a/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/listeners/TKTestListener.java
+++ b/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/listeners/TKTestListener.java
@@ -64,6 +64,16 @@ public interface TKTestListener extends TestListener
      */
     public void timing(Test test, long nanos, Long threadId);
 
+
+    /**
+     * Optionally called every time a test completes with the second timing test.
+     *
+     * @param test    The name of the test.
+     * @param nanos   The second timing information of the test in nanoseconds.
+     * @param threadId Optional thread id if not calling from thread that started the test method. May be null.
+     */
+    public void timing2(Test test, Long nanos, Long threadId);
+
     /**
      * Should be called every time a test completed with the amount of memory used before and after the test was run.
      *
diff --git a/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/listeners/XMLTestListener.java b/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/listeners/XMLTestListener.java
index ded07ef5bb..ac875f89cf 100644
--- a/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/listeners/XMLTestListener.java
+++ b/java/junit-toolkit/src/main/org/apache/qpid/junit/extensions/listeners/XMLTestListener.java
@@ -160,6 +160,16 @@ public class XMLTestListener implements TKTestListener, ShutdownHookable
     { }
 
     /**
+     * Optionally called every time a test completes with the second timing test.
+     *
+     * @param test    The name of the test.
+     * @param nanos   The second timing information of the test in nanoseconds.
+     * @param threadId Optional thread id if not calling from thread that started the test method. May be null.
+     */
+    public void timing2(Test test, Long nanos, Long threadId)
+    { }
+
+    /**
      * Should be called every time a test completed with the amount of memory used before and after the test was run.
      *
      * @param test     The test which memory was measured for.