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. 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();
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
