Vert.x breaks it's own Golden Rule ?

[Kris Groves]

Hi,

A test has been setup to load test a vert.x backend.  2 processors, with 2 instances of a secure NetServer.  As more connections come pouring in, some of the clients begin timing out waiting for the handshake to complete.  a thread dump of the vert.x shows that eventloop thread 0 is blocked waiting to aquire a lock that eventloop thread 1 has.

"vert.x-eventloop-thread-0" - Thread t@20
   java.lang.Thread.State: BLOCKED
    at java.io.PrintStream.write(PrintStream.java:447)
    - waiting to lock <400f73ac> (a java.io.PrintStream) owned by "vert.x-eventloop-thread-1" t@21
    at java.io.PrintStream.write(PrintStream.java:449)
    - locked <1015f04f> (a java.io.PrintStream)
    at sun.misc.HexDumpEncoder.hexDigit(HexDumpEncoder.java:67)
    at sun.misc.HexDumpEncoder.encodeAtom(HexDumpEncoder.java:93)
    at sun.misc.CharacterEncoder.encodeBuffer(CharacterEncoder.java:292)
    at sun.misc.CharacterEncoder.encodeBuffer(CharacterEncoder.java:312)
    at sun.misc.CharacterEncoder.encodeBuffer(CharacterEncoder.java:340)
    at sun.security.ssl.CipherBox.decrypt(CipherBox.java:562)
    at sun.security.ssl.EngineInputRecord.decrypt(EngineInputRecord.java:200)
    at sun.security.ssl.SSLEngineImpl.readRecord(SSLEngineImpl.java:974)
    at sun.security.ssl.SSLEngineImpl.readNetRecord(SSLEngineImpl.java:907)
    at sun.security.ssl.SSLEngineImpl.unwrap(SSLEngineImpl.java:781)
    - locked <123cebae> (a java.lang.Object)
    at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:624)
    at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:1001)
    at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:927)
    at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:873)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:241)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:149)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:333)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:319)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:787)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:125)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - None



"vert.x-eventloop-thread-1" - Thread t@21
   java.lang.Thread.State: RUNNABLE
    at java.io.FileOutputStream.writeBytes(Native Method)
    at java.io.FileOutputStream.write(FileOutputStream.java:326)
    at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
    at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
    - locked <640f320b> (a java.io.BufferedOutputStream)
    at java.io.PrintStream.write(PrintStream.java:482)
    - locked <400f73ac> (a java.io.PrintStream)
    at java.io.PrintStream.write(PrintStream.java:480)
    - locked <14f23108> (a java.io.PrintStream)
    at sun.nio.cs.StreamEncoder.writeBytes(StreamEncoder.java:221)
    at sun.nio.cs.StreamEncoder.implFlushBuffer(StreamEncoder.java:291)
    at sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:104)
    - locked <81cdb3> (a java.io.OutputStreamWriter)
    at java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:185)
    at java.io.PrintStream.write(PrintStream.java:527)
    - locked <14f23108> (a java.io.PrintStream)
    at java.io.PrintStream.print(PrintStream.java:669)
    at sun.misc.HexDumpEncoder.encodeAtom(HexDumpEncoder.java:94)
    at sun.misc.CharacterEncoder.encodeBuffer(CharacterEncoder.java:292)
    at sun.misc.CharacterEncoder.encodeBuffer(CharacterEncoder.java:312)
    at sun.misc.CharacterEncoder.encodeBuffer(CharacterEncoder.java:340)
    at sun.security.ssl.EngineWriter.dumpPacket(EngineWriter.java:141)
    at sun.security.ssl.EngineWriter.writeRecord(EngineWriter.java:172)
    - locked <3f29d264> (a sun.security.ssl.EngineWriter)
    at sun.security.ssl.SSLEngineImpl.writeRecord(SSLEngineImpl.java:1300)
    at sun.security.ssl.SSLEngineImpl.writeAppRecord(SSLEngineImpl.java:1271)
    - locked <4abd2fb4> (a java.lang.Object)
    at sun.security.ssl.SSLEngineImpl.wrap(SSLEngineImpl.java:1186)
    - locked <4fc23d9a> (a java.lang.Object)
    at javax.net.ssl.SSLEngine.wrap(SSLEngine.java:469)
    at io.netty.handler.ssl.SslHandler.wrap(SslHandler.java:606)
    at io.netty.handler.ssl.SslHandler.wrapNonAppData(SslHandler.java:546)
    at io.netty.handler.ssl.SslHandler.unwrap(SslHandler.java:943)
    at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:873)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:241)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:149)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:333)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:319)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:787)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:125)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:116)
    at java.lang.Thread.run(Thread.java:745)

   Locked ownable synchronizers:
    - None

