Bug 63916 - org.apache.catalina.nonblocking.TestNonBlockingAPI abysmally slow with NIO/NIO2 on FreeBSD
Summary: org.apache.catalina.nonblocking.TestNonBlockingAPI abysmally slow with NIO/NI...
Status: RESOLVED FIXED
Alias: None
Product: Tomcat 9
Classification: Unclassified
Component: Connectors (show other bugs)
Version: 9.0.x
Hardware: PC NetBSD
: P2 major (vote)
Target Milestone: -----
Assignee: Tomcat Developers Mailing List
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2019-11-10 19:00 UTC by Michael Osipov
Modified: 2019-11-14 17:57 UTC (History)
1 user (show)



Attachments
Test suite results as CSV (80.73 KB, application/vnd.ms-excel)
2019-11-10 19:01 UTC, Michael Osipov
Details
Test with APR (84.31 KB, text/plain)
2019-11-10 19:01 UTC, Michael Osipov
Details
Test with NIO (62 bytes, text/plain)
2019-11-10 19:01 UTC, Michael Osipov
Details
Test with NIO2 (126.37 KB, text/plain)
2019-11-10 19:02 UTC, Michael Osipov
Details
JStack dump (28.01 KB, text/plain)
2019-11-10 19:02 UTC, Michael Osipov
Details
JStack dump 2 (28.01 KB, text/plain)
2019-11-10 19:02 UTC, Michael Osipov
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Michael Osipov 2019-11-10 19:00:57 UTC
Running all tests regularily from master on
> FreeBSD 12.1-STABLE #1 r353717

on a very capable machine:
> $ sysctl hw.physmem
> hw.physmem: 34200395776
>
> $ sysctl hw.model hw.machine hw.ncpu
> hw.model: Intel(R) Xeon(R) CPU E5-2640 v4 @ 2.40GHz
> hw.machine: amd64
> hw.ncpu: 20

with 
> $ for jdk in  /usr/local/openjdk* ; do $jdk/bin/java -version; done
> openjdk version "11.0.5" 2019-10-15
> OpenJDK Runtime Environment (build 11.0.5+10-1)
> OpenJDK 64-Bit Server VM (build 11.0.5+10-1, mixed mode)
> openjdk version "12.0.2" 2019-07-16
> OpenJDK Runtime Environment (build 12.0.2+10-3)
> OpenJDK 64-Bit Server VM (build 12.0.2+10-3, mixed mode)
> openjdk version "1.8.0_232"
> OpenJDK Runtime Environment (build 1.8.0_232-b09)
> OpenJDK 64-Bit Server VM (build 25.232-b09, mixed mode)

with the same horrible results over and over again (see tests.csv marked with X in last col):
> org.apache.catalina.nonblocking.TestNonBlockingAPI;APR;9;0;0;1;37,114;X
> org.apache.catalina.nonblocking.TestNonBlockingAPI;NIO;9;1;0;1;2215,246;X
> org.apache.catalina.nonblocking.TestNonBlockingAPI;NIO2;9;1;0;1;2208,712;X

APR requires less than 40 s to complete, NIO more than 2200 s.

I have attached the test output as well as two thread dumps with 30 s apart during tests while it is completely blocked.
I wonder wether this issue is present in some form on macOS using the same KQueue NIO impl at least in Java 8.

It is not really clear to me: is it the test, Tomcat or a JVM on FreeBSD bug. I am not really skilled in reading thread dumps.

Any pointers I can start digging? I'd collect the appropriate data and contact the FreeBSD Java port maintainer.
Comment 1 Michael Osipov 2019-11-10 19:01:26 UTC
Created attachment 36875 [details]
Test suite results as CSV
Comment 2 Michael Osipov 2019-11-10 19:01:46 UTC
Created attachment 36876 [details]
Test with APR
Comment 3 Michael Osipov 2019-11-10 19:01:59 UTC
Created attachment 36877 [details]
Test with NIO
Comment 4 Michael Osipov 2019-11-10 19:02:12 UTC
Created attachment 36878 [details]
Test with NIO2
Comment 5 Michael Osipov 2019-11-10 19:02:32 UTC
Created attachment 36879 [details]
JStack dump
Comment 6 Michael Osipov 2019-11-10 19:02:48 UTC
Created attachment 36880 [details]
JStack dump 2
Comment 7 Mark Thomas 2019-11-12 14:00:28 UTC
I'm starting to look at this.

