httpd-bugs mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From bugzi...@apache.org
Subject [Bug 61301] ab slows dramatically with requests >8192 bytes, httpd seems to be working correctly
Date Mon, 02 Oct 2017 08:33:34 GMT
https://bz.apache.org/bugzilla/show_bug.cgi?id=61301

--- Comment #3 from Luca Toscano <toscano.luca@gmail.com> ---
The weird thing is that from a strace like "strace ./support/ab -k -n 1 -c 1 
https://DavidFavor.com/foo-8193.txt" it seems that the bottleneck seems to be
epoll waiting for 5s before getting the last POLLIN event and be done with the
response read (this was also indicated in the bug reported to ubuntu).

The default timeout for epoll in this case is 30s, so those 5s are not due to a
timeout or anything similar, but it seems something else. 

This is a tcpdump from my vagrant VM to davidfavor.com's IP (since the examples
are public I will not obfuscate IPs assuming that David is ok with it, please
let me know otherwise):

10:13:44.651245 IP 10.0.2.15.54212 > ip231.ip-144-217-33.net.https: Flags [S],
seq 1618786442, win 29200, options [mss 1460,sackOK,TS v
al 52282738 ecr 0,nop,wscale 6], length 0
10:13:44.763105 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54212: Flags [S.],
seq 568308225, ack 1618786443, win 65535, options [mss 1460], length 0
10:13:44.763142 IP 10.0.2.15.54212 > ip231.ip-144-217-33.net.https: Flags [.],
ack 1, win 29200, length 0
10:13:44.763941 IP 10.0.2.15.54212 > ip231.ip-144-217-33.net.https: Flags [P.],
seq 1:200, ack 1, win 29200, length 199
10:13:44.764160 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54212: Flags [.],
ack 200, win 65535, length 0
10:13:44.895769 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54212: Flags [P.],
seq 1:1441, ack 200, win 65535, length 1440
10:13:44.895834 IP 10.0.2.15.54212 > ip231.ip-144-217-33.net.https: Flags [.],
ack 1441, win 31240, length 0
10:13:44.895924 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54212: Flags [P.],
seq 1441:2881, ack 200, win 65535, length 1440
10:13:44.895938 IP 10.0.2.15.54212 > ip231.ip-144-217-33.net.https: Flags [.],
ack 2881, win 34080, length 0
10:13:44.895966 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54212: Flags [P.],
seq 2881:3461, ack 200, win 65535, length 580
10:13:44.895970 IP 10.0.2.15.54212 > ip231.ip-144-217-33.net.https: Flags [.],
ack 3461, win 36920, length 0
10:13:44.899156 IP 10.0.2.15.54212 > ip231.ip-144-217-33.net.https: Flags [P.],
seq 200:358, ack 3461, win 36920, length 158
10:13:44.899343 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54212: Flags [.],
ack 358, win 65535, length 0
10:13:45.013631 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54212: Flags [P.],
seq 3461:3735, ack 358, win 65535, length 274
10:13:45.014632 IP 10.0.2.15.54212 > ip231.ip-144-217-33.net.https: Flags [P.],
seq 358:505, ack 3735, win 39760, length 147
10:13:45.014797 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54212: Flags [.],
ack 505, win 65535, length 0
10:13:45.131029 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54212: Flags [.],
seq 3735:12255, ack 505, win 65535, length 8520
10:13:45.131063 IP 10.0.2.15.54212 > ip231.ip-144-217-33.net.https: Flags [.],
ack 12255, win 56800, length 0
10:13:45.131266 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54212: Flags [P.],
seq 12255:12349, ack 505, win 65535, length 94
10:13:45.171739 IP 10.0.2.15.54212 > ip231.ip-144-217-33.net.https: Flags [.],
ack 12349, win 56800, length 0

[..5 seconds waited in epoll..]

10:13:50.130862 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54212: Flags [P.],
seq 12349:12380, ack 505, win 65535, length 31
10:13:50.130902 IP 10.0.2.15.54212 > ip231.ip-144-217-33.net.https: Flags [.],
ack 12380, win 56800, length 0
10:13:50.130956 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54212: Flags [F.],
seq 12380, ack 505, win 65535, length 0
10:13:50.132552 IP 10.0.2.15.54212 > ip231.ip-144-217-33.net.https: Flags [R.],
seq 505, ack 12381, win 56800, length 0

Note: the last reset is probably due to the fact that httpd closes the TLS
connection but doesn't wait for the client's ack (afaik this is a know behavior
for all the webservers with TLS).

As far as I can see httpd sends the last 31 bytes after those 5 seconds, not
really sure why, since the ack for 12349 was already arrived (but I am not a
tcp expert so if anybody wants to chime in please do :).

