Continues to be broken in same way for latest Apache.

lxd: net12-david-favor-zesty # ab -k -t 10 -n 10000000 -c 5 https://DavidFavor.com/foo-8192.txt | egrep -e ^Failed -e ^Requests
Finished 116665 requests
Failed requests:        0
Requests per second:    11664.58 [#/sec] (mean)

lxd: net12-david-favor-zesty # ab -k -t 10 -n 10000000 -c 5 https://DavidFavor.com/foo-8193.txt | egrep -e ^Failed -e ^Requests
Finished 11 requests
Failed requests:        5
Requests per second:    1.09 [#/sec] (mean)

lxd: net12-david-favor-zesty # uname -a
Linux net12-david-favor-zesty 4.8.0-30-generic #32-Ubuntu SMP Fri Dec 2 03:43:27 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

lxd: net12-david-favor-zesty # lsb_release -a
No LSB modules are available.
Distributor ID:	Ubuntu
Description:	Ubuntu 17.04
Release:	17.04
Codename:	zesty

lxd: net12-david-favor-zesty # apt-cache policy apache2
apache2:
  Installed: 2.4.27-6.0+ubuntu17.04.1+deb.sury.org+1
  Candidate: 2.4.27-6.0+ubuntu17.04.1+deb.sury.org+1
  Version table:
 *** 2.4.27-6.0+ubuntu17.04.1+deb.sury.org+1 500
        500 http://ppa.launchpad.net/ondrej/apache2/ubuntu zesty/main amd64 Packages
        100 /var/lib/dpkg/status
     2.4.25-3ubuntu2.3 500
        500 http://archive.ubuntu.com/ubuntu zesty-updates/main amd64 Packages
        500 http://security.ubuntu.com/ubuntu zesty-security/main amd64 Packages
     2.4.25-3ubuntu2 500
        500 http://archive.ubuntu.com/ubuntu zesty/main amd64 Packages

Hi David,

thanks a lot for the report and for setting up a live test case scenario :)

With the following quick and dirty patch (just a quick hack) I can get the 8193 file without any blocking:

Index: support/ab.c
===================================================================
--- support/ab.c	(revision 1810256)
+++ support/ab.c	(working copy)
@@ -370,7 +370,7 @@
 int requests_initialized = 0;

 /* one global throw-away buffer to read stuff into */
-char buffer[8192];
+char buffer[8192*2];

 /* interesting percentiles */
 int percs[] = {50, 66, 75, 80, 90, 95, 98, 99, 100};

The 8192 value is hardcoded in ab in a couple of places, so some tuning/configurability might be needed?

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?

David, are you able to reproduce without the '-k' parameter in ab? I am starting to think that those 5 seconds might have something to do about it, since by default it is 5 seconds (http://httpd.apache.org/docs/2.4/mod/core.html#KeepAliveTimeout).

Will try to reproduce on a local environment soon.

At this point it would be also great to know what is the configuration of your httpd server (modules loaded, mpm used, etc..).

I am able to reproduce locally, it only happens with TLS and not with plain http. The request takes those 5s since after the end of the response, httpd waits 5s (KeepAliveTimeout) and then sends a TLS close notify (that should be those 31 bytes) and then a TCP FIN. So I suspect that ab might not handle correctly the semantic of Keep-Alive when dealing with these corner cases.

Weird, after inspecting again the various values of the variables it seems that the last byte (8193th) is send only when the keep alive timeout kicks in, probably together with the close notify? This might be a openssl internal gotcha that I am totally unaware of.

As proof of concept I just tested this code:

Index: support/ab.c
===================================================================
--- support/ab.c	(revision 1811570)
+++ support/ab.c	(working copy)
@@ -1508,7 +1508,7 @@
     r = sizeof(buffer);
 #ifdef USE_SSL
     if (c->ssl) {
-        status = SSL_read(c->ssl, buffer, r);
+        status = SSL_read(c->ssl, buffer, r+1);
         if (status <= 0) {
             int scode = SSL_get_error(c->ssl, status);

Since the buffer size is '8192', I added '1' to force the SSL_read to grab all the 8193 bytes, and the response comes super quick without waiting the 5 seconds. 

New tcpdump:

18:53:14.492000 IP 10.0.2.15.54540 > ip231.ip-144-217-33.net.https: Flags [S], seq 4209997998, win 29200, options [mss 1460,sackOK,TS val 111017592 ecr 0,nop,wscale 6], length 0
18:53:14.601366 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54540: Flags [S.], seq 153201153, ack 4209997999, win 65535, options [mss 1460], length 0
18:53:14.601425 IP 10.0.2.15.54540 > ip231.ip-144-217-33.net.https: Flags [.], ack 1, win 29200, length 0
18:53:14.601842 IP 10.0.2.15.54540 > ip231.ip-144-217-33.net.https: Flags [P.], seq 1:200, ack 1, win 29200, length 199
18:53:14.602031 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54540: Flags [.], ack 200, win 65535, length 0
18:53:14.730307 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54540: Flags [P.], seq 1:1441, ack 200, win 65535, length 1440
18:53:14.730334 IP 10.0.2.15.54540 > ip231.ip-144-217-33.net.https: Flags [.], ack 1441, win 31240, length 0
18:53:14.730609 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54540: Flags [P.], seq 1441:2881, ack 200, win 65535, length 1440
18:53:14.730624 IP 10.0.2.15.54540 > ip231.ip-144-217-33.net.https: Flags [.], ack 2881, win 34080, length 0
18:53:14.730659 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54540: Flags [P.], seq 2881:3461, ack 200, win 65535, length 580
18:53:14.730662 IP 10.0.2.15.54540 > ip231.ip-144-217-33.net.https: Flags [.], ack 3461, win 36920, length 0
18:53:14.733660 IP 10.0.2.15.54540 > ip231.ip-144-217-33.net.https: Flags [P.], seq 200:358, ack 3461, win 36920, length 158
18:53:14.733837 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54540: Flags [.], ack 358, win 65535, length 0
18:53:14.863159 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54540: Flags [P.], seq 3461:3735, ack 358, win 65535, length 274
18:53:14.863562 IP 10.0.2.15.54540 > ip231.ip-144-217-33.net.https: Flags [P.], seq 358:505, ack 3735, win 39760, length 147
18:53:14.863723 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54540: Flags [.], ack 505, win 65535, length 0
18:53:14.975417 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54540: Flags [P.], seq 3735:5175, ack 505, win 65535, length 1440
18:53:14.975451 IP 10.0.2.15.54540 > ip231.ip-144-217-33.net.https: Flags [.], ack 5175, win 42600, length 0
18:53:14.975733 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54540: Flags [P.], seq 5175:6615, ack 505, win 65535, length 1440
18:53:14.975753 IP 10.0.2.15.54540 > ip231.ip-144-217-33.net.https: Flags [.], ack 6615, win 45440, length 0
18:53:14.975803 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54540: Flags [P.], seq 6615:9495, ack 505, win 65535, length 2880
18:53:14.975811 IP 10.0.2.15.54540 > ip231.ip-144-217-33.net.https: Flags [.], ack 9495, win 51120, length 0
18:53:14.977422 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54540: Flags [P.], seq 9495:12349, ack 505, win 65535, length 2854
18:53:14.977457 IP 10.0.2.15.54540 > ip231.ip-144-217-33.net.https: Flags [.], ack 12349, win 56800, length 0
18:53:14.982993 IP 10.0.2.15.54540 > ip231.ip-144-217-33.net.https: Flags [F.], seq 505, ack 12349, win 56800, length 0
18:53:14.983322 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54540: Flags [.], ack 506, win 65535, length 0
18:53:15.092616 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54540: Flags [P.], seq 12349:12380, ack 506, win 65535, length 31
18:53:15.092688 IP 10.0.2.15.54540 > ip231.ip-144-217-33.net.https: Flags [R], seq 4209998504, win 0, length 0
18:53:15.092746 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54540: Flags [F.], seq 12380, ack 506, win 65535, length 0
18:53:15.092779 IP 10.0.2.15.54540 > ip231.ip-144-217-33.net.https: Flags [R], seq 4209998504, win 0, length 0
18:53:15.093107 IP ip231.ip-144-217-33.net.https > 10.0.2.15.54540: Flags [R.], seq 4141766143, ack 506, win 0, length 0

I've used https://www.openssl.org/docs/man1.1.0/ssl/SSL_pending.html and it seems that the byte left to read is indicated as "pending" right after reading 8192 bytes with SSL_read.

Created attachment 35407 [details]
Read more when body buffer is full

This seems to work for me...

net12 # sysctl net.ipv4.tcp_rmem net.ipv4.tcp_wmem
net.ipv4.tcp_rmem = 4096	87380	6291456
net.ipv4.tcp_wmem = 4096	16384	4194304

You may be write about the -k flag.

Here are runs for both 8192 + 8193 bytes with + without -k flag.

BTW, you're welcome to actually probe these files on my machine. No requirement to wait for me. This machine is tuned to handle massive traffic, so you're welcome to run any type of ab command you like against these files.

net11 # ab -k -t 10 -n 10000000 -c 5 https://DavidFavor.com/foo-8192.txt | egrep -e ^Failed -e ^Requests
Finished 72818 requests
Failed requests:        0
Requests per second:    7281.68 [#/sec] (mean)

net11 # ab -k -t 10 -n 10000000 -c 5 https://DavidFavor.com/foo-8193.txt | egrep -e ^Failed -e ^Requests
Finished 11 requests
Failed requests:        5
Requests per second:    1.09 [#/sec] (mean)

net11 # ab -t 10 -n 10000000 -c 5 https://DavidFavor.com/foo-8192.txt | egrep -e ^Failed -e ^Requests
Finished 1805 requests
Failed requests:        0
Requests per second:    180.48 [#/sec] (mean)

net11 # ab -t 10 -n 10000000 -c 5 https://DavidFavor.com/foo-8193.txt | egrep -e ^Failed -e ^Requests
Finished 1653 requests
Failed requests:        0
Requests per second:    165.25 [#/sec] (mean)

About strace + epoll...

Seems like epoll loses the plot. Maybe a out of bounds memory write.

Where the file numbers get overwritten + epoll never returns + instead a timeout fires.

(In reply to David Favor from comment #12)
> You may be write about the -k flag.
> 
> Here are runs for both 8192 + 8193 bytes with + without -k flag.

Was it with the patch from attachment 35407 [details]?

I can't reproduce here with a slow connection, will retry today from elsewhere.

Relatively, though:

- Without the patch:
$ support/ab -k -t 10 -n 10000000 -c 5 https://DavidFavor.com/foo-8193.txt | egrep -e ^Failed -e ^Requests
Finished 11 requests
Failed requests:        5
Requests per second:    0.86 [#/sec] (mean)

- With the patch:
$ support/ab -k -t 10 -n 10000000 -c 5 https://DavidFavor.com/foo-8193.txt | egrep -e ^Failed -e ^Requests
Finished 266 requests
Failed requests:        0
Requests per second:    26.50 [#/sec] (mean)

(In reply to Yann Ylavic from comment #10)
> Created attachment 35407 [details]
> Read more when body buffer is full
> 
> This seems to work for me...

Hi Yann, it works for me too :)

I don't particularly like the goto statement in general but in the context of the current ab code it seems a good solution to the problem. I'd have used a more restrictive if condition like the following (since I didn't find any issue with the plain http use case) but I don't think it changes much:

+    if (c->ssl && SSL_pending(c->ssl)) {
+        goto read_more;
+    }

Looks like the problem is solved!

Committed the TLS agnostic version in r1811649, probably worth it for the http: case too since it avoids poll()ing when the data are likely >8K (a nonblocking read, even in the unlikely failing case, is quite cheap compared to returning to the caller).

r1811664 may be worth a try too, particularly in the SSL case and/or large data and limited connection capacity.

All my testing done without applying any patches.

Thanks for working out the patch!

Looks like this patch missed making it into 2.4.28 as I don't see any mention of it in the changelog.

Please drop an update letting me know if this made it into 2.4.28 or missed this release.

Thanks.

Changes backported to 2.4.x in http://svn.apache.org/r1814468, will be part of the next httpd release.

Thanks a lot David for the useful info and the debugging!