Ok, here's a non job related post... Anyone know why urllib.urlopen() can be so much slower than using ab to do the same thing? I seem to be getting an extra 100ms latency on a simple HTTP GET request of a static, small image. e.g.
for x in range(10): ... t1 = time(); data = urlopen('http://example.com/kb-brain.png').read(); t2=time(); print t2-t1 ... 0.12966299057 0.131743907928 0.303734064102 0.136001110077 0.136011838913 0.13859796524 0.13979101181 0.145252943039 0.145727872849 0.150994062424
versus, on the same machine: dhcp90:funkload netsight$ ab -n10 -c1 http://example.com/kb-brain.png ... Concurrency Level: 1 Time taken for tests: 0.309 seconds Complete requests: 10 Failed requests: 0 Write errors: 0 Total transferred: 31870 bytes HTML transferred: 28990 bytes Requests per second: 32.32 [#/sec] (mean) Time per request: 30.942 [ms] (mean) Time per request: 30.942 [ms] (mean, across all concurrent requests) Transfer rate: 100.59 [Kbytes/sec] received ... I've tried it repeatedly and get consistent results. The server under test is a cluster of Plone instances behind haproxy. The client and server are connected via 100Mbit fairly lightly loaded network. I've tried taking the read() part out, still the same... I've tried using urllib2 and still pretty much the same. -Matt -- Matt Hamilton matth@netsight.co.uk Netsight Internet Solutions, Ltd. Business Vision on the Internet http://www.netsight.co.uk +44 (0)117 9090901 Web Design | Zope/Plone Development and Consulting | Co-location | Hosting
2010/12/20 Matt Hamilton <matth@netsight.co.uk>:
Ok, here's a non job related post...
Anyone know why urllib.urlopen() can be so much slower than using ab to do the same thing? I seem to be getting an extra 100ms latency on a simple HTTP GET request of a static, small image. I've tried it repeatedly and get consistent results. The server under test is a cluster of Plone instances behind haproxy. The client and server are connected via 100Mbit fairly lightly loaded network.
I've tried taking the read() part out, still the same... I've tried using urllib2 and still pretty much the same.
How does work twisted in this case? -- Quiero ser el rayo de sol que cada día te despierta para hacerte respirar y vivir en me. "Favola -Moda".
On 20 Dec 2010, at 14:04, Giorgio Zoppi wrote:
2010/12/20 Matt Hamilton <matth@netsight.co.uk>:
Ok, here's a non job related post...
Anyone know why urllib.urlopen() can be so much slower than using ab to do the same thing? I seem to be getting an extra 100ms latency on a simple HTTP GET request of a static, small image. I've tried it repeatedly and get consistent results. The server under test is a cluster of Plone instances behind haproxy. The client and server are connected via 100Mbit fairly lightly loaded network.
I've tried taking the read() part out, still the same... I've tried using urllib2 and still pretty much the same.
How does work twisted in this case?
No idea. I've not tried to use twisted in this case. Wouldn't it be overkill? How would twisted be any different making a single request to a server? Unless I'm wrong isn't twisted's main benefit that it allows concurrency? -Matt -- Matt Hamilton matth@netsight.co.uk Netsight Internet Solutions, Ltd. Business Vision on the Internet http://www.netsight.co.uk +44 (0)117 9090901 Web Design | Zope/Plone Development and Consulting | Co-location | Hosting
On 20 December 2010 13:54, Matt Hamilton <matth@netsight.co.uk> wrote:
Anyone know why urllib.urlopen() can be so much slower than using ab to do the same thing? I seem to be getting an extra 100ms latency on a simple HTTP GET request of a static, small image.
Just some possibles: - How many DNS lookups is each doing? Have you timed it by IP address, or with example.com in the hosts file? - I understand ab isn't reusing the HTTP connection - could it be reusing the TCP connection or avoiding the 3-way handshake? (My understanding of repeated HTTP requests is sketchy) - Are ab and urllib transferring the same number of bytes? Is one or the other (not) using compression? - Is ab somehow causing fewer, larger packets to be used in either the request or the response? I'd probably be reaching for a packet capture about now. -- Alex Willmer <alex@moreati.org.uk> http://moreati.org.uk/blog http://twitter.com/moreati
On 20 Dec 2010, at 14:15, Alex Willmer wrote:
On 20 December 2010 13:54, Matt Hamilton <matth@netsight.co.uk> wrote: Anyone know why urllib.urlopen() can be so much slower than using ab to do the same thing? I seem to be getting an extra 100ms latency on a simple HTTP GET request of a static, small image.
Just some possibles: - How many DNS lookups is each doing? Have you timed it by IP address, or with example.com in the hosts file?
Neither is doing DNS lookups, the DNS entry is cached. Adding it to /etc/host makes no difference either.
- I understand ab isn't reusing the HTTP connection - could it be reusing the TCP connection or avoiding the 3-way handshake? (My understanding of repeated HTTP requests is sketchy)
Indeed, neither are using http keepalive, and from what I can see from wireshark, they are creating and closing a TCP connection for each request.
- Are ab and urllib transferring the same number of bytes? Is one or the other (not) using compression?
Yes, same number of bytes, same number of packets 1514+67+1514+356 (bytes)
- Is ab somehow causing fewer, larger packets to be used in either the request or the response?
Nope, same number.
I'd probably be reaching for a packet capture about now.
That is what I'm doing... but slightly getting beyond me now in terms of TCP closing connections. Not really sure how best to share the capture data... but let me try and summarize some of the flows: s -> c last packet (shows as HTTP 200) c -> s ack s -> c fin,ack c -> s ack c -> s fin,ack s -> c ack Actually, I was wrong in my previous post... the close actually goes quite quickly. *The following SYN* from the client to open the next tcp connection seems to take 100ms. I'm off to go dig in the urllib code and see if I can see anything there. I'm wondering if urllib is taking some time to process the data after it receives it before doing anything. This is on OSX, but I'm going to go try it on a FreeBSD box as I can then use ktrace to see what might be happening. -Matt -- Matt Hamilton matth@netsight.co.uk Netsight Internet Solutions, Ltd. Business Vision on the Internet http://www.netsight.co.uk +44 (0)117 9090901 Web Design | Zope/Plone Development and Consulting | Co-location | Hosting
Matt Hamilton wrote:
I'm off to go dig in the urllib code and see if I can see anything there. I'm wondering if urllib is taking some time to process the data after it receives it before doing anything.
This is on OSX, but I'm going to go try it on a FreeBSD box as I can then use ktrace to see what might be happening.
Could it be SO_REUSEADDR? Seems unlikely but I can't think of anything else. If ab is specifying this but python isn't you might get a reconnection delay. Cheers, Doug. -- Telephone: +44 1904 567330, Mobile: +44 7879 423002 Switchboard: +44 1904 567349, Fax: +44 20 79006980 Post: Tower House, Fishergate, York, YO10 4UA, UK Registered in England. Company No 5171172. VAT GB843570325. Regd Office: 3&4 Park Court, Riccall Road, Escrick, York, YO19 6ED
On Mon, Dec 20, 2010 at 04:26:09PM +0000, Doug Winter wrote:
Matt Hamilton wrote:
I'm off to go dig in the urllib code and see if I can see anything there. I'm wondering if urllib is taking some time to process the data after it receives it before doing anything.
This is on OSX, but I'm going to go try it on a FreeBSD box as I can then use ktrace to see what might be happening.
Could it be SO_REUSEADDR?
Um... no ;-)
On 20/12/10 17:19, Jon Ribbens wrote:
Could it be SO_REUSEADDR?
Um... no ;-)
It did seem unlikely ;) -- Telephone: +44 1904 567330, Mobile: +44 7879 423002 Switchboard: +44 1904 567349, Fax: +44 20 79006980 Post: Tower House, Fishergate, York, YO10 4UA, UK Registered in England. Company No 5171172. VAT GB843570325. Regd Office: 3&4 Park Court, Riccall Road, Escrick, York, YO19 6ED
On 20 Dec 2010, at 16:26, Doug Winter wrote:
Matt Hamilton wrote:
I'm off to go dig in the urllib code and see if I can see anything there. I'm wondering if urllib is taking some time to process the data after it receives it before doing anything.
This is on OSX, but I'm going to go try it on a FreeBSD box as I can then use ktrace to see what might be happening.
Could it be SO_REUSEADDR? Seems unlikely but I can't think of anything else. If ab is specifying this but python isn't you might get a reconnection delay.
Close :) It appears to be some interaction between Nagle and delayed acks. The server is FreeBSD, and if I disable delayed acks on the server then I notice a bit of a speedup (seems there is a deadlock that occurs in the TCP sessions between my varnish and haproxy processes on that box). I then have a similar issue for the request I mentioned in this thread, that happens to be cached by varnish. If I then disable delayed acks on the OSX box running the python tests, that speeds up again and I lose the 100ms extra latency and it is on par with ab. ie. about 6ms to retrieve the request. Question is why does python suffer from this deadlock, yet ab on the same machine doesn't? I thought it could be something with TCP_NODELAY, but setting that on the socket on python doesn't seem to help. I'm just wondering if there is a particular order in which the packets and acks are being sent, but from my wireshark trace yesterday they did seem to be exactly the same. -Matt -- Matt Hamilton matth@netsight.co.uk Netsight Internet Solutions, Ltd. Business Vision on the Internet http://www.netsight.co.uk +44 (0)117 9090901 Web Design | Zope/Plone Development and Consulting | Co-location | Hosting
On 21 Dec 2010, at 10:29, Matt Hamilton wrote:
I then have a similar issue for the request I mentioned in this thread, that happens to be cached by varnish. If I then disable delayed acks on the OSX box running the python tests, that speeds up again and I lose the 100ms extra latency and it is on par with ab. ie. about 6ms to retrieve the request.
And then re-running the tests from the same python prompt that was open just before I wrote that email and I now have the 100ms delay back again... yet not still in ab. Quitting and starting a new python process and I still have the delay. Grrrrrrr...... -Matt -- Matt Hamilton matth@netsight.co.uk Netsight Internet Solutions, Ltd. Business Vision on the Internet http://www.netsight.co.uk +44 (0)117 9090901 Web Design | Zope/Plone Development and Consulting | Co-location | Hosting
On Tue, Dec 21, 2010 at 10:39:23AM +0000, Matt Hamilton wrote:
And then re-running the tests from the same python prompt that was open just before I wrote that email and I now have the 100ms delay back again... yet not still in ab. Quitting and starting a new python process and I still have the delay.
Trying it here with a web server on localhost I get ~1.7ms with urllib and 0.4ms with ab, or a remote web server gives 9ms with urllib and 8ms with ab - which I guess is kinda what I would expect. So it doesn't appear to be a generic problem with urllib. (Python 2.6.5)
On Tue, 21 Dec 2010, Matt Hamilton wrote: [...]
And then re-running the tests from the same python prompt that was open just before I wrote that email and I now have the 100ms delay back again... yet not still in ab. Quitting and starting a new python process and I still have the delay.
I guess this is obvious advice, but then again we all need the obvious stated from time to time: Since it seems to be tricky maybe a more mechanical approach would help -- reproduce it with a script that just uses module socket, then reproduce it with the equivalent C program if necessary? Then if it's still not apparent, to keep zeroing in on what is different between ab and your script, you can go in the other direction, simplifying the ab code drastically, until your two programs are identical apart from the one thing that makes the Python code slower (hopefully you'll spot the problem before that happens ;-). John
On 20 Dec 2010, at 13:54, Matt Hamilton wrote:
Ok, here's a non job related post...
Anyone know why urllib.urlopen() can be so much slower than using ab to do the same thing? I seem to be getting an extra 100ms latency on a simple HTTP GET request of a static, small image.
Some more info on this... I've been tracing the packets with wireshark to try and see what is going on, and it looks like with urllib the data is returned pretty quickly, but there is then a 100ms delay as it seems to be shutting down the socket afterwards. I'm trying to work out why, but both urllib and ab appear to go through the same tcp dance to shut down the connection (both client and server send FIN). -Matt -- Matt Hamilton matth@netsight.co.uk Netsight Internet Solutions, Ltd. Business Vision on the Internet http://www.netsight.co.uk +44 (0)117 9090901 Web Design | Zope/Plone Development and Consulting | Co-location | Hosting
participants (6)
-
Alex Willmer -
Doug Winter -
Giorgio Zoppi -
John J Lee -
Jon Ribbens -
Matt Hamilton