9 Replies Latest reply on Jul 12, 2006 12:32 PM by cptnkirk

    Considerably slow after execute phase

    andrew.rw.robinson
    andrew.rw.robinson Jul 11, 2006 4:15 PM

      After the execute phase there is a large delay in my application. I went hunting it down to find out why. I found the slowness in Seam.

      From inside of "isTransactionAvailableAndMarkedRollback" of Transactions.java, the "return (UserTransaction) Naming.getInitialContext().lookup(userTransactionName);" method throws a "CommunicationException" of message "Receive timed out".

      In this particular project, I am not using transactions or EJBs. All of my Seam components are POJOs and there is no entity manager or any other type of persistence configured in the Seam/JSF layer of our application.

      I have no components.xml and my seam.properties is empty. I do have a pages.xml though.

      The only Seam configuration I have in the web.xml is the filters (SeamRedirectFilter, SeamRedirectFilter) and the listener (org.jboss.seam.servlet.SeamListener).

      Environment:
      JBoss AS 4.0.3 SP1 (no EJB3 deployment, just the default deployment)
      JBoss Seam 1.0.1
      MyFaces 1.1.3
      Tomahawk 1.1.2
      Facelets 1.0.14

      We are not planning (any time soon) to use any user transactions or EJBs in this project. What must I do to speed this method up as it really doesn't need to execute in our environment?

      Thanks,
      Andrew


      • 5791 Views
      • Tags:
        • 1. Re: Considerably slow after execute phase
          andrew.rw.robinson
          andrew.rw.robinson Jul 11, 2006 4:45 PM (in response to andrew.rw.robinson)

          Here is the stack:

          2006-07-11 14:36:21,991 INFO [STDOUT] javax.naming.CommunicationException: Receive timed out [Root exception is java.net.SocketTimeoutException: Receive timed out]
