Bug 618697

Summary:	low performance when accessing specific HTTPS site on RHEL5
Product:	Red Hat Enterprise Linux 5	Reporter:	Oded Ben Ozer <oded>
Component:	nss	Assignee:	Elio Maldonado Batiz <emaldona>
Status:	CLOSED NOTABUG	QA Contact:	BaseOS QE Security Team <qe-baseos-security>
Severity:	medium	Docs Contact:
Priority:	low
Version:	5.4	CC:	amarecek, kengert, tmraz
Target Milestone:	rc
Target Release:	---
Hardware:	x86_64
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2013-02-19 16:25:39 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Oded Ben Ozer 2010-07-27 14:52:07 UTC

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)

Comment 1 Tomas Mraz 2010-08-02 08:59:35 UTC

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.

Comment 2 Andreas Schwab 2010-08-02 09:29:18 UTC

glibc does not do any SSL stuff.

Comment 3 Tomas Mraz 2010-08-02 13:47:05 UTC

I don't think it is an SSL issue at all - I suspect some DNS or TCP kernel stack problem.

Comment 4 Oded Ben Ozer 2011-04-03 16:19:52 UTC

Hi,is there any way I can get this issue fixed ? is there some data missing ? some test you need me to run ?

Comment 6 Elio Maldonado Batiz 2013-02-15 17:36:43 UTC

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.

Comment 7 Kai Engert (:kaie) (inactive account) 2013-02-19 16:25:39 UTC

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.)