Unexpected huge scalability improvement in Outrigger

[Peter Firmstone <ji...@zeus.net.au>]

I'm in the process of making some performance comparisons between 2.2.0 
and qa_refactoring code:

This is only preliminary; I'm still investigating, one stress test 
(com/sun/jini/test/impl/outrigger/matching/StressTestWithShutdown.td) 
generates random javaspace reads and writes as fast as possible.

Firstly this test comparison is made on an Ultra80 with 4x450MHz CPU's & 
4GB ram.

The test runs for a period of just under 5 minutes on River 2.2.0 and 
just under 16 minutes on qa_refactoring (River 2.2.3 pre-alpha), both 
tests pass.

With River 2.2.0 the test manages to consume 100% of all 4 cpu's for 30 
seconds, but spends most of the test around 50% idle.

The new code for comparison: all 4 cpu's 0% are idle for a similar 
period, then average around 50% idle or less for the remaining duration, 
in addition, the computer remains usable during that time in both 
tests.  During the test, MarshalledInstance.readObject is invoked 3,349 
times and BasicInvocationDispatcher.unmarshalArguments is invoked 4881 
times (representing remote method calls).

The initial 0% idle period represents jvisualvm's profiler method 
instrumentation.

In comparison River 2.2.0's code only calls 
MarshalledInstance.readObject 652 times, and 
BasicInvocationDispatcher.unmarshalArguments 154 times.

On River 2.2.0 one call that dominates cpu usage at 52% (hotspot) is 
com.sun.jeri.internal.runtime.Target$2.run(), the same call is only 2.3% 
in qa_refactoring.

The Javaspace calls / tasks executed are totally random, so are not 
directly comparable, however the number of calls made depends on how 
responsive the Jini infrastructure is.

With so much more activity it takes Outrigger 3 times longer to deal 
with all the requests in qa_refactoring.  There are two other JVM 
instances open and Outrigger is a service provided from another.

To make matters even more interesting, security is not enabled in the 
River 2.2.0 test.

You might also notice that 
net.jini.jeri.BasicInvocationDispatcher.checkAccess also has a factor of 
10 improvement in performance.

Anyone who wants a copy of the profiler results, just ask.

Or checkout the code and try it for yourself.  If someone's got the time 
& the hardware, I'd love to see how it goes on recent hardware with 8 or 
more cores.

Cheers,

Peter.


River 2.2.0

Hot Spots - Method 	Self time [%] 	Self time 	Invocations
com.sun.jini.jeri.internal.runtime.Target$2.run() 	51.15% 	101813.132 
ms 	202
net.jini.io.MarshalledInstance.readObject(java.io.ObjectInputStream) 
15.87% 	31593.839 ms 	652
com.sun.jini.thread.ThreadPool$Worker.run() 	9.52% 	18956.546 ms 	3
com.sun.jini.jeri.internal.mux.MuxServer$1.run() 	8.53% 	16987.654 ms 	201
net.jini.jeri.BasicInvocationDispatcher.unmarshalArguments(java.rmi.Remote, 
java.lang.reflect.Method, java.io.ObjectInputStream, 
java.util.Collection) 	7.55% 	15029.022 ms 	154
net.jini.jeri.BasicInvocationDispatcher.dispatch(java.rmi.Remote, 
net.jini.jeri.InboundRequest, java.util.Collection) 	5.57% 	11088.875 
ms 	154
net.jini.jeri.BasicInvocationDispatcher.invoke(java.rmi.Remote, 
java.lang.reflect.Method, Object[], java.util.Collection) 	1.02% 
2034.364 ms 	176
net.jini.jeri.BasicInvocationDispatcher.marshalReturn(java.rmi.Remote, 
java.lang.reflect.Method, Object, java.io.ObjectOutputStream, 
java.util.Collection) 	0.33% 	662.177 ms 	177
net.jini.jeri.BasicInvocationDispatcher.createMarshalInputStream(Object, 
net.jini.jeri.InboundRequest, boolean, java.util.Collection) 	0.14% 
277.418 ms 	154
net.jini.io.MarshalOutputStream.<init>(java.io.OutputStream, 
java.util.Collection) 	0.09% 	173.264 ms 	177
net.jini.core.constraint.ArraySet$Iter.hasNext() 	0.08% 	167.406 ms 	462
net.jini.io.MarshalInputStream.<init>(java.io.InputStream, ClassLoader, 
boolean, ClassLoader, java.util.Collection) 	0.02% 	48.366 ms 	154
net.jini.jeri.BasicInvocationDispatcher.unmarshalMethod(java.rmi.Remote, 
java.io.ObjectInputStream, java.util.Collection) 	0.02% 	30.719 ms 	154
net.jini.core.constraint.ArraySet.iterator() 	0.02% 	30.675 ms 	462
net.jini.jeri.tcp.Constraints$Distilled.<init>(net.jini.core.constraint.InvocationConstraints, 
boolean) 	0.01% 	26.085 ms 	153
net.jini.jeri.BasicInvocationDispatcher.createMarshalOutputStream(Object, 
java.lang.reflect.Method, net.jini.jeri.InboundRequest, 
java.util.Collection) 	0.01% 	14.517 ms 	177
net.jini.core.constraint.InvocationConstraints.requirements() 	0.01% 
13.841 ms 	308
net.jini.jeri.connection.ServerConnectionManager$Inbound.getResponseOutputStream() 
	0.01% 	13.24 ms 	507
