Author: ieb
Date: Wed Feb 27 10:38:06 2013
New Revision: 1450722
URL: http://svn.apache.org/r1450722
Log:
Better measurement of thread blockings. Running more threads than cpus was
misleading.
Current implementation causes threads to block about 0.5% of the time when
running flat out.
Modified:
sling/whiteboard/ieb/log/src/test/java/org/apache/sling/commons/log/internal/monitor/CounterTest.java
Modified:
sling/whiteboard/ieb/log/src/test/java/org/apache/sling/commons/log/internal/monitor/CounterTest.java
URL:
http://svn.apache.org/viewvc/sling/whiteboard/ieb/log/src/test/java/org/apache/sling/commons/log/internal/monitor/CounterTest.java?rev=1450722&r1=1450721&r2=1450722&view=diff
==============================================================================
---
sling/whiteboard/ieb/log/src/test/java/org/apache/sling/commons/log/internal/monitor/CounterTest.java
(original)
+++
sling/whiteboard/ieb/log/src/test/java/org/apache/sling/commons/log/internal/monitor/CounterTest.java
Wed Feb 27 10:38:06 2013
@@ -17,18 +17,41 @@
*/
package org.apache.sling.commons.log.internal.monitor;
+import java.lang.management.ManagementFactory;
+import java.lang.management.ThreadInfo;
+import java.lang.management.ThreadMXBean;
+import java.text.MessageFormat;
+import java.util.concurrent.atomic.AtomicInteger;
import java.util.concurrent.atomic.AtomicLong;
+import javax.management.Attribute;
+import javax.management.AttributeNotFoundException;
+import javax.management.InstanceNotFoundException;
+import javax.management.InvalidAttributeValueException;
+import javax.management.MBeanException;
+import javax.management.MBeanServer;
+import javax.management.MBeanServerFactory;
+import javax.management.MalformedObjectNameException;
+import javax.management.ObjectName;
+import javax.management.ReflectionException;
+import javax.management.openmbean.CompositeData;
+
import junit.framework.Assert;
+import
org.apache.sling.commons.log.internal.Activator.DummyLogManagerConfiguration;
import org.junit.Test;
+import org.osgi.service.cm.ManagedServiceFactory;
import org.slf4j.Marker;
import org.slf4j.MarkerFactory;
public class CounterTest {
+ private long lastBlockedTime;
+ private long lastBlockedCount;
+ private long lastCheck;
+
/**
- * Give a very rough idea of performance single threaded.
- * NB: This is a totally unscientific benchmark.
+ * Give a very rough idea of performance single threaded. NB: This is a
+ * totally unscientific benchmark.
*/
@Test
public void testCounter() {
@@ -36,80 +59,137 @@ public class CounterTest {
Counter counter = Counter.getInstance();
int loops = 100000;
int counters = 100;
- long ncounts = loops*counters;
- // attemt to warm up hotspot by causing the code to be executed > 10k
times.
- for ( int j = 0; j < loops+1; j++ ) {
- for ( int i = 0; i < counters+1; i++) {
- counter.increment(m, "cou\"nter"+i);
+ long ncounts = loops * counters;
+ // attemt to warm up hotspot by causing the code to be executed > 10k
+ // times.
+ for (int j = 0; j < loops + 1; j++) {
+ for (int i = 0; i < counters + 1; i++) {
+ counter.increment(m, "cou\"nter" + i);
}
}
long l = System.nanoTime();
- for ( int j = 0; j < loops; j++ ) {
- for ( int i = 0; i < counters; i++) {
- counter.increment(m, "cou\"nter"+i);
+ for (int j = 0; j < loops; j++) {
+ for (int i = 0; i < counters; i++) {
+ counter.increment(m, "cou\"nter" + i);
}
}
l = System.nanoTime() - l;
- System.err.println("Time Taken for 1 count operation is
"+(l/ncounts)+" nanoseconds");
+ System.err.println("Time Taken for 1 count operation is "
+ + (l / ncounts) + " nanoseconds");
String json = counter.toJson();
Assert.assertNotNull(json);
}
-
+
@Test
- public void testCounterMultiThreaded() throws InterruptedException {
- for (int i = 1; i < 32; i++ ) {
- doMulti(i, 10000, 100, Runtime.getRuntime().availableProcessors());
- }
+ public void testCounterMultiThreaded() throws InterruptedException,
+ MalformedObjectNameException, InstanceNotFoundException,
+ NullPointerException, ReflectionException, MBeanException,
+ InvalidAttributeValueException, AttributeNotFoundException {
+ doMulti(Runtime.getRuntime().availableProcessors(), 10000000, 100,
Runtime.getRuntime().availableProcessors());
}
-
- public long doMulti(int threads, final int loops, final int counters, int
cores) throws InterruptedException {
+
+ public void doMulti(int threads, final int loops, final int counters,
+ int cores) throws InterruptedException,
+ MalformedObjectNameException, InstanceNotFoundException,
+ NullPointerException, ReflectionException, MBeanException,
+ InvalidAttributeValueException, AttributeNotFoundException {
final Marker m = MarkerFactory.getMarker("count");
final Counter counter = Counter.getInstance();
- // attemt to warm up hotspot by causing the code to be executed > 10k
times.
- for ( int j = 0; j < loops+1; j++ ) {
- for ( int i = 0; i < counters+1; i++) {
- counter.increment(m, "cou\"nter"+i);
+ // attemt to warm up hotspot by causing the code to be executed > 10k
+ // times.
+ for (int j = 0; j < 10000 + 1; j++) {
+ for (int i = 0; i < counters + 1; i++) {
+ counter.increment(m, "cou\"nter" + i);
}
}
- final int ncounts = loops*counters;
- final int tcounts = ncounts*threads;
+ final int ncounts = loops * counters;
+ final int tcounts = ncounts * threads;
Thread[] t = new Thread[threads];
final long[] l = new long[threads];
- for ( int i = 0; i < threads; i++ ) {
+ final AtomicInteger running = new AtomicInteger();
+ for (int i = 0; i < threads; i++) {
final int threadn = i;
t[i] = new Thread() {
public void run() {
+ running.incrementAndGet();
l[threadn] = System.nanoTime();
- for ( int j = 0; j < loops; j++ ) {
- for ( int i = 0; i < counters; i++) {
- counter.increment(m, "cou\"nter"+i);
+ for (int j = 0; j < loops; j++) {
+ for (int i = 0; i < counters; i++) {
+ counter.increment(m, "cou\"nter" + i);
}
}
l[threadn] = System.nanoTime() - l[threadn];
+ running.decrementAndGet();
};
};
}
- for ( int i = 0; i < t.length; i++) {
- t[i].start();
- }
- for ( int i = 0; i < t.length; i++) {
- t[i].join();
- }
- // work out the total time over all threads.
- long overall = 0L;
- for ( int i = 0; i < t.length; i++) {
- overall += l[i];
- }
- // work out how long it should have taken if we had as many cores as
threads.
- // this number should remain constant if no threads block other threads
and both cores on the box are
- // fully utilized.
- long adjusted = overall/tcounts;
- if ( threads > cores ) {
- adjusted = (cores*100*(adjusted))/(100*threads);
- }
- System.err.println("Time Taken for 1 count operation over "+t.length+"
threads is "+(overall/tcounts)+" ns "+adjusted+" ns adjusted for CPUs");
- return adjusted;
+ MBeanServer mbeanServer = resetThreadMontoring();
+ dumpThreadWaits(mbeanServer);
+ for (int i = 0; i < t.length; i++) {
+ t[i].start();
+ }
+
+ while (running.get() > 0) {
+ dumpThreadWaits(mbeanServer);
+ Thread.sleep(10000);
+ }
+
+ for (int i = 0; i < t.length; i++) {
+ t[i].join();
+ }
+ // work out the total time over all threads.
+ long overall = 0L;
+ for (int i = 0; i < t.length; i++) {
+ overall += l[i];
+ }
+ // work out how long it should have taken if we had as many cores as
+ // threads.
+ // this number should remain constant if no threads block other threads
+ // and both cores on the box are
+ // fully utilized.
+ System.err.println("Time Taken for 1 count operation over " + t.length
+ + " threads is " + (overall / tcounts) + " ns ");
+
+ }
+
+ private MBeanServer resetThreadMontoring() throws
InstanceNotFoundException, InvalidAttributeValueException,
AttributeNotFoundException, MalformedObjectNameException, ReflectionException,
MBeanException, NullPointerException {
+ MBeanServer mbeanServer = ManagementFactory.getPlatformMBeanServer();
+ mbeanServer.setAttribute(new ObjectName("java.lang:type=Threading"),
+ new Attribute("ThreadContentionMonitoringEnabled", false));
+ mbeanServer.setAttribute(new ObjectName("java.lang:type=Threading"),
+ new Attribute("ThreadContentionMonitoringEnabled", true));
+ lastBlockedTime = 0;
+ lastBlockedCount = 0;
+ lastCheck = System.currentTimeMillis();
+ return mbeanServer;
+ }
+
+ private void dumpThreadWaits(MBeanServer mbeanServer)
+ throws MalformedObjectNameException, NullPointerException,
+ InstanceNotFoundException, ReflectionException, MBeanException {
+ CompositeData[] threads = (CompositeData[]) mbeanServer.invoke(
+ new ObjectName("java.lang:type=Threading"), "dumpAllThreads",
+ new Object[] { new Boolean(true), new Boolean(true) },
+ new String[] { "boolean", "boolean" });
+ long blockedTime = 0L;
+ long blockedCount = 0L;
+ for (CompositeData cd : threads) {
+ ThreadInfo ti = ThreadInfo.from(cd);
+ if (Thread.currentThread().getId() != ti.getThreadId()) {
+ blockedTime += ti.getBlockedTime();
+ blockedCount += ti.getBlockedCount();
+ }
+ }
+ long deltaTime = blockedTime - lastBlockedTime;
+ long deltaCount = blockedCount - lastBlockedCount;
+ long deltaRealTime = System.currentTimeMillis() - lastCheck;
+
+ lastBlockedTime = blockedTime;
+ lastBlockedCount = blockedCount;
+ lastCheck = System.currentTimeMillis();
+ System.err.println(MessageFormat.format("Total Blocked time over all
threads {0,number} ms in {1,number} ms threads blocked for {2,number,#.###}%
of the time or on average {3,number,#.##} ms
",deltaTime,deltaRealTime,((double)deltaTime*100)/((double)deltaRealTime),((deltaCount==0)?0:((double)deltaTime)/((double)deltaCount))));
+
}
}
