Showing posts with label jetty. Show all posts
Showing posts with label jetty. Show all posts

Tuesday, September 9, 2014

SSH: Performance and Behaviour


The problem

We had set up a Jetty server to use SSL much as in a previous post. This was fine until we started pooling connections (pooling connections didn't greatly improve performance in London-to-London communication but improved Hong Kong-to-London performance by about 30% since the ping time for a packet was a huge 220ms). But when we pooled connections and introduced SSL, all communication froze after some happy-path results.

The problem did not appear to be with encryption itself as the first few requests succeeded. But after 30 hits, all the Jetty threads were blocked like this (from running jstack):

"qtp401625763-13" #13 prio=5 os_prio=0 tid=0x00007f3e2021b800 nid=0x1ecb runnable [0x00007f3e0d2e7000]
   java.lang.Thread.State: RUNNABLE
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:150)
at java.net.SocketInputStream.read(SocketInputStream.java:121)
at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
at sun.security.ssl.InputRecord.read(InputRecord.java:503)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:954)
- locked <0x00000000d90404a8> (a java.lang.Object)
at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:911)
at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
- locked <0x00000000d906e358> (a sun.security.ssl.AppInputStream)
at org.eclipse.jetty.io.ByteArrayBuffer.readFrom(ByteArrayBuffer.java:391)