net.jini.jeri.connection.ServerConnectionManager$Inbound.getRequestInputStream() 
	0.01% 	11.515 ms 	461
net.jini.jeri.tcp.Constraints.check(net.jini.core.constraint.InvocationConstraints, 
boolean) 	0.01% 	10.828 ms 	153
net.jini.core.constraint.ArraySet$Iter.<init>(net.jini.core.constraint.ArraySet) 
	0.01% 	10.706 ms 	459
net.jini.core.constraint.ArraySet.<init>(Object[]) 	0.01% 	10.703 ms 	460
net.jini.jeri.tcp.TcpServerEndpoint$LH$ServerConnectionImpl.checkConstraints(net.jini.jeri.connection.InboundRequestHandle, 
net.jini.core.constraint.InvocationConstraints) 	0.00% 	7.452 ms 	154
net.jini.jeri.connection.ServerConnectionManager$Inbound.checkConstraints(net.jini.core.constraint.InvocationConstraints) 
	0.00% 	7.047 ms 	154
net.jini.jeri.tcp.Constraints.distill(net.jini.core.constraint.InvocationConstraints, 
boolean) 	0.00% 	7.025 ms 	153
net.jini.core.constraint.InvocationConstraints.preferences() 	0.00% 
6.89 ms 	154
net.jini.jeri.tcp.Constraints$Distilled.getUnfulfilledConstraints() 
0.00% 	3.785 ms 	154
net.jini.jeri.BasicInvocationDispatcher.checkAccess(java.rmi.Remote, 
java.lang.reflect.Method, 
net.jini.core.constraint.InvocationConstraints, java.util.Collection) 
0.00% 	3.424 ms 	154
net.jini.io.MarshalInputStream.useCodebaseAnnotations() 	0.00% 	3.328 
ms 	154
net.jini.id.Uuid.writeReplace() 	0.00% 	0.22 ms 	59



River 2.3.0 pre alpha (qa_refactoring)

Hot Spots - Method 	Self time [%] 	Self time 	Invocations

com.sun.jini.thread.ThreadPool$Worker.run()

	26.18% 	1163449.494 ms 	6

com.sun.jini.jeri.internal.mux.StreamConnectionIO$Writer.run()

	23.04% 	1023961.141 ms 	5

net.jini.io.MarshalledInstance.readObject(java.io.ObjectInputStream)

	11.49% 	510737.402 ms 	3349

net.jini.jeri.BasicInvocationDispatcher.unmarshalArguments(java.rmi.Remote, java.lang.reflect.Method, java.io.ObjectInputStream, java.util.Collection)

	9.56% 	424753.652 ms 	4881

com.sun.jini.jeri.internal.mux.MuxServer$1.run()

	5.93% 	263538.933 ms 	4902

