4 Replies Latest reply on Jun 6, 2011 10:52 AM by windigo

    Delay "reading version from input stream"

    windigo Newbie

      I'm connected remotely from a swing client on WinXP to a jboss 6.0.0 server on a Redhat-machine. I'm the only user on the server.

      The first access to the server is delayed:

       

      2011-05-31 17:48:45,712 TRACE MicroSocketClientInvoker:817  - SocketClientInvoker[1b29f80, socket://url.com:4173] got socketWrapper: ClientSocketWrapper[Socket[addr=/193.99.233.70,port=4173,localport=4457].1c2ec05]
      2011-05-31 17:48:45,712 TRACE MicroSocketClientInvoker:852  - SocketClientInvoker[1b29f80, socket://url.com:4173]got outputStream: org.jboss.remoting.serialization.impl.java.ClearableObjectOutputStream@82a13a
      2011-05-31 17:48:45,712 TRACE MicroSocketClientInvoker:855  - SocketClientInvoker[1b29f80, socket://url.com:4173] writing version
      2011-05-31 17:48:45,712 TRACE MicroSocketClientInvoker:1350  - SocketClientInvoker[1b29f80, socket://url.com:4173] writing version 22 on output stream
      2011-05-31 17:48:45,712 TRACE MicroSocketClientInvoker:857  - SocketClientInvoker[1b29f80, socket://url.com:4173] wrote version
      2011-05-31 17:48:45,712 TRACE MicroSocketClientInvoker:1321  - SocketClientInvoker[1b29f80, socket://url.com:4173] writing invocation to marshaller
      2011-05-31 17:48:45,728 TRACE MicroSocketClientInvoker:1326  - SocketClientInvoker[1b29f80, socket://url.com:4173] done writing invocation to marshaller
      2011-05-31 17:48:45,728 TRACE MicroSocketClientInvoker:1341  - SocketClientInvoker[1b29f80, socket://url.com:4173] reading version from input stream
      2011-05-31 17:48:46,946 TRACE MicroSocketClientInvoker:1343  - SocketClientInvoker[1b29f80, socket://url.com:4173] read version 22 from input stream
      2011-05-31 17:48:46,946 TRACE MicroSocketClientInvoker:1297  - SocketClientInvoker[1b29f80, socket://url.com:4173] reading response from unmarshaller
      

       

      Nearly a second the client is reading something from the input stream? In the serverlog there's nothing like it? What is this and how can I speed up this?

       

       

      thx in advance

      Felix

        • 1. Re: Delay "reading version from input stream"
          Mark Paluch Master

          Hi there,

          seems that your Stream reads something from the Network. It's not unusual, that sometimes small delays occour, when the opposite server needs some time to complete it's response.

           

          Best regards,

          Mark

          • 2. Re: Delay "reading version from input stream"
            windigo Newbie

            Thx for the response, but I dont understand what's happening in detail.

             

            This delay differs between 1-2s and on client-side its a bit annoying. As I could see in the serverlog all this "reading version from input stream" happend before the log output (login, ejbs-instantiation,...) of my actual deployed application.

            Here is a corresponding trace-info in the server-log (look at 11:46:59,252):

             

            ...
            2011-06-01 11:46:59,242 TRACE [org.jboss.detailed.classloader.ClassLoaderManager] (WorkerThread#0[Client-IP:4851]) ScheduleTask task=ClassLoadingTask@73c8a9{className=sun.reflect.SerializationConstructorAccessorImpl requestingThread=WorkerThread#0[Client-IP:4851] requestingClassLoader: BaseClassLoader@168c78e{vfs:///usr2/tools/server/jboss-6.0.0.Final/server/default/deploy/Application.ear} threadTaskCount: 0 state: null} loader=java.net.URLClassLoader@1e893df reschedule=false
            2011-06-01 11:46:59,242 TRACE [org.jboss.detailed.classloader.ClassLoaderManager] (WorkerThread#0[Client-IP:4851]) scheduleTask(1), created subtask: {thread=WorkerThread#0[Client-IP:4851] loader=java.net.URLClassLoader@1e893df requestingThread=WorkerThread#0[Client-IP:4851] releaseInNextTask=false}
            2011-06-01 11:46:59,242 TRACE [org.jboss.detailed.classloader.ClassLoaderManager] (WorkerThread#0[Client-IP:4851]) Next task thread=WorkerThread#0[Client-IP:4851] task=ClassLoadingTask@73c8a9{className=sun.reflect.SerializationConstructorAccessorImpl requestingThread=WorkerThread#0[Client-IP:4851] requestingClassLoader: BaseClassLoader@168c78e{vfs:///usr2/tools/server/jboss-6.0.0.Final/server/default/deploy/Application.ear} threadTaskCount: 1 state: null}
            2011-06-01 11:46:59,242 TRACE [org.jboss.detailed.classloader.ClassLoaderManager] (WorkerThread#0[Client-IP:4851]) Continue nextTask(1), task=ClassLoadingTask@73c8a9{className=sun.reflect.SerializationConstructorAccessorImpl requestingThread=WorkerThread#0[Client-IP:4851] requestingClassLoader: BaseClassLoader@168c78e{vfs:///usr2/tools/server/jboss-6.0.0.Final/server/default/deploy/Application.ear} threadTaskCount: 1 state: null}
            2011-06-01 11:46:59,242 TRACE [org.jboss.detailed.classloader.ClassLoaderManager] (WorkerThread#0[Client-IP:4851]) Begin nextTask(0), loadTask=ClassLoadingTask@73c8a9{className=sun.reflect.SerializationConstructorAccessorImpl requestingThread=WorkerThread#0[Client-IP:4851] requestingClassLoader: BaseClassLoader@168c78e{vfs:///usr2/tools/server/jboss-6.0.0.Final/server/default/deploy/Application.ear} threadTaskCount: 1 state: null}
            2011-06-01 11:46:59,242 TRACE [org.jboss.detailed.classloader.ClassLoaderManager] (WorkerThread#0[Client-IP:4851]) Running threadTask={thread=WorkerThread#0[Client-IP:4851] loader=java.net.URLClassLoader@1e893df requestingThread=WorkerThread#0[Client-IP:4851] releaseInNextTask=false}
            2011-06-01 11:46:59,242 TRACE [org.jboss.detailed.classloader.ClassLoadingTask] (WorkerThread#0[Client-IP:4851]) setLoadedClass, theClass=class sun.reflect.SerializationConstructorAccessorImpl
            2011-06-01 11:46:59,242 TRACE [org.jboss.detailed.classloader.ClassLoaderManager] (WorkerThread#0[Client-IP:4851]) Notifying task of thread completion, loadTask:ClassLoadingTask@73c8a9{className=sun.reflect.SerializationConstructorAccessorImpl requestingThread=WorkerThread#0[Client-IP:4851] requestingClassLoader: BaseClassLoader@168c78e{vfs:///usr2/tools/server/jboss-6.0.0.Final/server/default/deploy/Application.ear} loadedClass=class sun.reflect.SerializationConstructorAccessorImpl{cl=null codeSource=null} threadTaskCount: 0 state: null}
            2011-06-01 11:46:59,242 TRACE [org.jboss.detailed.classloader.ClassLoaderManager] (WorkerThread#0[Client-IP:4851]) End nextTask(0), loadTask=ClassLoadingTask@73c8a9{className=sun.reflect.SerializationConstructorAccessorImpl requestingThread=WorkerThread#0[Client-IP:4851] requestingClassLoader: BaseClassLoader@168c78e{vfs:///usr2/tools/server/jboss-6.0.0.Final/server/default/deploy/Application.ear} loadedClass=class sun.reflect.SerializationConstructorAccessorImpl{cl=null codeSource=null} threadTaskCount: 0 state: FINISHED}
            2011-06-01 11:46:59,242 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] (WorkerThread#0[Client-IP:4851]) BaseClassLoader@168c78e{vfs:///usr2/tools/server/jboss-6.0.0.Final/server/default/deploy/Application.ear} got class from domain class sun.reflect.SerializationConstructorAccessorImpl{cl=null codeSource=null}
            2011-06-01 11:46:59,242 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] (WorkerThread#0[Client-IP:4851]) BaseClassLoader@168c78e{vfs:///usr2/tools/server/jboss-6.0.0.Final/server/default/deploy/Application.ear} unlock WorkerThread#0[Client-IP:4851] holding=1
            2011-06-01 11:46:59,242 TRACE [org.jboss.detailed.classloader.ClassLoaderManager] (WorkerThread#0[Client-IP:4851]) unregisterLoaderThread, classloader=BaseClassLoader@168c78e{vfs:///usr2/tools/server/jboss-6.0.0.Final/server/default/deploy/Application.ear} thread=WorkerThread#0[Client-IP:4851] rescheduleTasks=true
            2011-06-01 11:46:59,252 TRACE [org.jboss.remoting.transport.socket.ServerThread] (WorkerThread#0[Client-IP:4851]) wrote response to the output stream
            2011-06-01 11:46:59,252 TRACE [org.jboss.remoting.transport.socket.ServerThread] (WorkerThread#0[Client-IP:4851]) preparing to process next invocation
            2011-06-01 11:46:59,252 TRACE [org.jboss.remoting.transport.socket.ServerThread] (WorkerThread#0[Client-IP:4851]) WorkerThread#0[Client-IP:4851] blocking to read version from input stream
            2011-06-01 11:46:59,855 TRACE [org.jboss.remoting.transport.socket.ServerThread] (WorkerThread#0[Client-IP:4851]) WorkerThread#0[Client-IP:4851] read version -1 from input stream
            2011-06-01 11:46:59,856 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] (WorkerThread#0[Client-IP:4851]) BaseClassLoader@5749c6{vfs:///usr2/tools/server/jboss-6.0.0.Final/server/default/deploy/ejb3-connectors-jboss-beans.xml} loadClass org.jboss.remoting.transport.socket.ServerThread resolve=false
            2011-06-01 11:46:59,856 TRACE [org.jboss.classloader.spi.base.BaseClassLoaderDomain] (WorkerThread#0[Client-IP:4851]) Found org.jboss.remoting.transport.socket.ServerThread in global cache: ClassLoaderDomain@682406{DefaultDomain}
            2011-06-01 11:46:59,856 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] (WorkerThread#0[Client-IP:4851]) BaseClassLoader@82f392{vfs:///usr2/tools/server/jboss-6.0.0.Final/server/default/conf/jboss-service.xml} getPackage org.jboss.remoting.transport.socket
            2011-06-01 11:46:59,856 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] (WorkerThread#0[Client-IP:4851]) BaseClassLoader@82f392{vfs:///usr2/tools/server/jboss-6.0.0.Final/server/default/conf/jboss-service.xml} already loaded package org.jboss.remoting.transport.socket org.jboss.remoting.transport.socket
            2011-06-01 11:46:59,856 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] (WorkerThread#0[Client-IP:4851]) BaseClassLoader@82f392{vfs:///usr2/tools/server/jboss-6.0.0.Final/server/default/conf/jboss-service.xml} getPackage org.jboss.remoting.transport.socket
            2011-06-01 11:46:59,857 TRACE [org.jboss.classloader.spi.base.BaseClassLoader] (WorkerThread#0[Client-IP:4851]) BaseClassLoader@82f392{vfs:///usr2/tools/server/jboss-6.0.0.Final/server/default/conf/jboss-service.xml} already loaded package org.jboss.remoting.transport.socket org.jboss.remoting.transport.socket
            2011-06-01 11:46:59,856 TRACE [org.jboss.remoting.transport.socket.ServerThread] (WorkerThread#0[Client-IP:4851]) WorkerThread#0[Client-IP:4851] EOFException received. This is likely due to client finishing communication.: java.io.EOFException
                 at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:740) [:6.0.0.Final]
                 at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:586) [:6.0.0.Final]
                 at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:234) [:6.0.0.Final]
            ...
            

            and what about workerthread-exception?

             

             

            in the sum takes the first call to a service function for 4-5 seconds.all subsequent calls of the same service functions from the same user tooks milliseconds.

             

            do you have any ideas how I could tune up the first access?

            I've already created a @Singleton, @Startup-EJB to force the instantiation of my different services at deploytime.

            • 3. Re: Delay "reading version from input stream"
              windigo Newbie

              I think I've the same problem described in this threads http://community.jboss.org/thread/111345 http://community.jboss.org/thread/104484

              Everytime I got this error

               

              2011-06-01 11:46:59,856 TRACE [org.jboss.remoting.transport.socket.ServerThread] (WorkerThread#0[Client-IP:4851]) WorkerThread#0[Client-IP:4851] EOFException received. This is likely due to client finishing communication.: java.io.EOFException
               at org.jboss.remoting.transport.socket.ServerThread.processInvocation(ServerThread.java:740) [:6.0.0.Final]
               at org.jboss.remoting.transport.socket.ServerThread.dorun(ServerThread.java:586) [:6.0.0.Final]
               at org.jboss.remoting.transport.socket.ServerThread.run(ServerThread.java:234) [:6.0.0.Final]
              
              

              the server create a new socket with a new portnumber.

               

              The problem described in the references was solved in remoting branch 2.4, but the implementation-version of the jboss-remoting.jar in jboss 6.0.0 final is 2.5.3.

              should it not be then solved?

              • 4. Re: Delay "reading version from input stream"
                windigo Newbie

                At the end I didn't get rid off the delay. Even the "invokerDestructionDelay" in ejb3-connectors-jboss-beans.xml doesn't help and I solved the problem otherwise:

                 

                I created a stateless bean with an asynchronous method. This method is called first time a client logs into my swing-application

                While the method is called the login-process on serverside is done + some common business-EJBs are instantiated. Thats all done in background (asynchronous). If the client wants to use a Business-method the server already holds  the sessionContext off the client and can use the cached ejbs in the pool.

                The server reacts (like excpected) in some ms.

                 

                cya

                Felix