JBossDeveloper

Dear Bernd,

I run bellow command about 1 minute,

# dd if=/dev/random of=random1g.1 bs=1M count=1024
dd: warning: partial read (19 bytes); suggest iflag=fullblock
^C0+5 records in
0+5 records out
51 bytes (51 B) copied, 55.7091 s, 0.0 kB/s

Now, Let replace random with  urandom:

#  mv /dev/random /dev/random_bak

#  ln -s /dev/urandom /dev/random

# dd if=/dev/random of=random1g.1 bs=1M count=1024
^C182+0 records in
181+0 records out
189792256 bytes (190 MB) copied, 17.6028 s, 10.8 MB/s

Now random number is generated very fast!

Now restart jboss 7, then run the ejb client:

Time used during connection: 10234 ms

getBigObject:big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.

getBigObjectWithJAASRole:big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.big.

Time interval1: 23531 ms

Time interval2: 20328 ms

EJB client is still VERY slow!

When statelessBean.getBigObject() is executed, ejb client trace log:

Sep 28, 2012 12:44:43 PM org.jboss.ejb.client.EJBClientContext getEJBReceiver

DEBUG: org.jboss.ejb.client.RandomDeploymentNodeSelector@76a85e deployment node selector selected bcloud node for appname=nms-server-ear,modulename=nms-server-ejb,distinctname=

Sep 28, 2012 12:44:43 PM org.jboss.remoting3.remote.RemoteConnectionChannel casState

TRACE: CAS Channel ID 956480f4 (outbound) of Remoting connection 0174dd2a to 135.251.246.123/135.251.246.123:4447

    old: RS=false WS=false IM=0 OM=0

    new: RS=false WS=false IM=0 OM=1

Sep 28, 2012 12:44:43 PM org.jboss.remoting3.remote.RemoteConnectionChannel openOutboundMessage

TRACE: Opened outbound message on Channel ID 956480f4 (outbound) of Remoting connection 0174dd2a to 135.251.246.123/135.251.246.123:4447

Sep 28, 2012 12:44:43 PM org.jboss.remoting3.remote.OutboundMessage$1 accept

TRACE: Sending message (with EOF) (java.nio.HeapByteBuffer[pos=0 lim=162 cap=8192]) to org.xnio.channels.FramedMessageChannel around org.xnio.ssl.JsseConnectedSslStreamChannel around TCP socket channel (NIO) <e664ac>

Sep 28, 2012 12:44:43 PM org.jboss.remoting3.remote.OutboundMessage$1 accept

TRACE: Message window is open, proceeding with send

Sep 28, 2012 12:44:43 PM org.xnio.channels.FramedMessageChannel send

TRACE: Accepting java.nio.HeapByteBuffer[pos=0 lim=162 cap=8192] into java.nio.HeapByteBuffer[pos=0 lim=8196 cap=8196]

Sep 28, 2012 12:44:43 PM org.xnio.channels.FramedMessageChannel send

TRACE: Accepted a message into java.nio.HeapByteBuffer[pos=166 lim=8196 cap=8196]

Sep 28, 2012 12:44:43 PM org.xnio.channels.FramedMessageChannel doFlushBuffer

TRACE: Fully flushed org.xnio.channels.FramedMessageChannel around org.xnio.ssl.JsseConnectedSslStreamChannel around TCP socket channel (NIO) <e664ac>

Sep 28, 2012 12:44:43 PM org.jboss.remoting3.remote.RemoteConnectionChannel free

TRACE: Removed Outbound message ID 0bfc on Channel ID 956480f4 (outbound) of Remoting connection 0174dd2a to 135.251.246.123/135.251.246.123:4447

Sep 28, 2012 12:44:43 PM org.jboss.remoting3.remote.RemoteConnectionChannel incrementState

TRACE: CAS Channel ID 956480f4 (outbound) of Remoting connection 0174dd2a to 135.251.246.123/135.251.246.123:4447

    old: RS=false WS=false IM=0 OM=1

    new: RS=false WS=false IM=0 OM=0

Sep 28, 2012 12:44:43 PM org.xnio.nio.WorkerThread run

TRACE: Selected on sun.nio.ch.WindowsSelectorImpl@b5efc8

Sep 28, 2012 12:44:43 PM org.jboss.remoting3.remote.RemoteConnectionChannel closeOutboundMessage

TRACE: Closed outbound message on Channel ID 956480f4 (outbound) of Remoting connection 0174dd2a to 135.251.246.123/135.251.246.123:4447

Sep 28, 2012 12:44:43 PM org.xnio.nio.WorkerThread run

TRACE: Selected key sun.nio.ch.SelectionKeyImpl@1e6c526 for java.nio.channels.SocketChannel[connected local=/0.0.0.0:3915 remote=135.251.246.123/135.251.246.123:4447]

