On Jul 3, 2008, at 2:12 PM, Gary Weaver wrote:
Hey,
Just wanted to share this info for anyone interested.
I noticed that one of my integration tests (the first one) was
taking a few seconds longer than expected to call a service using
Apache CXF v2.1.1 (using the client autogenerated by CXF using the
maven plugin that uses wsdl2java).
At first I was worried that it was something I had done wrong, and I
still wouldn't put that past me :), but I found out the following
about CXF setup time.
The very first call to the service constructor with null argument
(to keeps it from trying to load WSDL, per Dan's previous comment)
takes ~1.3 seconds (~1300 msec). The first call to the service
constructor is the heaviest while it constructs singleton instances,
loads config, etc. (Heavy operations appear to be creating
org.apache.cxf.wsdl.WSDLManager and
org
.springframework.beans.factory.xml.DefaultNamespaceHandlerResolver
loading mappings, but don't hold me to that because I was just
looking at log, not profiling.) All subsequent calls to it take 0
msec.
All of that can be pushed out of the constructor by calling
BusFactory.getDefaultBus() prior to creating your service object.
Basically, when you create the service object, it checks for the
default bus. If it's not there, it creates one. Thus, you can push
the creation of all that earlier. Doesn't change the overall startup
time, but it does allow you to separate that out.
For example:
MyService service = new MyService(null); // service constructor
The very first call to get the port takes ~0.7 seconds (~700 msec).
Subsequent calls still take ~0.3 seconds (~250 msec). Subsequent
calls seem to log that
"org.apache.cxf.service.factory.ReflectionServiceFactoryBean
buildServiceFromClass" is the culprit of this additional time, so it
seems that the use of reflection slows it down (since reflection is
slow). For example:
MyServicePortType portType = service.getMyServicePort();
I added a little bit more caching into the
ReflectionServiceFactoryBean for 2.1.2, but it probably doesn't change
a whole lot. :-( A big culprit of this step is the XmlSchema
library. There is a bit of processing in there that is very slow. I
keep meaning to write and contribute a patch for it, but haven't had a
chance yet. :-(
Dan
If you're interested in which steps take which amount of time in
CXF, you can do this easily by turning on full debugging in
log4j.properties (put in classpath, src/main/resources and/or src/
test/resources for m2 guys) like:
log4j.rootCategory=DEBUG, CONSOLE
log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.CONSOLE.layout.ConversionPattern=%-4r [%t] %-5p %c %x
- %m%n
the %r or %-4r (-4 being padding- see http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/PatternLayout.html
for info) is used to output the number of milliseconds elapsed from
the construction of the layout until the creation of the logging
event, so you can look from line to line and see which steps in the
process take longer, however the reflection call mentioned above is
the only one really impacting things on an ongoing basis if you have
called the service constructor at least once already.
I did this analysis on my dev box:
Model Name: Mac Pro
Processor Name: Dual-Core Intel Xeon
Processor Speed: 2.66 GHz
Number Of Processors: 2
Total Number Of Cores: 4
L2 Cache (per processor): 4 MB
Memory: 2 GB
using Apache CXF v2.1.1 and Java version:
java version "1.5.0_13"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_13-
b05-241)
Java HotSpot(TM) Client VM (build 1.5.0_13-120, mixed mode, sharing)
Sorry if this is just noise, but I found it interesting.
Hope this helps,
--
Gary Weaver
Internet Framework Services
Office of Information Technology
Duke University
---
Daniel Kulp
[EMAIL PROTECTED]
http://www.dankulp.com/blog