Shouldn't vert.x put the blocking SSL business into a worker thread ?  I realize that might not solve the client timeout problem, but it would certainly allow other verticle instances to do their business.  Or am I missing something here ?

[Alexander Lehmann]

I would expect the ssl code is not blocking at all, the net socket should be written to in only thread.

[Tim Fox]

Which version of Vert.x (and Netty) are you using?

--
You received this message because you are subscribed to the Google Groups "vert.x" group.
To unsubscribe from this group and stop receiving emails from it, send an email to vertx+un...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Hui Zhang]

We noticed the same issue in version 2.1.5 as well, and the root cause is that magic part of instantiating multiple NetServer/HttpServer listening on the same port, Vert.X has a cache to remember the serverId, if the same host/port is used, it wont start a new one since you will get Exception trying to listening on the same port, so multiple verticles are actually share the same NetSerber/HttpServer, as well as SSLEngine, and SSLEngine unwrap/wrap has synchronized block inside to guarantee the packet order, even though you have multiple verticles to handle the messages, the actually message wrapping (back to client) could be blocked.

Cheers,

Hui

...

[Kris Groves]

Version 2.1.5 and the netty dependency that is pulled from that.

...

[Kris Groves]

Have you seen different behavior in vert.x 3 ?

[Tim Fox]

Vert.x 2.15 uses Netty 4.0.21

I don't see any Vert.x classes in the stack trace at all, and looking at the SslHandler which uses the JDK SSL implementation it looks like thread contention due to an unfortunately synchronized part of the SSL engine, that will affect anyone creating a Netty SSL handler (i.e. not Vert.x specific).

I suggest you add an issue against the Netty project, and please can you add me on the cc as I would be interested in hearing feedback on this.

--

[Kris Groves]

The issue has been opened here https://github.com/netty/netty/issues/3854.

So, netty bottleneck aside, shouldn't vert.x farm the SSLHandler/SSLEngine access into a worker ?  At least then the eventloop threads would be free to work for other verticle instances, as opposed to waiting in a blocked state.  Looking into the NetSocketImpl.java, shows that vert.x 3 will suffer from the same.

[Tim Fox]

On 02/06/15 14:15, Kris Groves wrote:

The issue has been opened here https://github.com/netty/netty/issues/3854.

So, netty bottleneck aside, shouldn't vert.x farm the SSLHandler/SSLEngine access into a worker ?

No, I don't think so. Unwrapping SSL shouldn't introduce contention.

At least then the eventloop threads would be free to work for other verticle instances, as opposed to waiting in a blocked state.  Looking into the NetSocketImpl.java, shows that vert.x 3 will suffer from the same.


On Tuesday, June 2, 2015 at 9:25:14 AM UTC+2, Tim Fox wrote:

Vert.x 2.15 uses Netty 4.0.21

I don't see any Vert.x classes in the stack trace at all, and looking at the SslHandler which uses the JDK SSL implementation it looks like thread contention due to an unfortunately synchronized part of the SSL engine, that will affect anyone creating a Netty SSL handler (i.e. not Vert.x specific).

I suggest you add an issue against the Netty project, and please can you add me on the cc as I would be interested in hearing feedback on this.

--

[Nat]

The contention seems to come from running the process with -Djavax.net.debug. If you take it off, it should be ok.

[Tim Fox]

Ah good catch. I guess you are referring to the debug code here:

http://grepcode.com/file/repository.grepcode.com/java/root/jdk/openjdk/6-b14/sun/security/ssl/CipherBox.java#304

Which we can see in Kris's stack trace.

[Jez P]

This is a load test so I'd hope the process isn't being run with -Djavax.net.debug (if you are running with that you should check your other JVM parameters as well, you might have others set which will affect performance negatively).

[Kris Groves]

Bingo. 

Thanks for all the support.