You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@cxf.apache.org by Richard Plana <Ri...@enabil.com> on 2011/07/01 05:47:24 UTC
Long-Running Client Call
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]