This is related to QPId-1161.

Modified the soak tests to print latency samples and throughput rates for every iteration.
Added run_soak_client.sh soak_report.sh as an example of how to use soak test and produce a report.
Modified other scripts to add comments.




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

12 files changed, 289 insertions, 25 deletions

diff --git a/java/testkit/bin/perf_report.sh b/java/testkit/bin/perf_report.sh
index cafe4fa07f..9e574cad7a 100644
--- a/java/testkit/bin/perf_report.sh
+++ b/java/testkit/bin/perf_report.sh
@@ -18,9 +18,9 @@
 # under the License.
 #
 
-# Helper script to set classpath for running Qpid example classes
-# NB: You must add the Qpid client and common jars to your CLASSPATH
-# before running this script
+# This will run the 8 use cases defined below and produce
+# a report in tabular format. Refer to the documentation
+# for more details.
 
 SUB_MEM=-Xmx1024M
 PUB_MEM=-Xmx1024M
diff --git a/java/testkit/bin/run_pub.sh b/java/testkit/bin/run_pub.sh
index 2f3150d554..0702a55de9 100644
--- a/java/testkit/bin/run_pub.sh
+++ b/java/testkit/bin/run_pub.sh
@@ -18,10 +18,6 @@
 # under the License.
 #
 
-# Helper script to set classpath for running Qpid example classes
-# NB: You must add the Qpid client and common jars to your CLASSPATH
-# before running this script
-
 . $QPID_TEST_HOME/bin/setenv.sh
 
 echo "$@"
diff --git a/java/testkit/bin/run_soak_client.sh b/java/testkit/bin/run_soak_client.sh
new file mode 100644
index 0000000000..ea1721d988
--- /dev/null
+++ b/java/testkit/bin/run_soak_client.sh
@@ -0,0 +1,70 @@
+#!/bin/bash
+#
+# Licensed to the Apache Software Foundation (ASF) under one
+# or more contributor license agreements.  See the NOTICE file
+# distributed with this work for additional information
+# regarding copyright ownership.  The ASF licenses this file
+# to you under the Apache License, Version 2.0 (the
+# "License"); you may not use this file except in compliance
+# with the License.  You may obtain a copy of the License at
+#
+#   http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing,
+# software distributed under the License is distributed on an
+# "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+# KIND, either express or implied.  See the License for the
+# specific language governing permissions and limitations
+# under the License.
+#
+
+# This is a sample script for a soak test on
+# linux environment.
+# This will start n of Producers processors and record their CPU and memory stats.
+# Also the Producer out will be saved to a file as well.
+
+if [ "$JAR_PATH" = "" ] ; then
+    echo "ERROR: Please set JAR_PATH to point to the Qpid libraries ...."
+    exit 1
+fi
+
+#1 PID, $2 freq, $3 count
+calc_stats(){
+
+for ((  i = 0 ;  i <= $3; i++  ))
+ do
+     cpu=`ps auxw | grep $1 | grep -v 'grep' | awk '{print $3}'`
+     mem=`pmap $1 | grep total | grep -v 'grep' | awk '{print substr($2,0,length($2)-1)}'`
+     echo $i","$mem","$cpu
+     sleep $2
+     cpu="0.0"
+     mem="0"
+ done
+ kill -9 $1
+}
+
+# Num of producer processors to start
+num=$1
+# Log frequency in seconds
+log_freq=$2
+# Num of iterations
+log_iter=$3
+
+class_name=$4
+log_file_name=`echo $class_name | cut -d. -f6`
+
+# The total time for the test is determined by the
+# log_freq * log_iter.
+
+shift 4
+CLASSPATH=`find $JAR_PATH -name '*.jar' | tr '\n' ":"`
+
+JVM_ARGS="-Xmx1500M $@"
+echo "Starting $log_file_name with the following params $JVM_ARGS"
+
+for ((  c = 1 ;  c <= $num;  c++  ))
+do
+  $JAVA_HOME/bin/java $JVM_ARGS -cp $CLASSPATH $class_name > ${log_file_name}_${c}.log &
+  pid=`jobs -l %% | awk '{print $2}'`
+  calc_stats $pid $log_freq $log_iter > ${log_file_name}_process_${c}.log &
+done
diff --git a/java/testkit/bin/run_sub.sh b/java/testkit/bin/run_sub.sh
index 6e32451c34..f7e687de38 100644
--- a/java/testkit/bin/run_sub.sh
+++ b/java/testkit/bin/run_sub.sh
@@ -18,10 +18,6 @@
 # under the License.
 #
 