2006-07-11 14:36:21,992 INFO [STDOUT] at org.jnp.interfaces.NamingContext.discoverServer(NamingContext.java:1323)
2006-07-11 14:36:21,992 INFO [STDOUT] at org.jnp.interfaces.NamingContext.checkRef(NamingContext.java:1452)
2006-07-11 14:36:21,992 INFO [STDOUT] at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:595)
2006-07-11 14:36:21,992 INFO [STDOUT] at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:588)
2006-07-11 14:36:21,992 INFO [STDOUT] at javax.naming.InitialContext.lookup(InitialContext.java:351)
2006-07-11 14:36:21,992 INFO [STDOUT] at org.jboss.seam.util.Transactions.getUserTransaction(Transactions.java:48)
2006-07-11 14:36:21,992 INFO [STDOUT] at org.jboss.seam.util.Transactions.isTransactionAvailableAndMarkedRollback(Transactions.java:91)
2006-07-11 14:36:21,992 INFO [STDOUT] at org.jboss.seam.jsf.SeamPhaseListener.afterPhase(SeamPhaseListener.java:69)
2006-07-11 14:36:21,992 INFO [STDOUT] at org.apache.myfaces.lifecycle.PhaseListenerManager.informPhaseListenersAfter(PhaseListenerManager.java:89)
2006-07-11 14:36:21,992 INFO [STDOUT] at org.apache.myfaces.lifecycle.LifecycleImpl.invokeApplication(LifecycleImpl.java:345)
2006-07-11 14:36:21,992 INFO [STDOUT] at org.apache.myfaces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:86)
2006-07-11 14:36:21,992 INFO [STDOUT] at javax.faces.webapp.FacesServlet.service(FacesServlet.java:137)
2006-07-11 14:36:21,992 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
2006-07-11 14:36:21,993 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
2006-07-11 14:36:21,993 INFO [STDOUT] at org.apache.myfaces.webapp.filter.ExtensionsFilter.doFilter(ExtensionsFilter.java:144)
2006-07-11 14:36:21,993 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
2006-07-11 14:36:21,993 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
2006-07-11 14:36:21,993 INFO [STDOUT] at org.jboss.seam.servlet.SeamRedirectFilter.doFilter(SeamRedirectFilter.java:30)
2006-07-11 14:36:21,993 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
2006-07-11 14:36:21,993 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
2006-07-11 14:36:21,993 INFO [STDOUT] at com.outlooksoft.cpm.servlet.ExceptionLogFilter.doFilter(ExceptionLogFilter.java:43)
2006-07-11 14:36:21,993 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
2006-07-11 14:36:21,993 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
2006-07-11 14:36:21,993 INFO [STDOUT] at com.outlooksoft.cpm.security.SecurityFilter.doFilter(SecurityFilter.java:191)
2006-07-11 14:36:21,993 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
2006-07-11 14:36:21,993 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
2006-07-11 14:36:21,993 INFO [STDOUT] at org.ajaxanywhere.AAFilter.doFilter(AAFilter.java:57)
2006-07-11 14:36:21,993 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
2006-07-11 14:36:21,993 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
2006-07-11 14:36:21,993 INFO [STDOUT] at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:81)
2006-07-11 14:36:21,994 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
2006-07-11 14:36:21,994 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
2006-07-11 14:36:21,994 INFO [STDOUT] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
2006-07-11 14:36:21,994 INFO [STDOUT] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
2006-07-11 14:36:21,996 INFO [STDOUT] at org.jboss.web.tomcat.security.CustomPrincipalValve.invoke(CustomPrincipalValve.java:39)
2006-07-11 14:36:21,996 INFO [STDOUT] at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:159)
2006-07-11 14:36:21,996 INFO [STDOUT] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482)
2006-07-11 14:36:21,996 INFO [STDOUT] at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:59)
2006-07-11 14:36:21,996 INFO [STDOUT] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
2006-07-11 14:36:21,996 INFO [STDOUT] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
2006-07-11 14:36:21,996 INFO [STDOUT] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
2006-07-11 14:36:21,996 INFO [STDOUT] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
2006-07-11 14:36:21,996 INFO [STDOUT] at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:856)
2006-07-11 14:36:21,996 INFO [STDOUT] at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:744)
2006-07-11 14:36:21,996 INFO [STDOUT] at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
2006-07-11 14:36:21,996 INFO [STDOUT] at org.apache.tomcat.util.net.MasterSlaveWorkerThread.run(MasterSlaveWorkerThread.java:112)
2006-07-11 14:36:21,997 INFO [STDOUT] at java.lang.Thread.run(Thread.java:595)
2006-07-11 14:36:21,997 INFO [STDOUT] Caused by: java.net.SocketTimeoutException: Receive timed out
2006-07-11 14:36:21,997 INFO [STDOUT] at java.net.PlainDatagramSocketImpl.receive0(Native Method)
2006-07-11 14:36:21,997 INFO [STDOUT] at java.net.PlainDatagramSocketImpl.receive(PlainDatagramSocketImpl.java:136)
2006-07-11 14:36:21,997 INFO [STDOUT] at java.net.DatagramSocket.receive(DatagramSocket.java:712)
2006-07-11 14:36:21,997 INFO [STDOUT] at org.jnp.interfaces.NamingContext.discoverServer(NamingContext.java:1293)
2006-07-11 14:36:21,997 INFO [STDOUT] ... 46 more
2006-07-11 14:36:29,211 INFO [STDOUT] javax.naming.CommunicationException: Receive timed out [Root exception is java.net.SocketTimeoutException: Receive timed out]
2006-07-11 14:36:29,212 INFO [STDOUT] at org.jnp.interfaces.NamingContext.discoverServer(NamingContext.java:1323)
2006-07-11 14:36:29,212 INFO [STDOUT] at org.jnp.interfaces.NamingContext.checkRef(NamingContext.java:1452)
2006-07-11 14:36:29,212 INFO [STDOUT] at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:595)
2006-07-11 14:36:29,212 INFO [STDOUT] at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:588)
2006-07-11 14:36:29,212 INFO [STDOUT] at javax.naming.InitialContext.lookup(InitialContext.java:351)
2006-07-11 14:36:29,212 INFO [STDOUT] at org.jboss.seam.util.Transactions.getUserTransaction(Transactions.java:48)
2006-07-11 14:36:29,212 INFO [STDOUT] at org.jboss.seam.util.Transactions.isTransactionAvailableAndMarkedRollback(Transactions.java:91)
2006-07-11 14:36:29,212 INFO [STDOUT] at org.jboss.seam.jsf.SeamPhaseListener.afterPhase(SeamPhaseListener.java:69)
2006-07-11 14:36:29,212 INFO [STDOUT] at org.apache.myfaces.lifecycle.PhaseListenerManager.informPhaseListenersAfter(PhaseListenerManager.java:89)
2006-07-11 14:36:29,212 INFO [STDOUT] at org.apache.myfaces.lifecycle.LifecycleImpl.invokeApplication(LifecycleImpl.java:345)
2006-07-11 14:36:29,213 INFO [STDOUT] at org.apache.myfaces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:86)
2006-07-11 14:36:29,213 INFO [STDOUT] at javax.faces.webapp.FacesServlet.service(FacesServlet.java:137)
2006-07-11 14:36:29,213 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:252)
2006-07-11 14:36:29,213 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
2006-07-11 14:36:29,213 INFO [STDOUT] at org.apache.myfaces.webapp.filter.ExtensionsFilter.doFilter(ExtensionsFilter.java:144)
2006-07-11 14:36:29,213 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
2006-07-11 14:36:29,213 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
2006-07-11 14:36:29,213 INFO [STDOUT] at org.jboss.seam.servlet.SeamRedirectFilter.doFilter(SeamRedirectFilter.java:30)
2006-07-11 14:36:29,213 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
2006-07-11 14:36:29,213 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
2006-07-11 14:36:29,213 INFO [STDOUT] at com.outlooksoft.cpm.servlet.ExceptionLogFilter.doFilter(ExceptionLogFilter.java:43)
2006-07-11 14:36:29,213 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
2006-07-11 14:36:29,213 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
2006-07-11 14:36:29,213 INFO [STDOUT] at com.outlooksoft.cpm.security.SecurityFilter.doFilter(SecurityFilter.java:191)
2006-07-11 14:36:29,213 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
2006-07-11 14:36:29,214 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
2006-07-11 14:36:29,214 INFO [STDOUT] at org.ajaxanywhere.AAFilter.doFilter(AAFilter.java:57)
2006-07-11 14:36:29,214 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
2006-07-11 14:36:29,214 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
2006-07-11 14:36:29,214 INFO [STDOUT] at org.jboss.web.tomcat.filters.ReplyHeaderFilter.doFilter(ReplyHeaderFilter.java:81)
2006-07-11 14:36:29,214 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:202)
2006-07-11 14:36:29,214 INFO [STDOUT] at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:173)
2006-07-11 14:36:29,214 INFO [STDOUT] at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:213)
2006-07-11 14:36:29,214 INFO [STDOUT] at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:178)
2006-07-11 14:36:29,219 INFO [STDOUT] at org.jboss.web.tomcat.security.CustomPrincipalValve.invoke(CustomPrincipalValve.java:39)
2006-07-11 14:36:29,220 INFO [STDOUT] at org.jboss.web.tomcat.security.SecurityAssociationValve.invoke(SecurityAssociationValve.java:159)
2006-07-11 14:36:29,220 INFO [STDOUT] at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:482)
2006-07-11 14:36:29,220 INFO [STDOUT] at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:59)
2006-07-11 14:36:29,220 INFO [STDOUT] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
2006-07-11 14:36:29,220 INFO [STDOUT] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
2006-07-11 14:36:29,220 INFO [STDOUT] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
2006-07-11 14:36:29,220 INFO [STDOUT] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
2006-07-11 14:36:29,220 INFO [STDOUT] at org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:856)
2006-07-11 14:36:29,220 INFO [STDOUT] at org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.processConnection(Http11Protocol.java:744)
2006-07-11 14:36:29,220 INFO [STDOUT] at org.apache.tomcat.util.net.PoolTcpEndpoint.processSocket(PoolTcpEndpoint.java:527)
2006-07-11 14:36:29,220 INFO [STDOUT] at org.apache.tomcat.util.net.MasterSlaveWorkerThread.run(MasterSlaveWorkerThread.java:112)
2006-07-11 14:36:29,220 INFO [STDOUT] at java.lang.Thread.run(Thread.java:595)
2006-07-11 14:36:29,221 INFO [STDOUT] Caused by: java.net.SocketTimeoutException: Receive timed out
2006-07-11 14:36:29,221 INFO [STDOUT] at java.net.PlainDatagramSocketImpl.receive0(Native Method)
2006-07-11 14:36:29,221 INFO [STDOUT] at java.net.PlainDatagramSocketImpl.receive(PlainDatagramSocketImpl.java:136)
2006-07-11 14:36:29,221 INFO [STDOUT] at java.net.DatagramSocket.receive(DatagramSocket.java:712)
2006-07-11 14:36:29,221 INFO [STDOUT] at org.jnp.interfaces.NamingContext.discoverServer(NamingContext.java:1293)
2006-07-11 14:36:29,221 INFO [STDOUT] ... 46 mor


          By the way, I meant the INVOKE_APPLICATION phase when I said "execute"

            • Actions
          • 2. Re: Considerably slow after execute phase
            cptnkirk Jul 11, 2006 5:21 PM (in response to andrew.rw.robinson)

            Are you using HA Naming or some other remote naming config? There seems to be a remote naming discovery happening on each JNDI lookup. The remote bcast fails, and the object is eventually found locally. Lagtastic for sure, but it doesn't appear to be Seam's fault. Can you try installing your app on a clean domain? I'd expect the problem to go away unless you've configured your EAR to include remote JNDI contexts or something.

              • Actions
            • 3. Re: Considerably slow after execute phase
              andrew.rw.robinson
              andrew.rw.robinson Jul 11, 2006 5:31 PM (in response to andrew.rw.robinson)

              Your post just went over my head, sorry. I am not familiar with JBoss' naming configuration. I haven't touched any settings in JBoss since installing it. For the install, I just ran the "java -jar jboss*.jar".

              What do you mean by "clean domain"? There may be some network problems here, it wouldn't surprise me (our network guy quit and we never re-hired -- how fun).

              As for the EAR, here are my only config files:

              application.xml:

              <?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE application PUBLIC "-//Sun Microsystems, Inc.//DTD J2EE Application 1.3//EN"
 "application_1_3.dtd">
