[httperf] Connection: close problem

Arlitt, Martin martin.arlitt at hp.com
Fri Feb 29 13:30:33 PST 2008


Hi Elliot

It looks like httperf does not recognize "Connection: close" headers, it assumes Web servers that claim to be "HTTP/1.1" to support persistent connections.  Likewise, it assumes servers that claim to be "HTTP/1.0" do not support persistent connections.

Thus, the reset is occurring because httperf is trying to issue a second request on the connection that the server is trying to close.

One interesting thing I noticed in the tcpdump trace; for some reason the server send the response to the initial request on each connection in two separate packets.  The first packet appears to (based on the byte count) contain the status line and the "Connection: close" header, the remainder of the response comes in the second packet, a few milliseconds after the first response packet.  This shouldn't have any consequences for httperf, it just seems like an inefficient way to deliver the response.

Thus, my only suggestion is to use the --http-version=1.0 option, if you know you are communicating with a web server that does not support persistent connections, but claims to be HTTP/1.1. (if the status line reported HTTP/1.0, httperf should close the connection after the first request).

Martin

-----Original Message-----
From: Elliot Temple [mailto:curius at gmail.com] On Behalf Of Elliot Temple
Sent: Friday, February 29, 2008 11:37 AM
To: httperf at linux.hpl.hp.com
Cc: Arlitt, Martin
Subject: Re: [httperf] Connection: close problem

Here is more verbose httperf output, using a wsesslog with 2 url's,
and it gets one connreset. The server headers do say Connection:
close. tcpdump output is below; hopefully it's correct but I'm not
really sure what it means.

I can repeat this with the webrick server and sending it a Connection:
close\n header if that would help.

- Elliot




cg5:~/sbt/Website >httperf --hog --session-cookie --server=10.0.1.196
--port=3000 --wsesslog=1,0,test/httperf/simple -v --print-reply --
print-request
httperf --verbose --print-reply --print-request --hog --client=0/1 --
server=10.0.1.196 --port=3000 --uri=/ --send-buffer=4096 --recv-
buffer=16384 --session-cookies --wsesslog=1,0.000,test/httperf/simple
httperf: warning: open file limit > FD_SETSIZE; limiting max. # of
open files to FD_SETSIZE
httperf: maximum number of open descriptors = 0
SH0:GET /test/no_layout HTTP/1.1
SH0:User-Agent: httperf/0.8
SH0:Host: 10.0.1.196
SH0:
SS0: header 75 content 0
RH0:HTTP/1.1 200 OK
RH0:Connection: close
RH0:Date: Fri, 29 Feb 2008 19:22:34 GMT
RH0:Set-Cookie: _session_id=ab5465c4ce197ebc5275b5e52d398319; path=/
RH0:Status: 200 OK
RH0:X-Runtime: 0.00065
RH0:ETag: "4fd6f702eb53f80789f40f0d91399812"
RH0:Cache-Control: private, max-age=0, must-revalidate
RH0:Server: Mongrel 1.1.3
RH0:Content-Type: text/html; charset=utf-8
RH0:Content-Length: 11
RH0:
RB0:simple page
RS0: header 354 content 11 footer 0
SH1:GET /test/no_template HTTP/1.1
SH1:User-Agent: httperf/0.8
SH1:Host: 10.0.1.196
SH1:Cookie: _session_id=ab5465c4ce197ebc5275b5e52d398319
SH1:
SS1: header 131 content 0
SH1:GET /test/no_template HTTP/1.1
SH1:User-Agent: httperf/0.8
SH1:Host: 10.0.1.196
SH1:Cookie: _session_id=ab5465c4ce197ebc5275b5e52d398319
SH1:
SS1: header 131 content 0
RH1:HTTP/1.1 200 OK
RH1:Connection: close
RH1:Date: Fri, 29 Feb 2008 19:22:34 GMT
RH1:Set-Cookie: _session_id=ab5465c4ce197ebc5275b5e52d398319; path=/
RH1:Status: 200 OK
RH1:X-Runtime: 0.00026
RH1:ETag: "eb78aa56cffc28507cd7841c9a9ea87d"
RH1:Cache-Control: private, max-age=0, must-revalidate
RH1:Server: Mongrel 1.1.3
RH1:Content-Type: text/html; charset=utf-8
RH1:Content-Length: 13
RH1:
RB1:hi from rails
RS1: header 354 content 13 footer 0
Maximum connect burst length: 1