Sep 28, 2012 12:44:43 PM org.jboss.remoting3.remote.OutboundMessage$1 flush

TRACE: Flushing message channel

Sep 28, 2012 12:44:43 PM org.xnio.ChannelListeners invokeChannelListener

TRACE: Invoking listener Read listener for org.xnio.ssl.JsseConnectedSslStreamChannel around TCP socket channel (NIO) <e664ac> on channel TCP socket channel (NIO) <e664ac>

Sep 28, 2012 12:44:43 PM org.xnio.channels.FramedMessageChannel doFlushBuffer

TRACE: Fully flushed org.xnio.channels.FramedMessageChannel around org.xnio.ssl.JsseConnectedSslStreamChannel around TCP socket channel (NIO) <e664ac>

Sep 28, 2012 12:44:43 PM org.xnio.ChannelListeners invokeChannelListener

TRACE: Invoking listener Read listener for org.xnio.channels.FramedMessageChannel around org.xnio.ssl.JsseConnectedSslStreamChannel around TCP socket channel (NIO) <e664ac> on channel org.xnio.ssl.JsseConnectedSslStreamChannel around TCP socket channel (NIO) <e664ac>

Sep 28, 2012 12:44:43 PM org.xnio.ChannelListeners invokeChannelListener

TRACE: Invoking listener org.jboss.remoting3.remote.RemoteReadListener@1435978 on channel org.xnio.channels.FramedMessageChannel around org.xnio.ssl.JsseConnectedSslStreamChannel around TCP socket channel (NIO) <e664ac>

Sep 28, 2012 12:44:43 PM org.xnio.channels.FramedMessageChannel receive

TRACE: Copying message from java.nio.HeapByteBuffer[pos=4 lim=138 cap=8196] into java.nio.HeapByteBuffer[pos=0 lim=8192 cap=8192]

Sep 28, 2012 12:44:43 PM org.jboss.remoting3.remote.RemoteReadListener handleEvent

TRACE: Received message window open

Sep 28, 2012 12:44:43 PM org.xnio.channels.FramedMessageChannel receive

TRACE: Copying message from java.nio.HeapByteBuffer[pos=4 lim=123 cap=8196] into java.nio.HeapByteBuffer[pos=0 lim=8192 cap=8192]

Sep 28, 2012 12:44:43 PM org.jboss.remoting3.remote.RemoteReadListener handleEvent

TRACE: Received message data

Sep 28, 2012 12:44:43 PM org.jboss.remoting3.remote.RemoteConnectionChannel casState

TRACE: CAS Channel ID 956480f4 (outbound) of Remoting connection 0174dd2a to 135.251.246.123/135.251.246.123:4447

    old: RS=false WS=false IM=0 OM=0

    new: RS=false WS=false IM=1 OM=0

Sep 28, 2012 12:44:43 PM org.jboss.remoting3.remote.RemoteConnectionChannel openInboundMessage

TRACE: Opened inbound message on Channel ID 956480f4 (outbound) of Remoting connection 0174dd2a to 135.251.246.123/135.251.246.123:4447

Sep 28, 2012 12:44:43 PM org.jboss.remoting3.remote.RemoteConnectionChannel incrementState

TRACE: CAS Channel ID 956480f4 (outbound) of Remoting connection 0174dd2a to 135.251.246.123/135.251.246.123:4447

    old: RS=false WS=false IM=1 OM=0

    new: RS=false WS=false IM=0 OM=0

Sep 28, 2012 12:44:43 PM org.jboss.remoting3.remote.RemoteConnectionChannel closeInboundMessage

TRACE: Closed inbound message on Channel ID 956480f4 (outbound) of Remoting connection 0174dd2a to 135.251.246.123/135.251.246.123:4447

Sep 28, 2012 12:44:43 PM org.jboss.ejb.client.remoting.ChannelAssociation$ResponseReceiver handleMessage

TRACE: Received message with header 0x5

Sep 28, 2012 12:44:43 PM org.xnio.channels.FramedMessageChannel receive

TRACE: Did not read a length

Sep 28, 2012 12:44:43 PM org.jboss.remoting3.remote.RemoteReadListener handleEvent

TRACE: No message ready; returning

Sep 28, 2012 12:44:43 PM org.xnio.channels.FramedMessageChannel send

TRACE: Accepting java.nio.HeapByteBuffer[pos=0 lim=11 cap=8192] into java.nio.HeapByteBuffer[pos=0 lim=8196 cap=8196]

Sep 28, 2012 12:44:43 PM org.xnio.nio.WorkerThread run

TRACE: Beginning select on sun.nio.ch.WindowsSelectorImpl@b5efc8

