pganti
August 4, 2014, 8:49pm
1
I am not sure if I understand totally as to how dummynet on windows work but seems like an interesting issue popped up where the initial problem was to determine whats causing SSL slowness.
First measure the same page at different speeds like for example the following: http://www.webpagetest.org/video/compare.php?tests=140804_9G_10Q3,140804_M4_10NQ,140804_HY_10MP,140804_3A_10J0
Specifically focus on Chrome-Cable and you see really long SSL times on the domain assets-tup.insnw.net
http://www.webpagetest.org/result/140804_V4_10HX/
If I use Firefox the long SSL handshake disappears leading one to believe something is about chrome
http://www.webpagetest.org/result/140804_RP_10V3/
Next I took tcpdumps on both client and server side to see whats up
Serverside:
https://www.cloudshark.org/captures/b9cf10b1bd30?filter=tcp.port%20eq%201421
Clientside:
https://www.cloudshark.org/captures/1f8459d4e0cf?filter=tcp.port%20eq%201421
In particular you want to focus on the following pkt numbers
Serverside Pkts 37,56,59,60
Clientside Pkts 24,40,80,98
As you can see server is done within 6 ms to send all the 5 packets of interest but take around 120 ms to arrive at the client thus making it around 20-25ms spacing between the packets. What gives?
The RTT between the client and server in this case is around 40 ms
[hr]
If there is ratelimiting on public wpt is it done based on subnet/host or some other dimension as I see that per tcp stream there seems to be effectively a rate limit of 500Kbps, is that right?
pganti
August 4, 2014, 9:57pm
2
If we were to plot the throughput at the server side and then the same at client side you can see the attached graphs which show that server sends like 14KB in one go and then like 30KB in second go. The client however starts really small hovers around 1.*K for a while before going to 3K then 4K and ending the transfer at 5K.
Given that Chrome Cable is 5Mbps atleast 600K is permissible and particularly when the server sends out at that rate, whats stopping the client here?
Can you capture a net log? That should provide better detail about what the net stat sees than the traces (a lot of the net layer isn’t traced right now).
pganti
August 11, 2014, 5:38pm
4
If you go to about://net-internals in chrome you can import the netlog and poke around. There are 2 pages you probably care about. The “timeline” page shows you bytes trabsferred over time (you’ll need to zoom in quite a bit). The “events” page provides a lot more detail about what chrome is seeing, particularly around the SSL negotiation and the framing (looks like 4KB SSL frames).
It’s probably best to grab netlogs and tcpdumps from the same test so they can be compared. Also, if you want to evaluate dummynet’s impact you can turn it off by selecting a “native” connection.
t= 8852 [st= 0] +SOCKET_ALIVE [dt=8971]
--> source_dependency = 362 (CONNECT_JOB)
t= 8852 [st= 0] +TCP_CONNECT [dt=39]
--> address_list = ["192.33.31.52:443"]
t= 8852 [st= 0] TCP_CONNECT_ATTEMPT [dt=39]
--> address = "192.33.31.52:443"
t= 8891 [st= 39] -TCP_CONNECT
--> source_address = "192.168.102.81:51024"
t= 8891 [st= 39] +SOCKET_IN_USE [dt=8932]
--> source_dependency = 412 (CONNECT_JOB)
t= 8891 [st= 39] +SSL_CONNECT [dt=233]
t= 8891 [st= 39] SOCKET_BYTES_SENT
--> byte_count = 220
t= 8943 [st= 91] SOCKET_BYTES_RECEIVED
--> byte_count = 1460
t= 8984 [st= 132] SOCKET_BYTES_RECEIVED
--> byte_count = 1460
t= 9013 [st= 161] SOCKET_BYTES_RECEIVED
--> byte_count = 1460
t= 9055 [st= 203] SOCKET_BYTES_RECEIVED
--> byte_count = 1352
t= 9061 [st= 209] SOCKET_BYTES_SENT
--> byte_count = 122
t= 9117 [st= 265] SOCKET_BYTES_RECEIVED
--> byte_count = 238
t= 9117 [st= 265] SSL_CERTIFICATES_RECEIVED
--> certificates =
-----BEGIN CERTIFICATE-----
MIIQSTCCDzGgAwIBAgISESEY67MNixbSiR2fgKREb4Y9MA0GCSqGSIb3DQEBBQUA
MF0xCzAJBgNVBAYTAkJFMRkwFwYDVQQKExBHbG9iYWxTaWduIG52LXNhMTMwMQYD
VQQDEypHbG9iYWxTaWduIE9yZ2FuaXphdGlvbiBWYWxpZGF0aW9uIENBIC0gRzIw
HhcNMTQwODA3MjI1MjQwWhcNMTQxMDIzMTcxMjAyWjByMQswCQYDVQQGEwJVUzET
MBEGA1UECBMKQ2FsaWZvcm5pYTEWMBQGA1UEBxMNTW91bnRhaW4gVmlldzEbMBkG
A1UEChMSSW5zdGFydCBMb2dpYywgSW5jMRkwFwYDVQQDExBzc2wwMDEuaW5zbncu
bmV0MIIBIjANBgkqhkiG9w0BAQEFAAOCAQ8AMIIBCgKCAQEAx7rIRZz0jFxMsGVT
0/a+SXP8Mk2QV9BaH/T95thAaoSLCTHAwEW7uurIEx9++ZLaPQpF3zMIqfICxZrw
V+Ro+KJPP4YQkAhUC5tM4Uhu8rytmaHPcbnHcbE5q7AkFgTpiIPu9z0VvzZwF3Sm
z1eDvjiBIGd5fby6u0E3Zuv2YGZ3C4o91i1Ooye4KP2NXJA11spW/X/OG4Rv0wvE
G8i/ssPYUcYDNfYHz8wOZri3iU2B4GuM5tYJpUw2kkiJY58dn2o3JqU9MxTaqSNy
LW7PWKGlpxOx6J3oIHKgZfv5WWWdFVP5dw1VwlWALZ5uSzLRjb7sHXe40RTkFeVc
uLleMQIDAQABo4IM7DCCDOgwDgYDVR0PAQH/BAQDAgWgMEkGA1UdIARCMEAwPgYG
Z4EMAQICMDQwMgYIKwYBBQUHAgEWJmh0dHBzOi8vd3d3Lmdsb2JhbHNpZ24uY29t
L3JlcG9zaXRvcnkvMIILPwYDVR0RBIILNjCCCzKCEHNzbDAwMS5pbnNudy5uZXSC
GHJwbS1pbnN0YXJ0Lm5ld3JlbGljLmNvbYIObGluZWFwZWxsZS5jb22CECoubGlu
ZWFwZWxsZS5jb22CDnVhdC5naHVya2EuY29tggh1bmZlLm9yZ4IKKi51bmZlLm9y
Z4ILdjFpZGVhcy5jb22CDSoudjFpZGVhcy5jb22CC2JhcmV3ZWIuY29tgg0qLmJh
cmV3ZWIuY29tgg9pbnN0YXJ0bGFicy5jb22CEGluc3RhcnRsb2dpYy5jb22CDmtv
bmdyZWdhdGUuY29tghAqLmtvbmdyZWdhdGUuY29tghNrb25ncmVnYXRldHJ1bmsu
Y29tghUqLmtvbmdyZWdhdGV0cnVuay5jb22CFGxlcGFuaWVyZnJhbmNhaXMuY29t
ghYqLmxlcGFuaWVyZnJhbmNhaXMuY29tghJ3aW5lZW50aHVzaWFzdC5jb22CFCou
d2luZWVudGh1c2lhc3QuY29tgg93aW5lZXhwcmVzcy5jb22CESoud2luZWV4cHJl
c3MuY29tghJ3b3JsZG9md2F0Y2hlcy5jb22CFCoud29ybGRvZndhdGNoZXMuY29t
ghBtb2Rhb3BlcmFuZGkuY29tghIqLm1vZGFvcGVyYW5kaS5jb22CD25hc3R5Z2Fs
LmNvbS5hdYIRKi5uYXN0eWdhbC5jb20uYXWCDm5tci5hbGxjZG4ubmV0ghAqLm5t
ci5hbGxjZG4ubmV0ghtzdGFnaW5nLWltYWdlcy5uZXdyZWxpYy5jb22CDm5vbW9y
ZXJhY2suY29tghAqLm5vbW9yZXJhY2suY29tghF0b3VjaG9mbW9kZXJuLmNvbYIT
Ki50b3VjaG9mbW9kZXJuLmNvbYIOb21uaWhvdGVscy5jb22CECoub21uaWhvdGVs
cy5jb22CEG9uZWtpbmdzbGFuZS5jb22CEXBhZGxvY2tvdXRsZXQuY29tghMqLnBh
ZGxvY2tvdXRsZXQuY29tgg5waG90b3N1Z2FyLmNvbYIQKi5waG90b3N1Z2FyLmNv
bYIKcGl4bGVlLmNvbYIMKi5waXhsZWUuY29tgg9zdGVsbGFkb3RzdGcuZnKCESou
c3RlbGxhZG90c3RnLmZyghdzdGcua2VlcC1jb2xsZWN0aXZlLmNvbYIZKi5zdGcu
a2VlcC1jb2xsZWN0aXZlLmNvbYIOc3R5bGVzYWludC5jb22CECouc3R5bGVzYWlu
dC5jb22CFHRoaW5nc3JlbWVtYmVyZWQuY29tghYqLnRoaW5nc3JlbWVtYmVyZWQu
Y29tghJ0aG9tcHNvbmhvdGVscy5jb22CFCoudGhvbXBzb25ob3RlbHMuY29tggt0
aHJlZHVwLmNvbYINKi50aHJlZHVwLmNvbYIJYWRhZ2UuY29tggsqLmFkYWdlLmNv
bYIKYWxsY2RuLm5ldIIMKi5hbGxjZG4ubmV0ghJzYWF0dmFtYXR0cmVzcy5jb22C
FCouc2FhdHZhbWF0dHJlc3MuY29tghRzdGFnaW5nLm5ld3JlbGljLmNvbYIWc3Rh
dGljLnBhcmFzdG9yYWdlLmNvbYIPc3RlbGxhZG90LmNvLnVrghEqLnN0ZWxsYWRv
dC5jby51a4IUc3RhdGljLndpeHN0YXRpYy5jb22CDXN0ZWxsYWRvdC5jb22CDyou
c3RlbGxhZG90LmNvbYIMc3RlbGxhZG90LmRlgg4qLnN0ZWxsYWRvdC5kZYIVc2Vu
c2luZy5ob25leXdlbGwuY29tghhzZW5zaW5nLmhvbmV5d2VsbC5jb20uY26CFHNl
bnNpbmcuaG9uZXl3ZWxsLmRlghIqLm9uZWtpbmdzbGFuZS5jb22CEGlhc3NldHMu
YW5raS5jb22CFnFhLmtlZXAtY29sbGVjdGl2ZS5jb22CGCoucWEua2VlcC1jb2xs
ZWN0aXZlLmNvbYIJcXVvcmEuY29tggsqLnF1b3JhLmNvbYIIcmVudC5jb22CCiou
cmVudC5jb22CDHN0ZWxsYWRvdC5ldYIOKi5zdGVsbGFkb3QuZXWCDHN0ZWxsYWRv
dC5mcoIOKi5zdGVsbGFkb3QuZnKCEnN0ZWxsYWRvdHN0Zy5jby51a4IQc3RlbGxh
ZG90c3RnLmNvbYISKi5zdGVsbGFkb3RzdGcuY29tgg9zdGVsbGFkb3RzdGcuZGWC
ESouc3RlbGxhZG90c3RnLmRlgg9zdGVsbGFkb3RzdGcuZXWCESouc3RlbGxhZG90
c3RnLmV1ghBpbnQxMC5uZXdva2wuY29tghIqLmludDEwLm5ld29rbC5jb22CHGlu
dGVncmF0aW9uLm1vZGFvcGVyYW5kaS5jb22CHiouaW50ZWdyYXRpb24ubW9kYW9w
ZXJhbmRpLmNvbYINamR2aG90ZWxzLmNvbYIPKi5qZHZob3RlbHMuY29tghNrZWVw
LWNvbGxlY3RpdmUuY29tghUqLmtlZXAtY29sbGVjdGl2ZS5jb22CEWFzc2V0cy5w
aXhsZWUuY29tghMqLmFzc2V0cy5waXhsZWUuY29tghNiYXJlbmVjZXNzaXRpZXMu
Y29tghUqLmJhcmVuZWNlc3NpdGllcy5jb22CDSoua2l0Y2hpdC5jb22CDioucGlv
bmxpbmUuY29tgg4qLnF1b3JhY2RuLm5ldIITKi5zbWFydGJhcmdhaW5zLmNvbYIU
Ki5zdGVsbGFkb3RzdGcuY28udWuCESoudGhld2F0Y2hlcnkuY29tggwqLnYxaG9z
dC5jb22CEHNhaW50c29jaWV0eS5jb22CEiouc2FpbnRzb2NpZXR5LmNvbYINa29u
Z2RpZGR5LmNvbYIPKi5rb25nZGlkZHkuY29tggpib29raXQuY29tggwqLmJvb2tp
dC5jb22CE2Jvb2tpdHNwZWVkdGVzdC5jb22CFSouYm9va2l0c3BlZWR0ZXN0LmNv
bYIQc2h1dHRlcnN0b2NrLmNvbYISKi5zaHV0dGVyc3RvY2suY29tghhzdGFnaW5n
Lm1vZGFvcGVyYW5kaS5jb22CGiouc3RhZ2luZy5tb2Rhb3BlcmFuZGkuY29tgg4q
LmV3YXRjaGVzLmNvbYIOKi5ob25lc3RxYS5jb22CDiouaW5zY25hbWUubmV0ggsq
Lmluc253Lm5ldIIed3d3LmFtZXJpY2FuYnVpbGRlcnNvdXRsZXQuY29tgg53d3cu
Z2h1cmthLmNvbYIQd3d3LnJlbGF0ZWlxLmNvbYIRYmxvZy5yZWxhdGVpcS5jb22C
DCouaW5zdGFydC5jb4IRKi5pbnN0YXJ0bGFicy5jb22CEiouaW5zdGFydGxvZ2lj
LmNvbYIRKi5pcy5xdW9yYWNkbi5uZXSCCmFsbG91dC5vcmeCDCouYWxsb3V0Lm9y
Z4IQYXBwLnJlbGF0ZWlxLmNvbYIJY29tbXVuLml0ggsqLmNvbW11bi5pdIITZG9s
bGFyc2hhdmVjbHViLmNvbYIVKi5kb2xsYXJzaGF2ZWNsdWIuY29tgglmaWd1ZS5j
b22CCyouZmlndWUuY29tgg1maXZlcnJjZG4uY29tgg8qLmZpdmVycmNkbi5jb22C
B2dib3QubWWCCSouZ2JvdC5tZYILZ29nb2JvdC5jb22CDSouZ29nb2JvdC5jb22C
CmhvbmVzdC5jb22CDCouaG9uZXN0LmNvbYIJaWZ0dHQuY29tggsqLmlmdHR0LmNv
bYIKaW5zdGFydC5jb4IOc3RhdGljLndpeC5jb22CDnNsaWNrZGVhbHMubmV0ghAq
LnNsaWNrZGVhbHMubmV0MAkGA1UdEwQCMAAwHQYDVR0lBBYwFAYIKwYBBQUHAwEG
CCsGAQUFBwMCMEUGA1UdHwQ+MDwwOqA4oDaGNGh0dHA6Ly9jcmwuZ2xvYmFsc2ln
bi5jb20vZ3MvZ3Nvcmdhbml6YXRpb252YWxnMi5jcmwwgZYGCCsGAQUFBwEBBIGJ
MIGGMEcGCCsGAQUFBzAChjtodHRwOi8vc2VjdXJlLmdsb2JhbHNpZ24uY29tL2Nh
Y2VydC9nc29yZ2FuaXphdGlvbnZhbGcyLmNydDA7BggrBgEFBQcwAYYvaHR0cDov
L29jc3AyLmdsb2JhbHNpZ24uY29tL2dzb3JnYW5pemF0aW9udmFsZzIwHQYDVR0O
BBYEFFdVkeeMLkvXRZxGlIp4VQeAY7jpMB8GA1UdIwQYMBaAFF1Gso3ES3Qcu+31
c7Y6tziPdZ5+MA0GCSqGSIb3DQEBBQUAA4IBAQBDE0lC5PNepPCvDkWgB8G5UJDZ
gZKIC700X8cY9vN61URPYvyATf05HmSwyIKYd3tLoS+noeWmFQCZcv6m3WseQ+do
lg1bH25VX9Bpbiqo6LfxfrIVGFQRlO5QKA86uaHv0YDm31Q+20gj1n3EPRCWAevq
SVvIlrb74ZRyZehbobryvg4V3xw1YbQDYPn5HCJy3q5V0I9yvZeFbkRiBNepo8dP
d6E3tlw+pjNv2wb2r56Qcl66z0KwZlY/NjhP924L3QOS8M+r4+3DoBAvFgnF5PHf
Bi5rAAu5ojR1pHepZ0BRGbUvik1UnZ2WyQDrv+UUa+kLcL1Infzg6RW+u/Sl
-----END CERTIFICATE-----
-----BEGIN CERTIFICATE-----
MIIEYDCCA0igAwIBAgILBAAAAAABL07hRQwwDQYJKoZIhvcNAQEFBQAwVzELMAkG
A1UEBhMCQkUxGTAXBgNVBAoTEEdsb2JhbFNpZ24gbnYtc2ExEDAOBgNVBAsTB1Jv
b3QgQ0ExGzAZBgNVBAMTEkdsb2JhbFNpZ24gUm9vdCBDQTAeFw0xMTA0MTMxMDAw
MDBaFw0yMjA0MTMxMDAwMDBaMF0xCzAJBgNVBAYTAkJFMRkwFwYDVQQKExBHbG9i
YWxTaWduIG52LXNhMTMwMQYDVQQDEypHbG9iYWxTaWduIE9yZ2FuaXphdGlvbiBW
YWxpZGF0aW9uIENBIC0gRzIwggEiMA0GCSqGSIb3DQEBAQUAA4IBDwAwggEKAoIB
AQDdNR3yIFQmGtDvpW+Bdllw3Of01AMkHyQOnSKf1Ccyeit87ovjYWI4F6+0S3qf
ZyEcLZVUunm6tsTyDSF0F2d04rFkCJlgePtnwkv3J41vNnbPMYzl8QbX3FcOW6zu
zi2rqqlwLwKGyLHQCAeV6irs0Z7kNlw7pja1Q4ur944+ABv/hVlrYgGNguhKujiz
4MP0bRmn6gXdhGfCZsckAnNate6kGdn8AM62pI3ffr1fsjqdhDFPyGMM5NgNUqN+
ARvUZ6UYKOsBp4I82Y4d5UcNuotZFKMfH0vq4idGhs6dOcRmQafiFSNrVkfB7cVT
5NSAH2v6gEaYsgmmD5W+ZoiTAgMBAAGjggElMIIBITAOBgNVHQ8BAf8EBAMCAQYw
EgYDVR0TAQH/BAgwBgEB/wIBADAdBgNVHQ4EFgQUXUayjcRLdBy77fVztjq3OI91
nn4wRwYDVR0gBEAwPjA8BgRVHSAAMDQwMgYIKwYBBQUHAgEWJmh0dHBzOi8vd3d3
Lmdsb2JhbHNpZ24uY29tL3JlcG9zaXRvcnkvMDMGA1UdHwQsMCowKKAmoCSGImh0
dHA6Ly9jcmwuZ2xvYmFsc2lnbi5uZXQvcm9vdC5jcmwwPQYIKwYBBQUHAQEEMTAv
MC0GCCsGAQUFBzABhiFodHRwOi8vb2NzcC5nbG9iYWxzaWduLmNvbS9yb290cjEw
HwYDVR0jBBgwFoAUYHtmGkUNl8qJUC99BM00qP/8/UswDQYJKoZIhvcNAQEFBQAD
ggEBABvgiADHBREc/6stSEJSzSBo53xBjcEnxSxZZ6CaNduzUKcbYumlO/q2IQen
fPMOK25+Lk2TnLryhj5jiBDYW2FQEtuHrhm70t8ylgCoXtwtI7yw07VKoI5lkS/Z
9oL2dLLffCbvGSuXL+Ch7rkXIkg/pfcNYNUNUUflWP63n41edTzGQfDPgVRJEcYX
pOBWYdw9P91nbHZF2krqrhqkYE/Ho9aqp9nNgSvBZnWygI/1h01fwlr1kMbawb30
hag8IyrhFHvBN91i0ZJsumB9iOQct+R2UTjEqUdOqCsukNK1OFHrwZyKarXMsh3o
wFZUTKiL8IkyhtyTMr5NGvo1dbU=
-----END CERTIFICATE-----
t= 9117 [st= 265] +CERT_VERIFIER_REQUEST [dt=7]
t= 9117 [st= 265] CERT_VERIFIER_REQUEST_BOUND_TO_JOB
--> source_dependency = 620 (CERT_VERIFIER_JOB)
t= 9124 [st= 272] -CERT_VERIFIER_REQUEST
t= 9124 [st= 272] SIGNED_CERTIFICATE_TIMESTAMPS_RECEIVED
--> embedded_scts = ""
--> scts_from_ocsp_response = ""
--> scts_from_tls_extension = ""
t= 9124 [st= 272] SIGNED_CERTIFICATE_TIMESTAMPS_CHECKED
--> invalid_scts = []
--> unknown_logs_scts = []
--> verified_scts = []
t= 9124 [st= 272] -SSL_CONNECT
t= 9125 [st= 273] +SOCKET_IN_USE [dt=172]
--> source_dependency = 368 (HTTP_STREAM_JOB)
t= 9126 [st= 274] SSL_SOCKET_BYTES_SENT
--> byte_count = 384
t= 9126 [st= 274] SOCKET_BYTES_SENT
--> byte_count = 409
t= 9166 [st= 314] SOCKET_BYTES_RECEIVED
--> byte_count = 1460
t= 9183 [st= 331] SOCKET_BYTES_RECEIVED
--> byte_count = 1460
t= 9221 [st= 369] SOCKET_BYTES_RECEIVED
--> byte_count = 1460
t= 9248 [st= 396] SOCKET_BYTES_RECEIVED
--> byte_count = 1460
t= 9268 [st= 416] SOCKET_BYTES_RECEIVED
--> byte_count = 1460
t= 9293 [st= 441] SOCKET_BYTES_RECEIVED
--> byte_count = 1140
t= 9293 [st= 441] SSL_SOCKET_BYTES_RECEIVED
--> byte_count = 4096
t= 9297 [st= 445] SSL_SOCKET_BYTES_RECEIVED
--> byte_count = 4319
t= 9297 [st= 445] -SOCKET_IN_USE
t= 9394 [st= 542] +SOCKET_IN_USE [dt=77]
--> source_dependency = 764 (HTTP_STREAM_JOB)
t= 9394 [st= 542] SSL_SOCKET_BYTES_SENT
--> byte_count = 356
t= 9395 [st= 543] SOCKET_BYTES_SENT
--> byte_count = 381
t= 9433 [st= 581] SOCKET_BYTES_RECEIVED
--> byte_count = 1460
t= 9449 [st= 597] SOCKET_BYTES_RECEIVED
--> byte_count = 1039
t= 9449 [st= 597] SSL_SOCKET_BYTES_RECEIVED
--> byte_count = 2474
t= 9471 [st= 619] -SOCKET_IN_USE
t=17823 [st=8971] -SOCKET_IN_USE
t=17823 [st=8971] -SOCKET_ALIVE
pganti
August 14, 2014, 10:55pm
6
t= 9166 [st= 314] SOCKET_BYTES_RECEIVED
--> byte_count = 1460
t= 9183 [st= 331] SOCKET_BYTES_RECEIVED
--> byte_count = 1460
t= 9221 [st= 369] SOCKET_BYTES_RECEIVED
--> byte_count = 1460
t= 9248 [st= 396] SOCKET_BYTES_RECEIVED
--> byte_count = 1460
t= 9268 [st= 416] SOCKET_BYTES_RECEIVED
--> byte_count = 1460
t= 9293 [st= 441] SOCKET_BYTES_RECEIVED
--> byte_count = 1140
[@pmeenan ] : You see the above problem where there is 20-30 ms spacing between the packets which were sent in the same burst from the server
I would focus on this behavior using various connectivities
Even I observed strange behavior for Chrome and Firefox. The test which runs successfully on IE8 and IE10, doesn’t terminate on Chrome and FF resulting in time-out errors.
Anyone has a solution for this