(where we're using Jetty 7.6.15)

At first, we thought something was wrong with our certificates etc but a handful of requests at first went thorugh without issue. But look for this in the server-side logs when you have given the JVM argument -Djavax.net.debug=all

*** ServerHelloDone

on both the client and server side, then you know the server completed the handshake OK. Look for:

main, READ: TLSv1.2 Change Cipher Spec, length = 1

or, in Jetty: 

qtp1418621776-17, WRITE: TLSv1.2 Change Cipher Spec, length = 1

and you'll know the whole handshake pretty much completed OK.

What happens in SSL?

Asymmetric encryption used briefly at start-up to establish a more efficient cipher. The private keys in this exchange are ephemeral and generated on the server side as soon as it hears the client say "hello" and on the client side as soon as it receives the server's choice of key.

Syn

In kickstarting the SSL handshake, the client advertises all of its cipher suite codes, elliptic curve details etc to the server (see sun.security.ssl.HandshakeMessage$ClientHello.send(..) ). The client thread then blocks waiting for the server to respond.

Syn/Ack

Upon receiving the client's message, (see sun.security.ssl.ServerHandshaker.clientHello(..) ) the server chooses an algorithm that both client and server support. When I was stepping through the code, this appeared to be DSA. The server-side must have a public and private key that corresponds to this algorithm in its keystore (see ServerHandshaker.setupPrivateKeyAndChain(..)).

Here, a sun.security.ssl.DHCrypt is instantiated. From the JavaDocs:

"This class implements the Diffie-Hellman key exchange algorithm.  D-H means combining your private key with your partners public key to generate a number. The peer does the same with its private key and our public key. Through the magic of Diffie-Hellman we both come up with the same number. This number is secret (discounting MITM attacks) and hence called the shared secret."

Along with the server certificates, all of this is sent to the client and the server thread blocks.

Ack

The client then unblocks and deserializes the ServerHello created on the server side (via a bespoke deserialization process). It uses the cipher suite the server told it to use and checks the server's certificates and stores the server's public key. It then sends its own public key (via DHClientKeyExchange) to the server.

Symmetric cipher keys are then generated (Handshaker.calculateConnectionKeys), the client tells the server that it is ready to talk then blocks.

A little more server Ack

Given what the client and server have exchanged, the server now sets its own agreed secret key using the same method in Handshaker (that is the superclass to both ServerHandshaker and ClientHandshaker) and sends a Finished object back to the client. The server is now finished and it notifies an listeners in a separate thread (this listener can be found as an inner class in Jetty's SslConnectorEndPoint.run). The thread in SslConnectorEndPoint then awaits incoming data.

Introducing MAT

There's a very nice tool from the ladies and gentlemen of Eclipse called MAT. Very quickly, you can dump the memory of a JVM and query its contents with a SQL-like language. For instance, I found all the client-side sockets that were listening to my server port of 8192 by executing:

select * from java.net.SocksSocketImpl where port = 8192

Interestingly, all their incoming references originated in the connection pool. So that is what is keeping them open and correspondingly keeping the server threads listening for a request that never comes! All client threads doing something useful are blocked by Jetty not having any server threads to service them; and all those Jetty threads are listening on sockets whose other end is held open by the idle sockets in the client's connection pool.

Conclusion

By replacing Jetty's SslSocketConnector with its SslSelectChannelConnector, the server behaves asynchronously and connection pooling doesn't make it grind to a halt.

We rolled-our own nonce encryption and it performed poorly. When we got rid of it, we found that Jetty using SSL had roughly the same performance as plain, clear-text HTTP.


Further reading

1. A very good (maths) blog on elliptic curves.

Saturday, September 7, 2013

Anatomy of a file handle leak

Production issues are nasty. But when the same non-deterministic state happens in the performance test environment, it's a gift from the gods. You can now examine it in a controlled environment.

The back story: occasionally, a prod server running Jetty 6.1.24 on a 1.6.13 JVM would complain that it had run out of file handles. Using lsof, we could see that over a thousand handles were indeed open and that they appeared to belong to TCP ports.

Using netstat, we could see what these ports were doing:

mds@gbl04215[Skye]:~> netstat -nap 2>/dev/null | head -2 
Active Internet connections (servers and established) 
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name 
mds@gbl04215[Skye]:~> netstat -nap 2>/dev/null | grep 10302 | more 
tcp        0      0 127.0.0.1:32007         0.0.0.0:*               LISTEN      10302/java 
tcp        0      0 :::48746                :::*                    LISTEN      10302/java 
tcp        0      0 :::1099                 :::*                    LISTEN      10302/java 
tcp        0      0 128.162.27.126:8112     :::*                    LISTEN      10302/java 
tcp        0      0 :::19601                :::*                    LISTEN      10302/java 
tcp        0      0 :::41624                :::*                    LISTEN      10302/java 
tcp        0      0 :::10008                :::*                    LISTEN      10302/java 
tcp        0      0 :::19001                :::*                    LISTEN      10302/java 
tcp        0      0 :::56639                :::*                    LISTEN      10302/java 
tcp     1224      0 128.162.27.126:19001    128.164.34.13:47367     CLOSE_WAIT  10302/java 
tcp     1223      0 128.162.27.126:19001    128.164.34.13:41988     CLOSE_WAIT  10302/java 
tcp     1224      0 128.162.27.126:19001    128.164.34.11:56322     CLOSE_WAIT  10302/java 
tcp     1224      0 128.162.27.126:19001    128.164.34.11:49410     CLOSE_WAIT  10302/java 
tcp     1224      0 128.162.27.126:19001    128.164.34.11:55043     CLOSE_WAIT  10302/java 
tcp      815      0 128.162.27.126:19001    133.13.143.184:57011    ESTABLISHED 10302/java 
tcp     1224      0 128.162.27.126:19001    128.164.34.13:48896     CLOSE_WAIT  10302/java 
tcp     1769      0 128.162.27.126:19001    128.164.34.11:45830     CLOSE_WAIT  10302/java 
tcp     1768      0 128.162.27.126:19001    128.164.34.11:53254     CLOSE_WAIT  10302/java 
tcp     1770      0 128.162.27.126:19001    128.164.34.11:43783     CLOSE_WAIT  10302/java 
tcp     1224      0 128.162.27.126:19001    128.164.34.11:49927     CLOSE_WAIT  10302/java 
tcp     1224      0 128.162.27.126:19001    128.164.34.11:44040     CLOSE_WAIT  10302/java 
tcp     1769      0 128.162.27.126:19001    128.164.34.11:45321     CLOSE_WAIT  10302/java 
tcp     1770      0 128.162.27.126:19001    128.164.34.13:44300     CLOSE_WAIT  10302/java 
tcp     1768      0 128.162.27.126:19001    128.164.34.13:45066     CLOSE_WAIT  10302/java 
tcp     1769      0 128.162.27.126:19001    128.164.34.13:47114     CLOSE_WAIT  10302/java 
tcp     1224      0 128.162.27.126:19001    128.164.34.13:40970     CLOSE_WAIT  10302/java 
tcp     1224      0 128.162.27.126:19001    128.164.34.13:39434     CLOSE_WAIT  10302/java
.
.


(where our Java PID is 10303).

Hmm, OK. Well, some interesting things to note: first is that netstat tells you more than the state of the port. As the man page says, it tells you that data is backing up on the port (the second column, Recv-Q). This is measured in bytes.

The second point to note is that the local port, that is the port of our server (19001), is the port we're using for HTTP via Jetty. 

The third is the CLOSE_WAIT state. This means that the client has closed the session (by sending a FIN packet) and that our server has acknowledged it (by returning an ACK packet) but that our application has not yet told the OS to close the socket (see diagram).


Putting this information together, I dumped the JVM's memory to a file and examined its contents.



Randomly selecting a SocketChannel that happened to be lingering in memory, I took the port associated with it and checked that this was one of my ports that is in the CLOSE_WAIT state. It was and so were all the others I looked at.

So, was Jetty not closing ports? Googling didn't find anybody complaining about this but I did find a JVM bug report here that looks awfully similar.

More research is needed but this suspiciously looks like the culprit.