Sep 28, 2012 12:44:43 PM org.xnio.channels.FramedMessageChannel send

TRACE: Accepted a message into java.nio.HeapByteBuffer[pos=15 lim=8196 cap=8196]

Sep 28, 2012 12:44:43 PM org.xnio.channels.FramedMessageChannel doFlushBuffer

TRACE: Fully flushed org.xnio.channels.FramedMessageChannel around org.xnio.ssl.JsseConnectedSslStreamChannel around TCP socket channel (NIO) <e664ac>

The  server side debug log:

10:32:26,308 DEBUG [org.jboss.as.ejb3.remote.protocol.versionone.VersionOneProtocolChannelReceiver] (Remoting "bcloud" task-1) Channel Channel ID 156480f4 (inbound) of Remoting connection 6ead0057 to null closed
10:33:21,436 DEBUG [org.apache.catalina.session.ManagerBase] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) Start expire sessions StandardManager at 1337049201436 sessioncount 0
10:33:21,437 DEBUG [org.apache.catalina.session.ManagerBase] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) End expire sessions StandardManager processingTime 1 expired sessions: 0
10:33:21,437 DEBUG [org.apache.catalina.session.ManagerBase] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) Start expire sessions StandardManager at 1337049201437 sessioncount 0
10:33:21,437 DEBUG [org.apache.catalina.session.ManagerBase] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) End expire sessions StandardManager processingTime 0 expired sessions: 0
10:34:21,439 DEBUG [org.apache.catalina.session.ManagerBase] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) Start expire sessions StandardManager at 1337049261439 sessioncount 0
10:34:21,440 DEBUG [org.apache.catalina.session.ManagerBase] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) End expire sessions StandardManager processingTime 0 expired sessions: 0
10:34:21,440 DEBUG [org.apache.catalina.session.ManagerBase] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) Start expire sessions StandardManager at 1337049261440 sessioncount 0
10:34:21,440 DEBUG [org.apache.catalina.session.ManagerBase] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) End expire sessions StandardManager processingTime 0 expired sessions: 0
10:35:21,442 DEBUG [org.apache.catalina.session.ManagerBase] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) Start expire sessions StandardManager at 1337049321442 sessioncount 0
10:35:21,442 DEBUG [org.apache.catalina.session.ManagerBase] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) End expire sessions StandardManager processingTime 0 expired sessions: 0
10:35:21,442 DEBUG [org.apache.catalina.session.ManagerBase] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) Start expire sessions StandardManager at 1337049321442 sessioncount 0
10:35:21,443 DEBUG [org.apache.catalina.session.ManagerBase] (ContainerBackgroundProcessor[StandardEngine[jboss.web]]) End expire sessions StandardManager processingTime 1 expired sessions: 0

You sure it took 12s, the client trace is only 1s long, and on the server side it looks like everything is closed in the first line.

~~~~~~~~I am sure. During SSL connection, there is NO log printed.

My test code is:

        long connect_begin = System.currentTimeMillis();
        final ISecuredRemoteSession statelessBean = lookupRemoteStatelessCalculator();
        long connect_end = System.currentTimeMillis();
        System.out.println("Time used during connection: "+(connect_end-connect_begin)+" ms");

    private static ISecuredRemoteSession lookupRemoteStatelessCalculator() throws Exception {
        return lookupRemoteStatelessCalculator_WithoutPropertieFile_method2_ear();//ear
    }
   
    private static ISecuredRemoteSession lookupRemoteStatelessCalculator_WithoutPropertieFile_method2_ear() throws Exception {       
        String jndiName = "ejb:nms-server-ear/nms-server-ejb//SecuredRemoteSession!" + ISecuredRemoteSession.class.getName();//ear:good
       
        Properties p = new Properties();
        {
            ...
        }
        EJBClientConfiguration cc = new PropertiesBasedEJBClientConfiguration(p);
        ContextSelector<EJBClientContext> selector = new ConfigBasedEJBClientContextSelector(cc);
        EJBClientContext.setSelector(selector);
       
        Properties props = new Properties();
        props.put(Context.URL_PKG_PREFIXES, "org.jboss.ejb.client.naming");
        InitialContext context = new InitialContext(props);
        return (ISecuredRemoteSession)context.lookup(jndiName);
    }

related Log:

Time used during connection: 10234 ms

Thanks for your sugguestion.

I debugged XNIO code, SSL hand shaking is NOT slow, but after that the thread hung during listening event.

I will post more debugging details here.

I opened trace function, but after SSL hand shaking and during event listening, there is NO log printed.

Hi Lloyd,

Thanks for your reply. I think you came to the point.

That would be better.

I can wait and test it later on jboss 7.2.