-
15. Re: Why XNIO+SSL is so slow?
ybxiang.china Sep 27, 2012 9:37 PM (in response to b.eckenfels)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/sNow, 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/sNow 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!
-
16. Re: Why XNIO+SSL is so slow?
ybxiang.china Sep 28, 2012 12:50 AM (in response to 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
-
17. Re: Why XNIO+SSL is so slow?
b.eckenfels Oct 1, 2012 6:00 PM (in response to ybxiang.china)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 0You 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
-
18. Re: Why XNIO+SSL is so slow?
leonardo.devai Oct 2, 2012 5:20 PM (in response to b.eckenfels)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
-
19. Re: Why XNIO+SSL is so slow?
ybxiang.china Oct 5, 2012 1:26 AM (in response to b.eckenfels)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.
-
20. Re: Why XNIO+SSL is so slow?
ybxiang.china Oct 5, 2012 1:28 AM (in response to leonardo.devai)I opened trace function, but after SSL hand shaking and during event listening, there is NO log printed.
-
21. Re: Why XNIO+SSL is so slow?
dmlloyd Oct 5, 2012 9:28 AM (in response to ybxiang.china)1 of 1 people found this helpfulI'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.
-
22. Re: Why XNIO+SSL is so slow?
ybxiang.china Oct 7, 2012 7:18 AM (in response to dmlloyd)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.