On Tue, Oct 6, 2020 at 9:30 AM Martin Grigorov <mgrigo...@apache.org> wrote:
> Hi, > > I face an issue with the NIO2 protocol. > When I increase the request rate to more than 500 requests per second it > starts failing with: > > 06-Oct-2020 09:18:19.964 FINE [https-jsse-nio2-8080-exec-6] > org.apache.coyote.http2.Http2UpgradeHandler.init Connection [1], State [NEW] > 06-Oct-2020 09:18:19.978 FINE [https-jsse-nio2-8080-exec-6] > org.apache.coyote.http2.Http2AsyncParser$FrameCompletionHandler.failed > Connection [1], Stream [0], Frame type [null], Error > java.io.EOFException > at > org.apache.tomcat.util.net.SecureNio2Channel$2.completed(SecureNio2Channel.java:1005) > at > org.apache.tomcat.util.net.SecureNio2Channel$2.completed(SecureNio2Channel.java:1001) > at java.base/sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:127) > at java.base/sun.nio.ch.Invoker.invokeDirect(Invoker.java:158) > at > java.base/sun.nio.ch.UnixAsynchronousSocketChannelImpl.implRead(UnixAsynchronousSocketChannelImpl.java:568) > at > java.base/sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:276) > at > java.base/sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:297) > at > org.apache.tomcat.util.net.SecureNio2Channel.read(SecureNio2Channel.java:1126) > at > org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper$Nio2OperationState.run(Nio2Endpoint.java:1025) > at > org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100) > at > org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1054) > at > org.apache.tomcat.util.net.SecureNio2Channel$2.completed(SecureNio2Channel.java:1112) > at > org.apache.tomcat.util.net.SecureNio2Channel$2.completed(SecureNio2Channel.java:1001) > at java.base/sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:127) > at java.base/sun.nio.ch.Invoker.invokeDirect(Invoker.java:158) > at > java.base/sun.nio.ch.UnixAsynchronousSocketChannelImpl.implRead(UnixAsynchronousSocketChannelImpl.java:568) > at > java.base/sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:276) > at > java.base/sun.nio.ch.AsynchronousSocketChannelImpl.read(AsynchronousSocketChannelImpl.java:297) > at > org.apache.tomcat.util.net.SecureNio2Channel$2.completed(SecureNio2Channel.java:1038) > at > org.apache.tomcat.util.net.SecureNio2Channel$2.completed(SecureNio2Channel.java:1001) > at > org.apache.tomcat.util.net.SecureNio2Channel.read(SecureNio2Channel.java:1124) > at > org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper$Nio2OperationState.run(Nio2Endpoint.java:1025) > at > org.apache.tomcat.util.net.Nio2Endpoint$Nio2SocketWrapper$Nio2OperationState.start(Nio2Endpoint.java:1004) > at > org.apache.tomcat.util.net.SocketWrapperBase.vectoredOperation(SocketWrapperBase.java:1450) > at > org.apache.tomcat.util.net.SocketWrapperBase.read(SocketWrapperBase.java:1293) > at > org.apache.tomcat.util.net.SocketWrapperBase.read(SocketWrapperBase.java:1265) > at > org.apache.coyote.http2.Http2AsyncParser.readConnectionPreface(Http2AsyncParser.java:55) > at > org.apache.coyote.http2.Http2UpgradeHandler.init(Http2UpgradeHandler.java:241) > at > org.apache.coyote.http2.Http2AsyncUpgradeHandler.init(Http2AsyncUpgradeHandler.java:40) > at > org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch(Http2UpgradeHandler.java:316) > at > org.apache.coyote.http2.Http2AsyncUpgradeHandler.upgradeDispatch(Http2AsyncUpgradeHandler.java:40) > at > org.apache.coyote.http11.upgrade.UpgradeProcessorInternal.dispatch(UpgradeProcessorInternal.java:54) > at > org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:59) > at > org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868) > at > org.apache.tomcat.util.net.Nio2Endpoint$SocketProcessor.doRun(Nio2Endpoint.java:1679) > at > org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) > at > org.apache.tomcat.util.net.AbstractEndpoint.processSocket(AbstractEndpoint.java:1104) > at > org.apache.tomcat.util.net.SecureNio2Channel$HandshakeReadCompletionHandler.completed(SecureNio2Channel.java:99) > at > org.apache.tomcat.util.net.SecureNio2Channel$HandshakeReadCompletionHandler.completed(SecureNio2Channel.java:92) > at java.base/sun.nio.ch.Invoker.invokeUnchecked(Invoker.java:127) > at java.base/sun.nio.ch.Invoker$2.run(Invoker.java:219) > at > java.base/sun.nio.ch.AsynchronousChannelGroupImpl$1.run(AsynchronousChannelGroupImpl.java:112) > at > java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) > at > java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) > at > org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) > at java.base/java.lang.Thread.run(Thread.java:832) > 06-Oct-2020 09:18:19.980 FINE [https-jsse-nio2-8080-exec-6] > org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch Entry, > Connection [1], SocketStatus [ERROR] > > If I just change the protocol > to org.apache.coyote.http11.Http11NioProtocol then everything is OK. > I've just tested org.apache.coyote.http11.Http11AprProtocol - no problems! > > To reproduce: > 1) git clone https://github.com/martin-g/http2-server-perf-tests.git > 2) cd java/tomcat > 3) mvn package > 4) java > -Dtomcat.http2=true > -Dtomcat.protocol=org.apache.coyote.http11.Http11Nio2Protocol > -Djava.security.egd=file:/dev/./urandom -jar target/tomcat-embedded*.jar > > The Vegeta <https://github.com/tsenart/vegeta> command is: > > echo -e '{"method": "GET", "url": " > https://localhost:8080/testbed/plaintext"}' | vegeta attack -format=json > -http2 -rate=0 -max-workers=128 -insecure -duration=5s | vegeta encode > > /tmp/http2.json; and vegeta report -type=json /tmp/http2.json | jq . > { > "latencies": { > "total": 827683197623, > "mean": 5747799983, > "50th": 6261543134, > "90th": 6307893296, > "95th": 6311484598, > "99th": 7733411962, > "max": 30000471023, > "min": 28510451 > }, > "bytes_in": { > "total": 180, > "mean": 1.25 > }, > "bytes_out": { > "total": 0, > "mean": 0 > }, > "earliest": "2020-10-06T09:18:19.5182854+03:00", > "latest": "2020-10-06T09:18:25.304404661+03:00", > "end": "2020-10-06T09:18:55.304875684+03:00", > "duration": 5786119261, > "wait": 30000471023, > "requests": 144, > "rate": 24.887146894914306, > "throughput": 0.4191514162416983, > "success": 0.10416666666666667, > "status_codes": { > "0": 129, > "200": 15 > }, > "errors": [ > "Get \"https://localhost:8080/testbed/plaintext\": unexpected EOF", > "unexpected EOF", > "Get \"https://localhost:8080/testbed/plaintext\": net/http: request > canceled (Client.Timeout exceeded while awaiting headers)" > ] > } > > Here I use '-rate=0' for unlimited/maximum rate, but it starts failing > somewhere around 500: -rate=500/1s > > > Martin >
