[httperf] Httperf client timeout while making progress

[Chris Wilson]

Hi all,

First of all, thanks for writing httperf! It looks like an excellent tool 
and most suitable for the kind of network performance tests and debugging 
that I'm currently doing (fixing university networks in Kenya).

However, I think I've discovered a discrepancy between httperf's behaviour 
and the documentation. The man page says of the option --timeout:

    Specifies the amount of time X that httperf is willing to wait
    for a server reaction. [...] This timeout value is used when
    establishing a TCP connection, when sending a request, when waiting for
    a reply, and when receiving a reply. If during any of those activities
    a request fails to make forward progress within the alloted time,
    httperf considers the request to have died, closes the associated
    connection or session and increases the client-timo error count.

Now that makes perfect sense to me, and mirrors the way that I think a 
browser would work. My definition of "making forward progress while 
receiving a reply" is that packets continue to be received. So as long as 
the delay between packets (or TCP data delivery) does not exceed the 
timeout, httperf will not give up on the connection.

However, I think that I have observed httperf behaving differently. 
Specifically, it seems to apply the --timeout to receiving the entire 
response. Therefore, if I specify a reasonable timeout of 30 seconds, and 
download a large page over a slow connection, httperf reports a timeout 
error, even though a browser would not.

I've attached a pcap file and httperf debug log (level 3) as an example.

If there is any choice over this behaviour, I would like to configure 
httperf to behave the way that I described above, i.e. not to time out the 
connection as long as it continues to receive packets.

Thanks in advance for your help!

