Here are some SSL/core_write outputs (sizes) for me, with 2.4.x.
This is with a GET for a 2MB file, on localhost...
Please note that "EnableMMap on" avoids EnableSendfile (i.e.
"EnableMMap on" => "EnableSendfile off"), which is relevant only in
the http (non-ssl) case anyway.
Outputs (and the patch to produce them) attached.
TL;DR:
- http + EnableMMap => single write
- http + !EnableMMap + EnableSendfile => single write
- http + !EnableMMap + !EnableSendfile => 125KB writes
- https + EnableMMap => 16KB writes
- https + !EnableMMap => 8KB writes
http + EnableMMap:
[Thu Feb 16 09:42:33.725297 2017] [core:notice] [pid 25096:tid 139655069091584]
[client 127.0.0.1:56466] writev_nonblocking(): 2053620/2053620 bytes
http + !EnableMMap + EnableSendfile:
[Thu Feb 16 10:09:35.504327 2017] [core:notice] [pid 25598:tid 139674043262720]
[client 127.0.0.1:56494] writev_nonblocking(): 284/284 bytes
[Thu Feb 16 10:09:35.504733 2017] [core:notice] [pid 25598:tid 139674043262720]
[client 127.0.0.1:56494] sendfile_nonblocking(): 2053336/2053336 bytes
http + !EnableMMap + !EnableSendfile:
[Thu Feb 16 09:40:41.377781 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 120284/120284 bytes
[Thu Feb 16 09:40:41.377895 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 128000/128000 bytes
[Thu Feb 16 09:40:41.377973 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 128000/128000 bytes
[Thu Feb 16 09:40:41.378069 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 128000/128000 bytes
[Thu Feb 16 09:40:41.378145 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 128000/128000 bytes
[Thu Feb 16 09:40:41.378215 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 128000/128000 bytes
[Thu Feb 16 09:40:41.378291 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 128000/128000 bytes
[Thu Feb 16 09:40:41.378366 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 128000/128000 bytes
[Thu Feb 16 09:40:41.378446 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 128000/128000 bytes
[Thu Feb 16 09:40:41.378525 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 128000/128000 bytes
[Thu Feb 16 09:40:41.378592 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 128000/128000 bytes
[Thu Feb 16 09:40:41.378642 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 128000/128000 bytes
[Thu Feb 16 09:40:41.378708 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 128000/128000 bytes
[Thu Feb 16 09:40:41.378778 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 128000/128000 bytes
[Thu Feb 16 09:40:41.378931 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 128000/128000 bytes
[Thu Feb 16 09:40:41.379006 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 128000/128000 bytes
[Thu Feb 16 09:40:41.379040 2017] [core:notice] [pid 25057:tid 139655060698880]
[client 127.0.0.1:56464] writev_nonblocking(): 13336/13336 bytes
https + EnableMMap:
[Thu Feb 16 09:38:33.699387 2017] [ssl:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] bio_filter_out_write(): 2088 bytes
[Thu Feb 16 09:38:33.699429 2017] [ssl:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] bio_filter_out_write(): flush
[Thu Feb 16 09:38:33.699454 2017] [core:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] writev_nonblocking(): 2088/2088 bytes
[Thu Feb 16 09:38:33.700821 2017] [ssl:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] bio_filter_out_write(): 274 bytes
[Thu Feb 16 09:38:33.700835 2017] [ssl:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] bio_filter_out_write(): flush
[Thu Feb 16 09:38:33.700853 2017] [core:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] writev_nonblocking(): 274/274 bytes
[Thu Feb 16 09:38:33.701481 2017] [ssl:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] ssl_filter_write(): 284 bytes
[Thu Feb 16 09:38:33.701497 2017] [ssl:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] bio_filter_out_write(): 313 bytes
[Thu Feb 16 09:38:33.701502 2017] [ssl:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] ssl_filter_write(): 2053336 bytes
[Thu Feb 16 09:38:33.701524 2017] [ssl:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] bio_filter_out_write(): 16413 bytes
[Thu Feb 16 09:38:33.701551 2017] [core:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] writev_nonblocking(): 16726/16726 bytes
[...]
[Thu Feb 16 09:38:33.705384 2017] [ssl:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] bio_filter_out_write(): 16413 bytes
[Thu Feb 16 09:38:33.705396 2017] [core:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] writev_nonblocking(): 16413/16413 bytes
[Thu Feb 16 09:38:33.705407 2017] [ssl:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] bio_filter_out_write(): 5365 bytes
[Thu Feb 16 09:38:33.705430 2017] [core:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] writev_nonblocking(): 5365/5365 bytes
[Thu Feb 16 09:38:33.706128 2017] [ssl:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] bio_filter_out_write(): 31 bytes
[Thu Feb 16 09:38:33.706142 2017] [ssl:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] bio_filter_out_write(): flush
[Thu Feb 16 09:38:33.706179 2017] [core:notice] [pid 24930:tid 139655069091584]
[client 127.0.0.1:58074] writev_nonblocking(): 31/31 bytes
https + !EnableMMap:
[Thu Feb 16 09:39:49.732591 2017] [ssl:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] bio_filter_out_write(): 2088 bytes
[Thu Feb 16 09:39:49.732639 2017] [ssl:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] bio_filter_out_write(): flush
[Thu Feb 16 09:39:49.732679 2017] [core:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] writev_nonblocking(): 2088/2088 bytes
[Thu Feb 16 09:39:49.734701 2017] [ssl:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] bio_filter_out_write(): 274 bytes
[Thu Feb 16 09:39:49.734724 2017] [ssl:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] bio_filter_out_write(): flush
[Thu Feb 16 09:39:49.734753 2017] [core:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] writev_nonblocking(): 274/274 bytes
[Thu Feb 16 09:39:49.737907 2017] [ssl:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] ssl_filter_write(): 284 bytes
[Thu Feb 16 09:39:49.737984 2017] [ssl:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] bio_filter_out_write(): 313 bytes
[Thu Feb 16 09:39:49.737999 2017] [ssl:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] ssl_filter_write(): 8000 bytes
[Thu Feb 16 09:39:49.738032 2017] [ssl:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] bio_filter_out_write(): 8029 bytes
[Thu Feb 16 09:39:49.738159 2017] [core:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] writev_nonblocking(): 8342/8342 bytes
[Thu Feb 16 09:39:49.738191 2017] [ssl:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] ssl_filter_write(): 8000 bytes
[Thu Feb 16 09:39:49.738222 2017] [ssl:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] bio_filter_out_write(): 8029 bytes
[Thu Feb 16 09:39:49.738262 2017] [core:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] writev_nonblocking(): 8029/8029 bytes
[...]
[Thu Feb 16 09:39:49.745682 2017] [ssl:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] ssl_filter_write(): 8000 bytes
[Thu Feb 16 09:39:49.745692 2017] [ssl:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] bio_filter_out_write(): 8029 bytes
[Thu Feb 16 09:39:49.745703 2017] [core:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] writev_nonblocking(): 8029/8029 bytes
[Thu Feb 16 09:39:49.745708 2017] [ssl:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] ssl_filter_write(): 5336 bytes
[Thu Feb 16 09:39:49.745716 2017] [ssl:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] bio_filter_out_write(): 5365 bytes
[Thu Feb 16 09:39:49.745725 2017] [core:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] writev_nonblocking(): 5365/5365 bytes
[Thu Feb 16 09:39:49.746582 2017] [ssl:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] bio_filter_out_write(): 31 bytes
[Thu Feb 16 09:39:49.746598 2017] [ssl:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] bio_filter_out_write(): flush
[Thu Feb 16 09:39:49.746636 2017] [core:notice] [pid 25057:tid 139655069091584]
[client 127.0.0.1:58078] writev_nonblocking(): 31/31 bytes
Index: modules/ssl/ssl_engine_io.c
===================================================================
--- modules/ssl/ssl_engine_io.c (revision 1781789)
+++ modules/ssl/ssl_engine_io.c (working copy)
@@ -152,6 +152,9 @@ static int bio_filter_out_flush(BIO *bio)
bio_filter_out_ctx_t *outctx = (bio_filter_out_ctx_t *)(bio->ptr);
apr_bucket *e;
+ ap_log_cerror(APLOG_MARK, APLOG_NOTICE, 0, outctx->c,
+ "bio_filter_out_write(): flush");
+
AP_DEBUG_ASSERT(APR_BRIGADE_EMPTY(outctx->bb));
e = apr_bucket_flush_create(outctx->bb->bucket_alloc);
@@ -200,6 +203,9 @@ static int bio_filter_out_write(BIO *bio, const ch
return -1;
}
+ ap_log_cerror(APLOG_MARK, APLOG_NOTICE, 0, outctx->c,
+ "bio_filter_out_write(): %i bytes", inl);
+
/* when handshaking we'll have a small number of bytes.
* max size SSL will pass us here is about 16k.
* (16413 bytes to be exact)
@@ -784,6 +790,9 @@ static apr_status_t ssl_filter_write(ap_filter_t *
return APR_EGENERAL;
}
+ ap_log_cerror(APLOG_MARK, APLOG_NOTICE, 0, f->c,
+ "ssl_filter_write(): %"APR_SIZE_T_FMT" bytes", len);
+
/* We rely on SSL_get_error() after the write, which requires an empty error
* queue before the write in order to work properly.
*/
Index: server/core_filters.c
===================================================================
--- server/core_filters.c (revision 1781789)
+++ server/core_filters.c (working copy)
@@ -815,6 +815,10 @@ static apr_status_t writev_nonblocking(apr_socket_
}
*cumulative_bytes_written += bytes_written;
+ ap_log_cerror(APLOG_MARK, APLOG_NOTICE, 0, c,
+ "writev_nonblocking(): %"APR_SIZE_T_FMT"/%"APR_SIZE_T_FMT" bytes",
+ bytes_written, bytes_to_write);
+
arv = apr_socket_timeout_set(s, old_timeout);
if ((arv != APR_SUCCESS) && (rv == APR_SUCCESS)) {
return arv;
@@ -876,6 +880,11 @@ static apr_status_t sendfile_nonblocking(apr_socke
ap__logio_add_bytes_out(c, bytes_written);
}
*cumulative_bytes_written += bytes_written;
+
+ ap_log_cerror(APLOG_MARK, APLOG_NOTICE, 0, c,
+ "sendfile_nonblocking(): %"APR_SIZE_T_FMT"/%"APR_OFF_T_FMT" bytes",
+ bytes_written, file_length);
+
if ((bytes_written < file_length) && (bytes_written > 0)) {
apr_bucket_split(bucket, bytes_written);
apr_bucket_delete(bucket);
