Description of problem: When accessing specific HTTPS sites using wget,firefox,java or whatever I noticed a major performance penalty when using RHEL 5 (as appose to RHEL 4). How reproducible: using time and wget to measure a single file download Steps to Reproduce: run time wget https://myaccount.bellsouth.com/scripts/winstyles.css >> /dev/null 2>&1 Actual results: #using RHEL 5.4 : time wget https://myaccount.bellsouth.com/scripts/winstyles.css >> /dev/null 2>&1 real 0m48.798s user 0m0.008s sys 0m0.000s Expected results: using RHEL 4.8 : time wget https://myaccount.bellsouth.com/scripts/winstyles.css >> /dev/null 2>&1 real 0m0.628s user 0m0.000s sys 0m0.010s Additional info: * This behavior is present on other modern distributions I checked (Ubuntu 9.04/9.10/10.04) * This was tested on different hardwares/Virtualization technologies on different sites (on different continents !) * This HTTPS site doesn't answer ping (and maybe other ICMP) * Works like a charm on RHEL 4 and Windows XP Some tcpdump info : the bad - RHEL 5.4 04:08:06.840950 IP (tos 0x0, ttl 64, id 14288, offset 0, flags [none], proto: TCP (6), length: 60) 10.1.1.9.45188 > myaccount.bellsouth.com.https: S, cksum 0xae1a (correct), 277972641:277972641(0) win 5840 <mss 1460,sackOK,timestamp 1006376 0,nop,wscale 7> 04:08:06.907911 IP (tos 0x0, ttl 107, id 51210, offset 0, flags [DF], proto: TCP (6), length: 48) myaccount.bellsouth.com.https > 10.1.1.9.45188: S, cksum 0xb212 (correct), 19761080:19761080(0) ack 277972642 win 8760 <mss 1460,wscale 0,eol> 04:08:06.907926 IP (tos 0x0, ttl 64, id 14289, offset 0, flags [none], proto: TCP (6), length: 40) 10.1.1.9.45188 > myaccount.bellsouth.com.https: ., cksum 0xfee0 (correct), 1:1(0) ack 1 win 46 04:08:06.908118 IP (tos 0x0, ttl 64, id 14290, offset 0, flags [none], proto: TCP (6), length: 158) 10.1.1.9.45188 > myaccount.bellsouth.com.https: P 1:119(118) ack 1 win 46 04:08:06.976778 IP (tos 0x0, ttl 234, id 63452, offset 0, flags [none], proto: TCP (6), length: 86) myaccount.bellsouth.com.https > 10.1.1.9.45188: P 1:47(46) ack 119 win 12170 04:08:06.976814 IP (tos 0x0, ttl 64, id 14291, offset 0, flags [none], proto: TCP (6), length: 40) 10.1.1.9.45188 > myaccount.bellsouth.com.https: ., cksum 0xfe3c (correct), 119:119(0) ack 47 win 46 04:08:07.043170 IP (tos 0x0, ttl 234, id 63495, offset 0, flags [none], proto: TCP (6), length: 86) myaccount.bellsouth.com.https > 10.1.1.9.45188: P 47:93(46) ack 119 win 12170 04:08:07.043237 IP (tos 0x0, ttl 64, id 14292, offset 0, flags [none], proto: TCP (6), length: 40) 10.1.1.9.45188 > myaccount.bellsouth.com.https: ., cksum 0xfe0e (correct), 119:119(0) ack 93 win 46 04:08:07.109415 IP (tos 0x0, ttl 234, id 63587, offset 0, flags [none], proto: TCP (6), length: 86) myaccount.bellsouth.com.https > 10.1.1.9.45188: P 93:139(46) ack 119 win 12170 04:08:07.109485 IP (tos 0x0, ttl 64, id 14293, offset 0, flags [none], proto: TCP (6), length: 40) 10.1.1.9.45188 > myaccount.bellsouth.com.https: ., cksum 0xfde0 (correct), 119:119(0) ack 139 win 46 04:08:07.175523 IP (tos 0x0, ttl 234, id 63684, offset 0, flags [none], proto: TCP (6), length: 86) myaccount.bellsouth.com.https > 10.1.1.9.45188: P 139:185(46) ack 119 win 12170 04:08:07.175620 IP (tos 0x0, ttl 64, id 14294, offset 0, flags [none], proto: TCP (6), length: 40) 10.1.1.9.45188 > myaccount.bellsouth.com.https: ., cksum 0xfdb2 (correct), 119:119(0) ack 185 win 46 04:08:07.241776 IP (tos 0x0, ttl 234, id 63726, offset 0, flags [none], proto: TCP (6), length: 86) myaccount.bellsouth.com.https > 10 the good RHEL 4.8 tcpdump: listening on eth0, link-type EN10MB (Ethernet), capture size 96 bytes 04:04:37.208327 IP (tos 0x0, ttl 64, id 54711, offset 0, flags [DF], proto 6, length: 60) 10.1.1.151.32784 > myaccount.bellsouth.com.https: S [tcp sum ok] 4277436240:4277436240(0) win 5840 <mss 1460,sackOK,timestamp 2271975 0,nop,wscale 2> 04:04:37.275545 IP (tos 0x0, ttl 107, id 45873, offset 0, flags [DF], proto 6, length: 48) myaccount.bellsouth.com.https > 10.1.1.151.32784: S [tcp sum ok] 26138491:26138491(0) ack 4277436241 win 8760 <mss 1460,wscale 0,eol> 04:04:37.275583 IP (tos 0x0, ttl 64, id 54713, offset 0, flags [DF], proto 6, length: 40) 10.1.1.151.32784 > myaccount.bellsouth.com.https: . [tcp sum ok] 1:1(0) ack 1 win 1460 04:04:37.275835 IP (tos 0x0, ttl 64, id 54715, offset 0, flags [DF], proto 6, length: 182) 10.1.1.151.32784 > myaccount.bellsouth.com.https: P 1:143(142) ack 1 win 1460 04:04:37.344663 IP (tos 0x0, ttl 234, id 62601, offset 0, flags [none], proto 6, length: 119) myaccount.bellsouth.com.https > 10.1.1.151.32784: P 1:80(79) ack 143 win 12146 04:04:37.344689 IP (tos 0x0, ttl 64, id 54717, offset 0, flags [DF], proto 6, length: 40) 10.1.1.151.32784 > myaccount.bellsouth.com.https: . [tcp sum ok] 143:143(0) ack 80 win 1460 04:04:37.344909 IP (tos 0x0, ttl 234, id 62602, offset 0, flags [none], proto 6, length: 840) myaccount.bellsouth.com.https > 10.1.1.151.32784: P 80:880(800) ack 143 win 12146 04:04:37.344912 IP (tos 0x0, ttl 234, id 62603, offset 0, flags [none], proto 6, length: 49) myaccount.bellsouth.com.https > 10.1.1.151.32784: P [tcp sum ok] 880:889(9) ack 143 win 12146 04:04:37.344975 IP (tos 0x0, ttl 64, id 54719, offset 0, flags [DF], proto 6, length: 40) 10.1.1.151.32784 > myaccount.bellsouth.com.https: . [tcp sum ok] 143:143(0) ack 880 win 1860 04:04:37.344979 IP (tos 0x0, ttl 64, id 54721, offset 0, flags [DF], proto 6, length: 40) 10.1.1.151.32784 > myaccount.bellsouth.com.https: . [tcp sum ok] 143:143(0) ack 889 win 1860 04:04:37.345730 IP (tos 0x0, ttl 64, id 54723, offset 0, flags [DF], proto 6, length: 226) 10.1.1.151.32784 > myaccount.bellsouth.com.https: P 143:329(186) ack 889 win 1860 04:04:37.415340 IP (tos 0x0, ttl 234, id 62638, offset 0, flags [none], proto 6, length: 46) myaccount.bellsouth.com.https > 10.1.1.151.32784: P [tcp sum ok] 889:895(6) ack 329 win 11960 04:04:37.415826 IP (tos 0x0, ttl 234, id 62639, offset 0, flags [none], proto 6, length: 81) myaccount.bellsouth.com.https > 10.1.1.151.32784: P [tcp sum ok] 895:936(41) ack 329 win 11960 04:04:37.415852 IP (tos 0x0, ttl 64, id 54725, offset 0, flags [DF], proto 6, length: 40) 10.1.1.151.32784 > myaccount.bellsouth.com.https: . [tcp sum ok] 329:329(0) ack 936 win 1860 Notice the Dont Fragment flag and packet size(maybe its a PMTU discovery issue?) some strace The good : read(3, "\27\3\1\33g", 5) = 5 read(3, "w\240\330\314~M{\356\22\223\261\271\253\310\227Qq\324\223\304\307\321\210\26\16\201L\301\375\351\207\7"..., 7015) = 5899 read(3, "t\265{E?V1\24I%F\243\200\20\340J;`\3215\37\342\204[o\24O\325\316\30\246\334"..., 1116) = 1116 clock_gettime(CLOCK_MONOTONIC, {936008, 697757726}) = 0 write(4, "scOn { font-family: Verdana, Ari"..., 4096) = 4096 write(4, "ecoration: underline; }\n\n.leftNa"..., 2899) = 2899 write(2, " ", 1 ) = 1 write(2, ".", 1.) = 1 write(2, ".", 1.) = 1 write(2, ".", 1.) = 1 write(2, ".", 1.) = 1 write(2, ".", 1.) = 1 write(2, ".", 1.) = 1 write(2, ".", 1.) = 1 the bad : read(3, "\237\210RY\201\201<\33\366\n\357B\372\205B\377j\367)d\311\200In'\246U1\264\264\241*"..., 1412) = 46 read(3, "mE\232\331F_M\311 \251\371;H]\347\316D\371\302\305Ft\264\272\215\226\207RG[\327\273"..., 1366) = 46 read(3, "\316t\3062\310K.B\6J\337\352\271\24\256\1P\264W\340\265\3656\352<a\244\304y\221\307\201"..., 1320) = 46 read(3, "z\227\0\245\355\253-\27\221j7\321\313\r\5Fy\2251\16\361%>\217fA\275\360g\242$\214"..., 1274) = 46 read(3, "\232\236\271\\\7Q$c\303\351\351\366a\336\4\353!M[E\272\271\222\227\312\262|H<\207\373r"..., 1228) = 46 read(3, "4<\4\351i\214\373z\231\350\276t'\345P\351\333\234\312\212\215\307\324\235C\22\264\277\307>W\231"..., 1182) = 46 read(3, "\3239\362\2319JW\252\3428\364j\361 \r\312\316\34XO\226\33},\220\362\25;\267O\4,"..., 1136) = 46 read(3, "\372\322A\255a\262\22\342\305\10\21\3122x{\257\260f\352\1R\326\333\360\247\276u\263\310\272\331c"..., 1090) = 46 read(3, "<f3\221\36\r\373io\314\5\225\213\21\221\362\210`\372\241U\361EN)!f\345/W\226["..., 1044) = 46 read(3, "\301\t\223i\337\331\5x\302.\262\261k\6F!\203\257\0\342\333\352\3415\240\177t#\301Z\357\336"..., 998) = 46 read(3, "\256\17l\22\32d[\367d\21c!\302M\273G\376Xv\217\324e-\301\34\377L1\201\234\26N"..., 952) = 46 read(3, "\25`\243\226\227F\4\221\30\231'\35\237v\0248\226\350\36\30\214Fz\"\300\365\355\314\r-\307\1"..., 906) = 46 read(3, "C7j)\251d\274t\327M\21\273W<\204Myvr\230\203\217\375\201\251^\260j\207\301=z"..., 860) = 46 read(3, "_\6D\326\0\243\340\315\235T\31'\321\363\207\200\33sy@\322\20f_\10cl\"\326\252\232\204"..., 814) = 46 read(3, "\337W>f\301%\177u\276\373\3729\34\250\206\r\213\234%\247j\274u\322\333\254E?\377\314\f\26"..., 768) = 46 read(3, "\6\240\227\3\310+\344\347\v\327\351Qy\374\f\250z4\201\17B\227;\233\226l\25\363\321AV\202"..., 722) = 46 read(3, "\272\222!\17\343\253\306\363M=\220\247pL\335w\233_\365\267C\270\25\327J\340\226i\315\31v\r"..., 676) = 46 read(3, "\275Ko\300\223)}\240\312!\217\324\r`\243bg\370}\222\335-\365\230\f\205\22\236\272\271A;"..., 630) = 46 read(3, "\337Y\30`\221\213\206\"6\310\360-\36\0037\223\322u\276O\306\363#%\277#d\24\253hU\251"..., 584) = 46 read(3, "\206vYk\2F\356\226\25\314\324\263\327\225!\205\225\322a8\265C-\200\3430\306\23\33\177\0\255"..., 538) = 46 read(3, "\201\211\0\217K\200<\322\340\221\\\347j\237_\21\363\v\360\315\7\200bj\221\322\300\342\370\r\226s"..., 492) = 46 read(3, "c\274n\235\320\234[\363;\205\23\257\352\247\0\326{NO\244\304\316\310.\346_\326\222{?\252E"..., 446) = 46 read(3, "\372?\4\365\240Q\326l\361\256\5\246y\273\334\373v\212\321\224M\31\225\373\35\31\231vM]\23:"..., 400) = 46 read(3, "C|\223[\215\210\24\16\270\204C\26\352\177\207@\325\253YH\201\322\313\240\212s\264^\343\330db"..., 354) = 46 read(3, "g\222\306~S\352\3255\313\365\255\346c\250l\335b)C\222=\272\363Z}\351\331\232$p%\217"..., 308) = 46 read(3, "9i\373\234\221 \r&y\211\251\16\335_\267gF\31#\350\346\rAW\320\32\257K%\27\t\302"..., 262) = 46 read(3, ")k\324\242\333E\33X\231f\347)\221\326\361}\234\305\241\7\327\2SC\366Vx\216\312\"\337."..., 216) = 46 read(3, "\236G\316\\\17\310X\0\367\272\301\242\304\253&/\305r\357\323V\322\317\3102y\241\31\356\220\v\4"..., 170) = 46 read(3, ">\372\232\313\245\210\vrZ\213&\2563\337\276\0366\253,[\201\224\277\27\3/\37\2305\354=\315"..., 124) = 46 read(3, "E#\214\223\272\34\37\223\35Y^\350\240\r\22S\211\375\r\20\315]&\2506\355\255\17ai0_"..., 78) = 46 read(3, "G\357g\236\335\23DO\323\230\266\225'\230<\301yo\274=X\203c\245\17d\240@w\37\21\270", 32) = 32 clock_gettime(CLOCK_MONOTONIC, {1023056, 347253320}) = 0 write(4, "scOn { font-family: Verdana, Ari"..., 4096) = 4096 write(4, "ecoration: underline; }\n\n.leftNa"..., 2899) = 2899 write(2, " ", 1 ) = 1 write(2, ".", 1.) = 1 write(2, ".", 1.) = 1 write(2, ".", 1.) = 1 write(2, ".", 1.) = 1 write(2, ".", 1.) = 1 write(2, ".", 1.) = 1 write(2, ".", 1.) = 1 (file descriptor 3 is /lib64/libnss_dns.so.2 and 4 is wget output)
I suppose this is a configuration or the remote site issue. However I am reassigning to glibc as it is certainly not an issue of one particular SSL implementation.
glibc does not do any SSL stuff.
I don't think it is an SSL issue at all - I suspect some DNS or TCP kernel stack problem.
Hi,is there any way I can get this issue fixed ? is there some data missing ? some test you need me to run ?
Using REL-6.4 (pre-release) time wget https://myaccount.bellsouth.com/scripts/winstyles.css >> /dev/null 2>&1 real 0m27.177s user 0m0.016s sys 0m0.017s Lower that 5.4 but still high. Whether nss is the main culprit I don't know yet.
This is a broken or slow server. The server needs 5 seconds in total to send the initial sever_hello message plus the certificates message, which it actually sends very inefficiently in many small data packages, with delays in between. Immediately afterwards we get the key exchange and cipher agreement, immediately followed by the client sending the HTTP request. Then the server continuous to send the web content very inefficiently in many small packets. This isn't a bug in NSS. If this slowness can only be seen with certain kind of requests (based on client OS or client configuration which lists the options to the server during the SSL/TLS handshake), then in my opinion, the server deliberately decides to throttle the data delivery to the client. (Note that I wasn't able to connect to the server at all using a different OS that used curl with openssl, in that configuration curl reported a broken protocol.)