Total: connections 2 requests 3 replies 2 test-duration 0.019 s

Connection rate: 107.6 conn/s (9.3 ms/conn, <=2 concurrent connections)
Connection time [ms]: min 7.6 avg 9.3 max 11.0 median 7.5 stddev 2.4
Connection time [ms]: connect 1.4
Connection length [replies/conn]: 1.000

Request rate: 161.4 req/s (6.2 ms/req)
Request size [B]: 156.0

Reply rate [replies/s]: min 0.0 avg 0.0 max 0.0 stddev 0.0 (0 samples)
Reply time [ms]: response 6.7 transfer 0.3
Reply size [B]: header 354.0 content 12.0 footer 0.0 (total 366.0)
Reply status: 1xx=0 2xx=2 3xx=0 4xx=0 5xx=0

CPU time [s]: user 0.00 system 0.01 (user 21.4% system 73.9% total
95.2%)
Net I/O: 63.0 KB/s (0.5*10^6 bps)

Errors: total 1 client-timo 0 socket-timo 0 connrefused 0 connreset 1
Errors: fd-unavail 0 addrunavail 0 ftab-full 0 other 0

Session rate [sess/s]: min 0.00 avg 53.79 max 0.00 stddev 0.00 (1/1)
Session: avg 2.00 connections/session
Session lifetime [s]: 0.0
Session failtime [s]: 0.0
Session length histogram: 0 0 1





