HTTP 1.0 and the Connection header
I have a long backlog of things to write about. One of those things is Varnish (more on that in a future post). So, over these Christmas holidays, while intentionally taking a break from real work, I decided to finally do some of the research required before I can really write about how Varnish is going to make your web apps much faster.
To get some actual numbers, I broke out the Apache Benchmarking utility (ab), and decided to let it loose on my site (100 requests, 10 requests concurrently):ab -n 100 -c 10 http://seancoates.com/codes
To my surprise, this didn't finish almost immediately. The command ran for what seemed like forever. Finally, I was presented with its output (excerpted for your reading pleasure):Concurrency Level: 10 Time taken for tests: 152.476 seconds Complete requests: 100 Failed requests: 0 Write errors: 0 Total transferred: 592500 bytes html transferred: 566900 bytes Requests per second: 0.66 [#/sec] (mean) Time per request: 15247.644 [ms] (mean) Time per request: 1524.764 [ms] (mean, across all concurrent requests) Transfer rate: 3.79 [Kbytes/sec] received
Less than one request per second? That surely doesn't seem right. I chose /codes because the content does not depend on any sort of external service or expensive server-side processing (as described in an earlier post). Manually browsing to this same URL also feels much faster than one request per second. There's something fishy going on here.
I thought that there might be something off with my server configuration, so in order to rule out a concurrency issue, I decided to benchmark a single request:ab -n 1 -c 1 http://seancoates.com/codes
I expected this page to load in less than 200ms. That seems reasonable for a light page that has no external dependencies, and doesn't even hit a database. Instead, I got this:Concurrency Level: 1 Time taken for tests: 15.090 seconds Complete requests: 1 Failed requests: 0 Write errors: 0 Total transferred: 5925 bytes html transferred: 5669 bytes Requests per second: 0.07 [#/sec] (mean) Time per request: 15089.559 [ms] (mean) Time per request: 15089.559 [ms] (mean, across all concurrent requests) Transfer rate: 0.38 [Kbytes/sec] received
Over 15 seconds to render a single pagea€˝ Clearly, this isn't what's actually happening on my site. I can confirm this with a browser, or very objectively with time and curl:$ time curl -s http://seancoates.com/codes /dev/null real 0m0.122s user 0m0.000s sys 0m0.010s
The next step is to figure out what ab is actually doing that's taking an extra ~15 seconds. Let's crank up the verbosity (might as well go all the way to 11).$ ab -v 11 -n 1 -c 1 http://seancoates.com/codes (snip) Benchmarking seancoates.com (be patient)...INFO: POST header == --- GET /codes HTTP/1.0 Host: seancoates.com User-Agent: ApacheBench/2.3 Accept: */* --- LOG: header received: HTTP/1.1 200 OK Date: Mon, 26 Dec 2011 16:27:32 GMT Server: Apache/2.2.17 (Ubuntu) DAV/2 SVN/1.6.12 mod_fcgid/2.3.6 mod_ssl/2.2.17 OpenSSL/0.9.8o PHP/5.3.2 X-Powered-By: PHP/5.3.2 Vary: Accept-Encoding Content-Length: 5669 Content-Type: text/html (html snipped from here) LOG: Response code = 200 ..done (snip)
This all looked just fine. The really strange thing is that the output stalled right after LOG: Response code = 200 and right before ..done. So, something was causing ab to stall after the request was answered (we got a 200, and it's a small number of bytes).
This is the part where I remembered that I've seen a similar behaviour before. I've lost countless hours of my life (and now one more) to this problem: some clients (such as PHP's streams) don't handle Keep-Alives in the way that one might expect.
HTTP is hard. Really hard. Way harder than you think. Actually, it's not that hard if you remember that what you think is probably wrong if you're not absolutely sure that you
Truncated by Planet PHP, read more at the original (another 2524 bytes)