With my hack to double the buffer size:

10:25:33.152120 IP 10.0.2.15.54214 > ip231.ip-144-217-33.net.https: Flags [S],
seq 2516251832, win 29200, options [mss 1460,sackOK,TS val 52459800 ecr
0,nop,wscale 6], length 0
10:25:33.266348 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54214: Flags [S.],
seq 656436225, ack 2516251833, win 65535, options [mss1460], length 0
10:25:33.266403 IP 10.0.2.15.54214 > ip231.ip-144-217-33.net.https: Flags [.],
ack 1, win 29200, length 0
10:25:33.267526 IP 10.0.2.15.54214 > ip231.ip-144-217-33.net.https: Flags [P.],
seq 1:200, ack 1, win 29200, length 199
10:25:33.267781 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54214: Flags [.],
ack 200, win 65535, length 0
10:25:33.401127 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54214: Flags [P.],
seq 1:1441, ack 200, win 65535, length 1440
10:25:33.401153 IP 10.0.2.15.54214 > ip231.ip-144-217-33.net.https: Flags [.],
ack 1441, win 31240, length 0
10:25:33.401563 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54214: Flags [P.],
seq 1441:2881, ack 200, win 65535, length 1440
10:25:33.401580 IP 10.0.2.15.54214 > ip231.ip-144-217-33.net.https: Flags [.],
ack 2881, win 34080, length 0
10:25:33.401609 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54214: Flags [P.],
seq 2881:3461, ack 200, win 65535, length 580
10:25:33.401614 IP 10.0.2.15.54214 > ip231.ip-144-217-33.net.https: Flags [.],
ack 3461, win 36920, length 0
10:25:33.405102 IP 10.0.2.15.54214 > ip231.ip-144-217-33.net.https: Flags [P.],
seq 200:358, ack 3461, win 36920, length 158
10:25:33.405368 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54214: Flags [.],
ack 358, win 65535, length 0
10:25:33.519007 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54214: Flags [P.],
seq 3461:3735, ack 358, win 65535, length 274
10:25:33.519910 IP 10.0.2.15.54214 > ip231.ip-144-217-33.net.https: Flags [P.],
seq 358:505, ack 3735, win 39760, length 147
10:25:33.520109 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54214: Flags [.],
ack 505, win 65535, length 0
10:25:33.631128 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54214: Flags [P.],
seq 3735:5175, ack 505, win 65535, length 1440
10:25:33.631165 IP 10.0.2.15.54214 > ip231.ip-144-217-33.net.https: Flags [.],
ack 5175, win 42600, length 0
10:25:33.631595 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54214: Flags [P.],
seq 5175:6615, ack 505, win 65535, length 1440
10:25:33.631608 IP 10.0.2.15.54214 > ip231.ip-144-217-33.net.https: Flags [.],
ack 6615, win 45440, length 0
10:25:33.631634 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54214: Flags [P.],
seq 6615:8055, ack 505, win 65535, length 1440
10:25:33.631638 IP 10.0.2.15.54214 > ip231.ip-144-217-33.net.https: Flags [.],
ack 8055, win 48280, length 0
10:25:33.633024 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54214: Flags [P.],
seq 8055:12349, ack 505, win 65535, length 4294
10:25:33.633047 IP 10.0.2.15.54214 > ip231.ip-144-217-33.net.https: Flags [.],
ack 12349, win 56800, length 0
10:25:33.645524 IP 10.0.2.15.54214 > ip231.ip-144-217-33.net.https: Flags [F.],
seq 505, ack 12349, win 56800, length 0
10:25:33.645630 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54214: Flags [.],
ack 506, win 65535, length 0
10:25:33.756624 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54214: Flags [P.],
seq 12349:12380, ack 506, win 65535, length 31
10:25:33.756675 IP 10.0.2.15.54214 > ip231.ip-144-217-33.net.https: Flags [R],
seq 2516252338, win 0, length 0
10:25:33.756749 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54214: Flags [F.],
seq 12380, ack 506, win 65535, length 0
10:25:33.756762 IP 10.0.2.15.54214 > ip231.ip-144-217-33.net.https: Flags [R],
seq 2516252338, win 0, length 0
10:25:33.757214 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54214: Flags [R.],
seq 3638531071, ack 506, win 0, length 0

As far as I can see the only thing that changes in here is that ab sends the
FIN in this case, and then there are no issues for those 31 bytes.

Is this maybe a TLS only issue? David, just to have more details, would you
mind to dump your sysctl net.ipv4.tcp_rmem and net.ipv4.tcp_wmem settings?

-- 
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: bugs-unsubscribe@httpd.apache.org
For additional commands, e-mail: bugs-help@httpd.apache.org


Mime
View raw message