com.sun.jini.jeri.internal.mux.StreamConnectionIO$Reader.run()

	3.44% 	152769.871 ms 	2

net.jini.jeri.BasicInvocationDispatcher.dispatch(java.rmi.Remote, net.jini.jeri.InboundRequest, java.util.Collection)

	3.31% 	146959.497 ms 	4881

com.sun.jini.jeri.internal.runtime.Target$2.run()

	2.35% 	104347.742 ms 	4901

net.jini.jeri.BasicInvocationDispatcher.invoke(java.rmi.Remote, java.lang.reflect.Method, Object[], java.util.Collection)

	1.91% 	84857.449 ms 	4892

org.apache.river.api.net.UriParser.parseURI(String, boolean)

	1.79% 	79736.929 ms 	328811

net.jini.jeri.BasicInvocationDispatcher.marshalReturn(java.rmi.Remote, java.lang.reflect.Method, Object, java.io.ObjectOutputStream, java.util.Collection)

	1.70% 	75376.782 ms 	1053

org.apache.river.api.security.URIGrant.implies(java.security.CodeSource, java.security.Principal[])

	0.80% 	35421.372 ms 	330386

au.net.zeus.collection.ReferenceMap.get(Object)

	0.74% 	32973.028 ms 	229307

org.apache.river.api.net.UriParser.validateSegment(String, String, int, String)

	0.61% 	27295.063 ms 	2362865

org.apache.river.api.security.CertificateGrant.implies(java.security.ProtectionDomain)

	0.52% 	23215.116 ms 	330770

org.apache.river.api.net.URIEncoderDecoder.quoteIllegal(String, String)

	0.47% 	20748.571 ms 	328853

org.apache.river.api.net.UriParser.normalize(String)

	0.44% 	19669.965 ms 	328810

net.jini.io.MarshalOutputStream.<init>(java.io.OutputStream, java.util.Collection)

	0.42% 	18868.243 ms 	4892

net.jini.jeri.BasicInvocationDispatcher.marshalThrow(java.rmi.Remote, java.lang.reflect.Method, Throwable, java.io.ObjectOutputStream, java.util.Collection)

	0.38% 	17083.125 ms 	3839

org.apache.river.api.net.Uri.constructor1(String)

	0.38% 	16826.311 ms 	328811

java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run()

	0.35% 	15441.505 ms 	3055970

org.apache.river.api.net.URIEncoderDecoder.decodeUnreserved(String)

	0.32% 	14260.82 ms 	328811

org.apache.river.api.net.Uri.fixWindowsURI(String)

	0.30% 	13528.753 ms 	328881

net.jini.jeri.BasicInvocationDispatcher.createMarshalInputStream(Object, net.jini.jeri.InboundRequest, boolean, java.util.Collection)

	0.30% 	13406.273 ms 	4881

au.net.zeus.collection.AbstractReferrerDecorator.get()

	0.29% 	13010.299 ms 	469326

au.net.zeus.collection.ReferenceProcessor.referenced(Object, boolean, boolean)

	0.28% 	12435.958 ms 	263096

org.apache.river.api.net.Uri.urlToUri(java.net.URL)

	0.28% 	12222.749 ms 	329375

au.net.zeus.collection.ReferenceFactory.singleUseForLookup(Object, au.net.zeus.collection.Ref)

	0.27% 	12024.533 ms 	262992

org.apache.river.api.net.URIEncoderDecoder.validate(String, String)

	0.22% 	9954.947 ms 	2362438

org.apache.river.api.net.Uri.implies(org.apache.river.api.net.Uri)

	0.20% 	8950.05 ms 	588758

org.apache.river.api.net.UriParser.setSchemeSpecificPart(String, String, String)

	0.17% 	7684.196 ms 	328810

org.apache.river.api.net.Uri.getHashString()

	0.14% 	6436.446 ms 	328811

com.sun.jini.qa.harness.MergedPolicyProvider.getPermissionGrants(java.security.ProtectionDomain)

	0.09% 	4176.725 ms 	66207

au.net.zeus.collection.ReferenceProcessor$CleanerTask.run()

	0.09% 	4094.826 ms 	3034999

