Delay "reading version from input stream"

[windigo]

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

[mp911de]

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

[windigo]

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.

[windigo]

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?

[windigo]

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