6:01 a.m.
Author: manik.surtani(a)jboss.com
Date: 2008-09-18 07:01:52 -0400 (Thu, 18 Sep 2008)
New Revision: 6748
Modified:
core/trunk/src/test/java/org/jboss/cache/profiling/MockAsyncReplTest.java
core/trunk/src/test/java/org/jboss/cache/profiling/ProfileTest.java
Log:
Better throughput measurement
Modified: core/trunk/src/test/java/org/jboss/cache/profiling/MockAsyncReplTest.java
===================================================================
--- core/trunk/src/test/java/org/jboss/cache/profiling/MockAsyncReplTest.java 2008-09-17
23:24:20 UTC (rev 6747)
+++ core/trunk/src/test/java/org/jboss/cache/profiling/MockAsyncReplTest.java 2008-09-18
11:01:52 UTC (rev 6748)
@@ -63,27 +63,27 @@
boolean anycasting, boolean oob, RspFilter
filter) throws NotSerializableException
{
// make sure we do the marshalling though
- if (m == null && m2 == null)
- {
- m = getRequestMarshaller();
- if (m instanceof Marshaller2)
- {
- m2 = (Marshaller2) m;
- m = null;
- }
- }
+// if (m == null && m2 == null)
+// {
+// m = getRequestMarshaller();
+// if (m instanceof Marshaller2)
+// {
+// m2 = (Marshaller2) m;
+// m = null;
+// }
+// }
+//
+// try
+// {
+// if (m2 == null) m.objectToByteBuffer(command);
+// else m2.objectToBuffer(command);
+// }
+// catch (Exception e)
+// {
+// e.printStackTrace();
+// throw new NotSerializableException(e.getMessage());
+// }
- try
- {
- if (m2 == null) m.objectToByteBuffer(command);
- else m2.objectToBuffer(command);
- }
- catch (Exception e)
- {
- e.printStackTrace();
- throw new NotSerializableException(e.getMessage());
- }
-
int i = ai.incrementAndGet();
if (i % 1000 == 0) log.warn("Dispatching operation #" + i);
// no-op
Modified: core/trunk/src/test/java/org/jboss/cache/profiling/ProfileTest.java
===================================================================
--- core/trunk/src/test/java/org/jboss/cache/profiling/ProfileTest.java 2008-09-17
23:24:20 UTC (rev 6747)
+++ core/trunk/src/test/java/org/jboss/cache/profiling/ProfileTest.java 2008-09-18
11:01:52 UTC (rev 6748)
@@ -17,6 +17,7 @@
import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;
import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicLong;
/**
* Test to use with a profiler to profile replication. To be used in conjunction with
ProfileSlaveTest.
@@ -53,7 +54,7 @@
Log log = LogFactory.getLog(ProfileTest.class);
- @Test(enabled = false)
+ @Test(enabled = true)
public void testLocalModePess() throws Exception
{
cache.getConfiguration().setCacheMode(Configuration.CacheMode.LOCAL);
@@ -249,24 +250,28 @@
private void doTest() throws Exception
{
ExecutorService exec = Executors.newFixedThreadPool(NUM_THREADS);
- // Executor exec = new DirectExecutor();
- long startTime = System.currentTimeMillis();
log.warn("Starting test");
int i;
long print = NUM_OPERATIONS / 10;
+
+ AtomicLong durationPuts = new AtomicLong();
+ AtomicLong durationGets = new AtomicLong();
+ AtomicLong durationRemoves = new AtomicLong();
+
+ long stElapsed = System.nanoTime();
for (i = 0; i < NUM_OPERATIONS; i++)
{
MyRunnable r = null;
switch (i % 3)
{
case 0:
- r = new Putter(i);
+ r = new Putter(i, durationPuts);
break;
case 1:
- r = new Getter(i);
+ r = new Getter(i, durationGets);
break;
case 2:
- r = new Remover(i);
+ r = new Remover(i, durationRemoves);
break;
}
if (i % print == 0)
@@ -278,12 +283,33 @@
log.warn("Finished generating runnables; awaiting executor completion");
// wait for executors to complete!
exec.shutdown();
- exec.awaitTermination(((long) i), TimeUnit.SECONDS); // wait up to 1 sec for each
call?
- long duration = System.currentTimeMillis() - startTime;
- log.warn("Finished test. " + printDuration(duration));
- log.warn("Throughput: " + (NUM_OPERATIONS * 1000 / duration) + "
operations per second (roughly equal numbers of PUT, GET and REMOVE)");
+ while (!exec.awaitTermination(((long) i), TimeUnit.SECONDS))
+ {
+ Thread.sleep(1);
+ }
+ ; // wait up to 1 sec for each call?
+ long elapsedTimeNanos = System.nanoTime() - stElapsed;
+
+ log.warn("Finished test. " + printDuration((long)
toMillis(elapsedTimeNanos)));
+ log.warn("Throughput: " + ((double) NUM_OPERATIONS * 1000 /
toMillis(elapsedTimeNanos)) + " operations per second (roughly equal numbers of PUT,
GET and REMOVE)");
+ log.warn("Average GET time: " + printAvg(durationGets.get()));
+ log.warn("Average PUT time: " + printAvg(durationPuts.get()));
+ log.warn("Average REMOVE time: " + printAvg(durationRemoves.get()));
}
+ private String printAvg(long totalNanos)
+ {
+ double nOps = (double) (NUM_OPERATIONS / 3);
+ double avg = ((double) totalNanos) / nOps;
+ double avgMicros = avg / 1000;
+ return avgMicros + " �s";
+ }
+
+ private double toMillis(long nanos)
+ {
+ return ((double) nanos / (double) 1000000);
+ }
+
enum Mode
{
PUT, GET, REMOVE
@@ -293,53 +319,61 @@
{
int id;
Mode mode;
+ AtomicLong duration;
-
public void run()
{
String k = getRandomString();
Fqn f = fqns.get(r.nextInt(MAX_OVERALL_NODES));
+ long d = 0, st = 0;
switch (mode)
{
case PUT:
+ st = System.nanoTime();
cache.put(f, k, getRandomString());
- // cache.put(BELAS_FQN, BELAS_KEY, new byte[10000]);
+ d = System.nanoTime() - st;
break;
case GET:
- // cache.get(BELAS_FQN, BELAS_KEY);
+ st = System.nanoTime();
cache.get(f, k);
+ d = System.nanoTime() - st;
break;
case REMOVE:
- // cache.remove(BELAS_FQN, BELAS_KEY);
+ st = System.nanoTime();
cache.remove(f, k);
+ d = System.nanoTime() - st;
break;
}
+ duration.getAndAdd(d);
}
}
private class Putter extends MyRunnable
{
- private Putter(int id)
+ private Putter(int id, AtomicLong duration)
{
this.id = id;
+ this.duration = duration;
mode = Mode.PUT;
}
}
private class Getter extends MyRunnable
{
- private Getter(int id)
+ private Getter(int id, AtomicLong duration)
{
this.id = id;
+ this.duration = duration;
mode = Mode.GET;
}
}
private class Remover extends MyRunnable
{
- private Remover(int id)
+ private Remover(int id, AtomicLong duration)
{
this.id = id;
+ this.duration = duration;
mode = Mode.REMOVE;
}
}