org.apache.river.api.security.PrincipalGrant.implies(java.security.Principal[])

	0.09% 	3812.522 ms 	329365

org.apache.river.api.security.ConcurrentPolicyFile.getPermissionGrants(java.security.ProtectionDomain)

	0.08% 	3663.7 ms 	66162

org.apache.river.api.net.Uri.quoteComponent(String, String)

	0.07% 	3314.403 ms 	328851

net.jini.io.MarshalInputStream.<init>(java.io.InputStream, ClassLoader, boolean, ClassLoader, java.util.Collection)

	0.07% 	3276.258 ms 	4881

org.apache.river.api.net.Uri.<init>(String, String, String, String, String, String, int, String, String, String, boolean, boolean, boolean, int, boolean)

	0.07% 	3159.704 ms 	328811

com.sun.jini.reggie.RegistrarImpl$DecodeRequestTask.run()

	0.07% 	3104.961 ms 	2

au.net.zeus.collection.RefReferenceQueue.poll()

	0.07% 	2916.806 ms 	3034095

org.apache.river.api.net.Uri.parseAndCreate(String)

	0.05% 	2305.746 ms 	328881

org.apache.river.api.net.UriParser.validateScheme(String, String, int)

	0.05% 	2286.858 ms 	328810

org.apache.river.api.net.Uri.<init>(org.apache.river.api.net.UriParser)

	0.05% 	2105.161 ms 	328811

org.apache.river.api.net.Uri.equals(Object)

	0.04% 	1943.142 ms 	142464

org.apache.river.api.io.DistributedObjectOutputStream.<init>(java.io.OutputStream)

	0.04% 	1802.426 ms 	4892

com.sun.jini.reggie.RegistrarImpl$AddressTask.run()

	0.04% 	1711.409 ms 	2

net.jini.security.policy.DynamicPolicyProvider.getPermissionGrants(java.security.ProtectionDomain)

	0.04% 	1685.747 ms 	65796

org.apache.river.api.security.PrincipalGrant.getPrincipals(java.security.ProtectionDomain)

	0.04% 	1635.426 ms 	330386

au.net.zeus.collection.TempIdentityReferrer.equals(Object)

	0.03% 	1483.964 ms 	182697

org.apache.river.api.net.UriParser.<init>()

	0.03% 	1447.006 ms 	328811

org.apache.river.api.net.Uri.<init>(String)

	0.03% 	1446.377 ms 	328851

org.apache.river.api.net.Uri.convertHexToUpperCase(String)

	0.03% 	1437.298 ms 	328746

au.net.zeus.collection.ReferenceProcessor$FinalizerTask.run()

	0.03% 	1383.824 ms 	3

org.apache.river.api.net.URIEncoderDecoder.validateSimple(String, String)

	0.03% 	1345.947 ms 	328809

au.net.zeus.collection.ReferenceMap.wrapKey(Object, boolean, boolean)

	0.03% 	1335.613 ms 	229358

org.apache.river.api.net.UriParser.parseAuthority(boolean)

	0.03% 	1248.211 ms 	328810

au.net.zeus.collection.TempEqualReferrer.hashCode()

	0.02% 	1097.283 ms 	57130

net.jini.jeri.BasicInvocationDispatcher.unmarshalMethod(java.rmi.Remote, java.io.ObjectInputStream, java.util.Collection)

	0.02% 	703.319 ms 	4881

au.net.zeus.collection.TempIdentityReferrer.<init>(Object)

	0.01% 	609.781 ms 	262992

au.net.zeus.collection.TempEqualReferrer.equals(Object)

	0.01% 	607.318 ms 	57080

org.apache.river.api.io.DistributedObjectInputStream.<init>(java.io.InputStream)

	0.01% 	574.919 ms 	4881

au.net.zeus.collection.ReferenceProcessor.referenced(Object, boolean, boolean)

	0.01% 	515.753 ms 	263096

net.jini.loader.pref.PreferredClassProvider$LoaderKey.equals(Object)

	0.01% 	483.595 ms 	10798

au.net.zeus.collection.TimedReferrer.get()

	0.01% 	442.21 ms 	46500

