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)))); + } }