Details
-
Sub-task
-
Resolution: Other
-
P2
-
None
-
None
Description
The purpose of this task is to evaluate the profiling results of running the SPECjEnterprise performance benchmark against the Web Logic Server, and with and without the SecurityManager enabled. Profiling was done with the Oracle Studio profiler.
Environment
------------------
* WLS 1221141208 (12.2.1)
* JDK 1.8.0_40b17
* Linux 2.6.32-100.26.2.e15
* SPECjEnterprise 2010
About the Benchmark
--------------------------------
(quoting from https://www.spec.org/jEnterprise2010/):
"The SPECjEnterprise2010 benchmark is a full system benchmark which allows performance measurement and characterization of Java EE 5.0 servers and supporting infrastructure such as JVM, Database, CPU, disk and servers.
The workload consists of an end to end web based order processing domain, an RMI and Web Services driven manufacturing domain and a supply chain model utilizing document based Web Services. The application is a collection of Java classes, Java Servlets, Java Server Pages , Enterprise Java Beans, Java Persistence Entities (pojo's) and Message Driven Beans."
Response Time Differences
----------------------------------------
SecMgr(-) SecMgr (+)
-------------- -----------------
Avg 0.0261 0.0281 (-7.66%)
90th 0.048 0.050 (-4.17%)
CPU 69.5 72 (-3.60%)
Note: see evaluation section for an issue subsequently discovered with the configuration.
Profiling Results
------------------------
Attached are the results of running the benchmark with and without a SecurityManager, and a comparison. There is one notable oddity. For some unexplained reason, the total CPU time when running without an SM was 553.780 seconds, while with an SM it was 7411.080 seconds, even though the total runtime of both was the same. When looking at the comparison file, you need to evaluate the results with that ratio in mind, in other words, look for comparative results that are greater than 13.38%.
* NoSM.html: list of methods called by WLS without a SecurityManager, sorted by CPU time
* SM.html: list of methods called by WLS with a SecurityManager, sorted by CPU time
* Comparison.html - a comparison of methods called by WLS with and without a SecurityManager. NOTE! - the comparison table is not always accurate. For example, row 10 allocates 0 seconds to HashMap.getNode when run w/o a SM, but this is not correct, it is 4.9 seconds according to the profile. Always cross-check the comparison table with the actual results.
Inclusive for any metric refers to the metric value in that function or method, including metrics accumulated in all the functions or methods that it calls. Exclusive refers only to the metric accumulated within that function or method.
Evaluation
---------------
Here is an evaluation of the three top hot spots. A major issue was later discovered in the configuration in that AllPermission was granted to all code (see the end of the attached weblogic.policy). This means that there was very little time spent evaluating permissions, which is known to be a hot spot in other tests. I hope to go back and re-run the benchmark with a better policy.
1. sun.reflect.Reflection.getCallerClass()
Exclusive CPU Time (with SM): 2.1%
Inclusive CPU Time (with SM): 2.14%
Exclusive CPU Time (w/o SM): 0.05%
Inclusive CPU Time (w/o SM): 0.05%
Most of these are called by Class.newInstance(), which is called by weblogic.utils.wrapper.WrapperFactory.createWrapper. getCallerClass is a native method, so it is relatively expensive. Class.newInstance checks the caller class to see if a package access check can be skipped when an SM is enabled.
Possible Solutions
- Change Weblogic WrapperFactory to not use reflection.
- https://bugs.openjdk.java.net/browse/JDK-8020968 : Provide a replacement for sun.reflect.Reflection.getCallerClass
2. java.security.AccessController.getStackAccessControlContext()
Exclusive CPU Time (with SM): 0.39%
Inclusive CPU Time (with SM): 0.40%
Excl/Incl CPU Time (w/o SM): 0%
Called by java.io.ObjectStreamClass.forClass(). Native method. Expensive.
Possible Solutions: http://openjdk.java.net/jeps/8043814 (postponed to JDK 10).
3. java.lang.SecurityManager.checkPackageAccess
Exclusive CPU Time (with SM): 0.08%
Inclusive CPU Time (with SM): 0.34%
Excl/Incl CPU Time (w/o SM): 0%
Possible solutions:
- Several optimizations will be made to checkPackageAccess to speed it up. See https://bugs.openjdk.java.net/browse/JDK-8072692
- Additional optimizations may be possible with modules, see https://bugs.openjdk.java.net/browse/JDK-8055206
-----------------------------------------------------------------------
There are 12 code paths that call System.getSecurityManager(). Here is an evaluation of each:
1. java.lang.ClassLoader.getParent()
Incl CPU Time (with SM): 0.08%
Incl CPU Time (w/o SM): N/A (never called)
Not a major hot spot, but cost is associated with checking for classloader permission, so pretty much unavoidable.
2. java.lang.Class.getClassLoader()
Incl CPU Time (with SM): 0.06%
Incl CPU Time (w/o SM): 0.03
Not a major hot spot, but cost is associated with checking for classloader permission, so pretty much unavoidable.
3. java.lang.ClassLoader.checkClassLoaderPermission()
Incl CPU Time (with SM): 0.06%
Incl CPU Time (w/o SM): N/A (never called)
See 1 and 2 above.
4. java.io.ObjectStreamClass.forClass()
Incl CPU Time (with SM): 0.30%
Incl CPU Time (w/o SM): 0.01
Most of the cost is associated with calling Reflection.getCallerClass, see analysis in first section above.
5. java.lang.Class.newInstance()
Incl CPU Time (with SM): 2.29%
Incl CPU Time (w/o SM): 0.19
Most of the cost is associated with calling Reflection.getCallerClass, see analysis in first section above.
6. java.lang.Class.checkPackageAccess()
Incl CPU Time (with SM): 0.09%
Incl CPU Time (w/o SM): 0.01%
This is a utility method that calls SecurityManager.checkPackageAccess, and will benefit from improvements to that method.
7. java.lang.Class.checkMemberAccess()
Incl CPU Time (with SM): 0.12%
Incl CPU Time (w/o SM): N/A (never called)
This is a utility method that calls SecurityManager.checkPackageAccess, and will benefit from improvements to that method.
8. sun.reflect.misc.ReflectUtils.checkPackageAccess()
Incl CPU Time (with SM): 0.39%
Incl CPU Time (w/o SM): 0.01
A slight improvement has been made not to call String.replace unless necessary, but otherwise this is a utility method that calls SecurityManager.checkPackageAccess, and will benefit from improvements to that method.
9. java.io.ObjectInputStream.verifySubclass()
Incl CPU Time (with SM): 0.0%
Incl CPU Time (w/o SM): N/A (never called)
Not a hot spot.
10. java.io.ObjectOutputStream.verifySubclass()
Incl CPU Time (with SM): 0.00%
Incl CPU Time (w/o SM): N/A (never called)
Not a hot spot.
11. java.io.ObjectStreamField.getType()
Incl CPU Time (with SM): 0.00%
Incl CPU Time (w/o SM): 0.00%
Not a hot spot.
12. System.getProperty()
Incl CPU Time (with SM): 0.06%
Incl CPU Time (w/o SM): 0.01
Caching of properties could be done at WLS layer to avoid retrieving same property multiple times.
Environment
------------------
* WLS 1221141208 (12.2.1)
* JDK 1.8.0_40b17
* Linux 2.6.32-100.26.2.e15
* SPECjEnterprise 2010
About the Benchmark
--------------------------------
(quoting from https://www.spec.org/jEnterprise2010/):
"The SPECjEnterprise2010 benchmark is a full system benchmark which allows performance measurement and characterization of Java EE 5.0 servers and supporting infrastructure such as JVM, Database, CPU, disk and servers.
The workload consists of an end to end web based order processing domain, an RMI and Web Services driven manufacturing domain and a supply chain model utilizing document based Web Services. The application is a collection of Java classes, Java Servlets, Java Server Pages , Enterprise Java Beans, Java Persistence Entities (pojo's) and Message Driven Beans."
Response Time Differences
----------------------------------------
SecMgr(-) SecMgr (+)
-------------- -----------------
Avg 0.0261 0.0281 (-7.66%)
90th 0.048 0.050 (-4.17%)
CPU 69.5 72 (-3.60%)
Note: see evaluation section for an issue subsequently discovered with the configuration.
Profiling Results
------------------------
Attached are the results of running the benchmark with and without a SecurityManager, and a comparison. There is one notable oddity. For some unexplained reason, the total CPU time when running without an SM was 553.780 seconds, while with an SM it was 7411.080 seconds, even though the total runtime of both was the same. When looking at the comparison file, you need to evaluate the results with that ratio in mind, in other words, look for comparative results that are greater than 13.38%.
* NoSM.html: list of methods called by WLS without a SecurityManager, sorted by CPU time
* SM.html: list of methods called by WLS with a SecurityManager, sorted by CPU time
* Comparison.html - a comparison of methods called by WLS with and without a SecurityManager. NOTE! - the comparison table is not always accurate. For example, row 10 allocates 0 seconds to HashMap.getNode when run w/o a SM, but this is not correct, it is 4.9 seconds according to the profile. Always cross-check the comparison table with the actual results.
Inclusive for any metric refers to the metric value in that function or method, including metrics accumulated in all the functions or methods that it calls. Exclusive refers only to the metric accumulated within that function or method.
Evaluation
---------------
Here is an evaluation of the three top hot spots. A major issue was later discovered in the configuration in that AllPermission was granted to all code (see the end of the attached weblogic.policy). This means that there was very little time spent evaluating permissions, which is known to be a hot spot in other tests. I hope to go back and re-run the benchmark with a better policy.
1. sun.reflect.Reflection.getCallerClass()
Exclusive CPU Time (with SM): 2.1%
Inclusive CPU Time (with SM): 2.14%
Exclusive CPU Time (w/o SM): 0.05%
Inclusive CPU Time (w/o SM): 0.05%
Most of these are called by Class.newInstance(), which is called by weblogic.utils.wrapper.WrapperFactory.createWrapper. getCallerClass is a native method, so it is relatively expensive. Class.newInstance checks the caller class to see if a package access check can be skipped when an SM is enabled.
Possible Solutions
- Change Weblogic WrapperFactory to not use reflection.
- https://bugs.openjdk.java.net/browse/JDK-8020968 : Provide a replacement for sun.reflect.Reflection.getCallerClass
2. java.security.AccessController.getStackAccessControlContext()
Exclusive CPU Time (with SM): 0.39%
Inclusive CPU Time (with SM): 0.40%
Excl/Incl CPU Time (w/o SM): 0%
Called by java.io.ObjectStreamClass.forClass(). Native method. Expensive.
Possible Solutions: http://openjdk.java.net/jeps/8043814 (postponed to JDK 10).
3. java.lang.SecurityManager.checkPackageAccess
Exclusive CPU Time (with SM): 0.08%
Inclusive CPU Time (with SM): 0.34%
Excl/Incl CPU Time (w/o SM): 0%
Possible solutions:
- Several optimizations will be made to checkPackageAccess to speed it up. See https://bugs.openjdk.java.net/browse/JDK-8072692
- Additional optimizations may be possible with modules, see https://bugs.openjdk.java.net/browse/JDK-8055206
-----------------------------------------------------------------------
There are 12 code paths that call System.getSecurityManager(). Here is an evaluation of each:
1. java.lang.ClassLoader.getParent()
Incl CPU Time (with SM): 0.08%
Incl CPU Time (w/o SM): N/A (never called)
Not a major hot spot, but cost is associated with checking for classloader permission, so pretty much unavoidable.
2. java.lang.Class.getClassLoader()
Incl CPU Time (with SM): 0.06%
Incl CPU Time (w/o SM): 0.03
Not a major hot spot, but cost is associated with checking for classloader permission, so pretty much unavoidable.
3. java.lang.ClassLoader.checkClassLoaderPermission()
Incl CPU Time (with SM): 0.06%
Incl CPU Time (w/o SM): N/A (never called)
See 1 and 2 above.
4. java.io.ObjectStreamClass.forClass()
Incl CPU Time (with SM): 0.30%
Incl CPU Time (w/o SM): 0.01
Most of the cost is associated with calling Reflection.getCallerClass, see analysis in first section above.
5. java.lang.Class.newInstance()
Incl CPU Time (with SM): 2.29%
Incl CPU Time (w/o SM): 0.19
Most of the cost is associated with calling Reflection.getCallerClass, see analysis in first section above.
6. java.lang.Class.checkPackageAccess()
Incl CPU Time (with SM): 0.09%
Incl CPU Time (w/o SM): 0.01%
This is a utility method that calls SecurityManager.checkPackageAccess, and will benefit from improvements to that method.
7. java.lang.Class.checkMemberAccess()
Incl CPU Time (with SM): 0.12%
Incl CPU Time (w/o SM): N/A (never called)
This is a utility method that calls SecurityManager.checkPackageAccess, and will benefit from improvements to that method.
8. sun.reflect.misc.ReflectUtils.checkPackageAccess()
Incl CPU Time (with SM): 0.39%
Incl CPU Time (w/o SM): 0.01
A slight improvement has been made not to call String.replace unless necessary, but otherwise this is a utility method that calls SecurityManager.checkPackageAccess, and will benefit from improvements to that method.
9. java.io.ObjectInputStream.verifySubclass()
Incl CPU Time (with SM): 0.0%
Incl CPU Time (w/o SM): N/A (never called)
Not a hot spot.
10. java.io.ObjectOutputStream.verifySubclass()
Incl CPU Time (with SM): 0.00%
Incl CPU Time (w/o SM): N/A (never called)
Not a hot spot.
11. java.io.ObjectStreamField.getType()
Incl CPU Time (with SM): 0.00%
Incl CPU Time (w/o SM): 0.00%
Not a hot spot.
12. System.getProperty()
Incl CPU Time (with SM): 0.06%
Incl CPU Time (w/o SM): 0.01
Caching of properties could be done at WLS layer to avoid retrieving same property multiple times.