au.net.zeus.collection.TempEqualReferrer.<init>(Object)

	0.01% 	369.973 ms 	57094

au.net.zeus.collection.TempIdentityReferrer.hashCode()

	0.01% 	310.866 ms 	205979

au.net.zeus.collection.TempComparableReferrer.<init>(Object)

	0.01% 	298.275 ms 	34466

net.jini.jeri.BasicObjectEndpoint.writeObject(java.io.ObjectOutputStream)

	0.00% 	210.359 ms 	3

net.jini.jeri.tcp.Constraints$Distilled.<init>(net.jini.core.constraint.InvocationConstraints, boolean)

	0.00% 	130.724 ms 	4881

net.jini.security.GrantPermission$GrantPermissionCollection.elements()

	0.00% 	118.332 ms 	20655

net.jini.io.MarshalOutputStream$1.<init>(net.jini.io.MarshalOutputStream)

	0.00% 	110.301 ms 	4892

au.net.zeus.collection.ReferrerDecorator.<init>(au.net.zeus.collection.Referrer)

	0.00% 	102.755 ms 	96

net.jini.id.Uuid.readObject(java.io.ObjectInputStream)

	0.00% 	58.876 ms 	3843

au.net.zeus.collection.ReferenceProcessor$EnqueGarbageTask.run()

	0.00% 	50.966 ms 	971

net.jini.core.constraint.ArraySet.<init>(Object[])

	0.00% 	34.889 ms 	14661

net.jini.io.MarshalledInstance.equals(Object)

	0.00% 	32.365 ms 	2510

net.jini.id.Uuid.hashCode()

	0.00% 	30.357 ms 	17128

net.jini.id.Uuid.equals(Object)

	0.00% 	26.507 ms 	10113

net.jini.jeri.BasicInvocationDispatcher.createMarshalOutputStream(Object, java.lang.reflect.Method, net.jini.jeri.InboundRequest, java.util.Collection)

	0.00% 	25.599 ms 	4892

com.sun.jini.thread.ThreadPool$Task.run()

	0.00% 	25.175 ms 	4913

net.jini.jeri.tcp.Constraints.check(net.jini.core.constraint.InvocationConstraints, boolean)

	0.00% 	24.637 ms 	4881

net.jini.id.Uuid.isValid()

	0.00% 	20.674 ms 	7686

net.jini.jeri.connection.ServerConnectionManager$Inbound.getResponseOutputStream()

	0.00% 	20.445 ms 	14664

net.jini.core.constraint.InvocationConstraints.preferences()

	0.00% 	20.016 ms 	4889

net.jini.core.constraint.ArraySet$Iter.hasNext()

	0.00% 	17.301 ms 	14728

net.jini.jeri.connection.ServerConnectionManager$Inbound.getRequestInputStream()

	0.00% 	17.291 ms 	14643

net.jini.core.constraint.ArraySet.iterator()

	0.00% 	16.009 ms 	14728

net.jini.core.constraint.InvocationConstraints.requirements()

	0.00% 	12.379 ms 	9772

net.jini.jeri.connection.ServerConnectionManager$Inbound.checkConstraints(net.jini.core.constraint.InvocationConstraints)

	0.00% 	11.451 ms 	4881

net.jini.jeri.tcp.Constraints.distill(net.jini.core.constraint.InvocationConstraints, boolean)

	0.00% 	11.441 ms 	4881

net.jini.jeri.tcp.TcpServerEndpoint$LH$ServerConnectionImpl.checkConstraints(net.jini.jeri.connection.InboundRequestHandle, net.jini.core.constraint.InvocationConstraints)

	0.00% 	10.047 ms 	4881

au.net.zeus.collection.TimedReferrerDecorator.updateClock(long)

	0.00% 	9.063 ms 	1583

net.jini.core.constraint.ArraySet$Iter.<init>(net.jini.core.constraint.ArraySet)

	0.00% 	7.971 ms 	14706

net.jini.jeri.tcp.Constraints$Distilled.getUnfulfilledConstraints()

	0.00% 	6.438 ms 	4881

au.net.zeus.collection.TimedReferrer.updateClock(long)

	0.00% 	6.159 ms 	1583

