Policy Provider and Extensible RMI Performance.

Peter Firmstone peter.firmstone at zeus.net.au
Wed Jul 16 12:56:46 UTC 2014 

Who said security and RMI had to be performance dogs?

Anyone ever notice it's native code that uses all the CPU?

100% CPU Utilisation
0% monitor
Peak live threads 99

Test run time 2 minutes.

4891 Remote Object Invocations, includes remote code downloading and 
class loading (thread confined).

Hot Spots - Method 	Self time [%] 	Self time 	Self time (CPU)
java.net.SocketInputStream.socketRead0[native]() 	37.509655 
434975.725 ms 	434975.725 ms
java.net.DualStackPlainSocketImpl.accept0[native]() 	25.825586 
299482.984 ms 	299482.984 ms
java.net.TwoStacksPlainDatagramSocketImpl.socketNativeSetOption[native]() 
15.138092 	175546.873 ms 	175546.873 ms
sun.management.ThreadImpl.dumpThreads0[native]() 	9.167401 	106308.549 
ms 	106308.549 ms
java.net.TwoStacksPlainDatagramSocketImpl.peekData[native]() 
7.8661814 	91219.129 ms 	91219.129 ms
java.net.SocketOutputStream.socketWrite0[native]() 	1.8873161 
21886.01 ms 	21886.01 ms


Impact of Security (thread confined PermissionCollection's created on 
demand in optimum order, discarded in CPU cache):

java.security.AccessController.doPrivileged[native]() 	0.2687941 
3117.035 ms 	3117.035 ms
java.security.AccessController.getStackAccessControlContext[native]() 
0.14554662 	1687.812 ms 	1687.812 ms

java.security.AccessControlContext.checkPermission() 	0 	0.0 ms 	0.0 ms
com.sun.jini.start.AggregatePolicyProvider$AggregateSecurityContext.setCCL() 
	0 	0.0 ms 	0.0 ms
org.apache.river.api.security.CombinerSecurityManager$DelegateProtectionDomain.implies() 
	0 	0.0 ms 	0.0 ms
org.apache.river.api.net.RFC3986URLClassLoader.findClassImpl() 	0 	0.0 
ms 	0.0 ms
com.sun.proxy.$Proxy5.prepareAndCommit() 	0 	0.0 ms 	0.0 ms
com.sun.jini.start.AggregatePolicyProvider.getCurrentSubPolicy() 	0 
0.0 ms 	0.0 ms
java.io.ObjectOutputStream.writeProxyDesc() 	0 	0.0 ms 	0.0 ms
java.lang.Class.forName() 	0 	0.0 ms 	0.0 ms
java.security.ProtectionDomain.implies() 	0 	0.0 ms 	0.0 ms
sun.reflect.GeneratedMethodAccessor25.invoke() 	0 	0.0 ms 	0.0 ms
com.sun.jini.start.AggregatePolicyProvider.implies() 	0 	0.0 ms 	0.0 ms
com.sun.jini.start.AggregatePolicyProvider$AggregateSecurityContext.access$500() 
	0 	0.0 ms 	0.0 ms
org.apache.river.api.net.RFC3986URLClassLoader.findClass() 	0 	0.0 ms 
0.0 ms
net.jini.loader.pref.PreferredClassLoader.loadClass() 	0 	0.0 ms 	0.0 ms
java.security.AccessController.getContext() 	0 	0.0 ms 	0.0 ms
java.security.AccessController.doPrivileged() 	0 	0.0 ms 	0.0 ms



Thread confined classloading (1 Thread per child ClassLoader).

java.lang.Class.forName0[native]() 	0.030607257 	354.933 ms 	354.933 ms



ant -f 
C:\\Users\\peter\\Documents\\NetBeansProjects\\peterConcurrentPolicy 
qa.run-tests
qa.run-tests:
qa.james-brown:
Deleting directory 
C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\soul
Created dir: 
C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\soul
Creating 
C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\soul\soul.201407162226006985
qa.run-tests:

-----------------------------------------
CONFIGURATION FILE:

    
C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\src\com\sun\jini\test\resources\qaHarness.prop

-----------------------------------------
SETTING UP THE TEST LIST:

    Adding test: com/sun/jini/test/impl/mahalo/RandomStressTest.td

-----------------------------------------
GENERAL HARNESS CONFIGURATION INFORMATION:

    Date started:
       Wed Jul 16 22:26:08 EST 2014
    Installation directory of the JSK:
       
com.sun.jini.jsk.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy
    Installation directory of the harness:
       
com.sun.jini.qa.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa
    Categories being tested:
       categories=No Categories
-----------------------------------------
ENVIRONMENT PROPERTIES:

    JVM information:
       Java HotSpot(TM) Client VM, 25.0-b70, 32 bit VM mode
       Oracle Corporation
    OS information:
       Windows 7, 6.1, x86

-----------------------------------------
STARTING TO RUN THE TESTS