cg5:~ >sudo tcpdump -i en0 -vvv -n -s 0
tcpdump: listening on en0, link-type EN10MB (Ethernet), capture size
65535 bytes
11:22:32.857848 IP (tos 0x0, ttl 56, id 7501, offset 0, flags [DF],
proto TCP (6), length 154) 209.177.146.34.6667 > 10.0.1.200.55937: P,
cksum 0xd160 (correct), 2186495712:2186495814(102) ack 3155911579 win
91 <nop,nop,timestamp 58926742 276443328>
11:22:32.857943 IP (tos 0x0, ttl 64, id 3476, offset 0, flags [DF],
proto TCP (6), length 52) 10.0.1.200.55937 > 209.177.146.34.6667: .,
cksum 0x6fc2 (incorrect (-> 0xbd53), 1:1(0) ack 102 win 65535
<nop,nop,timestamp 276443485 58926742>
11:22:34.038807 IP (tos 0x0, ttl 64, id 26062, offset 0, flags [DF],
proto TCP (6), length 64) 10.0.1.200.1024 > 10.0.1.196.3000: S, cksum
0x17be (incorrect (-> 0x2ed4), 3177226662:3177226662(0) win 16384 <mss
1460,nop,wscale 0,nop,nop,timestamp 276443497 0,sackOK,eol>
11:22:34.039646 IP (tos 0x0, ttl 64, id 4634, offset 0, flags [DF],
proto TCP (6), length 64) 10.0.1.196.3000 > 10.0.1.200.1024: S, cksum
0x0509 (correct), 31809672:31809672(0) ack 3177226663 win 65535 <mss
1460,nop,wscale 3,nop,nop,timestamp 46204041 276443497,sackOK,eol>
11:22:34.039714 IP (tos 0x0, ttl 64, id 27407, offset 0, flags [DF],
proto TCP (6), length 52) 10.0.1.200.1024 > 10.0.1.196.3000: ., cksum
0x17b2 (incorrect (-> 0x00f6), 1:1(0) ack 1 win 17376
<nop,nop,timestamp 276443497 46204041>
11:22:34.040282 IP (tos 0x0, ttl 64, id 25401, offset 0, flags [DF],
proto TCP (6), length 127) 10.0.1.200.1024 > 10.0.1.196.3000: P, cksum
0x17fd (incorrect (-> 0x1e42), 1:76(75) ack 1 win 17376
<nop,nop,timestamp 276443497 46204041>
11:22:34.040349 IP (tos 0x0, ttl 64, id 13884, offset 0, flags [DF],
proto TCP (6), length 52) 10.0.1.196.3000 > 10.0.1.200.1024: ., cksum
0x44d6 (correct), 1:1(0) ack 1 win 65535 <nop,nop,timestamp 46204041
276443497>
11:22:34.040867 IP (tos 0x0, ttl 64, id 64333, offset 0, flags [DF],
proto TCP (6), length 52) 10.0.1.196.3000 > 10.0.1.200.1024: ., cksum
0x448b (correct), 1:1(0) ack 76 win 65535 <nop,nop,timestamp 46204041
276443497>
11:22:34.047431 IP (tos 0x0, ttl 64, id 860, offset 0, flags [DF],
proto TCP (6), length 88) 10.0.1.196.3000 > 10.0.1.200.1024: P, cksum
0x5e22 (correct), 1:37(36) ack 76 win 65535 <nop,nop,timestamp
46204041 276443497>
11:22:34.047499 IP (tos 0x0, ttl 64, id 16280, offset 0, flags [DF],
proto TCP (6), length 52) 10.0.1.200.1024 > 10.0.1.196.3000: ., cksum
0x17b2 (incorrect (-> 0x00ab), 76:76(0) ack 37 win 17340
<nop,nop,timestamp 276443497 46204041>
11:22:34.047782 IP (tos 0x0, ttl 64, id 5479, offset 0, flags [DF],
proto TCP (6), length 381) 10.0.1.196.3000 > 10.0.1.200.1024: FP,
cksum 0xbd4d (correct), 37:366(329) ack 76 win 65535
<nop,nop,timestamp 46204041 276443497>
11:22:34.047818 IP (tos 0x0, ttl 64, id 17826, offset 0, flags [DF],
proto TCP (6), length 52) 10.0.1.200.1024 > 10.0.1.196.3000: ., cksum
0x17b2 (incorrect (-> 0x0086), 76:76(0) ack 367 win 17047
<nop,nop,timestamp 276443497 46204041>
11:22:34.049627 IP (tos 0x0, ttl 64, id 5092, offset 0, flags [DF],
proto TCP (6), length 183) 10.0.1.200.1024 > 10.0.1.196.3000: P, cksum
0x1835 (incorrect (-> 0xb1b9), 76:207(131) ack 367 win 17376
<nop,nop,timestamp 276443497 46204041>
11:22:34.049760 IP (tos 0x0, ttl 64, id 16228, offset 0, flags [DF],
proto TCP (6), length 64) 10.0.1.200.1025 > 10.0.1.196.3000: S, cksum
0x17be (incorrect (-> 0xcac1), 2437427664:2437427664(0) win 16384 <mss
1460,nop,wscale 0,nop,nop,timestamp 276443497 0,sackOK,eol>
11:22:34.049871 IP (tos 0x0, ttl 64, id 23750, offset 0, flags [DF],
proto TCP (6), length 52) 10.0.1.200.1024 > 10.0.1.196.3000: F, cksum
0x17b2 (incorrect (-> 0xfeb8), 207:207(0) ack 367 win 17376
<nop,nop,timestamp 276443497 46204041>
11:22:34.050789 IP (tos 0x0, ttl 64, id 12157, offset 0, flags [DF],
proto TCP (6), length 40) 10.0.1.196.3000 > 10.0.1.200.1024: R, cksum
0x24c1 (correct), 31810039:31810039(0) win 0
11:22:34.051298 IP (tos 0x0, ttl 64, id 37675, offset 0, flags [DF],
proto TCP (6), length 64) 10.0.1.196.3000 > 10.0.1.200.1025: S, cksum
0x290e (correct), 64280193:64280193(0) ack 2437427665 win 65535 <mss
1460,nop,wscale 3,nop,nop,timestamp 46204041 276443497,sackOK,eol>
11:22:34.051328 IP (tos 0x0, ttl 64, id 26117, offset 0, flags [DF],
proto TCP (6), length 52) 10.0.1.200.1025 > 10.0.1.196.3000: ., cksum
0x17b2 (incorrect (-> 0x24fb), 1:1(0) ack 1 win 17376
<nop,nop,timestamp 276443497 46204041>
11:22:34.051464 IP (tos 0x0, ttl 64, id 11013, offset 0, flags [DF],
proto TCP (6), length 183) 10.0.1.200.1025 > 10.0.1.196.3000: P, cksum
0x1835 (incorrect (-> 0xd777), 1:132(131) ack 1 win 17376
<nop,nop,timestamp 276443497 46204041>
11:22:34.052356 IP (tos 0x0, ttl 64, id 39950, offset 0, flags [DF],
proto TCP (6), length 40) 10.0.1.196.3000 > 10.0.1.200.1024: R, cksum
0x24c1 (correct), 31810039:31810039(0) win 0
11:22:34.052579 IP (tos 0x0, ttl 64, id 26897, offset 0, flags [DF],
proto TCP (6), length 52) 10.0.1.196.3000 > 10.0.1.200.1025: ., cksum
0x68db (correct), 1:1(0) ack 1 win 65535 <nop,nop,timestamp 46204041
276443497>
11:22:34.052702 IP (tos 0x0, ttl 64, id 39294, offset 0, flags [DF],
proto TCP (6), length 52) 10.0.1.196.3000 > 10.0.1.200.1025: ., cksum
0x6858 (correct), 1:1(0) ack 132 win 65535 <nop,nop,timestamp 46204041
276443497>
11:22:34.056847 IP (tos 0x0, ttl 64, id 39689, offset 0, flags [DF],
proto TCP (6), length 88) 10.0.1.196.3000 > 10.0.1.200.1025: P, cksum
0x81ef (correct), 1:37(36) ack 132 win 65535 <nop,nop,timestamp
46204041 276443497>
11:22:34.056908 IP (tos 0x0, ttl 64, id 25581, offset 0, flags [DF],
proto TCP (6), length 52) 10.0.1.200.1025 > 10.0.1.196.3000: ., cksum
0x17b2 (incorrect (-> 0x2478), 132:132(0) ack 37 win 17340
<nop,nop,timestamp 276443497 46204041>
11:22:34.057189 IP (tos 0x0, ttl 64, id 56168, offset 0, flags [DF],
proto TCP (6), length 383) 10.0.1.196.3000 > 10.0.1.200.1025: FP,
cksum 0x1e23 (correct), 37:368(331) ack 132 win 65535
<nop,nop,timestamp 46204041 276443497>
11:22:34.057226 IP (tos 0x0, ttl 64, id 2305, offset 0, flags [DF],
proto TCP (6), length 52) 10.0.1.200.1025 > 10.0.1.196.3000: ., cksum
0x17b2 (incorrect (-> 0x2453), 132:132(0) ack 369 win 17045
<nop,nop,timestamp 276443497 46204041>
11:22:34.057475 IP (tos 0x0, ttl 64, id 32433, offset 0, flags [DF],
proto TCP (6), length 52) 10.0.1.200.1025 > 10.0.1.196.3000: F, cksum
0x17b2 (incorrect (-> 0x2307), 132:132(0) ack 369 win 17376
<nop,nop,timestamp 276443497 46204041>
11:22:34.058040 IP (tos 0x0, ttl 64, id 36458, offset 0, flags [DF],
proto TCP (6), length 52) 10.0.1.196.3000 > 10.0.1.200.1025: ., cksum
0x66e7 (correct), 369:369(0) ack 133 win 65535 <nop,nop,timestamp
46204041 276443497>
^C
28 packets captured
28 packets received by filter
0 packets dropped by kernel






More information about the httperf mailing list