-# Helper script to set classpath for running Qpid example classes
-# NB: You must add the Qpid client and common jars to your CLASSPATH
-# before running this script
-
 . $QPID_TEST_HOME/bin/setenv.sh
 
 echo "$@"
diff --git a/java/testkit/bin/setenv.sh b/java/testkit/bin/setenv.sh
index da039271a3..24135e711b 100644
--- a/java/testkit/bin/setenv.sh
+++ b/java/testkit/bin/setenv.sh
@@ -18,9 +18,7 @@
 # under the License.
 #
 
-# Helper script to set classpath for running Qpid example classes
-# NB: You must add the Qpid client and common jars to your CLASSPATH
-# before running this script
+# Compiles the test classes and sets the CLASSPATH
 
 # check for QPID_TEST_HOME
 if [ "$QPID_TEST_HOME" = "" ] ; then
diff --git a/java/testkit/bin/soak_report.sh b/java/testkit/bin/soak_report.sh
new file mode 100644
index 0000000000..9753cf79d8
--- /dev/null
+++ b/java/testkit/bin/soak_report.sh
@@ -0,0 +1,157 @@
+#!/bin/sh
+#
+# Licensed to the Apache Software Foundation (ASF) under one
+# or more contributor license agreements.  See the NOTICE file
+# distributed with this work for additional information
+# regarding copyright ownership.  The ASF licenses this file
+# to you under the Apache License, Version 2.0 (the
+# "License"); you may not use this file except in compliance
+# with the License.  You may obtain a copy of the License at
+#
+#   http://www.apache.org/licenses/LICENSE-2.0
+#
+# Unless required by applicable law or agreed to in writing,
+# software distributed under the License is distributed on an
+# "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
+# KIND, either express or implied.  See the License for the
+# specific language governing permissions and limitations
+# under the License.
+#
+
+# Sample script to run a soak test with MultiThreadedProducer/Consumer.
+# You need to provide the log freq and no of iterations
+# Ex to run 10 hours and collect 1 second samples 
+# soak_report.sh 1 36000
+
+# This script assumes that a suitable broker instance is started.
+
+log_freq=$1
+log_iter=$2
+
+if [ "$QPID_TEST_HOME" = "" ] ; then
+    echo "ERROR: Please set QPID_TEST_HOME ...."
+    exit 1
+fi
+
+print_rates()
+{
+ cat $1 | awk '{
+ FS = ",";
+ count = 0;
+ total_latency = 0; 
+ min_latency = 9223372036854775807;
+ max_latency = 0;
+
+ total_tp = 0;
+ min_tp = 50000;
+ max_tp = 0;
+
+ while ((getline) == 1) 
+ { 
+     total_latency = total_latency + $3
+     total_tp = total_tp + $2
+
+     if ($3 > 0)
+     { 
+        min_latency = (($3 < min_latency) ? $3 : min_latency);
+        max_latency = (($3 > max_latency) ? $3 : max_latency);
+     }
+     if ($2 > 0)
+     { 
+        min_tp = (($2 < min_tp) ? $2 : min_tp);
+        max_tp = (($2 > max_tp) ? $2 : max_tp);
+     }
+
+     count =  count + 1
+ }
+
+ print "Avg Latency (ms) : " total_latency/count
+ print "Max Latency (ms) : " max_latency
+ print "Min Latency (ms) : " min_latency
+
+ print ""
+ print "Avg Throughput (msg/sec) : " total_tp/count
+ print "Max Throughput (msg/sec) : " max_tp
+ print "Min Throughput (msg/sec) : " min_tp
+
+ print ""
+ print "Total Iteratons " count
+
+ }'
+}
+
+print_system_stats()
+{
+ cat $1 | awk '{
+ FS = ",";
+ count = 0;
+ total_memory = 0;
+ min_memory = 9223372036854775807;
+ max_memory = 0;
+
+ total_cp = 0;
+ min_cp = 50000;
+ max_cp = 0;
+
+ while ((getline) == 1) 
+ { 
+     total_memory = total_memory + $2
+     total_cp = total_cp + $3
+
+     if ($2 > 0)
+     { 
+        min_memory = (($2 < min_memory) ? $2 : min_memory);
+        max_memory = (($2 > max_memory) ? $2 : max_memory);
+     }
+     if ($3 > 0)
+     { 
+        min_cp = (($3 < min_cp) ? $3 : min_cp);
+        max_cp = (($3 > max_cp) ? $3 : max_cp);
+     }
+
+     count =  count + 1
+ }
+
+ print "Avg Memory (MB) : " total_memory/(count*1024)
+ print "Max Memory (MB) : " max_memory/1024
+ print "Min Memory (MB) : " min_memory/1024
+
+ print ""
+ print "Avg CPU         : " total_cp/count
+ print "Max CPU         : " max_cp
+ print "Min CPU         : " min_cp
+
+ print ""
+ print "Total Iteratons " count
+
+ }'
+}
+
+
+cleanup()
+{
+  kill -9 `ps aux | grep soak_client | awk '{ print $2 }'`
+}
+
+print_results()
+{  
+  printf "\n======================================================= \n"
+  print_rates MultiThreadedConsumer_1.log
+  printf "\nConsumer process stats "
+  printf "\n----------------------- \n"
+  print_system_stats MultiThreadedConsumer_process_1.log
+  printf "\nProducer process stats "
+  printf "\n----------------------- \n"
+  print_system_stats MultiThreadedProducer_process_1.log
+  printf "\n------------------------------------------------------- \n"
+}
+
+trap cleanup EXIT
+
+# runs a single instance of the MultiThreadedConsumer and MultiThreadedProducer
+sh $QPID_TEST_HOME/bin/run_soak_client.sh 1 $log_freq $log_iter org.apache.qpid.testkit.soak.MultiThreadedConsumer
+sh $QPID_TEST_HOME/bin/run_soak_client.sh 1 $log_freq $log_iter org.apache.qpid.testkit.soak.MultiThreadedProducer
+
+sleep $log_iter
+
+print_results
diff --git a/java/testkit/src/main/java/org/apache/qpid/testkit/soak/BaseTest.java b/java/testkit/src/main/java/org/apache/qpid/testkit/soak/BaseTest.java
index be8c4bbc75..0c3a17b3d8 100644
--- a/java/testkit/src/main/java/org/apache/qpid/testkit/soak/BaseTest.java
+++ b/java/testkit/src/main/java/org/apache/qpid/testkit/soak/BaseTest.java
@@ -22,6 +22,8 @@ package org.apache.qpid.testkit.soak;
 
 
 import java.text.DateFormat;
