Just a quick FYI: I've now fixed (on trunk) the areas identified in this email trail.
1) avoid element.setAttributeNS. Creating an Attr node and calling setAttributeNodeNS is actually a LOT faster. 2) I updated the context mapping to map things on demand (and I've run the TCK to verify it works). Thus, if you don't use a WebServiceContext, there is very little overhead now. 3) I've updated the PhaseInterceptorChain to get the logging level at the beginning. In anycase, thanks for the Analysis and graphs and such. Every little bit helps. :-) Dan On Thursday 17 July 2008 10:48:45 am Daniel Kulp wrote: > On Jul 17, 2008, at 10:10 AM, David Soroko wrote: > > Hello all > > I apologise for cross posting, but I was not getting much traction in > > the users-list and I do think that my question is worth asking and > > answering. > > Doesn't really matter, although I do disagree with Glen on this. This > really is a "dev" thing, not a users thing so it does belong here. > > That said, the person that has done the most work in JProfiler > (Benson) is on vacation right now. I've never used it. > > (That said, CXF does have license keys for project use. If any of > the committers wants to jump in here, send a note to [EMAIL PROTECTED] > and we can give you the key) > > > Here is what I have so far: > > > > Hello Daniel > > > > I had another profiling session and this time saved the snapshot so we > > can have a fixed point of reference. I am using JProfiler with CPU > > measurement set to "Elapsed time", which according to the > > documentation > > should ignore time spent while waiting or blocking. > > > > > > > > This time I have: > > > > > > > > 74.1% PhaseInterceptorChain.doIntercept() > > > > 30.5% OutgoingChainInterceptor.handleMessage > > > > 21.3% ReadHeadersInterceptor.handleMessage > > > > 7.3% DocLiteralInInterceptor.handleMessage > > > > 5.3% ServiceInvokerInterceptor.handleMessage > > > > > > > > Regarding ReadHeadersInterceptor.handleMessage. See image at: > > http://drop.io/pul3us5/asset/readheadersinterceptor > > Interesting. Definitely something to dig into. My first "WTF?" > moment was the 18.6% spent in StaxUtils.declare, most of which is in > xerces setAttributeNS call. Looking at that code in xerces, we > probably do want to avoid it. When you see comments like: > > // REVISIT: this is not efficient, we are creating twice the same > // strings for prefix and localName. > > it might be best to try something else. Most likely, we can do: > element > .setAttributeNode(element.getOwnerDocument().createAttributeNS(....)); > > Defintely a bunch of things to dig into there. Just need some time to > do it. > > > (The stack trace was re-rooted for display purposes to and that is why > > it is at 100%) > > > > It seems that most of the time is spent in xerces and wstx but what is > > it they do? > > Well, wstx is the XML Parser. It has do do all the UTF-8 decoding, > parsing the XML stuff into events, etc... Woodstox is one of the > fastest XML parsers around and is definitely the best option for > that. Unfortunately, XML is very verbose and is not exactly cheap to > parse. (BTW: you could enable the fastinfoset feature which would > flip to a binary XML which is faster for parsing) > > Xerces is the DOM that we are parsing into. We only parse PART of > the soap message into the dom (just the soap:headers for the most > part). The rest are parsed directly into JAXB objects (or whatever > your choice is for databinding). Thus, the DOM stuff should be a > "small part". That is why the setAttributeNS stuff just "jumps out" > at me. :-( > > > Regarding DocLiteralInInterceptor.handleMessage. See image at: > > http://drop.io/pul3us5/asset/docliteralininterceptor > > > > Most work seems to be JAXB related. > > Yep. If you plugin the SXC runtime (sxc.codehaus.org), this can go > down significantly. > > > Regarding ServiceInvokerInterceptor.handleMessage. Here the actual > > business logic is invoked. This reflective invocation takes up 3% of > > the > > total of ServiceInvokerInterceptor.handleMessage. Not sure what the > > rest > > is. Snapshot image is here: > > > > http://drop.io/pul3us5/asset/serviceinvokerinterceptor > > The context mapping. Was afraid of that. That's been on my "to > do" list to rewrite for a while. :-( I know what the issue is and > how to fix it, I just need some time to do it. Basically, up > front, we current map all the CXF "keys" into JAX-WS keys (and back at > the end of invoke). We do this all the time even if the service > doesn't use a context. I want to rewrite this to override the get/ > set calls to do the mapping during the get/set call. Thus, the > expense only occurs specifically for the keys you use and ONLY for > that. The normal cases would be fast. > > > Regarding OutgoingChainInterceptor.handleMessage. An image is here: > > http://drop.io/pul3us5/asset/outgoingchaininterceptor > > > > Would you say that 30% of the CPU is about the right slice size of the > > cake for CXF to take? > > Probably. This is the reverse of the stuff coming in. Basically, > jaxb needs to write stuff (which involves a bunch of relflection > unless you use sxc), woodstox needs to encode to UTF-8, streams need > to be flushed, etc.... That said, there are things that jump out > there as well. The 4.2% and 75,680 calls to Logger.isLoggable is not > a good sign. Most likely we should call that at the beginning of the > doIntercept method and store it in a boolean. > > Dan > > > Thanks > > > > > > > > -- david > > > > > > > > > > > > > > > > -----Original Message----- > > > > From: Daniel Kulp [mailto:[EMAIL PROTECTED] > > > > Sent: 15 July 2008 23:16 > > > > To: [EMAIL PROTECTED] > > > > Subject: Re: A CXF 2.1 CPU consumption question > > > > On Jul 11, 2008, at 10:18 AM, David Soroko wrote: > >> Hi all > >> > >> > >> > >> We are now in profiling stages of some CXF 2.1 based web services. In > >> > >> all our services we observe that most of the CPU time is not > >> > >> consumed by > >> > >> the service logic itself but by CXF. I attach a picture (worth 1000 > >> > >> words) of a JProfiler snapshot. In the snapshot we see the > >> > >> PhaseInterceptorChain.doIntercept() taking 78.4% of the CPU which is > >> > >> fine as this includes the eventual service logic execution. What > >> > >> happens > >> > >> next is a bit strange, here is the ASCII art rendering: > >> > >> > >> > >> 78.4% PhaseInterceptorChain.doIntercept() > >> > >> 26.4% OutgoingChainInterceptor.handleMessage > > > > This makes complete sense. The OutgoingChainInterceptor sets up the > > > > outgoing chain and invokes it. Thus, this number would include ALL > > > > of the work required to send the response including the JAXB > > > > marshalling, flushing the streams, etc.... > > > >> 20.0% ServiceInvokerInterceptor.handleMessage > >> > >> 16.9% ReadHeadersInterceptor.handleMessage > >> > >> > >> > >> > >> > >> The call to ServiceInvokerInterceptor.handleMessage() ends up calling > >> > >> the actual service logic which takes about 5% of the CPU time so, the > >> > >> extra 15% penalty seems to excessive, > > > > That's really not good. Any chance you can dig into that one a bit > > > > furthur? > > > >> what's even more worrying are the > >> > >> other two handleMessage calls (OutgoingChainInterceptor and > >> > >> ReadHeadersInterceptor) that gobble up together more then 40% of the > >> > >> CPU. > > > > ReadHeadersInteceptor is the first interceptor that actual reads stuff > > > > off the wire. Question: is it actually measuring CPU usage or just a > > > > "nanosecond count" or something. (raw time) Normally, this is where > > > > it would pause waiting for the message to come off the network. > > > > Everytime I see a large number hear, it's not really using the CPU, > > > > it's actually down in the ServletInputStream waiting for data from the > > > > socket. > > > > > > > > > > > > Dan > > > >> Note that we have no custom interceptors defined, our configuration > >> > >> looks like this: > >> > >> > >> > >> > >> > >> <import resource="classpath:META-INF/cxf/cxf.xml"/> > >> > >> <import resource="classpath:META-INF/cxf/cxf-servlet.xml"/> > >> > >> <import resource="classpath:META-INF/cxf/cxf-extension-soap.xml"/> > >> > >> > >> > >> <bean id="cxf" class="org.apache.cxf.bus.CXFBusImpl"> > >> > >> > >> > >> <jaxws:endpoint id="SomeServiceEndpoint" > >> > >> address="/SomeService" > >> > >> implementor="#someService" > >> > >> > >> > >> implementorClass > >> > >> ="com.betfair.services.someservice.SomeServiceServiceImp > >> > >> l"> > >> > >> > >> > >> > >> > >> > >> > >> Is this behaviour expected in a properly configured system? > >> > >> > >> > >> Thanks > >> > >> > >> > >> -- david > > > > ________________________________________________________________________ > > In order to protect our email recipients, Betfair Group use SkyScan > > from > > MessageLabs to scan all Incoming and Outgoing mail for viruses. > > > > ________________________________________________________________________ > > --- > Daniel Kulp > [EMAIL PROTECTED] > http://www.dankulp.com/blog -- Daniel Kulp [EMAIL PROTECTED] http://www.dankulp.com/blog