net.jini.jeri.BasicInvocationDispatcher.checkAccess(java.rmi.Remote, java.lang.reflect.Method, net.jini.core.constraint.InvocationConstraints, java.util.Collection)

	0.00% 	4.886 ms 	4881

net.jini.io.MarshalInputStream.useCodebaseAnnotations()

	0.00% 	4.091 ms 	4881

net.jini.io.MarshalInputStream$1.<init>(net.jini.io.MarshalInputStream)

	0.00% 	4.03 ms 	4881

net.jini.core.constraint.InvocationConstraints.reduce()

	0.00% 	3.833 ms 	3

au.net.zeus.collection.TimedReferrer.enqueue()

	0.00% 	3.223 ms 	110

net.jini.id.Uuid.readResolve()

	0.00% 	3.172 ms 	3843

org.apache.river.api.net.UriParser.isValidDomainName(String)

	0.00% 	2.722 ms 	88

au.net.zeus.collection.TimedReferrerDecorator.<init>(au.net.zeus.collection.Referrer)

	0.00% 	1.545 ms 	48

au.net.zeus.collection.ReferenceFactory.create(Object, au.net.zeus.collection.RefQueue, au.net.zeus.collection.Ref)

	0.00% 	1.404 ms 	102

au.net.zeus.collection.TimedReferrer.hashCode()

	0.00% 	1.342 ms 	157

au.net.zeus.collection.TimedReferrer.equals(Object)

	0.00% 	1.326 ms 	109

net.jini.core.constraint.InvocationConstraints.<init>(java.util.Collection, java.util.Collection)

	0.00% 	1.13 ms 	3

net.jini.id.Uuid.writeReplace()

	0.00% 	0.948 ms 	676

org.apache.river.api.net.UriParser.isValidHost(boolean, String)

	0.00% 	0.893 ms 	94

au.net.zeus.collection.StrongReference.<init>(Object)

	0.00% 	0.741 ms 	48

au.net.zeus.collection.WeakIdentityReference.equals(Object)

	0.00% 	0.584 ms 	69

au.net.zeus.collection.TimedReferrer.<init>(Object, au.net.zeus.collection.TimedRefQueue)

	0.00% 	0.535 ms 	48

au.net.zeus.collection.AbstractReferrerDecorator.hashCode()

	0.00% 	0.31 ms 	119

net.jini.core.constraint.InvocationConstraints.reduce(int, int)

	0.00% 	0.299 ms 	3

au.net.zeus.collection.StrongReference.<init>(Object, java.lang.ref.ReferenceQueue)

	0.00% 	0.254 ms 	48

net.jini.core.constraint.ArraySet.toArray(Object[])

	0.00% 	0.241 ms 	6

au.net.zeus.collection.TimedComparableReferrerDecorator.<init>(au.net.zeus.collection.Referrer)

	0.00% 	0.237 ms 	45

au.net.zeus.collection.AbstractReferrerDecorator.<init>()

	0.00% 	0.181 ms 	96

au.net.zeus.collection.AbstractReferrerDecorator.equals(Object)

	0.00% 	0.139 ms 	4

net.jini.core.constraint.InvocationConstraints.hashCode()

	0.00% 	0.134 ms 	1

au.net.zeus.collection.StrongReference.hashCode()

	0.00% 	0.097 ms 	1

org.apache.river.api.net.URLClassLoader$UriCodeSource.equals(Object)

	0.00% 	0.076 ms 	10

net.jini.core.constraint.ArraySet.size()

	0.00% 	0.076 ms 	10

net.jini.core.constraint.InvocationConstraints.setRelative(net.jini.core.constraint.InvocationConstraint[], int)

	0.00% 	0.046 ms 	6

net.jini.core.constraint.Constraint.trim(Object[], int)

	0.00% 	0.043 ms 	6

net.jini.core.constraint.Constraint.hash(Object[])

	0.00% 	0.026 ms 	2

net.jini.core.lookup.ServiceID.equals(Object)

	0.00% 	0.012 ms 	4

net.jini.core.lookup.ServiceID.hashCode()

	0.00% 	0.0060 ms 	2