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 called
startHandshake 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 00 04 01 00 80 00 00 05 00 .9... ..........
0010: 00 2F 00 00 33 00 00 32 00 00 0A 07 00 C0 00 00 ./..3..2........
0020: 16 00 00 13 00 00 09 06 00 40 00 00 15 00 00 12 .........@......
0030: 00 00 03 02 00 80 00 00 08 00 00 14 00 00 11 44 ...............D
0040: 20 81 73 DE 0D 11 4E DA 06 A5 05 05 98 31 C3 4B .s...N......1.K
0050: DD 74 9A F7 F3 59 DE 32 FE 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 RSA public 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 54 68 B0 83 8E 44 93 F7 13 / .T...Th...D...
0010: 1C 84 1B D7 74 D8 9C D8 61 85 16 4E 63 82 E9 3D ....t...a..Nc..=
0020: 44 73 77 53 0C D6 C4 D0 A8 FE 9E 23 BD 3A BC B2 DswS.......#.:..
0030: 83 B6 E0 6D 3B 5F 4E 5B AA 40 12 D2 95 FC 4C 2C ...m;_N[.@....L,
0040: C2 02 BD 82 6C F1 20 B3 71 02 64 7D 89 42 4C 7D ....l. .q.d..BL.
0050: 83 7E FA 89 74 40 61 F4 99 5F 15 B9 77 48 67 A6 ....t@a.._..wHg.
0060: B0 4E 39 CB C6 27 5A 37 7F 5B F0 0B 8F 2C 37 6D .N9..'Z7.[...,7m
0070: 6B 41 33 F7 7D 56 A4 F3 9C 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 20 81 73 5C 83 4C D7 FD 27 ...F..D .s\.L..'
0010: F4 AE 94 0F B2 C8 4B 69 95 07 CD 38 49 B5 C5 21 ......Ki...8I..!
0020: 01 02 A9 D1 B9 02 20 44 20 81 73 9F 52 A9 E0 52 ...... D .s.R..R
0030: 31 ED 1A C9 B9 5D 70 1D 18 C4 5C 5A B0 AF 61 71 1....]p...\Z..aq
0040: F6 69 C9 39 5A 43 E5 00 2F 00 0B 00 02 40 00 02 .i.9ZC../....@..
0050: 3D 00 02 3A 30 82 02 36 30 82 01 9F 02 04 44 03 =..:0..60.....D.
0060: C1 F5 30 0D 06 09 2A 86 48 86 F7 0D 01 01 04 05 ..0...*.H.......
0070: 00 30 62 31 0B 30 09 06 03 55 04 06 13 02 61 75 .0b1.0...U....au
0080: 31 0F 30 0D 06 03 55 04 08 13 06 41 6E 64 72 65 1.0...U....Andre
0090: 77 31 0F 30 0D 06 03 55 04 07 13 06 41 6E 64 72 w1.0...U....Andr
00A0: 65 77 31 0F 30 0D 06 03 55 04 0A 13 06 41 6E 64 ew1.0...U....And
00B0: 72 65 77 31 0F 30 0D 06 03 55 04 0B 13 06 41 6E rew1.0...U....An
00C0: 64 72 65 77 31 0F 30 0D 06 03 55 04 03 13 06 41 drew1.0...U....A
00D0: 6E 64 72 65 77 30 1E 17 0D 30 36 30 32 32 38 30 ndrew0...0602280
00E0: 33 32 32 32 39 5A 17 0D 33 33 30 37 31 35 30 33 32229Z..33071503
00F0: 32 32 32 39 5A 30 62 31 0B 30 09 06 03 55 04 06 2229Z0b1.0...U..
0100: 13 02 61 75 31 0F 30 0D 06 03 55 04 08 13 06 41 ..au1.0...U....A
0110: 6E 64 72 65 77 31 0F 30 0D 06 03 55 04 07 13 06 ndrew1.0...U....
0120: 41 6E 64 72 65 77 31 0F 30 0D 06 03 55 04 0A 13 Andrew1.0...U...
0130: 06 41 6E 64 72 65 77 31 0F 30 0D 06 03 55 04 0B .Andrew1.0...U..
0140: 13 06 41 6E 64 72 65 77 31 0F 30 0D 06 03 55 04 ..Andrew1.0...U.
0150: 03 13 06 41 6E 64 72 65 77 30 81 9F 30 0D 06 09 ...Andrew0..0...
0160: 2A 86 48 86 F7 0D 01 01 01 05 00 03 81 8D 00 30 *.H............0
0170: 81 89 02 81 81 00 A9 50 39 05 2B 23 CB 05 05 EF .......P9.+#....
0180: D7 0B B9 F9 75 AA 74 C8 8A B5 C3 F1 CB B5 09 5D ....u.t........]
0190: DB C3 F2 5E F7 CE BF 01 BE 4D 8D C0 71 CC 81 1F ...^.....M..q...
01A0: 5C 38 95 89 93 1B 0D 9E 73 2E A5 F0 F2 1E 92 E4 \8......s.......
01B0: 19 57 F2 F9 A1 E7 AB 6A 15 CF F9 D7 8B EC 15 CB .W.....j........
01C0: E4 39 5F 12 F1 B0 D3 16 C9 A6 3A 27 21 9E 30 4F .9_.......:'!.0O
01D0: 77 21 0A 5A 83 D2 3B C2 AA A1 55 8F 3B B0 54 0A w!.Z..;...U.;.T.
01E0: F0 35 45 94 09 CE 46 F7 19 DC 89 21 56 34 E8 34 .5E...F....!V4.4
01F0: 20 F5 E3 B9 6A 5D 02 03 01 00 01 30 0D 06 09 2A ...j].....0...*
0200: 86 48 86 F7 0D 01 01 04 05 00 03 81 81 00 2F 20 .H............/
0210: B9 54 B5 DF AF 54 68 B0 83 8E 44 93 F7 13 1C 84 .T...Th...D.....
0220: 1B D7 74 D8 9C D8 61 85 16 4E 63 82 E9 3D 44 73 ..t...a..Nc..=Ds
0230: 77 53 0C D6 C4 D0 A8 FE 9E 23 BD 3A BC B2 83 B6 wS.......#.:....
0240: E0 6D 3B 5F 4E 5B AA 40 12 D2 95 FC 4C 2C C2 02 .m;_N[.@....L,..
0250: BD 82 6C F1 20 B3 71 02 64 7D 89 42 4C 7D 83 7E ..l. .q.d..BL...
0260: FA 89 74 40 61 F4 99 5F 15 B9 77 48 67 A6 B0 4E ..t@a.._..wHg..N
0270: 39 CB C6 27 5A 37 7F 5B F0 0B 8F 2C 37 6D 6B 41 9..'Z7.[...,7mkA
0280: 33 F7 7D 56 A4 F3 9C 49 FC 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 implementation for 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 28 44 DB 87 07 BE 06 FB EC .... .e(D.......
0010: 42 84 0E 72 B1 3A 75 E3 73 27 69 AB 3F 6D B7 1E B..r.:u.s'i.?m..
0020: 20 84 62 85 8A E9 93 60 03 DE 33 19 8A 66 D0 14 .b....`..3..f..
CONNECTION KEYGEN:
Client Nonce:
0000: 44 20 81 73 DE 0D 11 4E DA 06 A5 05 05 98 31 C3 D .s...N......1.
0010: 4B DD 74 9A F7 F3 59 DE 32 FE 6E 38 10 55 83 E6 K.t...Y.2.n8.U..
Server Nonce:
0000: 44 20 81 73 5C 83 4C D7 FD 27 F4 AE 94 0F B2 C8 D .s\.L..'......
0010: 4B 69 95 07 CD 38 49 B5 C5 21 01 02 A9 D1 B9 02 Ki...8I..!......
Master Secret:
0000: CC E5 5A 01 1E 21 FB 78 1C 6C 79 AC 97 CF 74 D2 ..Z..!.x.ly...t.
0010: 75 C9 D7 FC D1 41 14 8D 99 97 5C D1 4B 50 C0 71 u....A....\.KP.q
0020: 90 F1 7D D6 F7 C2 4F 32 5C F5 A7 ED 56 B0 62 C6 ......O2\...V.b.
Client MAC write Secret:
0000: 3B A6 E8 E4 A0 CD 81 91 F4 72 06 32 8A 82 E4 43 ;........r.2...C
0010: 68 61 72 3C har<
Server MAC write Secret:
0000: 36 DC 6A D5 AA F8 A0 82 C8 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 96 EB 82 19 D6 65 EC D3 C0 ..6<........e...
Server write key:
0000: FA 41 F6 8A 38 C6 7E A7 1A 37 7D D8 D8 3E 49 32 .A..8....7...>I2
Client write IV:
0000: 8F 57 52 BC AF C8 C8 CF 72 8E A6 6A C4 16 B1 DD .WR.....r..j....
Server write IV:
0000: 6F 56 F8 28 8B EB 29 86 87 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 92 C4 12 6D 61 42 47 0F C5 ..........maBG..
0010: AA BB D2 7A D8 3F 24 08 B4 82 C0 F0 9F DD F2 15 ...z.?$.........
0020: EC E7 77 23 5A A6 18 F6 50 F8 88 2E 1B A0 BE A3 ..w#Z...P.......
0030: E7 10 F5 6B 5C 6E 78 1F 04 5E AC 72 7B 6E 13 64 ...k\nx..^.r.n.d
0040: C2 66 35 D8 27 21 F5 F9 6F 76 42 26 A8 A7 F6 A0 .f5.'!..ovB&....
0050: 57 E8 F8 7F EF D7 37 B5 AE E9 D6 C6 9E 15 38 56 W.....7.......8V
0060: 14 AB C3 65 15 9A EF A4 2F C6 7F 8D BC 04 9A 4D ...e..../......M
0070: D0 4B 2B FE 94 16 49 E2 00 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 1A C7 C2 4C B4 CC BC 9F 1E .....=R...L.....
0010: 4C BB FC 2E 84 10 69 04 3C 14 23 5C 02 91 45 C6 L.....i.<.#\..E.
0020: 5C 18 A9 91 0B 0B 0B 0B 0B 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 1A C7 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 D0 94 E7 CE 9C 3B 5A D8 76 ......6.....;Z.v
Padded plaintext before ENCRYPTION: len = 48
0000: 14 00 00 0C B7 18 36 D0 94 E7 CE 9C 3B 5A D8 76 ......6.....;Z.v
0010: A5 23 2C 7D 01 E6 B2 D4 6D D1 3F 0E 17 EB 92 09 .#,.....m.?.....
0020: 3B E5 A3 A8 0B 0B 0B 0B 0B 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 40 85 0D 96 1C 24 85 0D 94 .......@....$...
0010: 41 02 40 02 00 10 08 0D 11 10 00 A4 8F D9 FD 86 A.@.............
0020: EA 3E 1E FA 2E B3 7A 63 22 81 31 4A 1F 57 C6 00 .>....zc".1J.W..
Padded plaintext before ENCRYPTION: len = 64
0000: 00 21 01 00 00 C0 00 40 85 0D 96 1C 24 85 0D 94 .!.....@....$...
0010: 00 04 00 05 0F E3 1D 41 D3 5A B7 9B 9D 37 06 8D .......A.Z...7..
0020: 32 20 08 F3 D5 56 07 DD F2 B9 25 A0 8B EF 72 EF 2 ...V....%...r.
0030: 1C 03 93 19 3E F8 2E 08 08 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 07 EE 7B 90 15 78 66 86 79 ..o..E......xf.y
0010: 91 71 86 59 97 F3 09 09 09 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 08 AD A0 96 40 36 FB 09 60 .....Oq....@6..`
0010: F0 6D E5 FC 4E B9 09 09 09 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)