Hi,
I have a web service call that's taking 7 minutes for CXF to process
(client-side). In the logs below, I'm seeing that once the response comes back
to CXF, it goes through its usual process and spends six (6) minutes in
"Invoking handleMessage on interceptor
org.apache.cxf.binding.soap.interceptor.RPCInInterceptor@e754aa" before
continuing on to " Invoking handleMessage on interceptor
org.apache.cxf.binding.soap.interceptor.SoapHeaderInterceptor@1679cc1" (See the
logs at 2011-06-30 21:22:53,820 below).
Granted that the response XML is nearly 2MB long (XML), is there any way to
speed up this processing?
--
Richard Plana
LOGS:
2011-06-30 21:20:49,316 [btpool0-3] DEBUG
org.apache.cxf.transport.http.HTTPConduit.makeTrustDecision(HTTPConduit.java:770)
null - No Trust Decider for Conduit
'{http://webservices.aurora.enabil.com}AuroraCustCarePort.http-conduit'. An
afirmative Trust Decision is assumed.
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:2230)
null - Response Code: 200 Conduit:
{http://webservices.aurora.enabil.com}AuroraCustCarePort.http-conduit
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:2233)
null - Content length: -1
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:2246)
null - Header fields:
X-Powered-By: [Servlet/2.4 JSP/2.0]
null: [HTTP/1.1 200 OK]
Date: [Fri, 01 Jul 2011 03:20:49 GMT]
SOAPAction: [""]
Content-Type: [text/xml; charset="utf-8"]
Transfer-Encoding: [chunked]
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.endpoint.ClientImpl.onMessage(ClientImpl.java:677) null -
Interceptors contributed by bus:
[org.apache.cxf.ws.policy.PolicyInInterceptor@64eee0]
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.endpoint.ClientImpl.onMessage(ClientImpl.java:681) null -
Interceptors contributed by client: []
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.endpoint.ClientImpl.onMessage(ClientImpl.java:685) null -
Interceptors contributed by endpoint:
[org.apache.cxf.jaxws.interceptors.WrapperClassInInterceptor@7ebd8f,
org.apache.cxf.jaxws.interceptors.HolderInInterceptor@cf07f3,
org.apache.cxf.jaxws.interceptors.SwAInInterceptor@13142c]
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.endpoint.ClientImpl.onMessage(ClientImpl.java:689) null -
Interceptors contributed by binding:
[org.apache.cxf.interceptor.AttachmentInInterceptor@917176,
org.apache.cxf.interceptor.StaxInInterceptor@b031a9,
org.apache.cxf.binding.soap.interceptor.SoapActionInInterceptor@18c6f6c,
org.apache.cxf.binding.soap.interceptor.RPCInInterceptor@e754aa,
org.apache.cxf.binding.soap.interceptor.SoapHeaderInterceptor@1679cc1,
org.apache.cxf.binding.soap.interceptor.ReadHeadersInterceptor@1646786,
org.apache.cxf.binding.soap.interceptor.StartBodyInterceptor@c8c164,
org.apache.cxf.binding.soap.interceptor.CheckFaultInterceptor@10b7b8,
org.apache.cxf.binding.soap.interceptor.MustUnderstandInterceptor@18db5fe,
org.apache.cxf.interceptor.URIMappingInterceptor@a75851]
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.endpoint.ClientImpl.onMessage(ClientImpl.java:696) null -
Interceptors contributed by databinging:
[org.apache.cxf.jaxb.attachment.JAXBAttachmentSchemaValidationHack@974df9]
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.outputChainToLog(PhaseInterceptorChain.java:654)
null - Chain org.apache.cxf.phase.PhaseInterceptorChain@95aeb7 was created.
Current flow:
receive [PolicyInInterceptor, AttachmentInInterceptor]
post-stream [StaxInInterceptor]
read [ReadHeadersInterceptor, SoapActionInInterceptor, StartBodyInterceptor]
pre-protocol [MustUnderstandInterceptor]
post-protocol [CheckFaultInterceptor, JAXBAttachmentSchemaValidationHack]
unmarshal [URIMappingInterceptor, RPCInInterceptor, SoapHeaderInterceptor]
post-logical [WrapperClassInInterceptor]
pre-invoke [SwAInInterceptor, HolderInInterceptor]
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:252)
null - Invoking handleMessage on interceptor
org.apache.cxf.ws.policy.PolicyInInterceptor@64eee0
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.add(PhaseInterceptorChain.java:205)
null - Adding interceptor
org.apache.cxf.ws.policy.PolicyVerificationInInterceptor@b702f0 to phase
pre-invoke
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.outputChainToLog(PhaseInterceptorChain.java:652)
null - Chain org.apache.cxf.phase.PhaseInterceptorChain@95aeb7 was modified.
Current flow:
receive [PolicyInInterceptor, AttachmentInInterceptor]
post-stream [StaxInInterceptor]
read [ReadHeadersInterceptor, SoapActionInInterceptor, StartBodyInterceptor]
pre-protocol [MustUnderstandInterceptor]
post-protocol [CheckFaultInterceptor, JAXBAttachmentSchemaValidationHack]
unmarshal [URIMappingInterceptor, RPCInInterceptor, SoapHeaderInterceptor]
post-logical [WrapperClassInInterceptor]
pre-invoke [SwAInInterceptor, HolderInInterceptor,
PolicyVerificationInInterceptor]
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:252)
null - Invoking handleMessage on interceptor
org.apache.cxf.interceptor.AttachmentInInterceptor@917176
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:252)
null - Invoking handleMessage on interceptor
org.apache.cxf.interceptor.StaxInInterceptor@b031a9
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:252)
null - Invoking handleMessage on interceptor
org.apache.cxf.binding.soap.interceptor.ReadHeadersInterceptor@1646786
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:252)
null - Invoking handleMessage on interceptor
org.apache.cxf.binding.soap.interceptor.SoapActionInInterceptor@18c6f6c
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:252)
null - Invoking handleMessage on interceptor
org.apache.cxf.binding.soap.interceptor.StartBodyInterceptor@c8c164
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:252)
null - Invoking handleMessage on interceptor
org.apache.cxf.binding.soap.interceptor.MustUnderstandInterceptor@18db5fe
2011-06-30 21:22:53,805 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:252)
null - Invoking handleMessage on interceptor
org.apache.cxf.binding.soap.interceptor.CheckFaultInterceptor@10b7b8
2011-06-30 21:22:53,820 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:252)
null - Invoking handleMessage on interceptor
org.apache.cxf.jaxb.attachment.JAXBAttachmentSchemaValidationHack@974df9
2011-06-30 21:22:53,820 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:252)
null - Invoking handleMessage on interceptor
org.apache.cxf.interceptor.URIMappingInterceptor@a75851
2011-06-30 21:22:53,820 [btpool0-3] DEBUG
org.apache.cxf.interceptor.URIMappingInterceptor.handleMessage(URIMappingInterceptor.java:68)
null - Invoking HTTP method null
2011-06-30 21:22:53,820 [btpool0-3] DEBUG
org.apache.cxf.interceptor.URIMappingInterceptor.handleMessage(URIMappingInterceptor.java:72)
null - URIMappingInterceptor can only handle HTTP GET, not HTTP null
2011-06-30 21:22:53,820 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:252)
null - Invoking handleMessage on interceptor
org.apache.cxf.binding.soap.interceptor.RPCInInterceptor@e754aa
2011-06-30 21:29:02,082 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:252)
null - Invoking handleMessage on interceptor
org.apache.cxf.binding.soap.interceptor.SoapHeaderInterceptor@1679cc1
2011-06-30 21:29:02,082 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:252)
null - Invoking handleMessage on interceptor
org.apache.cxf.jaxws.interceptors.WrapperClassInInterceptor@7ebd8f
2011-06-30 21:29:02,082 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:252)
null - Invoking handleMessage on interceptor
org.apache.cxf.jaxws.interceptors.SwAInInterceptor@13142c
2011-06-30 21:29:02,082 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:252)
null - Invoking handleMessage on interceptor
org.apache.cxf.jaxws.interceptors.HolderInInterceptor@cf07f3
2011-06-30 21:29:02,082 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:252)
null - Invoking handleMessage on interceptor
org.apache.cxf.ws.policy.PolicyVerificationInInterceptor@b702f0
2011-06-30 21:29:02,082 [btpool0-3] DEBUG
org.apache.cxf.ws.policy.PolicyVerificationInInterceptor.handle(PolicyVerificationInInterceptor.java:111)
null - Verified policies for inbound message.
2011-06-30 21:29:02,082 [btpool0-3] DEBUG
org.apache.cxf.endpoint.ClientImpl.processResult(ClientImpl.java:595) null -
set responseContext to be{org.apache.cxf.message.Message.RESPONSE_CODE=200,
org.apache.cxf.service.model.MessageInfo=[MessageInfo OUTPUT:
{http://webservices.aurora.enabil.com}getAddOnDealsResponse],
org.apache.cxf.headers.Header.list=[],
org.apache.cxf.ws.policy.AssertionInfoMap={},
org.apache.cxf.message.Message.ENCODING=UTF-8, Content-Type=text/xml;
charset="utf-8", org.apache.cxf.client=true,
org.apache.cxf.message.inbound=true,
org.apache.cxf.message.Message.PROTOCOL_HEADERS={X-Powered-By=[Servlet/2.4
JSP/2.0], SOAPAction=[""], Date=[Fri, 01 Jul 2011 03:20:49 GMT],
transfer-encoding=[chunked], content-type=[text/xml; charset="utf-8"]}}
2011-06-30 21:29:02,082 [btpool0-3] DEBUG
com.enabil.vega.gwt.server.service.VegaBRMDataServiceImpl.getAddOns(VegaBRMDataServiceImpl.java:311)
null - getAddOnDeals W/S elapsed time: 492781 msecs
2011-06-30 21:29:02,098 [btpool0-3] DEBUG
com.enabil.vega.gwt.server.service.VegaBRMDataServiceImpl.getAddOns(VegaBRMDataServiceImpl.java:329)
null - importAddOnDeals elapsed time: 16 msecs
2011-06-30 21:29:02,098 [btpool0-3] DEBUG
com.enabil.vega.gwt.server.service.VegaBRMDataServiceImpl.fetchAllData(VegaBRMDataServiceImpl.java:118)
null - Get AddOns elapsed time: 492797
2011-06-30 21:29:02,098 [btpool0-3] DEBUG
com.enabil.vega.gwt.server.service.VegaBRMDataServiceImpl.getRatePlans(VegaBRMDataServiceImpl.java:394)
null - getRatePlans called for user: vroot.0.0.0.9
2011-06-30 21:29:02,098 [btpool0-3] DEBUG
org.apache.cxf.endpoint.ClientImpl.invoke(ClientImpl.java:477) null - Invoke,
operation info: [BindingOperationInfo:
{http://webservices.aurora.enabil.com}getRatePlans], params:
[com.enabil.aurorawebsvc.custcare.inquiry.GetRatePlansReq@1cd4b11]
2011-06-30 21:29:02,098 [btpool0-3] DEBUG
org.apache.cxf.endpoint.ClientImpl.setContext(ClientImpl.java:630) null - set
requestContext to message be{java.lang.reflect.Method=public abstract
com.enabil.aurorawebsvc.custcare.inquiry.GetRatePlansResponse
com.enabil.aurora.webservices.AuroraCustCare.getRatePlans(com.enabil.aurorawebsvc.custcare.inquiry.GetRatePlansReq)
throws com.enabil.aurora.webservices.GetRatePlansFault,
org.apache.cxf.message.Message.ENDPOINT_ADDRESS=http://easaut11z01:50401/aurorawebsvc_custcare/Aurora,
org.apache.cxf.jaxws.context.WrappedMessageContext.SCOPES={org.apache.cxf.message.Message.ENDPOINT_ADDRESS=APPLICATION}}
2011-06-30 21:29:02,113 [btpool0-3] DEBUG
org.apache.cxf.endpoint.ClientImpl.setupInterceptorChain(ClientImpl.java:890)
null - Interceptors contributed by bus:
[org.apache.cxf.ws.policy.PolicyOutInterceptor@10909bc]
2011-06-30 21:29:02,113 [btpool0-3] DEBUG
org.apache.cxf.endpoint.ClientImpl.setupInterceptorChain(ClientImpl.java:894)
null - Interceptors contributed by client: []
2011-06-30 21:29:02,113 [btpool0-3] DEBUG
org.apache.cxf.endpoint.ClientImpl.setupInterceptorChain(ClientImpl.java:898)
null - Interceptors contributed by endpoint:
[org.apache.cxf.interceptor.MessageSenderInterceptor@5e1b4c,
org.apache.cxf.jaxws.interceptors.SwAOutInterceptor@525b64,
org.apache.cxf.jaxws.interceptors.WrapperClassOutInterceptor@ee2d7b,
org.apache.cxf.jaxws.interceptors.HolderOutInterceptor@ec1d15]
2011-06-30 21:29:02,113 [btpool0-3] DEBUG
org.apache.cxf.endpoint.ClientImpl.setupInterceptorChain(ClientImpl.java:902)
null - Interceptors contributed by binding:
[org.apache.cxf.interceptor.AttachmentOutInterceptor@1696beb,
org.apache.cxf.interceptor.StaxOutInterceptor@2c444a,
org.apache.cxf.binding.soap.interceptor.SoapHeaderOutFilterInterceptor@3765bf,
org.apache.cxf.binding.soap.interceptor.RPCOutInterceptor@f9161a,
org.apache.cxf.binding.soap.interceptor.SoapPreProtocolOutInterceptor@11a19f9,
org.apache.cxf.binding.soap.interceptor.SoapOutInterceptor@9f688c]
2011-06-30 21:29:02,113 [btpool0-3] DEBUG
org.apache.cxf.endpoint.ClientImpl.setupInterceptorChain(ClientImpl.java:908)
null - Interceptors contributed by databinding: []
2011-06-30 21:29:02,113 [btpool0-3] DEBUG
org.apache.cxf.phase.PhaseInterceptorChain.outputChainToLog(PhaseInterceptorChain.java:654)
null - Chain org.apache.cxf.phase.PhaseInterceptorChain@fb554c was created.
Current flow:
setup [PolicyOutInterceptor]
pre-logical [HolderOutInterceptor, SwAOutInterceptor,
WrapperClassOutInterceptor, SoapHeaderOutFilterInterceptor]
post-logical [SoapPreProtocolOutInterceptor]
prepare-send [MessageSenderInterceptor]
pre-stream [AttachmentOutInterceptor, StaxOutInterceptor]
write [SoapOutInterceptor]
marshal [RPCOutInterceptor]
