Performance issues - jbr-listener
hoschi Apr 2, 2008 8:07 AMHi everyone,
I got a "little" problem when invoking services using jbr-listener: every time a service gets invoked using jbr-listener, the request takes three seconds and more until it gets to the first action in the action pipeline.
I've built the following testing scenario:
A client sends a SOAP request to the ESB using XFire. This request gets forwarded to a Webservice on another JBossAS instance (let's call it JB2 - JBoss ESB is not deployed there), the response gets send back to the client.
Long story short: Client <--> ESB <--> External Webservice
When the SOAP request arrives at the first action it just takes some milliseconds until the response of the external webservice is back at the client - however, as stated above, until the request gets to the first action it takes about three seconds - I'm sure you understand that this is simply too much time for using it in a production environment.
What I've tried so far:
-) Blaming XFire - well, it is not XFires fault - the request gets send to the ESB in no time (used tcpmon for recording messages and their timestamps). Additionaly, a direct call to the external webservice results in about 25 calls per second, not 1 call in 3 seconds.
-) Using SOAPClient with a transformer action for SOAP --> Map transformation: well, same problem - three seconds until the request gets to the transformer
-) just print out the message which gets onto the bus using org.jboss.soa.esb.actions.SystemPrintln: same here, 3 seconds
-) Debugging -- well, didn't get far with this - it seems that the lag is caused by jmsMessage = _messageConsumer.receive(millis); in JmsCourier.pickupPayload() -- however, I think the real problem is between keyboard an chair writing the configuration ;)
So, now to the configuration details:
JBoss ESB is deployed on JBoss EAP 4.3.0 (the problem persists when deploying on the standalone version of JBoss ESB)
jboss-esb.xml:
<jbossesb xmlns="http://anonsvn.labs.jboss.com/labs/jbossesb/trunk/product/etc/schemas/xml/jbossesb-1.0.1.xsd" parameterReloadSecs="5"> <providers> <jbr-provider name="JBR-Http" protocol="http" host="localhost"> <jbr-bus busid="Http-1" port="8888" /> </jbr-provider> <jms-provider name="JMS-Provider" connection-factory="ConnectionFactory" jndi-context-factory="org.jnp.interfaces.NamingContextFactory" jndi-URL="localhost"> <jms-bus busid="EchoEsbChannel"> <jms-message-filter dest-type="QUEUE" dest-name="queue/inet_esb_test_echo" /> </jms-bus> </jms-provider> </providers> <services> <service category="EchoEsb" name="EchoForward" description="Simple SOAP Forwarding Example"> <listeners> <jbr-listener name="Http-Gateway" busidref="Http-1" is-gateway="true" maxThreads="1" /> <jms-listener name="JMS-ESBListener" busidref="EchoEsbChannel" maxThreads="1" /> </listeners> <actions mep="RequestResponse"> <action name="forwardAction" class="inet.esb.test.jboss.actions.SOAPForwarder"> <property name="listenerPath" value="EchoWs" /> <property name="forwardUrl" value="http://localhost:8280/EchoWs/EchoWs" /> <property name="portName" value="EchoWsHttpPort" /> <property name="namespace" value="http://inet.esb.test" /> </action> </actions> </service> </services> </jbossesb>
server.log: The first line is from the response of a previous service call - after that, a new request gets send within some milliseconds
2008-04-02 13:27:10,712 DEBUG [org.jboss.soa.esb.listeners.gateway.JBossRemotingGatewayListener] Re turning response [<soap:Envelope xmlns:soap='http://schemas.xmlsoap.org/soap/envelope/' xmlns:xsd=' http://www.w3.org/2001/XMLSchema' xmlns:xsi='http://www.w3.org/2001/XMLSchema-instance'><soap:Body> <ns1:doEchoResponse xmlns:ns1='http://inet.esb.test'><ns1:out>Echo: ECHO2</ns1:out></ns1:doEchoResp onse></soap:Body></soap:Envelope>]. 2008-04-02 13:27:13,899 DEBUG [org.jboss.soa.esb.addressing.eprs.JMSEpr] 'acknowledge-mode' is : AU TO_ACKNOWLEDGE 2008-04-02 13:27:13,899 DEBUG [org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool] Return ing session, poolsize=4, maxsize=20, number of pools=1 2008-04-02 13:27:13,899 DEBUG [org.jboss.internal.soa.esb.couriers.JmsCourier] JMSCourier delivery Mode: 2, peristent:true 2008-04-02 13:27:13,914 DEBUG [org.jboss.soa.esb.notification.jms.DefaultJMSPropertiesSetter] Setti ng outgoing JMSCorreletionID to : 63cf2f61-e1df-4fd2-bcff-5bf11a6af503 2008-04-02 13:27:13,914 DEBUG [org.jboss.soa.esb.notification.jms.DefaultJMSPropertiesSetter] Setti ng outgoing JMSProperty, key : HttpVersion, value : HTTP/1.1 2008-04-02 13:27:13,914 DEBUG [org.jboss.soa.esb.notification.jms.DefaultJMSPropertiesSetter] Setti ng outgoing JMSProperty, key : MethodType, value : POST 2008-04-02 13:27:13,914 DEBUG [org.jboss.soa.esb.notification.jms.DefaultJMSPropertiesSetter] Setti ng outgoing JMSProperty, key : Path, value : /EchoWs 2008-04-02 13:27:13,914 DEBUG [org.jboss.soa.esb.notification.jms.DefaultJMSPropertiesSetter] Setti ng outgoing JMSProperty, key : expect, value : 100-continue 2008-04-02 13:27:13,914 DEBUG [org.jboss.soa.esb.notification.jms.DefaultJMSPropertiesSetter] Setti ng outgoing JMSProperty, key : soapaction, value : "" 2008-04-02 13:27:13,914 DEBUG [org.jboss.soa.esb.notification.jms.DefaultJMSPropertiesSetter] Setti ng outgoing JMSProperty, key : host, value : localhost:8888 2008-04-02 13:27:13,930 DEBUG [org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool] Return ing session, poolsize=4, maxsize=20, number of pools=1 2008-04-02 13:27:13,992 DEBUG [org.jboss.soa.esb.listeners.message.ActionProcessingPipeline] pipeli ne process for message: header: [ To: JMSEpr [ PortReference < <wsa:Address jms://localhost/queue/i net_esb_test_echo/>, <wsa:ReferenceProperties jbossesb:java.naming.factory.initial : org.jnp.interf aces.NamingContextFactory/>, <wsa:ReferenceProperties jbossesb:java.naming.provider.url : localhost />, <wsa:ReferenceProperties jbossesb:destination-type : queue/>, <wsa:ReferenceProperties jbossesb :specification-version : 1.1/>, <wsa:ReferenceProperties jbossesb:connection-factory : ConnectionFa ctory/>, <wsa:ReferenceProperties jbossesb:persistent : true/>, <wsa:ReferenceProperties jbossesb:a cknowledge-mode : 1/> > ] ReplyTo: JMSEpr [ PortReference < <wsa:Address jms://localhost/queue/inet _esb_test_echo_reply/>, <wsa:ReferenceProperties jbossesb:java.naming.provider.url : localhost/>, < wsa:ReferenceProperties jbossesb:java.naming.factory.initial : org.jnp.interfaces.NamingContextFact ory/>, <wsa:ReferenceProperties jbossesb:destination-type : queue/>, <wsa:ReferenceProperties jboss esb:specification-version : 1.1/>, <wsa:ReferenceProperties jbossesb:connection-factory : Connectio nFactory/>, <wsa:ReferenceProperties jbossesb:message-selector : jbossESBresponseUUID='228f572e-d93 0-4834-a2b7-fb7e6d2ac27d'/>, <wsa:ReferenceProperties jbossesb:persistent : true/>, <wsa:ReferenceP roperties jbossesb:acknowledge-mode : 1/>, <wsa:ReferenceProperties jbossesb:type : urn:jboss/esb/e pr/type/jms/> > ] MessageID: ID:JBM-90187 RelatesTo: jms:correlationID#63cf2f61-e1df-4fd2-bcff-5bf1 1a6af503 ] 2008-04-02 13:27:13,992 DEBUG [org.jboss.soa.esb.listeners.message.ActionProcessingPipeline] execut ing processor 0 inet.esb.test.jboss.actions.SOAPForwarder@114b420 header: [ To: JMSEpr [ PortRefere nce < <wsa:Address jms://localhost/queue/inet_esb_test_echo/>, <wsa:ReferenceProperties jbossesb:ja va.naming.factory.initial : org.jnp.interfaces.NamingContextFactory/>, <wsa:ReferenceProperties jbo ssesb:java.naming.provider.url : localhost/>, <wsa:ReferenceProperties jbossesb:destination-type : queue/>, <wsa:ReferenceProperties jbossesb:specification-version : 1.1/>, <wsa:ReferenceProperties jbossesb:connection-factory : ConnectionFactory/>, <wsa:ReferenceProperties jbossesb:persistent : t rue/>, <wsa:ReferenceProperties jbossesb:acknowledge-mode : 1/> > ] ReplyTo: JMSEpr [ PortReference < <wsa:Address jms://localhost/queue/inet_esb_test_echo_reply/>, <wsa:ReferenceProperties jbossesb :java.naming.provider.url : localhost/>, <wsa:ReferenceProperties jbossesb:java.naming.factory.init ial : org.jnp.interfaces.NamingContextFactory/>, <wsa:ReferenceProperties jbossesb:destination-type : queue/>, <wsa:ReferenceProperties jbossesb:specification-version : 1.1/>, <wsa:ReferenceProperti es jbossesb:connection-factory : ConnectionFactory/>, <wsa:ReferenceProperties jbossesb:message-sel ector : jbossESBresponseUUID='228f572e-d930-4834-a2b7-fb7e6d2ac27d'/>, <wsa:ReferenceProperties jbo ssesb:persistent : true/>, <wsa:ReferenceProperties jbossesb:acknowledge-mode : 1/>, <wsa:Reference Properties jbossesb:type : urn:jboss/esb/epr/type/jms/> > ] MessageID: ID:JBM-90187 RelatesTo: jms: correlationID#63cf2f61-e1df-4fd2-bcff-5bf11a6af503 ] 2008-04-02 13:27:13,992 DEBUG [org.jboss.ws.metadata.umdm.EndpointMetaData] Create new config [name =Standard Client,file=META-INF/standard-jaxws-client-config.xml] 2008-04-02 13:27:13,992 DEBUG [org.jboss.ws.metadata.config.JBossWSConfigFactory] getConfig: [name= Standard Client,url=META-INF/standard-jaxws-client-config.xml] 2008-04-02 13:27:13,992 DEBUG [org.jboss.ws.metadata.config.JBossWSConfigFactory] parse: file:/D:/a ppl/aik/Teststellungen/Server/JBoss/jboss-eap-4.3/jboss-as/server/default/deploy/jbossws.sar/META-I NF/standard-jaxws-client-config.xml 2008-04-02 13:27:14,055 DEBUG [org.jboss.ws.metadata.umdm.EndpointMetaData] Configure EndpointMetaD ata 2008-04-02 13:27:14,055 DEBUG [org.jboss.ws.metadata.umdm.EndpointMetaData] Added 0 PRE handlers 2008-04-02 13:27:14,055 DEBUG [org.jboss.ws.metadata.umdm.EndpointMetaData] Added 0 ENDPOINT handle rs 2008-04-02 13:27:14,055 DEBUG [org.jboss.ws.metadata.umdm.EndpointMetaData] Added 0 POST handlers 2008-04-02 13:27:14,055 DEBUG [org.jboss.ws.metadata.umdm.EndpointMetaData] Configure SOAPBinding 2008-04-02 13:27:14,055 DEBUG [org.jboss.ws.core.soap.MessageFactoryImpl] createMessage: [contentTy pe=text/xml] 2008-04-02 13:27:14,055 DEBUG [org.jboss.ws.core.client.RemotingConnectionImpl] Get locator for: ht tp://localhost:8280/EchoWs/EchoWs 2008-04-02 13:27:14,055 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] org.jboss.remoting.tran sport.http.HTTPClientInvoker@4acc69 connecting 2008-04-02 13:27:14,055 DEBUG [org.jboss.remoting.MicroRemoteClientInvoker] org.jboss.remoting.tran sport.http.HTTPClientInvoker@4acc69 connected 2008-04-02 13:27:14,055 DEBUG [org.jboss.ws.core.client.RemotingConnectionImpl] Remoting metadata: {NoThrowOnError=true, HEADER={SOAPAction="", Content-Type=text/xml; charset=UTF-8}} 2008-04-02 13:27:14,055 DEBUG [org.jboss.remoting.transport.http.HTTPClientInvoker] Setting request header with SOAPAction : "" 2008-04-02 13:27:14,055 DEBUG [org.jboss.remoting.transport.http.HTTPClientInvoker] Setting request header with Content-Type : text/xml; charset=UTF-8 2008-04-02 13:27:14,071 DEBUG [org.jboss.ws.core.soap.SOAPMessageUnMarshaller] getMimeHeaders from: {Date=[Wed, 02 Apr 2008 11:27:14 GMT], Transfer-Encoding=[chunked], NoThrowOnError=true, HEADER={S OAPAction="", Content-Type=text/xml; charset=UTF-8}, ResponseCode=200, ResponseCodeMessage=OK, Cont ent-Type=[text/xml;charset=UTF-8], X-Powered-By=[Servlet 2.4; JBoss-4.3.0.GA (build: SVNTag=JBPAPP_ 4_3_0_GA date=200801031548)/Tomcat-5.5], Server=[Apache-Coyote/1.1]} 2008-04-02 13:27:14,071 DEBUG [org.jboss.ws.core.soap.MessageFactoryImpl] createMessage: [contentTy pe=text/xml; charset=UTF-8] 2008-04-02 13:27:14,071 DEBUG [org.jboss.remoting.InvokerRegistry] removed org.jboss.remoting.trans port.http.HTTPClientInvoker@4acc69 from registry 2008-04-02 13:27:14,071 DEBUG [org.jboss.internal.soa.esb.rosetta.pooling.JmsConnectionPool] Return ing session, poolsize=4, maxsize=20, number of pools=1 2008-04-02 13:27:14,071 DEBUG [org.jboss.internal.soa.esb.couriers.JmsCourier] JMSCourier delivery Mode: 2, peristent:true 2008-04-02 13:27:14,086 DEBUG [org.jboss.soa.esb.notification.jms.DefaultJMSPropertiesSetter] Setti ng outgoing JMSCorreletionID to : fb3435d7-ccac-4f09-9af4-2fd8a08baceb 2008-04-02 13:27:14,086 DEBUG [org.jboss.soa.esb.notification.jms.DefaultJMSPropertiesSetter] Setti ng outgoing JMSCorreletionID to : null 2008-04-02 13:27:14,086 DEBUG [org.jboss.soa.esb.notification.jms.DefaultJMSPropertiesSetter] Setti ng outgoing JMSProperty, key : HttpVersion, value : HTTP/1.1 2008-04-02 13:27:14,086 DEBUG [org.jboss.soa.esb.notification.jms.DefaultJMSPropertiesSetter] Setti ng outgoing JMSProperty, key : MethodType, value : POST 2008-04-02 13:27:14,086 DEBUG [org.jboss.soa.esb.notification.jms.DefaultJMSPropertiesSetter] Setti ng outgoing JMSProperty, key : Path, value : /EchoWs 2008-04-02 13:27:14,086 DEBUG [org.jboss.soa.esb.notification.jms.DefaultJMSPropertiesSetter] Setti ng outgoing JMSProperty, key : expect, value : 100-continue 2008-04-02 13:27:14,086 DEBUG [org.jboss.soa.esb.notification.jms.DefaultJMSPropertiesSetter] Setti ng outgoing JMSProperty, key : host, value : localhost:8888 2008-04-02 13:27:14,086 DEBUG [org.jboss.soa.esb.notification.jms.DefaultJMSPropertiesSetter] Setti ng outgoing JMSProperty, key : soapaction, value : "" 2008-04-02 13:27:14,117 DEBUG [org.jboss.soa.esb.listeners.gateway.JBossRemotingGatewayListener] Re turning response [<soap:Envelope xmlns:soap='http://schemas.xmlsoap.org/soap/envelope/' xmlns:xsd=' http://www.w3.org/2001/XMLSchema' xmlns:xsi='http://www.w3.org/2001/XMLSchema-instance'><soap:Body> <ns1:doEchoResponse xmlns:ns1='http://inet.esb.test'><ns1:out>Echo: ECHO3</ns1:out></ns1:doEchoResp onse></soap:Body></soap:Envelope>].
Any ideas how to remove this lag?
Thanks & Regards
Johannes