+import java.text.DecimalFormat;
+import java.text.NumberFormat;
 import java.text.SimpleDateFormat;
 import java.util.Date;
 
@@ -54,6 +56,7 @@ public class BaseTest
     protected AMQConnection con;
     protected Destination dest = null;
     protected DateFormat df = new SimpleDateFormat("yyyy.MM.dd 'at' HH:mm:ss");
+    protected NumberFormat nf = new DecimalFormat("##.00");
 
     public BaseTest()
     {
diff --git a/java/testkit/src/main/java/org/apache/qpid/testkit/soak/MultiThreadedConsumer.java b/java/testkit/src/main/java/org/apache/qpid/testkit/soak/MultiThreadedConsumer.java
index 3117d268a3..a44760be46 100644
--- a/java/testkit/src/main/java/org/apache/qpid/testkit/soak/MultiThreadedConsumer.java
+++ b/java/testkit/src/main/java/org/apache/qpid/testkit/soak/MultiThreadedConsumer.java
@@ -48,6 +48,9 @@ public class MultiThreadedConsumer extends BaseTest
     {
         super();
         transacted = Boolean.getBoolean("transacted");
+        // needed only to calculate throughput.
+        // If msg_count is different set it via -Dmsg_count
+        msg_count = 10;
     }
 
     /**
@@ -75,14 +78,33 @@ public class MultiThreadedConsumer extends BaseTest
                             consumer.setMessageListener(new MessageListener()
                             {
 
+                                private boolean startIteration = true;
+                                private long startTime = 0;
+
                                 public void onMessage(Message m)
                                 {
                                     try
                                     {
-                                        String payload = ((TextMessage) m).getText();
-                                        if (payload.equals("End"))
+                                        long now = System.currentTimeMillis();
+                                        if (startIteration)
+                                        {
+                                            startTime = m.getJMSTimestamp();
+                                            startIteration = false;
+                                        }
+
+                                        if (m instanceof TextMessage && ((TextMessage) m).getText().equals("End"))
                                         {
-                                            System.out.println(m.getJMSMessageID() + "," + System.currentTimeMillis());
+                                            startIteration = true;
+                                            long totalIterationTime = now - startTime;
+                                            double throughput = ((double)msg_count/(double)totalIterationTime) * 1000;
+                                            long latencySample = now - m.getJMSTimestamp();
+
+                                            StringBuilder sb = new StringBuilder();
+                                            sb.append(m.getJMSMessageID()).append(",").
+                                            append(nf.format(throughput)).append(",").append(latencySample);
+
+                                            System.out.println(sb.toString());
+
                                             MessageProducer temp = session.createProducer(m.getJMSReplyTo());
                                             Message controlMsg = session.createTextMessage();
                                             temp.send(controlMsg);
diff --git a/java/testkit/src/main/java/org/apache/qpid/testkit/soak/MultiThreadedProducer.java b/java/testkit/src/main/java/org/apache/qpid/testkit/soak/MultiThreadedProducer.java
index 886c64bb81..279e5ea0bf 100644
--- a/java/testkit/src/main/java/org/apache/qpid/testkit/soak/MultiThreadedProducer.java
+++ b/java/testkit/src/main/java/org/apache/qpid/testkit/soak/MultiThreadedProducer.java
@@ -117,7 +117,6 @@ public class MultiThreadedProducer extends SimpleProducer
                                 }
 
                                 TextMessage m = session.createTextMessage("End");
-                                m.setJMSMessageID("ID:" + UUID.randomUUID());
                                 m.setJMSReplyTo(feedbackQueue);
                                 prod.send(m);
 
@@ -126,7 +125,7 @@ public class MultiThreadedProducer extends SimpleProducer
                                     session.commit();
                                 }
 
-                                System.out.println(m.getJMSMessageID() + "," + System.currentTimeMillis());
+                                System.out.println(df.format(System.currentTimeMillis()));
                                 feedbackConsumer.receive();
                                 if (transacted)
                                 {
diff --git a/java/testkit/src/main/java/org/apache/qpid/testkit/soak/ResourceLeakTest.java b/java/testkit/src/main/java/org/apache/qpid/testkit/soak/ResourceLeakTest.java
index 1faa9be864..c33f9ffbf2 100644
--- a/java/testkit/src/main/java/org/apache/qpid/testkit/soak/ResourceLeakTest.java
+++ b/java/testkit/src/main/java/org/apache/qpid/testkit/soak/ResourceLeakTest.java
@@ -103,6 +103,7 @@ public class ResourceLeakTest extends BaseTest
                       j++;
                     }
                 }
+                System.out.println(df.format(System.currentTimeMillis()));
                 Thread.sleep(connection_idle_time);
 
                 try
diff --git a/java/testkit/src/main/java/org/apache/qpid/testkit/soak/SimpleConsumer.java b/java/testkit/src/main/java/org/apache/qpid/testkit/soak/SimpleConsumer.java
index 5ef72d7538..d353e44816 100644
--- a/java/testkit/src/main/java/org/apache/qpid/testkit/soak/SimpleConsumer.java
+++ b/java/testkit/src/main/java/org/apache/qpid/testkit/soak/SimpleConsumer.java
@@ -53,6 +53,9 @@ public class SimpleConsumer extends BaseTest
     public SimpleConsumer()
     {
         super();
+        //needed only to calculate throughput.
+        // If msg_count is different set it via -Dmsg_count
+        msg_count = 10;
     }
 
     public void test()
@@ -69,14 +72,34 @@ public class SimpleConsumer extends BaseTest
                 cons[i].setMessageListener(new MessageListener()
                 {
 
+                    private boolean startIteration = true;
+                    private long startTime = 0;
+
                     public void onMessage(Message m)
                     {
                         try
                         {
-                            String payload = ((TextMessage) m).getText();
-                            if (payload.equals("End"))
+                            long now = System.currentTimeMillis();
+                            if (startIteration)
+                            {
+                                startTime = m.getJMSTimestamp();
+                                startIteration = false;
+                            }
+
+                            if (m instanceof TextMessage && ((TextMessage) m).getText().equals("End"))
                             {
-                                System.out.println(m.getJMSMessageID() + "," + System.currentTimeMillis());
+
+                                long totalIterationTime = now - startTime;
+                                startIteration = true;
+                                double throughput = ((double)msg_count/(double)totalIterationTime) * 1000;
+                                long latencySample = now - m.getJMSTimestamp();
+
+                                StringBuilder sb = new StringBuilder();
+                                sb.append(m.getJMSMessageID()).append(",").
+                                append(nf.format(throughput)).append(",").append(latencySample);
+
+                                System.out.println(sb.toString());
+
                                 MessageProducer temp = sessions[0].createProducer(m.getJMSReplyTo());
                                 Message controlMsg = sessions[0].createTextMessage();
                                 temp.send(controlMsg);
diff --git a/java/testkit/src/main/java/org/apache/qpid/testkit/soak/SimpleProducer.java b/java/testkit/src/main/java/org/apache/qpid/testkit/soak/SimpleProducer.java
index bdae79fd41..1080092536 100644
--- a/java/testkit/src/main/java/org/apache/qpid/testkit/soak/SimpleProducer.java
+++ b/java/testkit/src/main/java/org/apache/qpid/testkit/soak/SimpleProducer.java
@@ -109,7 +109,7 @@ public class SimpleProducer extends BaseTest
                 for (int i = 0; i < msg_count - 1; i++)
                 {
                     Message msg = getNextMessage();
-                    msg.setJMSMessageID("ID:" + UUID.randomUUID());
+                    msg.setJMSTimestamp(System.currentTimeMillis());
                     prods[prod_pointer].send(msg);
                     if (multi_session)
                     {
@@ -122,10 +122,9 @@ public class SimpleProducer extends BaseTest
                 }
 
                 TextMessage m = sessions[0].createTextMessage("End");
-                m.setJMSMessageID("ID:" + UUID.randomUUID());
                 m.setJMSReplyTo(feedbackQueue);
                 prods[prod_pointer].send(m);
-                System.out.println(m.getJMSMessageID() + "," + System.currentTimeMillis());
+                System.out.println(df.format(System.currentTimeMillis()));
                 feedbackConsumer.receive();
                 Thread.sleep(1000);
             }