<application>
 <display-name>MyJSFClient</display-name>
 <module>
 <web>
 <web-uri>MyJSFClient.war</web-uri>
 <context-root>MyCodeName</context-root>
 </web>
 </module>
</application>


              jboss-app.xml: 
              <?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE jboss-app
 PUBLIC "-//JBoss//DTD J2EE Application 1.3V2//EN"
 "http://www.jboss.org/j2ee/dtd/jboss-app_3_2.dtd">

<jboss-app>
 <loader-repository>
 dot.com:loader=unique-archive-name
 <loader-repository-config>
 java2ParentDelegation=false
 </loader-repository-config>
 </loader-repository>
</jboss-app>


              I don't have a jboss-web.xml anymore. Other than that, everything is the default settings for jboss 4.0.3 sp1.

              Thanks,
              Andrew

                • Actions
              • 4. Re: Considerably slow after execute phase
                andrew.rw.robinson
                andrew.rw.robinson Jul 11, 2006 5:34 PM (in response to andrew.rw.robinson)

                Okay, I dropped my wireless connection, and everything was blazing fast (Faster then I have ever had a response), so it looks like you are on to something

                Any idea on where I should look next?

                BTW - I am using "localhost" on my browser to hit the server if that makes a difference

                  • Actions
                • 5. Re: Considerably slow after execute phase
                  cptnkirk Jul 11, 2006 5:43 PM (in response to andrew.rw.robinson)

                  You can always try a restart. This could simply be a networking issue on your machine. Sometimes with a flaky network interface, after prolonged periods of uptime you'll run across strange networking errors on other interfaces (kernel bug?).

                  See if things magically work after your entropy abatement restart. I'll cross my fingers for you. :)

                    • Actions
                  • 6. Re: Considerably slow after execute phase
                    andrew.rw.robinson
                    andrew.rw.robinson Jul 11, 2006 7:06 PM (in response to andrew.rw.robinson)

                    No dice unfortunately, still a problem. I started BIND for DNS caching and although it made my internet a little faster, it didn't help JBoss at all

                      • Actions
                    • 7. Re: Considerably slow after execute phase
                      cptnkirk Jul 11, 2006 8:15 PM (in response to andrew.rw.robinson)

                      Are you running a personal firewall or something that might interfere with local networking? You also mentioned another wireless interface on your machine. Try starting up JBoss with the -b option (eg, run.sh -b 127.0.0.1). This should tell JBoss to only bind to the loopback device on your system. Normally when JBoss boots up it tries to bind on every device on the machine. If there's a network problem with other devices this could side step it.

                      Then try hitting http://127.0.0.1:8080/... or whatever port you've configured the web server to run on.

                      Maybe this will help. If it does help then there seems to be a networking issue on your local machine. Maybe it's the wireless device, maybe it's some other device (VPN, PPP, or another NIC).

                      If it doesn't help I'm afraid I'm running out of straws. Might want to check with the JB networking folks. And in case I'm wrong and somehow this is a Seam issue, you can try another non-seam app that does a JNDI lookup. Should see the same lag.

                      -Jim

                      PS: Another straw, try a JVM upgrade. In the past either Windows or Java had a problem with loopback for something. It may have just been multicast, I don't remember. A JVM upgrade shouldn't hurt in any case. Nor should taking a trip to Windows Update and ensuring you're up to date there as well.

                      PPS: I guess if we think loopback could be a problem we can try binding to your primary NIC (I hope that isn't the wireless device). Bring up ifconfig, ipconfig, wincfg, winipcfg (one of those, it's been a while since I've done Windows networking). You should see an eth0 device. This should be your primary network device. Make note of that IP, do the same -b thing, and rehit the app under your new URL.

                        • Actions
                      • 8. Re: Considerably slow after execute phase
                        andrew.rw.robinson
                        andrew.rw.robinson Jul 12, 2006 12:23 PM (in response to andrew.rw.robinson)

                        Found a solution. I created seam-jndi.properties and added:

                        java.naming.provider.url=jnp://127.0.0.1:1099/

                        to it. Not sure why this was needed (shouldn't it be the default?).


                          • Actions
                        • 9. Re: Considerably slow after execute phase
                          cptnkirk Jul 12, 2006 12:32 PM (in response to andrew.rw.robinson)

                          Not 100% sure what the default is. Default may be to use a hostname lookup and hit whatever interface that returns.

                          On systems without networking problems all roads lead to the same place. Since by default the server will bind to 1099 on all interfaces it typically doesn't matter. Unfortunately in your case either a misconfiguration or glitchy hardware seem to be causing problems with the defaults.

                          I'm glad things are working in any case.

                            • Actions