JSSE Server Performance Problem handshake takes several second and max CPU
Hello,
I am hoping someone may be able to help with this performance problem.
It seems to take a couple of seconds for a TLS connection to establish over TCP
and then when I make several simultaneous connections to my server, performance becomes really bad.
For example 10 simultaneous connections from clients take 20 seconds.
The CPU usage on the server also appears to go through the roof.
The SSL debug and thread dump are shown below.
The thread dump shows that I have calledstartHandshake to kick off the SSL negotiation but I get
the same performance if I let the negotiation happen when the first bit of data flows.
Note that I am not using HTTP but just TCP.
I have highlighted the spot where the hangup occurs.
I am wondering if anyone could help with this.
I am using the cipher TLS_RSA_WITH_AES_128_CBC_SHA and have found that I can select other
ciphers with worse performance, for example SSL_RSA_EXPORT_WITH_RC4_40_MD5
Thanks
neil
[read] MD5 and SHA1 hashes: len = 3
0000: 01 03 01...
[read] MD5 and SHA1 hashes: len = 95
0000: 00 39 00 00 00 20 00 0004 01 00 80 00 00 05 00 .9... ..........
0010: 00 2F 00 00 33 00 00 3200 00 0A 07 00 C0 00 00 ./..3..2........
0020: 16 00 00 13 00 00 09 0600 40 00 00 15 00 00 12 .........@......
0030: 00 00 03 02 00 80 00 0008 00 00 14 00 00 11 44 ...............D
0040: 20 81 73 DE 0D 11 4E DA06 A5 05 05 98 31 C3 4B.s...N......1.K
0050: DD 74 9A F7 F3 59 DE 32FE 6E 38 10 55 83 E6.t...Y.2.n8.U..
Thread-48, READ: SSL v2, contentType = Handshake, translated length = 73
*** ClientHello, TLSv1
RandomCookie: GMT: 1142915443 bytes ={ 222, 13, 17, 78, 218, 6, 165, 5, 5, 152, 49, 195, 75, 221, 116, 154, 247, 243, 89, 222, 50, 254, 110, 56, 16, 85, 131, 230}
Session ID:{}
Cipher Suites: [SSL_RSA_WITH_RC4_128_MD5, SSL_RSA_WITH_RC4_128_SHA, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_RSA_WITH_AES_128_CBC_SHA, TLS_DHE_DSS_WITH_AES_128_CBC_SHA, SSL_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_RSA_WITH_3DES_EDE_CBC_SHA, SSL_DHE_DSS_WITH_3DES_EDE_CBC_SHA, SSL_RSA_WITH_DES_CBC_SHA, SSL_DHE_RSA_WITH_DES_CBC_SHA, SSL_DHE_DSS_WITH_DES_CBC_SHA, SSL_RSA_EXPORT_WITH_RC4_40_MD5, SSL_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_DHE_RSA_EXPORT_WITH_DES40_CBC_SHA, SSL_DHE_DSS_EXPORT_WITH_DES40_CBC_SHA]
Compression Methods:{ 0}
***
%% Created: [Session-2, TLS_RSA_WITH_AES_128_CBC_SHA]
*** ServerHello, TLSv1
RandomCookie: GMT: 1142915443 bytes ={ 92, 131, 76, 215, 253, 39, 244, 174, 148, 15, 178, 200, 75, 105, 149, 7, 205, 56, 73, 181, 197, 33, 1, 2, 169, 209, 185, 2}
Session ID:{68, 32, 129, 115, 159, 82, 169, 224, 82, 49, 237, 26, 201, 185, 93, 112, 29, 24, 196, 92, 90, 176, 175, 97, 113, 246, 105, 201, 57, 90, 67, 229}
Cipher Suite: TLS_RSA_WITH_AES_128_CBC_SHA
Compression Method: 0
***
Cipher suite: TLS_RSA_WITH_AES_128_CBC_SHA
*** Certificate chain
chain [0] = [
[
Version: V1
Subject: CN=Andrew, OU=Andrew, O=Andrew, L=Andrew, ST=Andrew, C=au
Signature Algorithm: MD5withRSA, OID = 1.2.840.113549.1.1.4
Key: SunJSSE RSApublic key:
public exponent:
010001
modulus:
a9503905 2b23cb05 05efd70b b9f975aa 74c88ab5 c3f1cbb5 095ddbc3 f25ef7ce
bf01be4d 8dc071cc 811f5c38 9589931b 0d9e732e a5f0f21e 92e41957 f2f9a1e7
ab6a15cf f9d78bec 15cbe439 5f12f1b0 d316c9a6 3a27219e 304f7721 0a5a83d2
3bc2aaa1 558f3bb0 540af035 459409ce 46f719dc 89215634 e83420f5 e3b96a5d
Validity: [From: Tue Feb 28 14:22:29 EST 2006,
To: Fri Jul 15 13:22:29 EST 2033]
Issuer: CN=Andrew, OU=Andrew, O=Andrew, L=Andrew, ST=Andrew, C=au
SerialNumber: [4403c1f5]
]
Algorithm: [MD5withRSA]
Signature:
0000: 2F 20 B9 54 B5 DF AF 5468 B0 83 8E 44 93 F7 13 / .T...Th...D...
0010: 1C 84 1B D7 74 D8 9C D861 85 16 4E 63 82 E9 3D ....t...a..Nc..=
0020: 44 73 77 53 0C D6 C4 D0A8 FE 9E 23 BD 3A BC B2 DswS.......#.:..
0030: 83 B6 E0 6D 3B 5F 4E 5BAA 40 12 D2 95 FC 4C 2C ...m;_N[.@....L,
0040: C2 02 BD 82 6C F1 20 B371 02 64 7D 89 42 4C 7D ....l. .q.d..BL.
0050: 83 7E FA 89 74 40 61 F499 5F 15 B9 77 48 67 A6 ....t@a.._..wHg.
0060: B0 4E 39 CB C6 27 5A 377F 5B F0 0B 8F 2C 37 6D .N9..'Z7.[...,7m
0070: 6B 41 33 F7 7D 56 A4 F39C 49 FC 7B B9 7D D3 52 kA3..V...I.....R
]
***
*** ServerHelloDone
[write] MD5 and SHA1 hashes: len = 658
0000: 02 00 00 46 03 01 44 2081 73 5C 83 4C D7 FD 27 ...F..D .s\.L..'
0010: F4 AE 94 0F B2 C8 4B 6995 07 CD 38 49 B5 C5 21 ......Ki...8I..!
0020: 01 02 A9 D1 B9 02 20 4420 81 73 9F 52 A9 E0 52 ...... D .s.R..R
0030: 31 ED 1A C9 B9 5D 70 1D18 C4 5C 5A B0 AF 61 71 1....]p...\Z..aq
0040: F6 69 C9 39 5A 43 E5 002F 00 0B 00 02 40 00 02 .i.9ZC../....@..
0050: 3D 00 02 3A 30 82 02 3630 82 01 9F 02 04 44 03 =..:0..60.....D.
0060: C1 F5 30 0D 06 09 2A 8648 86 F7 0D 01 01 04 05 ..0...*.H.......
0070: 00 30 62 31 0B 30 09 0603 55 04 06 13 02 61 75 .0b1.0...U....au
0080: 31 0F 30 0D 06 03 55 0408 13 06 41 6E 64 72 65 1.0...U....Andre
0090: 77 31 0F 30 0D 06 03 5504 07 13 06 41 6E 64 72 w1.0...U....Andr
00A0: 65 77 31 0F 30 0D 06 0355 04 0A 13 06 41 6E 64 ew1.0...U....And
00B0: 72 65 77 31 0F 30 0D 0603 55 04 0B 13 06 41 6E rew1.0...U....An
00C0: 64 72 65 77 31 0F 30 0D06 03 55 04 03 13 06 41 drew1.0...U....A
00D0: 6E 64 72 65 77 30 1E 170D 30 36 30 32 32 38 30 ndrew0...0602280
00E0: 33 32 32 32 39 5A 17 0D33 33 30 37 31 35 30 33 32229Z..33071503
00F0: 32 32 32 39 5A 30 62 310B 30 09 06 03 55 04 06 2229Z0b1.0...U..
0100: 13 02 61 75 31 0F 30 0D06 03 55 04 08 13 06 41 ..au1.0...U....A
0110: 6E 64 72 65 77 31 0F 300D 06 03 55 04 07 13 06 ndrew1.0...U....
0120: 41 6E 64 72 65 77 31 0F30 0D 06 03 55 04 0A 13 Andrew1.0...U...
0130: 06 41 6E 64 72 65 77 310F 30 0D 06 03 55 04 0B .Andrew1.0...U..
0140: 13 06 41 6E 64 72 65 7731 0F 30 0D 06 03 55 04 ..Andrew1.0...U.
0150: 03 13 06 41 6E 64 72 6577 30 81 9F 30 0D 06 09 ...Andrew0..0...
0160: 2A 86 48 86 F7 0D 01 0101 05 00 03 81 8D 00 30 *.H............0
0170: 81 89 02 81 81 00 A9 5039 05 2B 23 CB 05 05 EF .......P9.+#....
0180: D7 0B B9 F9 75 AA 74 C88A B5 C3 F1 CB B5 09 5D ....u.t........]
0190: DB C3 F2 5E F7 CE BF 01BE 4D 8D C0 71 CC 81 1F ...^.....M..q...
01A0: 5C 38 95 89 93 1B 0D 9E73 2E A5 F0 F2 1E 92 E4 \8......s.......
01B0: 19 57 F2 F9 A1 E7 AB 6A15 CF F9 D7 8B EC 15 CB .W.....j........
01C0: E4 39 5F 12 F1 B0 D3 16C9 A6 3A 27 21 9E 30 4F .9_.......:'!.0O
01D0: 77 21 0A 5A 83 D2 3B C2AA A1 55 8F 3B B0 54 0A w!.Z..;...U.;.T.
01E0: F0 35 45 94 09 CE 46 F719 DC 89 21 56 34 E8 34 .5E...F....!V4.4
01F0: 20 F5 E3 B9 6A 5D 02 0301 00 01 30 0D 06 09 2A...j].....0...*
0200: 86 48 86 F7 0D 01 01 0405 00 03 81 81 00 2F 20 .H............/
0210: B9 54 B5 DF AF 54 68 B083 8E 44 93 F7 13 1C 84 .T...Th...D.....
0220: 1B D7 74 D8 9C D8 61 8516 4E 63 82 E9 3D 44 73 ..t...a..Nc..=Ds
0230: 77 53 0C D6 C4 D0 A8 FE9E 23 BD 3A BC B2 83 B6 wS.......#.:....
0240: E0 6D 3B 5F 4E 5B AA 4012 D2 95 FC 4C 2C C2 02 .m;_N[.@....L,..
0250: BD 82 6C F1 20 B3 71 0264 7D 89 42 4C 7D 83 7E ..l. .q.d..BL...
0260: FA 89 74 40 61 F4 99 5F15 B9 77 48 67 A6 B0 4E ..t@a.._..wHg..N
0270: 39 CB C6 27 5A 37 7F 5BF0 0B 8F 2C 37 6D 6B 41 9..'Z7.[...,7mkA
0280: 33 F7 7D 56 A4 F3 9C 49FC 7B B9 7D D3 52 0E 00 3..V...I.....R..
0290: 00 00 ..
Thread-48, WRITE: TLSv1 Handshake, length = 658
Thread-48, READ: TLSv1 Handshake, length = 134
JsseJCE: Using JSSE internal implementationfor cipher RSA/ECB/PKCS1Padding
[NEILH] *********** THIS IS WHERE WE PAUSE FOR A COUPLE OF SECONDS ************ [NEILH]
RSA PreMasterSecret version: TLSv1
*** ClientKeyExchange, RSA PreMasterSecret, TLSv1
Random Secret:{ 3, 1, 3, 0, 32, 246, 101, 40, 68, 219, 135, 7, 190, 6, 251, 236, 66, 132, 14, 114, 177, 58, 117, 227, 115, 39, 105, 171, 63, 109, 183, 30, 32, 132, 98, 133, 138, 233, 147, 96, 3, 222, 51, 25, 138, 102, 208, 20}
SESSION KEYGEN:
PreMaster Secret:
0000: 03 01 03 00 20 F6 65 2844 DB 87 07 BE 06 FB EC .... .e(D.......
0010: 42 84 0E 72 B1 3A 75 E373 27 69 AB 3F 6D B7 1E B..r.:u.s'i.?m..
0020: 20 84 62 85 8A E9 93 6003 DE 33 19 8A 66 D0 14.b....`..3..f..
CONNECTION KEYGEN:
Client Nonce:
0000: 44 20 81 73 DE 0D 11 4EDA 06 A5 05 05 98 31 C3 D .s...N......1.
0010: 4B DD 74 9A F7 F3 59 DE32 FE 6E 38 10 55 83 E6 K.t...Y.2.n8.U..
Server Nonce:
0000: 44 20 81 73 5C 83 4C D7FD 27 F4 AE 94 0F B2 C8 D .s\.L..'......
0010: 4B 69 95 07 CD 38 49 B5C5 21 01 02 A9 D1 B9 02 Ki...8I..!......
Master Secret:
0000: CC E5 5A 01 1E 21 FB 781C 6C 79 AC 97 CF 74 D2 ..Z..!.x.ly...t.
0010: 75 C9 D7 FC D1 41 14 8D99 97 5C D1 4B 50 C0 71 u....A....\.KP.q
0020: 90 F1 7D D6 F7 C2 4F 325C F5 A7 ED 56 B0 62 C6 ......O2\...V.b.
Client MAC write Secret:
0000: 3B A6 E8 E4 A0 CD 81 91F4 72 06 32 8A 82 E4 43 ;........r.2...C
0010: 68 61 72 3Char<
Server MAC write Secret:
0000: 36 DC 6A D5 AA F8 A0 82C8 B4 CF B6 11 BC 93 3F 6.j............?
0010: 2D 1F 5F 43-._C
Client write key:
0000: 0B 97 36 3C FA 15 BA 96EB 82 19 D6 65 EC D3 C0 ..6<........e...
Server write key:
0000: FA 41 F6 8A 38 C6 7E A71A 37 7D D8 D8 3E 49 32 .A..8....7...>I2
Client write IV:
0000: 8F 57 52 BC AF C8 C8 CF72 8E A6 6A C4 16 B1 DD .WR.....r..j....
Server write IV:
0000: 6F 56 F8 28 8B EB 29 8687 70 3A 60 E9 97 57 55 oV.(..)..p:`..WU
[read] MD5 and SHA1 hashes: len = 134
0000: 10 00 00 82 00 80 9B 92C4 12 6D 61 42 47 0F C5 ..........maBG..
0010: AA BB D2 7A D8 3F 24 08B4 82 C0 F0 9F DD F2 15 ...z.?$.........
0020: EC E7 77 23 5A A6 18 F650 F8 88 2E 1B A0 BE A3 ..w#Z...P.......
0030: E7 10 F5 6B 5C 6E 78 1F04 5E AC 72 7B 6E 13 64 ...k\nx..^.r.n.d
0040: C2 66 35 D8 27 21 F5 F96F 76 42 26 A8 A7 F6 A0 .f5.'!..ovB&....
0050: 57 E8 F8 7F EF D7 37 B5AE E9 D6 C6 9E 15 38 56 W.....7.......8V
0060: 14 AB C3 65 15 9A EF A42F C6 7F 8D BC 04 9A 4D ...e..../......M
0070: D0 4B 2B FE 94 16 49 E200 8D 82 B1 88 D6 86 A7 .K+...I.........
0080: F7 00 35 F9 38 B5 ..5.8.
Thread-48, READ: TLSv1 Change Cipher Spec, length = 1
JsseJce: Using cipher AES/CBC/NoPadding from provider SunJCE
Thread-48, READ: TLSv1 Handshake, length = 48
Padded plaintext after DECRYPTION: len = 48
0000: 14 00 00 0C 81 3D 52 1AC7 C2 4C B4 CC BC 9F 1E .....=R...L.....
0010: 4C BB FC 2E 84 10 69 043C 14 23 5C 02 91 45 C6 L.....i.<.#\..E.
0020: 5C 18 A9 91 0B 0B 0B 0B0B 0B 0B 0B 0B 0B 0B 0B \...............
*** Finished
verify_data:{ 129, 61, 82, 26, 199, 194, 76, 180, 204, 188, 159, 30}
***
[read] MD5 and SHA1 hashes: len = 16
0000: 14 00 00 0C 81 3D 52 1AC7 C2 4C B4 CC BC 9F 1E .....=R...L.....
Thread-48, WRITE: TLSv1 Change Cipher Spec, length = 1
JsseJce: Using cipher AES/CBC/NoPadding from provider SunJCE
*** Finished
verify_data:{ 183, 24, 54, 208, 148, 231, 206, 156, 59, 90, 216, 118}
***
[write] MD5 and SHA1 hashes: len = 16
0000: 14 00 00 0C B7 18 36 D094 E7 CE 9C 3B 5A D8 76 ......6.....;Z.v
Padded plaintext before ENCRYPTION: len = 48
0000: 14 00 00 0C B7 18 36 D094 E7 CE 9C 3B 5A D8 76 ......6.....;Z.v
0010: A5 23 2C 7D 01 E6 B2 D46D D1 3F 0E 17 EB 92 09 .#,.....m.?.....
0020: 3B E5 A3 A8 0B 0B 0B 0B0B 0B 0B 0B 0B 0B 0B 0B ;...............
Thread-48, WRITE: TLSv1 Handshake, length = 48
%% Cached server session: [Session-2, TLS_RSA_WITH_AES_128_CBC_SHA]
MyListener.handshakeCompleted() GOT the completion event: javax.net.ssl.HandshakeCompletedEvent[source=1addb59[TLS_RSA_WITH_AES_128_CBC_SHA: Socket[addr=/10.102.26.23,port=39142,localport=9071]]]
MyConnection@15575e0, READ: TLSv1 Application Data, length = 48
Padded plaintext after DECRYPTION: len = 48
0000: 00 19 01 01 00 80 00 4085 0D 96 1C 24 85 0D 94 .......@....$...
0010: 41 02 40 02 00 10 08 0D11 10 00 A4 8F D9 FD 86 A.@.............
0020: EA 3E 1E FA 2E B3 7A 6322 81 31 4A 1F 57 C6 00 .>....zc".1J.W..
Padded plaintext before ENCRYPTION: len = 64
0000: 00 21 01 00 00 C0 00 4085 0D 96 1C 24 85 0D 94 .!.....@....$...
0010: 00 04 00 05 0F E3 1D 41D3 5A B7 9B 9D 37 06 8D .......A.Z...7..
0020: 32 20 08 F3 D5 56 07 DDF2 B9 25 A0 8B EF 72 EF 2 ...V....%...r.
0030: 1C 03 93 19 3E F8 2E 0808 08 08 08 08 08 08 08 ....>...........
Thread-50, WRITE: TLSv1 Application Data, length = 64
MyConnection@15575e0, READ: TLSv1 Alert, length = 32
Padded plaintext after DECRYPTION: len = 32
0000: 01 00 6F AB 1A 45 7D 07EE 7B 90 15 78 66 86 79 ..o..E......xf.y
0010: 91 71 86 59 97 F3 09 0909 09 09 09 09 09 09 09 .q.Y............
MyConnection@15575e0, RECV TLSv1 ALERT: warning, close_notify
MyConnection@15575e0, called closeInternal(false)
MyConnection@15575e0, SEND TLSv1 ALERT: warning, description = close_notify
Padded plaintext before ENCRYPTION: len = 32
0000: 01 00 D9 DD D6 4F 71 08AD A0 96 40 36 FB 09 60 .....Oq....@6..`
0010: F0 6D E5 FC 4E B9 09 0909 09 09 09 09 09 09 09 .m..N...........
MyConnection@15575e0, WRITE: TLSv1 Alert, length = 32
MyConnection@15575e0, called close()
MyConnection@15575e0, called closeInternal(true)
MyConnection@15575e0, called close()
MyConnection@15575e0, called closeInternal(true)
And here is the thread dump of the relevant thread:
Full thread dump Java HotSpot(TM) Client VM (1.4.2_08-b03 interpreted mode):
"Thread-29" prio=5 tid=0x0025b750 nid=0x2b runnable [eceff000..eceffc30]
at COM.rsa.jsafe.SunJSSE_ep.a(DashoA12275)
at COM.rsa.jsafe.SunJSSE_ep.b(DashoA12275)
at COM.rsa.jsafe.SunJSSE_ep.b(DashoA12275)
at COM.rsa.jsafe.SunJSSE_ep.a(DashoA12275)
at COM.rsa.jsafe.SunJSSE_c3.a(DashoA12275)
at COM.rsa.jsafe.SunJSSE_cv.a(DashoA12275)
at com.sun.net.ssl.internal.ssl.SunJSSE_bl.b(DashoA12275)
at com.sun.net.ssl.internal.ssl.SunJSSE_be.<init>(DashoA12275)
at com.sun.net.ssl.internal.ssl.SunJSSE_aw.a(DashoA12275)
at com.sun.net.ssl.internal.ssl.SunJSSE_ax.a(DashoA12275)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.a(DashoA12275)
- locked <0xf2178c28> (a com.sun.net.ssl.internal.ssl.SSLSocketImpl)
- locked <0xf218f8d0> (a java.lang.Object)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.j(DashoA12275)
- locked <0xf218f8f0> (a java.lang.Object)
at com.sun.net.ssl.internal.ssl.SSLSocketImpl.startHandshake(DashoA12275)
at connections.MyListenerNewConnectionThread.run(MyListenerNewConnectionThread.java:102)
- locked <0xf1b5df00> (a connections.MyListenerNewConnectionThread)