Cheers, Chris.
-- 
(aidworld) chris wilson | chief engineer (http://www.aidworld.org)
-------------- next part --------------
A non-text attachment was scrubbed...
Name: cnn-3.pcap
Type: application/octet-stream
Size: 4280 bytes
Desc: 
Url : http://napali.hpl.hp.com/pipermail/httperf/attachments/20061124/22e59b99/cnn-3.obj
-------------- next part --------------
root at utalii(root)$ httperf --hog --timeout=30 --server=www.cnn.com --port=80 --uri=/ --http-version=1.0 --num-conns=1 --debug 3
httperf --hog --timeout=30 --client=0/1 --server=www.cnn.com --port=80 --uri=/ --http-version=1.0 --send-buffer=4096 --recv-buffer=16384 --num-conns=1 --num-calls=1
httperf: warning: open file limit > FD_SETSIZE; limiting max. # of open files to FD_SETSIZE
event_signal: EV_HOSTNAME_LOOKUP_START (obj=0x0,arg=bfbfed9c)
event_signal: EV_HOSTNAME_LOOKUP_STOP (obj=0x0,arg=bfbfed9c)
timer_schedule: t=0x80d1120, delay=5s, arg=0
event_signal: EV_CONN_NEW (obj=0x80d6800,arg=0)
event_signal: EV_CONN_CONNECTING (obj=0x80d6800,arg=0)
timer_schedule: t=0x80d1140, delay=30s, arg=80d6800
timer_cancel: t=0x80d1140
event_signal: EV_CONN_CONNECTED (obj=0x80d6800,arg=0)
event_signal: EV_CALL_NEW (obj=0x80dc100,arg=0)
event_signal: EV_CALL_ISSUE (obj=0x80dc100,arg=0)
event_signal: EV_CALL_SEND_START (obj=0x80dc100,arg=0)
timer_schedule: t=0x80d1140, delay=30s, arg=80d6800
timer_cancel: t=0x80d1140
event_signal: EV_CALL_SEND_RAW_DATA (obj=0x80dc100,arg=0)
do_send.0: wrote 62 bytes on 0x80d6800
event_signal: EV_CALL_SEND_STOP (obj=0x80dc100,arg=0)
timer_schedule: t=0x80d1140, delay=30s, arg=80d6800
event_signal: EV_PERF_SAMPLE (obj=0x0,arg=b89332db)
timer_schedule: t=0x80d1160, delay=5s, arg=0
timer_cancel: t=0x80d1140
event_signal: EV_CALL_RECV_RAW_DATA (obj=0x80dc100,arg=bfbfc5b0)
parse_status_line.0: reply is HTTP/1.1, status = 200
event_signal: EV_CALL_RECV_START (obj=0x80dc100,arg=c8)
event_signal: EV_CALL_RECV_HDR (obj=0x80dc100,arg=80d684c)
event_signal: EV_CALL_RECV_HDR (obj=0x80dc100,arg=80d684c)
event_signal: EV_CALL_RECV_HDR (obj=0x80dc100,arg=80d684c)
event_signal: EV_CALL_RECV_HDR (obj=0x80dc100,arg=80d684c)
event_signal: EV_CALL_RECV_HDR (obj=0x80dc100,arg=80d684c)
event_signal: EV_CALL_RECV_HDR (obj=0x80dc100,arg=80d684c)
event_signal: EV_CALL_RECV_HDR (obj=0x80dc100,arg=80d684c)
event_signal: EV_CALL_RECV_HDR (obj=0x80dc100,arg=80d684c)
timer_schedule: t=0x80d1140, delay=24.8235s, arg=80d6800
timer_cancel: t=0x80d1140
event_signal: EV_CALL_RECV_RAW_DATA (obj=0x80dc100,arg=bfbfc5b0)
event_signal: EV_CALL_RECV_DATA (obj=0x80dc100,arg=bfbfc580)
timer_schedule: t=0x80d1140, delay=24.7287s, arg=80d6800
event_signal: EV_PERF_SAMPLE (obj=0x0,arg=c7d900d)
timer_schedule: t=0x80d1120, delay=5s, arg=0
timer_cancel: t=0x80d1140
event_signal: EV_CALL_RECV_RAW_DATA (obj=0x80dc100,arg=bfbfc5b0)
event_signal: EV_CALL_RECV_DATA (obj=0x80dc100,arg=bfbfc580)
timer_schedule: t=0x80d1140, delay=20.036s, arg=80d6800
timer_cancel: t=0x80d1140
event_signal: EV_CALL_RECV_RAW_DATA (obj=0x80dc100,arg=bfbfc5b0)
event_signal: EV_CALL_RECV_DATA (obj=0x80dc100,arg=bfbfc580)
timer_schedule: t=0x80d1140, delay=19.6252s, arg=80d6800
event_signal: EV_PERF_SAMPLE (obj=0x0,arg=16c4e9bd)
timer_schedule: t=0x80d1160, delay=5s, arg=0
timer_cancel: t=0x80d1140
event_signal: EV_CALL_RECV_RAW_DATA (obj=0x80dc100,arg=bfbfc5b0)
event_signal: EV_CALL_RECV_DATA (obj=0x80dc100,arg=bfbfc580)
timer_schedule: t=0x80d1140, delay=14.1929s, arg=80d6800
timer_cancel: t=0x80d1140
event_signal: EV_CALL_RECV_RAW_DATA (obj=0x80dc100,arg=bfbfc5b0)
event_signal: EV_CALL_RECV_DATA (obj=0x80dc100,arg=bfbfc580)
timer_schedule: t=0x80d1140, delay=13.7474s, arg=80d6800
timer_cancel: t=0x80d1140
event_signal: EV_CALL_RECV_RAW_DATA (obj=0x80dc100,arg=bfbfc5b0)
event_signal: EV_CALL_RECV_DATA (obj=0x80dc100,arg=bfbfc580)
timer_schedule: t=0x80d1140, delay=13.217s, arg=80d6800
event_signal: EV_PERF_SAMPLE (obj=0x0,arg=68a0774f)
timer_schedule: t=0x80d1120, delay=5s, arg=0
timer_cancel: t=0x80d1140
event_signal: EV_CALL_RECV_RAW_DATA (obj=0x80dc100,arg=bfbfc5b0)
event_signal: EV_CALL_RECV_DATA (obj=0x80dc100,arg=bfbfc580)
timer_schedule: t=0x80d1140, delay=9.39508s, arg=80d6800
timer_cancel: t=0x80d1140
event_signal: EV_CALL_RECV_RAW_DATA (obj=0x80dc100,arg=bfbfc5b0)
event_signal: EV_CALL_RECV_DATA (obj=0x80dc100,arg=bfbfc580)
timer_schedule: t=0x80d1140, delay=8.65049s, arg=80d6800
timer_cancel: t=0x80d1140
event_signal: EV_CALL_RECV_RAW_DATA (obj=0x80dc100,arg=bfbfc5b0)
event_signal: EV_CALL_RECV_DATA (obj=0x80dc100,arg=bfbfc580)
timer_schedule: t=0x80d1140, delay=7.93852s, arg=80d6800
timer_cancel: t=0x80d1140
event_signal: EV_CALL_RECV_RAW_DATA (obj=0x80dc100,arg=bfbfc5b0)
event_signal: EV_CALL_RECV_DATA (obj=0x80dc100,arg=bfbfc580)
timer_schedule: t=0x80d1140, delay=7.06708s, arg=80d6800
event_signal: EV_PERF_SAMPLE (obj=0x0,arg=53ca6a65)
timer_schedule: t=0x80d1160, delay=5.00004s, arg=0
timer_cancel: t=0x80d1140
event_signal: EV_CALL_RECV_RAW_DATA (obj=0x80dc100,arg=bfbfc5b0)
event_signal: EV_CALL_RECV_DATA (obj=0x80dc100,arg=bfbfc580)
timer_schedule: t=0x80d1140, delay=4.56339s, arg=80d6800
timer_cancel: t=0x80d1140
event_signal: EV_CALL_RECV_RAW_DATA (obj=0x80dc100,arg=bfbfc5b0)
event_signal: EV_CALL_RECV_DATA (obj=0x80dc100,arg=bfbfc580)
timer_schedule: t=0x80d1140, delay=3.5021s, arg=80d6800
timer_cancel: t=0x80d1140
event_signal: EV_CALL_RECV_RAW_DATA (obj=0x80dc100,arg=bfbfc5b0)
event_signal: EV_CALL_RECV_DATA (obj=0x80dc100,arg=bfbfc580)
timer_schedule: t=0x80d1140, delay=1.94623s, arg=80d6800
event_signal: EV_PERF_SAMPLE (obj=0x0,arg=1cb0931)
timer_schedule: t=0x80d1120, delay=5.00008s, arg=0
timer_cancel: t=0x80d1140
event_signal: EV_CALL_RECV_RAW_DATA (obj=0x80dc100,arg=bfbfc5b0)
event_signal: EV_CALL_RECV_DATA (obj=0x80dc100,arg=bfbfc580)
timer_schedule: t=0x80d1140, delay=0.433076s, arg=80d6800
connection_timeout.0: t=0x80d1140, connection=0x80d6800
event_signal: EV_CONN_TIMEOUT (obj=0x80d6800,arg=0)
event_signal: EV_CALL_DESTROYED (obj=0x80dc100,arg=0)
event_signal: EV_CONN_CLOSE (obj=0x80d6800,arg=0)
event_signal: EV_CONN_DESTROYED (obj=0x80d6800,arg=0)
Maximum connect burst length: 0

Total: connections 1 requests 1 replies 0 test-duration 30.682 s

Connection rate: 0.0 conn/s (30682.3 ms/conn, <=1 concurrent connections)
Connection time [ms]: min 0.0 avg 0.0 max 0.0 median 0.0 stddev 0.0
Connection time [ms]: connect 681.3
Connection length [replies/conn]: 0.000

Request rate: 0.0 req/s (30682.3 ms/req)
Request size [B]: 62.0

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

CPU time [s]: user 3.16 system 25.46 (user 10.3% system 83.0% total 93.3%)
Net I/O: 0.0 KB/s (0.0*10^6 bps)

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