How are you installing Java on FreeBSD? From the ports?
Comment 8 Mark Thomas 2019-11-12 15:50:48 UTC
I see some timing differences on Linux, but not as extreme.

For one test testNonBlockingWriteWithKeepAlive

NIO: 55s
APR:  8s

The NIO slowness is caused by the non-blocking write. The test does a large write. There is then, essentially a loop where:
- non-blocking write (8k, the buffer size)
- add socket to poller
- wait for poller to signal write is possible

There is a delay of ~40ms in each loop iteration waiting for the poller.
10MB of data in 8k chunks with a 40ms delay per chunk = 51s.

Set socket.appWriteBufSize to 64k and the time for that test with NIO drops to 8s.

I don't see anything that would let us configure the Poller to react any faster.

I want to use a Profiler to investigate that delay to see if it really does happen in the Poller or if it is in the Tomcat code using the Poller.

I also want to run the test on FreeBSD to see if the delays you see have a similar root cause. I'm guessing from the version number you aren't using Java from ports but are using the AdoptOpenJDK for Linux builds.
Comment 9 Michael Osipov 2019-11-12 19:29:37 UTC
(In reply to Mark Thomas from comment #8)
> I see some timing differences on Linux, but not as extreme.
> 
> For one test testNonBlockingWriteWithKeepAlive
> 
> NIO: 55s
> APR:  8s
> 
> The NIO slowness is caused by the non-blocking write. The test does a large
> write. There is then, essentially a loop where:
> - non-blocking write (8k, the buffer size)
> - add socket to poller
> - wait for poller to signal write is possible
> 
> There is a delay of ~40ms in each loop iteration waiting for the poller.
> 10MB of data in 8k chunks with a 40ms delay per chunk = 51s.
> 
> Set socket.appWriteBufSize to 64k and the time for that test with NIO drops
> to 8s.
> 
> I don't see anything that would let us configure the Poller to react any
> faster.
> 
> I want to use a Profiler to investigate that delay to see if it really does
> happen in the Poller or if it is in the Tomcat code using the Poller.

Thanks for looking into, but even on Linux, is that a sound difference? Why is APR so much faster here?

> I also want to run the test on FreeBSD to see if the delays you see have a
> similar root cause. I'm guessing from the version number you aren't using
> Java from ports but are using the AdoptOpenJDK for Linux builds.

I am using OpenJDK straight from Ports which is a fork of AdoptOpenJDK: The canonical fork for all BSDs: https://github.com/battleblow/
Comment 10 Mark Thomas 2019-11-12 22:56:49 UTC
No, the Linux performance is not what I expect. There is something wrong here. I'm going to build a simple test case to demonstrate it.

FreeBSD has the same issue but the pause before select() returns is longer so the impact is greater.

I'm still not sure if this is a JRE bug or it is the way Tomcat is using the API. I hope to be able to explore that in my test case.
Comment 11 Mark Thomas 2019-11-12 23:44:28 UTC
Simpler test case that reproduces the issue

https://github.com/markt-asf/tomcat-bugs/blob/master/src/java/org/apache/tomcat/Bug63916NioPoller.java

Run the test case and connect with telnet to localhost 8080.
Uncomment the line that sets the send buffer to 8k and watch the time taken to write the 10MB jump from ~400ms to ~50s.

Tomorrow's task is to experiment to see if I can figure out the root cause of the time difference.
Comment 12 Remy Maucherat 2019-11-13 10:45:10 UTC
By default on my Linux the socket send buffer size is 2304. For NIO to have the same "performance" and behavior running the test [as seen with the debug logs] as NIO2, the send buffer size needs to be exactly >= to 4737.

Note: CI used to show this behavior but that's no longer the case, now NIO and NIO2 are equal and APR is quite a bit behind.
https://ci.apache.org/projects/tomcat/tomcat9/logs/4721/TEST-org.apache.catalina.nonblocking.TestNonBlockingAPI.NIO.txt
https://ci.apache.org/projects/tomcat/tomcat9/logs/4721/TEST-org.apache.catalina.nonblocking.TestNonBlockingAPI.NIO2.txt
https://ci.apache.org/projects/tomcat/tomcat9/logs/4721/TEST-org.apache.catalina.nonblocking.TestNonBlockingAPI.APR.txt

I have yet to notice any performance impact at all in a "real" test, NIO async with HTTP/2 is very fine performance wise compared to NIO2, same as sendfile, etc.

Also at this point given the difference and most importantly that NIO2 is also affected, I would say FreeBSD's Java IO might be broken. AFAIK it is not a platform directly supported by OpenJDK.
Comment 13 Michael Osipov 2019-11-13 10:56:10 UTC
(In reply to Mark Thomas from comment #11)
> Simpler test case that reproduces the issue
> 
> https://github.com/markt-asf/tomcat-bugs/blob/master/src/java/org/apache/
> tomcat/Bug63916NioPoller.java
> 
> Run the test case and connect with telnet to localhost 8080.
> Uncomment the line that sets the send buffer to 8k and watch the time taken
> to write the 10MB jump from ~400ms to ~50s.
> 
> Tomorrow's task is to experiment to see if I can figure out the root cause
> of the time difference.

Ran the test on the same FreeBSD server:

Without explicit buffer size:
> Default send buffer size is [49032]
> Writing 10MB took [2601] milliseconds
With explicit buffer size of 8 KiB:
> Writing 10MB took [135095] milliseconds

That's insane!

On HP-UX with Java 8 for comparison:
Without explicit buffer size:
> Default send buffer size is [32768]
> Writing 10MB took [2851] milliseconds
With explicit buffer size of 8 KiB:
> Writing 10MB took [89457] milliseconds

and on RHEL 7, Java 8u232:
Without explicit buffer size:
> Default send buffer size is [1313280]
> Writing 10MB took [661] milliseconds
With explicit buffer size of 8 KiB:
Writing 10MB took [50696] milliseconds
Comment 14 Mark Thomas 2019-11-13 11:00:34 UTC
I think I have a fix. I've updated the test to keep writing until the non-blocking write returns 0 bytes written and only then add the connection to the Poller. Performance is back to normal for me even with the (relatively) small buffer.

Can you test this on your platforms as well?

Meanwhile, I'm going to be looking at implementing a similar change in the Tomcat code.
Comment 15 Remy Maucherat 2019-11-13 11:25:39 UTC
The performance numbers would still indicate FreeBSD has a specific poller issue of some kind though, the difference is too large there.
Comment 16 Michael Osipov 2019-11-13 11:44:52 UTC
(In reply to Remy Maucherat from comment #15)
> The performance numbers would still indicate FreeBSD has a specific poller
> issue of some kind though, the difference is too large there.

I will inquire this with the port maintainer afterwards.
Comment 17 Michael Osipov 2019-11-13 11:49:22 UTC
(In reply to Mark Thomas from comment #14)
> I think I have a fix. I've updated the test to keep writing until the
> non-blocking write returns 0 bytes written and only then add the connection
> to the Poller. Performance is back to normal for me even with the
> (relatively) small buffer.
> 
> Can you test this on your platforms as well?
> 
> Meanwhile, I'm going to be looking at implementing a similar change in the
> Tomcat code.

The file did not change, did you push your changes to remote?
Comment 18 Mark Thomas 2019-11-13 12:48:25 UTC
Tomcat is calling write until 0 bytes are written before adding to the poller so that isn't what is going on here.

(In reply to Remy Maucherat from comment #12)
> By default on my Linux the socket send buffer size is 2304. For NIO to have
> the same "performance" and behavior running the test [as seen with the debug
> logs] as NIO2, the send buffer size needs to be exactly >= to 4737.

On my Linux box the default send buffer size is 1313280. With the stand-alone test, I see slowness if the buffer size < 4537 and no slowness when it is >=4537.

It does seem that performance is related to how many times we have to call select(). With a larger buffer size, the network write seems to be more efficient so there are far fewer calls to select().

I'd expect the stand-alone test to be writing faster than Tomcat and therefore need a larger buffer to avoid the slowness. I want to add use of a executor for the writes to see if that gives more realistic results.
Comment 19 Mark Thomas 2019-11-13 13:03:05 UTC
Hmm. No change at all with a Executor. The cut-off for buffer size between good and bad performance is still exactly 4537 bytes. That doesn't match with what I thought was going on.
Comment 20 Remy Maucherat 2019-11-13 13:28:51 UTC
With NIO2, when I set a really low send buffer (I tried as low as 32 bytes) it does change what the read/write logs from TestNonBlockingAPI look like as expected, but the "performance" does not go down meaningfully. Just a little.
Comment 21 Michael Osipov 2019-11-13 13:57:30 UTC
New test results:

RHEL:
8 KiB: Writing 10MB took [1601] milliseconds; nothing added
default: Writing 10MB took [1176] milliseconds

HP-UX:
8 KiB: Writing 10MB took [89460] milliseconds; add 68 ms for each select()
default: Writing 10MB took [2712] milliseconds

FreeBSD:
8 KiB: Writing 10MB took [134837] milliseconds ; adds 102 ms for each select()
default: Writing 10MB took [2733] milliseconds

I am trying to understand what this really means and needs to be documented for users and what I need to report with bugs.freebsd.org.

I will performs another test where telnet will redirect to /dev/null and see how this effects performance.
Comment 22 Rainer Jung 2019-11-13 14:10:26 UTC
According to the Javadoc, the Selector has various impls and is encapsulated via a SelectorProvider. The chosen provider decides about which system api is being used (poll, epoll, event ports, kqueue, ...).

I added

System.out.println("Selector Provider: " + selector.provider());

to the beginning of the run() method of the Poller and got:

Linux:
Selector Provider: sun.nio.ch.EPollSelectorProvider@5ff0e400

Solaris:
Selector Provider: sun.nio.ch.DevPollSelectorProvider@3927e6ad

Maybe one can check the output for FreeBSD? Maybe it falls bac to poll instead of kqueue on FreeBSD? If this would be true, we could check, whther there is a better provider for FreeBSD and try to choose it explicitly.

Just my 0.01 cents.
Comment 23 Rainer Jung 2019-11-13 14:26:04 UTC
Plus: performance behavior plus provider string would also be interesting for MacOS.
Comment 24 Michael Osipov 2019-11-13 14:27:53 UTC
(In reply to Rainer Jung from comment #22)
> According to the Javadoc, the Selector has various impls and is encapsulated
> via a SelectorProvider. The chosen provider decides about which system api
> is being used (poll, epoll, event ports, kqueue, ...).
> 
> I added
> 
> System.out.println("Selector Provider: " + selector.provider());
> 
> to the beginning of the run() method of the Poller and got:
> 
> Linux:
> Selector Provider: sun.nio.ch.EPollSelectorProvider@5ff0e400
> 
> Solaris:
> Selector Provider: sun.nio.ch.DevPollSelectorProvider@3927e6ad
> 
> Maybe one can check the output for FreeBSD? Maybe it falls bac to poll
> instead of kqueue on FreeBSD? If this would be true, we could check, whther
> there is a better provider for FreeBSD and try to choose it explicitly.
> 
> Just my 0.01 cents.

Selector Provider: sun.nio.ch.KQueueSelectorProvider@626007aa

Should be the same as on macOS, imho.
Comment 25 Michael Osipov 2019-11-13 14:29:06 UTC
Here are new test results, is the terminal/consumer (telnet) too slow?

For both: telnet localhost 8888 > /dev/null

FreeBSD:
All telnet output has been redirected to /dev/null.

default: Writing 10MB took [256] milliseconds
8 KiB: as slow as before
16 KiB: ""
20 KiB: ""
22 KiB: ""
23,5 KiB: ""
bisected to 24 KiB..
24 KiB: Writing 10MB took [288] milliseconds
32 KiB: Writing 10MB took [252] milliseconds
64 KiB: Writing 10MB took [256] milliseconds

Anything below 24 KiB is unusable.


HP-UX:
All telnet output has been redirected to /dev/null.

default: Writing 10MB took [283] milliseconds
8 KiB: as slow as before
8193 B: Writing 10MB took [279] milliseconds
8,5 KiB: Writing 10MB took [305] milliseconds
9 KiB: Writing 10MB took [284] milliseconds
10 KiB: Writing 10MB took [270] milliseconds
12 KiB: Writing 10MB took [278] milliseconds
16 KiB: Writing 10MB took [274] milliseconds
32 KiB: ""

Anything below 8193 B is unusable.


What does that mean now for Tomcat and the tests?
Comment 26 Michael Osipov 2019-11-13 14:46:31 UTC
A local change to Tomcat master:

> diff --git a/test/org/apache/catalina/nonblocking/TestNonBlockingAPI.java b/test/org/apache/catalina/nonblocking/TestNonBlockingAPI.java
> index 7f16f26c1e..c8ec7a7eb8 100644
> --- a/test/org/apache/catalina/nonblocking/TestNonBlockingAPI.java
> +++ b/test/org/apache/catalina/nonblocking/TestNonBlockingAPI.java
> @@ -157,7 +157,6 @@ public class TestNonBlockingAPI extends TomcatBaseTest {
>          String servletName = NBWriteServlet.class.getName();
>          Tomcat.addServlet(ctx, servletName, servlet);
>          ctx.addServletMappingDecoded("/", servletName);
> -        tomcat.getConnector().setProperty("socket.txBufSize", "1024");
>          tomcat.start();
> 
>          SocketFactory factory = SocketFactory.getDefault();
> @@ -323,7 +322,6 @@ public class TestNonBlockingAPI extends TomcatBaseTest {
>          String servletName = NBWriteServlet.class.getName();
>          Tomcat.addServlet(ctx, servletName, servlet);
>          ctx.addServletMappingDecoded("/", servletName);
> -        tomcat.getConnector().setProperty("socket.txBufSize", "1024");
>          tomcat.start();
> 
>          SocketFactory factory = SocketFactory.getDefault();

Gives me:

osipovmi@deblndw011x:~/var/Projekte/tomcat (master *=)
$ for file in output/build/logs/*TestNonBlockingAPI* ; do head -2 $file; done
Testsuite: org.apache.catalina.nonblocking.TestNonBlockingAPI
Tests run: 9, Failures: 0, Errors: 0, Skipped: 1, Time elapsed: 37,629 sec
Testsuite: org.apache.catalina.nonblocking.TestNonBlockingAPI
Tests run: 9, Failures: 0, Errors: 0, Skipped: 1, Time elapsed: 36,315 sec
Testsuite: org.apache.catalina.nonblocking.TestNonBlockingAPI
Tests run: 9, Failures: 0, Errors: 0, Skipped: 1, Time elapsed: 33,279 sec
Comment 27 Mark Thomas 2019-11-13 14:48:34 UTC
I have been mixing up socket.txBufSize and socket.appWriteBufSize.

My testing shows that socket.appWriteBufSize has no measurable impact on performance of the stand-alone test.

Performance of the stand-alone test is tightly linked to socket.txBufSize. The smaller the buffer, the more likely it is the writing thread will fill it before the OS thread  writes some data. That will cause the socket to be placed in the Poller and polling does appear to be relatively slow.

The log messages are a significant factor as writing them to stdout slows things down. I've commented them out for now in my stand-alone test.

The Tomcat unit test in question deliberately sets the txBufSize small to trigger the use of the Poller. It appears that that setting is far too small. I'll do some tests and increase it - probably to around 1MB.
Comment 28 Mark Thomas 2019-11-13 14:57:38 UTC
Fixed in:
- master for 9.0.28 onwards
- 8.5.x for 8.5.48 onwards
Comment 29 Michael Osipov 2019-11-13 15:11:44 UTC
(In reply to Mark Thomas from comment #28)
> Fixed in:
> - master for 9.0.28 onwards
> - 8.5.x for 8.5.48 onwards

I see now

$ for file in output/build/logs/*TestNonBlockingAPI* ; do head -2 $file; done
Testsuite: org.apache.catalina.nonblocking.TestNonBlockingAPI
Tests run: 9, Failures: 0, Errors: 0, Skipped: 1, Time elapsed: 36,975 sec
Testsuite: org.apache.catalina.nonblocking.TestNonBlockingAPI
Tests run: 9, Failures: 1, Errors: 0, Skipped: 1, Time elapsed: 69,567 sec
Testsuite: org.apache.catalina.nonblocking.TestNonBlockingAPI
Tests run: 9, Failures: 1, Errors: 0, Skipped: 1, Time elapsed: 65,669 sec

Is there a reason why you did not change the second socket.txBufSize? It would cut the time in half.
Comment 30 Michael Osipov 2019-11-13 15:16:00 UTC
(In reply to Michael Osipov from comment #29)
> (In reply to Mark Thomas from comment #28)
> > Fixed in:
> > - master for 9.0.28 onwards
> > - 8.5.x for 8.5.48 onwards
> 
> I see now
> 
> $ for file in output/build/logs/*TestNonBlockingAPI* ; do head -2 $file; done
> Testsuite: org.apache.catalina.nonblocking.TestNonBlockingAPI
> Tests run: 9, Failures: 0, Errors: 0, Skipped: 1, Time elapsed: 36,975 sec
> Testsuite: org.apache.catalina.nonblocking.TestNonBlockingAPI
> Tests run: 9, Failures: 1, Errors: 0, Skipped: 1, Time elapsed: 69,567 sec
> Testsuite: org.apache.catalina.nonblocking.TestNonBlockingAPI
> Tests run: 9, Failures: 1, Errors: 0, Skipped: 1, Time elapsed: 65,669 sec
> 
> Is there a reason why you did not change the second socket.txBufSize? It
> would cut the time in half.

The failures are timing issues for 200 ms which can be ignored as I have learned two weeks ago.
Comment 31 Mark Thomas 2019-11-13 15:17:17 UTC
Thanks. Missed that. Fixed now.
Comment 32 Michael Osipov 2019-11-13 16:20:43 UTC
I am down now to:

$ for file in output/build/logs/*TestNonBlockingAPI* ; do head -2 $file; done
Testsuite: org.apache.catalina.nonblocking.TestNonBlockingAPI
Tests run: 9, Failures: 0, Errors: 0, Skipped: 1, Time elapsed: 35,434 sec
Testsuite: org.apache.catalina.nonblocking.TestNonBlockingAPI
Tests run: 9, Failures: 0, Errors: 0, Skipped: 1, Time elapsed: 41,08 sec
Testsuite: org.apache.catalina.nonblocking.TestNonBlockingAPI
Tests run: 9, Failures: 0, Errors: 0, Skipped: 1, Time elapsed: 36,316 sec

All tests run now with 18 threads in 10 minutes on that server. What a tremendous improvement.

Mark, thank you very much looking into this. Shouldn't the findings for buffer sizes be documented somewhere on the connectors page for our users?
Comment 33 Christopher Schultz 2019-11-13 17:29:02 UTC
(In reply to Rainer Jung from comment #23)
> Plus: performance behavior plus provider string would also be interesting
> for MacOS.

Some info from MacOS:

$ java -showversion org/apache/tomcat/Bug63916NioPoller
openjdk version "13.0.1" 2019-10-15
OpenJDK Runtime Environment (build 13.0.1+9)
OpenJDK 64-Bit Server VM (build 13.0.1+9, mixed mode, sharing)
Selector Provider: sun.nio.ch.KQueueSelectorProvider@1ac1a5f6
Default send buffer size is [146988]
Using send buffer size [146988]
Writing 10MB took [35] milliseconds

With 16k buffer:

$ java -showversion org/apache/tomcat/Bug63916NioPoller 16384
openjdk version "13.0.1" 2019-10-15
OpenJDK Runtime Environment (build 13.0.1+9)
OpenJDK 64-Bit Server VM (build 13.0.1+9, mixed mode, sharing)
Selector Provider: sun.nio.ch.KQueueSelectorProvider@1ac1a5f6
Default send buffer size is [146988]
Using send buffer size [16384]
Writing 10MB took [42] milliseconds

With 8k buffer:

$ java -showversion org/apache/tomcat/Bug63916NioPoller 8192
openjdk version "13.0.1" 2019-10-15
OpenJDK Runtime Environment (build 13.0.1+9)
OpenJDK 64-Bit Server VM (build 13.0.1+9, mixed mode, sharing)
Selector Provider: sun.nio.ch.KQueueSelectorProvider@1ac1a5f6
Default send buffer size is [146988]
Using send buffer size [8192]
Writing 10MB took [63] milliseconds

With 4k buffer:

$ java -showversion org/apache/tomcat/Bug63916NioPoller 4096
openjdk version "13.0.1" 2019-10-15
OpenJDK Runtime Environment (build 13.0.1+9)
OpenJDK 64-Bit Server VM (build 13.0.1+9, mixed mode, sharing)
Selector Provider: sun.nio.ch.KQueueSelectorProvider@1ac1a5f6
Default send buffer size is [146988]
Using send buffer size [4096]
Writing 10MB took [91] milliseconds

With 1k buffer:

$ java -showversion org/apache/tomcat/Bug63916NioPoller 1024
openjdk version "13.0.1" 2019-10-15
OpenJDK Runtime Environment (build 13.0.1+9)
OpenJDK 64-Bit Server VM (build 13.0.1+9, mixed mode, sharing)
Selector Provider: sun.nio.ch.KQueueSelectorProvider@1ac1a5f6
Default send buffer size is [146988]
Using send buffer size [1024]
Writing 10MB took [248] milliseconds

With 32 byte buffer:

$ java -showversion org/apache/tomcat/Bug63916NioPoller 32
openjdk version "13.0.1" 2019-10-15
OpenJDK Runtime Environment (build 13.0.1+9)
OpenJDK 64-Bit Server VM (build 13.0.1+9, mixed mode, sharing)
Selector Provider: sun.nio.ch.KQueueSelectorProvider@1ac1a5f6
Default send buffer size is [146988]
Using send buffer size [32]
Writing 10MB took [5279] milliseconds

More data (buffer size, duration):
16,10383
32,5206
64,2695
128,1413
256,744
512,435
1024,238
2048,149
4096,85
8192,61
16384,40
146988,35

Graphed: https://jsfiddle.net/etp8sa5f/

Interestingly, it's almost a perfectly straight trend line when graphed on a logarithmic scale. I think that means there aren't any inconsistencies on this platform: buffer size is hugely important but there aren't any particularly bad buffer sizes (other than "smaller is worse").
Comment 34 Michael Osipov 2019-11-13 19:36:49 UTC
(In reply to Christopher Schultz from comment #33)
> (In reply to Rainer Jung from comment #23)
> > Plus: performance behavior plus provider string would also be interesting
> > for MacOS.
> 
> Some info from MacOS:
> 
> $ java -showversion org/apache/tomcat/Bug63916NioPoller
> openjdk version "13.0.1" 2019-10-15
> OpenJDK Runtime Environment (build 13.0.1+9)
> OpenJDK 64-Bit Server VM (build 13.0.1+9, mixed mode, sharing)
> Selector Provider: sun.nio.ch.KQueueSelectorProvider@1ac1a5f6
> Default send buffer size is [146988]
> Using send buffer size [146988]
> Writing 10MB took [35] milliseconds
> 
> With 16k buffer:
> 
> $ java -showversion org/apache/tomcat/Bug63916NioPoller 16384
> openjdk version "13.0.1" 2019-10-15
> OpenJDK Runtime Environment (build 13.0.1+9)
> OpenJDK 64-Bit Server VM (build 13.0.1+9, mixed mode, sharing)
> Selector Provider: sun.nio.ch.KQueueSelectorProvider@1ac1a5f6
> Default send buffer size is [146988]
> Using send buffer size [16384]
> Writing 10MB took [42] milliseconds
> 
> With 8k buffer:
> 
> $ java -showversion org/apache/tomcat/Bug63916NioPoller 8192
> openjdk version "13.0.1" 2019-10-15
> OpenJDK Runtime Environment (build 13.0.1+9)
> OpenJDK 64-Bit Server VM (build 13.0.1+9, mixed mode, sharing)
> Selector Provider: sun.nio.ch.KQueueSelectorProvider@1ac1a5f6
> Default send buffer size is [146988]
> Using send buffer size [8192]
> Writing 10MB took [63] milliseconds
> 
> With 4k buffer:
> 
> $ java -showversion org/apache/tomcat/Bug63916NioPoller 4096
> openjdk version "13.0.1" 2019-10-15
> OpenJDK Runtime Environment (build 13.0.1+9)
> OpenJDK 64-Bit Server VM (build 13.0.1+9, mixed mode, sharing)
> Selector Provider: sun.nio.ch.KQueueSelectorProvider@1ac1a5f6
> Default send buffer size is [146988]
> Using send buffer size [4096]
> Writing 10MB took [91] milliseconds
> 
> With 1k buffer:
> 
> $ java -showversion org/apache/tomcat/Bug63916NioPoller 1024
> openjdk version "13.0.1" 2019-10-15
> OpenJDK Runtime Environment (build 13.0.1+9)
> OpenJDK 64-Bit Server VM (build 13.0.1+9, mixed mode, sharing)
> Selector Provider: sun.nio.ch.KQueueSelectorProvider@1ac1a5f6
> Default send buffer size is [146988]
> Using send buffer size [1024]
> Writing 10MB took [248] milliseconds
> 
> With 32 byte buffer:
> 
> $ java -showversion org/apache/tomcat/Bug63916NioPoller 32
> openjdk version "13.0.1" 2019-10-15
> OpenJDK Runtime Environment (build 13.0.1+9)
> OpenJDK 64-Bit Server VM (build 13.0.1+9, mixed mode, sharing)
> Selector Provider: sun.nio.ch.KQueueSelectorProvider@1ac1a5f6
> Default send buffer size is [146988]
> Using send buffer size [32]
> Writing 10MB took [5279] milliseconds
> 
> More data (buffer size, duration):
> 16,10383
> 32,5206
> 64,2695
> 128,1413
> 256,744
> 512,435
> 1024,238
> 2048,149
> 4096,85
> 8192,61
> 16384,40
> 146988,35
> 
> Graphed: https://jsfiddle.net/etp8sa5f/
> 
> Interestingly, it's almost a perfectly straight trend line when graphed on a
> logarithmic scale. I think that means there aren't any inconsistencies on
> this platform: buffer size is hugely important but there aren't any
> particularly bad buffer sizes (other than "smaller is worse").

Awesome, can you retry with Java 8?

But the results are quite surprising because I have expected similar results as with FreeBSD due to the BSD userland and kernel parts in macOS.
Comment 35 Christopher Schultz 2019-11-14 04:41:56 UTC
(In reply to Michael Osipov from comment #34)
> Awesome, can you retry with Java 8?

This is Oracle 1.8.0_181.
Selector Provider: sun.nio.ch.KQueueSelectorProvider@16e15b65

16,10461
32,5245
64,2696
128,1403
256,728
512,400
1024,223
2048,131
4096,71
8192,50
16384,28
146988,27

Curve is the same: https://jsfiddle.net/mrw3o96t/

> But the results are quite surprising because I have expected similar results
> as with FreeBSD due to the BSD userland and kernel parts in macOS.

The Macos kernel is quite a bit different than the BSD kernel(s). It's really a mach kernel with a BSD interface slapped on top so they didn't have to write all their own custom userland.

Note that this is running the code from Mark's test source from github. All I did was replace the logging and add an optional command-line argument to make it easier to run repeatedly. In light of Mark's comment #27, I'd like to confirm that this is the correct code to run. It's setting the socket's send buffer size and not the appWriteBufSize.
Comment 36 Mark Thomas 2019-11-14 14:01:59 UTC
That is the right code.

Testing locally on Linux:

java -showversion org.apache.tomcat.Bug63916NioPoller
openjdk version "1.8.0_222"
OpenJDK Runtime Environment (AdoptOpenJDK)(build 1.8.0_222-b10)
OpenJDK 64-Bit Server VM (AdoptOpenJDK)(build 25.222-b10, mixed mode)
Selector provider: sun.nio.ch.EPollSelectorProvider@4cd646ad
Default send buffer size is [1313280]
Writing 10MB took [259] milliseconds

And with specific buffer sizes

16k    379ms
8k     402ms
4k  56,091ms


On MacOS
s2laptop:classes mthomas$ java -version
openjdk version "1.8.0_212"
OpenJDK Runtime Environment (AdoptOpenJDK)(build 1.8.0_212-b03)
OpenJDK 64-Bit Server VM (AdoptOpenJDK)(build 25.212-b03, mixed mode)

s2laptop:classes mthomas$ java org.apache.tomcat.Bug63916NioPoller
Selector provider: sun.nio.ch.KQueueSelectorProvider@227974ab
Default send buffer size is [146988]
Writing 10MB took [364] milliseconds

And with specific buffer sizes

16k    332ms
8k     309ms
4k     319ms
2k     356ms
1k  20,041ms

Both Oracle Java 7 and OpenJDK 13 give more reasonable results of around 440 ms.

There looks to be an issue with the JVM. Given how bad these figures are I agree with Michael's suggestion to add something to the docs. I'll also open a JRE bug.
Comment 37 Mark Thomas 2019-11-14 17:57:17 UTC
https://bugs.openjdk.java.net/browse/JDK-8234191