[ybxiang.china]

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!

[ybxiang.china]

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

[b.eckenfels]

xiang yingbing wrote:

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

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

...

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

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.

BTW: you should not read the /dev/random to check if it is filled, you can use cat /proc/sys/kernel/random/entropy_avail

[leonardo.devai]

You should give it a shot on Bernd's idea of using strace, I think it's the easiest and quickest way to figure out the exact point it's hanging at this point.

You could also try checking if DMA is enabled on your disks. Although I think the issue here is unrelated to this, it wouldn't hurt to check it out: http://en.kioskea.net/faq/1940-linux-enabling-the-ultra-dma-on-an-ide-hard-disk

[ybxiang.china]

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.

[ybxiang.china]

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

[dmlloyd]

I'm not sure whether this will help you, but we've just released a new version of Remoting (3.2.11.GA) and XNIO (3.0.7.GA), which might solve some of the issues you are having.

[ybxiang.china]

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.