Running com/sun/jini/test/impl/mahalo/RandomStressTest.td
Time is Wed Jul 16 22:26:08 EST 2014
Starting test in separate process with command:
'C:\Program Files\Java\jdk1.8.0\jre\bin\java' 
-Djava.security.manager=org.apache.river.api.security.CombinerSecurityManager 
-Djava.security.policy=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/policy/defaulttest.policy 
'-Djava.rmi.server.codebase=http://medusa:9082/qa1-share-dl.jar 
http://medusa:9082/qa1-mahalo-dl.jar' -cp 
C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jiniharness.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jinitests.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\jsk-platform.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\jsk-lib.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\high-scale-lib.jar;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib\custard-apple-1.0.3.jar 
-ea -esa '-Djava.ext.dirs=C:\Program 
Files\Java\jdk1.8.0\jre\lib\ext;C:\windows\Sun\Java\lib\ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib-ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib-ext' 
-Dcom.sun.jini.jsk.port=9080 -Dcom.sun.jini.qa.port=9081 
-Dcom.sun.jini.jsk.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy 
-Dcom.sun.jini.qa.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa 
-Dcom.sun.jini.qa.harness.harnessJar=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jiniharness.jar 
-Dcom.sun.jini.qa.harness.testJar=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\jinitests.jar 
-Dcom.sun.jini.qa.harness.runjiniserver=true 
-Dcom.sun.jini.qa.harness.runkitserver=true 
-Djava.security.properties=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/harness/trust/dynamic-policy.properties 
-Dcom.sun.jini.qa.harness.testhosts= 
-Djava.util.logging.config.file=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\src\com\sun\jini\test\resources\qa1.logging 
-Djava.rmi.server.useCodebaseOnly=false 
-Dnet.jini.core.lookup.ServiceRegistrar.portAbitraryIfInUse=true 
-Dcom.sun.jini.test.home=C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa 
-Dcom.sun.jini.test.port=9082 
-Dcom.sun.jini.qa.harness.policies=file:/C:/Users/peter/Documents/NetBeansProjects/peterConcurrentPolicy/qa/src/com/sun/jini/test/resources/jinitest.policy 
'-Djava.ext.dirs=C:\Program 
Files\Java\jdk1.8.0\jre\lib\ext;C:\windows\Sun\Java\lib\ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib-ext;C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib-ext' 
com.sun.jini.qa.harness.MasterTest 
com/sun/jini/test/impl/mahalo/RandomStressTest.td

TIME: 10:26:09 PM

MasterTest.doTest INFO:
============================== CALLING CONSTRUCT() 
==============================

Jul 16, 2014 10:26:09 PM com.sun.jini.tool.ClassServer run
INFO: ClassServer started 
[[C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\], 
port 9081]
MasterTest.doTest INFO:
=============================== CALLING RUN() 
===============================

RandomStressTest.run INFO: RandomStressTest: To repeat the test, note 
down the seed
RandomStressTest.run INFO: RandomStressTest: seed = 1405513570013
RandomStressTest.run INFO: TEST NOT FINISHED UNTIL I SAY DONE
Jul 16, 2014 10:26:10 PM com.sun.jini.tool.ClassServer run
INFO: ClassServer started 
[[C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\qa\lib\], 
port 9082]
Jul 16, 2014 10:26:10 PM com.sun.jini.tool.ClassServer run
INFO: ClassServer started 
[[C:\Users\peter\Documents\NetBeansProjects\peterConcurrentPolicy\lib-dl\], 
port 9080]
NonActGrp-out: Profiler Agent: Waiting for connection on port 5140 
(Protocol version: 13)
NonActGrp-out: Profiler Agent: Established connection with the tool
NonActGrp-out: Profiler Agent: Local accelerated session
NonActGrp-out: java.lang.ClassNotFoundException: 
java/util/LinkedHashMap$KeyIterator
NonActGrp-out:     at java.lang.Class.forName0(Native Method)
NonActGrp-out:     at java.lang.Class.forName(Class.java:259)
NonActGrp-out:     at 
org.netbeans.lib.profiler.server.ProfilerInterface$InitiateProfilingThread.initiateInstrumentation(ProfilerInterface.java:138)
NonActGrp-out:     at 
org.netbeans.lib.profiler.server.ProfilerInterface$InitiateProfilingThread.run(ProfilerInterface.java:100)

TIME: 10:27:36 PM

RandomStressTest.run INFO: Wait about 15 sec.

TIME: 10:27:51 PM

RandomStressTest.run INFO: TEST DONE
MasterTest.doTest INFO:
============================ CALLING TEARDOWN() 
=============================

NonActGrp-out: Profiler Agent: Connection with agent closed
NonActGrp-out: Profiler Agent: Connection with agent closed
NonActGrp-out: Profiler Agent: JNI OnLoad Initializing...
NonActGrp-out: Profiler Agent: JNI OnLoad Initialized successfully
NonActGrp-out: Profiler Agent: 250 classes cached.
Jul 16, 2014 10:27:58 PM com.sun.jini.tool.ClassServer terminate
INFO: ClassServer terminated [port 9081]
Jul 16, 2014 10:27:58 PM com.sun.jini.tool.ClassServer terminate
INFO: ClassServer terminated [port 9081]
Jul 16, 2014 10:27:58 PM com.sun.jini.tool.ClassServer terminate
INFO: ClassServer terminated [port 9082]
Jul 16, 2014 10:27:58 PM com.sun.jini.tool.ClassServer terminate
INFO: ClassServer terminated [port 9082]
Jul 16, 2014 10:27:58 PM com.sun.jini.tool.ClassServer terminate
INFO: ClassServer terminated [port 9080]
Jul 16, 2014 10:27:58 PM com.sun.jini.tool.ClassServer terminate
INFO: ClassServer terminated [port 9080]

TIME: 10:28:03 PM

Test process was destroyed and returned code 0
com/sun/jini/test/impl/mahalo/RandomStressTest.td
Test Passed: OK


-----------------------------------------

SUMMARY =================================

com/sun/jini/test/impl/mahalo/RandomStressTest.td
Test Passed: OK

-----------------------------------------

# of tests started   = 1
# of tests completed = 1
# of tests passed    = 1
# of tests failed    = 0

-----------------------------------------

    Date finished:
       Wed Jul 16 22:28:08 EST 2014
    Time elapsed:
       119 seconds

qa.collect-result:
BUILD SUCCESSFUL (total time: 2 minutes 1 second)

More information about the core-libs-dev mailing list