You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@tomcat.apache.org by Martin Grigorov <mg...@apache.org> on 2020/09/15 11:37:43 UTC
Low throughput with HTTP2
Hi,
I am running some load tests on Tomcat and I've noticed that when HTTP2 is
enabled the throughput drops considerably.
Here are the steps to reproduce:
1) Enable HTTP2, e.g. by commenting out this connector:
https://github.com/apache/tomcat/blob/d381d87005fa89d1f19d9091c0954f317c135d9d/conf/server.xml#L103-L112
2) Download Vegeta load tool from:
https://github.com/tsenart/vegeta/releases/
3) Run the load tests:
3.1) HTTP/1.1
echo -e '{"method": "GET", "url": "http://localhost:8080/examples/"}' |
vegeta attack -format=json -rate=0 -max-workers=1000 -duration=10s |
vegeta encode > /tmp/http1.json; and vegeta report -type=json
/tmp/http1.json | jq .
3.2) HTTP2
echo -e '{"method": "GET", "url": "https://localhost:8443/examples/"}' |
vegeta attack -format=json -http2 -rate=0 -max-workers=1000 -insecure
-duration=10s | vegeta encode > /tmp/http2.json; and vegeta report
-type=json /tmp/http2.json | jq .
As explained at https://github.com/tsenart/vegeta#-rate -rate=0 means that
Vegeta will try to send as many requests as possible with the configured
number of workers.
I use '-insecure' because I use self-signed certificate.
On my machine I get around 14-15K reqs/sec for HTTP1.1 with only responses
with code=200 .
But for HTTP2 Tomcat starts returning such kind of errors:
"errors": [
"Get \"https://localhost:8443/examples/\": http2: server sent GOAWAY
and closed the connection; LastStreamID=9259, ErrCode=PROTOCOL_ERROR,
debug=\"Stream [9,151] has been closed for some time\"",
"http2: server sent GOAWAY and closed the connection;
LastStreamID=9259, ErrCode=PROTOCOL_ERROR, debug=\"Stream [9,151] has been
closed for some time\"",
"Get \"https://localhost:8443/examples/\": http2: server sent GOAWAY
and closed the connection; LastStreamID=239, ErrCode=PROTOCOL_ERROR,
debug=\"Stream [49] has been closed for some time\""
]
when I ask for more than 2000 reqs/sec, i.e. -rate=2000/1s
All the access logs look like:
127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
1126
127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
1126
127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
1126
127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
1126
127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
1126
127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
1126
i.e. there are no error codes, just 200.
Vegeta reports the error with status code = 0. I think this just means that
it didn't get a proper HTTP response but just TCP error.
There are no errors in catalina.out.
Are there any settings I can tune to get better throughput with HTTP2 ?
Tomcat 10.0.0-M8.
Regards,
Martin
Re: Low throughput with HTTP2
Posted by Mark Thomas <ma...@apache.org>.
On 21/09/2020 10:44, Martin Grigorov wrote:
> On Mon, Sep 21, 2020 at 12:08 PM Martin Grigorov <mg...@apache.org>
> wrote:
>> On Mon, Sep 21, 2020 at 11:23 AM Mark Thomas <ma...@apache.org> wrote:
<snip/>
>>> RFC 7540 allows the connection to be closed with a protocol error if the
>>> reset is received "a significant time after sending END_STREAM".
>>>
>>> Tomcat retains state for maxConcurrentStreams + 10% with closed streams
>>> being pruned (oldest first) every 10 new streams.
>>
>> The spec talks about time but Tomcat uses the number of streams.
>> I understand that under normal usage this could be enough "time" but under
>> heavy load this number is reached quickly and the time is short.
Agreed. The closed stream is being pruned within a fraction of a second.
However, the window where the client could legitimately send RST_STREAM
is also very small. Looking at the timings, I don't think the client is
sending the RST_STREAM within that window.
You get back to the (lack of) definition of significant. I think I could
make a case for significant being anything from a few milliseconds to
several minutes.
>>> It isn't clear at this point why the client is sending the RST_STREAM.
>>>
>>
>> I don't know either. But Vegeta is using the Golang standard libraries, so
>> any Golang application should behave the same way.
>> Also as I investigated last week - Golang/Node.js/Rust/Netty HTTP2 servers
>> do not complain about it.
>>
>>
>>> This normally indicates an error condition. From the description of the
>>> load test I don't see why the client would be sending a RST_STREAM.
>>>
>>> If the RST_STREAM is valid and it isn't received a significant time
>>> after the END_STREAM then Tomcat needs to handle this.
>>>
>>> If the RST_STREAM is valid but received a significant amount of time
>>> after the END_STREAM that would be a client error would be a client error.
>>>
>>> Of course, significant isn't defined in the specification.
>>>
>>> Any special handling for RST_STREAM also needs to be applied to
>>> WINDOW_UPDATE. It also needs to differentiate between a frame received
>>> for a past closed stream and a frame received for an stream that never
>>> existed.
>>>
>>> I think the key question here is why is the client sending the
>>> RST_STREAM in the first place. Is Tomcat doing something it shouldn't /
>>> not doing something it should to cause this? If so, we need to fix the
>>> root cause rather than tackle the symptom.
>>>
>>> There are a couple of options for debugging this to see why the client
>>> is sending the RST_STREAM:
>>> - Enable debug logging for HTTP/2 in Tomcat. This is very verbose and
>>> if the root cause is threading related typically changes the timing
>>> enough to mask the issue.
>>>
>>
>> Here are the logs of 20 seconds load:
>>
>> https://gist.githubusercontent.com/martin-g/37dacc12149d5cecbfd4e16dc2248cfd/raw/76693cd1dd1f37ba126edb84ebd7631802aa91a6/tomcat-http2.log
Thanks.
My first observation is that we aren't helping ourselves by having some
messages display stream IDs in 0,000 format, and others without the
commas. That should be a fairly simple fix.
I picked a request somewhere in the middle and I see the expected
sequence of frames for a normal request. Total processing time is about
30ms. Then about 50ms later, the client sends a RST_STREAM. I'd really
like to see what reason code was sent with that reset. That is another
simple fix.
>> This is with my patch in #reset(). Without it there are also errors that
>> stream XYZ is already closed
ACK.
<snip/>
>> According to https://tools.ietf.org/html/rfc7540#section-5.1 when the
>> stream is in HALF_CLOSED_REMOTE state it should send either END_STREAM or
>> RST_STREAM to the remote peer.
>> In the logs I see such sequence of events:
>>
>> ...
>> o.a.coyote.http2.StreamStateMachine : Connection [124], Stream
>> [5,279], State changed from [OPEN] to [HALF_CLOSED_REMOTE]
>> o.a.coyote.http2.Http2UpgradeHandler : Connection [124], Stream
>> [5,279], Writing the headers
>> org.apache.coyote.http2.Stream : Connection [124], Stream
>> [5,279], flushing output with buffer at position [12], writeInProgress
>> [false] and closed [true]
>> org.apache.coyote.http2.AbstractStream : Connection [124], Stream
>> [5,279], reduce flow control window by [12] to [4194292]
>> o.a.coyote.http2.Http2UpgradeHandler : Connection [124], Stream
>> [5,279], Data length [12]
>> o.a.coyote.http2.StreamStateMachine : Connection [124], Stream
>> [5,279], State changed from [HALF_CLOSED_REMOTE] to [CLOSED_TX]
>> org.apache.coyote.http2.Stream : Connection [124], Stream
>> [5,279] has been recycled
>>
>>
>> From the logs it is not clear whether any of these flags is being sent to
>> the client. I will investigate!
>>
>
> The flag is always being sent with the data!
Agreed. Tomcat's debug logs show a normal stream with a clean closure.
> One minor thing though: at
> https://github.com/apache/tomcat/blob/613787d26fe14aec775fe82e59d0e4bc079d1814/java/org/apache/coyote/http2/Http2AsyncUpgradeHandler.java#L211
> the internal state is being changed but the actual sending may not happen
> if the stream is not writeable.
That should be fine. The stream will be marked as not-writeable if the
client has sent a RST_STREAM. The test is there to stop the client
having to send additional RST_STREAM frames if the server continues
writing (which would be a protocol violation after receiving a RST_STREAM).
I think it may be time to download Vegeta to try and dig into the root
cause of these RST_STREAM frames.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Low throughput with HTTP2
Posted by Martin Grigorov <mg...@apache.org>.
On Mon, Sep 21, 2020 at 12:08 PM Martin Grigorov <mg...@apache.org>
wrote:
>
>
> On Mon, Sep 21, 2020 at 11:23 AM Mark Thomas <ma...@apache.org> wrote:
>
>> On 21/09/2020 08:18, Martin Grigorov wrote:
>> > On Fri, Sep 18, 2020 at 6:16 PM Mark Thomas <ma...@apache.org> wrote:
>> >
>> >> On 18/09/2020 14:07, Martin Grigorov wrote:
>> >>
>> >> <snip/>
>> >>
>> >>> What is the difference
>> >>> between org.apache.coyote.http2.StreamStateMachine.State#CLOSED_RX
>> >>> and org.apache.coyote.http2.StreamStateMachine.State#CLOSED_TX ?
>> >>
>> >> Compare the parameters used to construct the enums.
>> >>
>> >>> I read some parts of https://tools.ietf.org/html/rfc7540 but I don't
>> see
>> >>> anything related to two types of CLOSED state.
>> >>
>> >> Section 5.1. Definition of the closed state (page 20) explains the
>> >> difference between the two.
>> >>
>> >
>> > Still I do not understand what RX and TX stand for. But this is not
>> > important.
>>
>> TX - transmit
>>
>> RX - receive
>>
>
> Thanks!
>
>
>>
>>
>> > The following patch fixes the issue for me/Vegeta:
>> >
>> > @@ -1570,12 +1571,15 @@ class Http2UpgradeHandler extends AbstractStream
>> > implements InternalHttpUpgradeH
>> >
>> > @Override
>> > public void reset(int streamId, long errorCode) throws
>> Http2Exception
>> > {
>> > - Stream stream = getStream(streamId, true);
>> > - boolean active = stream.isActive();
>> > - stream.checkState(FrameType.RST);
>> > - stream.receiveReset(errorCode);
>> > - if (active) {
>> > - activeRemoteStreamCount.decrementAndGet();
>> > + boolean unknownIsError = Http2Error.CANCEL.getCode() !=
>> errorCode;
>> > + Stream stream = getStream(streamId, unknownIsError);
>> > + if (stream != null) {
>> > + boolean active = stream.isActive();
>> > + stream.checkState(FrameType.RST);
>> > + stream.receiveReset(errorCode);
>> > + if (active) {
>> > + activeRemoteStreamCount.decrementAndGet();
>> > + }
>> > }
>> > }
>> >
>> > I.e. do not throw an error if the remote peer is trying to cancel an
>> > already closed stream.
>>
>> RFC 7540 allows the connection to be closed with a protocol error if the
>> reset is received "a significant time after sending END_STREAM".
>>
>> Tomcat retains state for maxConcurrentStreams + 10% with closed streams
>> being pruned (oldest first) every 10 new streams.
>>
>
> The spec talks about time but Tomcat uses the number of streams.
> I understand that under normal usage this could be enough "time" but under
> heavy load this number is reached quickly and the time is short.
>
> I've tried with these values for
> maxConcurrentStreams/maxConcurrentStreamExecution: 8 (number of CPU cores),
> 16, 100 (the default), 1024 and 8196. The throughput is around 10K only
> until 100. After that it drops (as you said earlier).
>
>
>>
>> It isn't clear at this point why the client is sending the RST_STREAM.
>>
>
> I don't know either. But Vegeta is using the Golang standard libraries, so
> any Golang application should behave the same way.
> Also as I investigated last week - Golang/Node.js/Rust/Netty HTTP2 servers
> do not complain about it.
>
>
>> This normally indicates an error condition. From the description of the
>> load test I don't see why the client would be sending a RST_STREAM.
>>
>> If the RST_STREAM is valid and it isn't received a significant time
>> after the END_STREAM then Tomcat needs to handle this.
>>
>> If the RST_STREAM is valid but received a significant amount of time
>> after the END_STREAM that would be a client error would be a client error.
>>
>> Of course, significant isn't defined in the specification.
>>
>> Any special handling for RST_STREAM also needs to be applied to
>> WINDOW_UPDATE. It also needs to differentiate between a frame received
>> for a past closed stream and a frame received for an stream that never
>> existed.
>>
>> I think the key question here is why is the client sending the
>> RST_STREAM in the first place. Is Tomcat doing something it shouldn't /
>> not doing something it should to cause this? If so, we need to fix the
>> root cause rather than tackle the symptom.
>>
>> There are a couple of options for debugging this to see why the client
>> is sending the RST_STREAM:
>> - Enable debug logging for HTTP/2 in Tomcat. This is very verbose and
>> if the root cause is threading related typically changes the timing
>> enough to mask the issue.
>>
>
> Here are the logs of 20 seconds load:
>
> https://gist.githubusercontent.com/martin-g/37dacc12149d5cecbfd4e16dc2248cfd/raw/76693cd1dd1f37ba126edb84ebd7631802aa91a6/tomcat-http2.log
>
> This is with my patch in #reset(). Without it there are also errors that
> stream XYZ is already closed
>
>
>> - Client side logging (I don't know what the capabilities are here).
>> - JVM level TLS debug logging (even more verbose than Tomcat's HTTP/2
>> debug and harder to work with)
>> - Wireshark (or similar)
>>
>> I'd recommend Wireshark. I don't think JSSE supports SSLKEYLOGFILE so
>> I'd use the APR/Native connector with SSLKEYLOGFILE to get the cleartext
>> in Wireshark.
>>
>> > With this change and Vegeta's -max-workers=100 I can get 12 K reqs/sec.
>>
>> That is odd. If the client is sending RST_STREAM messages then I'd
>> expect to see requests failing as RST_STREAM indicates something has
>> gone wrong or the client has aborted the request.
>>
>
> According to https://tools.ietf.org/html/rfc7540#section-5.1 when the
> stream is in HALF_CLOSED_REMOTE state it should send either END_STREAM or
> RST_STREAM to the remote peer.
> In the logs I see such sequence of events:
>
> ...
> o.a.coyote.http2.StreamStateMachine : Connection [124], Stream
> [5,279], State changed from [OPEN] to [HALF_CLOSED_REMOTE]
> o.a.coyote.http2.Http2UpgradeHandler : Connection [124], Stream
> [5,279], Writing the headers
> org.apache.coyote.http2.Stream : Connection [124], Stream
> [5,279], flushing output with buffer at position [12], writeInProgress
> [false] and closed [true]
> org.apache.coyote.http2.AbstractStream : Connection [124], Stream
> [5,279], reduce flow control window by [12] to [4194292]
> o.a.coyote.http2.Http2UpgradeHandler : Connection [124], Stream
> [5,279], Data length [12]
> o.a.coyote.http2.StreamStateMachine : Connection [124], Stream
> [5,279], State changed from [HALF_CLOSED_REMOTE] to [CLOSED_TX]
> org.apache.coyote.http2.Stream : Connection [124], Stream
> [5,279] has been recycled
>
>
> From the logs it is not clear whether any of these flags is being sent to
> the client. I will investigate!
>
The flag is always being sent with the data!
One minor thing though: at
https://github.com/apache/tomcat/blob/613787d26fe14aec775fe82e59d0e4bc079d1814/java/org/apache/coyote/http2/Http2AsyncUpgradeHandler.java#L211
the internal state is being changed but the actual sending may not happen
if the stream is not writeable.
>
> Note: ", Writing the headers" is added by me. The current log entry is
> "upgradeHandler.writeHeaders=Connection [{0}], Stream [{1}]"
>
>
>>
>> > With more workers it starts failing with:
>> >
>> > "status_codes": {
>> > "0": 1000,
>> > "200": 1
>> > },
>> > "errors": [
>> > "Get \"https://localhost:18080/testbed/plaintext\": net/http:
>> request
>> > canceled while waiting for connection (Client.Timeout exceeded while
>> > awaiting headers)",
>> > "Get \"https://localhost:18080/testbed/plaintext\": context
>> deadline
>> > exceeded",
>> > "Get \"https://localhost:18080/testbed/plaintext\": context
>> deadline
>> > exceeded (Client.Timeout exceeded while awaiting headers)"
>> > ]
>> > i.e. out of 1001 requests only one succeeds and the others fail with
>> > timeout. I will try to debug this one too and run a profiler too.
>>
>> I'd probably start by enabling Tomcat's HTTP/2 debug logging for this
>> one. I'm wondering if something is triggering a connection level error
>> early in the processing.
>>
>> Mark
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>>
Re: Low throughput with HTTP2
Posted by Martin Grigorov <mg...@apache.org>.
On Mon, Sep 21, 2020 at 3:48 PM Martin Grigorov <mg...@apache.org>
wrote:
> Hi Remy,
>
> On Mon, Sep 21, 2020 at 2:56 PM Rémy Maucherat <re...@apache.org> wrote:
>
> <snip/>
>
>
>> > 2020-09-21 14:25:04.850 DEBUG 232086 --- [https-jsse-nio-18080-exec-8]
>> > o.a.coyote.http11.Http11NioProtocol : Found processor [null] for
>> > socket [org.apache.tomcat.util.net.SecureNioChannel@2b435926
>> > :java.nio.channels.SocketChannel[connected
>> > local=/127.0.0.1:18080 remote=/127.0.0.1:42229]]
>> > 2020-09-21 14:25:04.850 DEBUG 232086 --- [https-jsse-nio-18080-exec-6]
>> > o.a.coyote.http2.Http2UpgradeHandler : Connection [2]
>> >
>> > java.io.IOException: Unable to unwrap data, invalid status [CLOSED]
>> > at org.apache.tomcat.util.net
>> > .SecureNioChannel.read(SecureNioChannel.java:766)
>> > at org.apache.tomcat.util.net
>> >
>> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>> >
>>
>> When I tested HTTP/2, I used h2c (unencrypted) to get a better idea at
>> what's going on. Otherwise you don't really know what proportion of TLS or
>> HTTP/2 impacts performance more [and then you have to test more things
>> like
>> OpenSSL, be careful that the ciphers used are the same and equally well
>> optimized in each impl, etc].
>>
>> Then once you feel happy about h2c, you can see how things go with TLS.
>>
>
> Chris also suggested that TLS might be the problem for the low throughput
> but I get good throughput for both HTTP (15-16 K) and HTTPS (12-13 K
> reqs/s). Only when HTTP2 is enabled it drops. The reason is more clear now
> - it is due to the extra RST packets being sent.
>
> Vegeta does support h2c! So I can give it a try!
>
> How one configures Tomcat to support h2c ? Just remove <SSLHostConfig> ?
> I've just tried this but I am not sure how to verify that it works.
> The browsers do not support h2c. curl and httpie neither.
> Quick search suggested me https://github.com/fstab/h2c "h2c connect
> localhost:18080" failed with "Failed to connect to localhost:18080: tls:
> oversized record received with length 20527"
>
fstab/h2c is a normal http2 client. Confusingly named one though.
>
>
>>
>> Rémy
>>
>>
>>
>>
Re: Low throughput with HTTP2
Posted by Martin Grigorov <mg...@apache.org>.
Hi,
<snip/>
I've debugged further with Wireshark:
1) Golang: https://pasteboard.co/Jsnvx1z.png (SETTINGS, HEADERS+DATA)
2) Nodejs: https://pasteboard.co/JsnwRNV.png (SETTINGS, HEADERS+PARTIAL
DATA, DATA)
3) Rust: https://pasteboard.co/JsnxvKGU.png (SETTINGS, HEADERS+PARTIAL
DATA+DATA)
4) Netty: https://pasteboard.co/JsnxYJp.png (SETTINGS+HEADERS+DATA)
5) Tomcat: https://pasteboard.co/JsnyjpA.png (SETTINGS, HEADERS, DATA)
From the images above you can see that only Tomcat sends two separate
packets for HEADERS and DATA frames. All others put several frames into one
packet.
Netty puts the SETTINGS, the HEADERS and the DATA into one TCP packet. I
guess this is the reason for the high throughput
Node.js writes the HEADERS and PARTIAL DATA in one packet and the actual
DATA in a separate one
Rust also uses PARTIAL DATA but puts the actual one in the same TCP packet
Tomcat's way is spec compliant but most probably is also a reason for the
lower throughput.
More findings:
I've debugged Netty code and it never receives RST_STREAM with CANCEL error
at
https://github.com/martin-g/http2-server-perf-tests/blob/2f628c407e2ea29be99e756a61e555d88addaa01/java/netty-http2-test/src/main/java/com/example/netty/http2/Http2ServerResponseHandler.java#L30
I've looked at Golang net code and found that it will send RST_STREAM with
CANCEL if there is a problem reading the body:
https://github.com/tsenart/vegeta/issues/540#issuecomment-696757695
It is not clear to me whether this is about the request body or response
body. But since the unit test uses Transport.RoundTrip() I think it is
about the response body.
So, it looks like Tomcat sends a DATA frame which is not liked by Golang
net package code and Golang sends this CANCEL error that causes the
problems.
The DATA frames in Wireshark look good to me, but I've made them by using
Firefox as a client to be able to decrypt TLS in Wireshark (SSLKEYLOGFILE)
Martin
Re: Low throughput with HTTP2
Posted by Martin Grigorov <mg...@apache.org>.
On Mon, Sep 21, 2020 at 4:46 PM Rémy Maucherat <re...@apache.org> wrote:
> On Mon, Sep 21, 2020 at 2:49 PM Martin Grigorov <mg...@apache.org>
> wrote:
>
> > Hi Remy,
> >
> > On Mon, Sep 21, 2020 at 2:56 PM Rémy Maucherat <re...@apache.org> wrote:
> >
> > <snip/>
> >
> >
> > > > 2020-09-21 14:25:04.850 DEBUG 232086 ---
> [https-jsse-nio-18080-exec-8]
> > > > o.a.coyote.http11.Http11NioProtocol : Found processor [null] for
> > > > socket [org.apache.tomcat.util.net.SecureNioChannel@2b435926
> > > > :java.nio.channels.SocketChannel[connected
> > > > local=/127.0.0.1:18080 remote=/127.0.0.1:42229]]
> > > > 2020-09-21 14:25:04.850 DEBUG 232086 ---
> [https-jsse-nio-18080-exec-6]
> > > > o.a.coyote.http2.Http2UpgradeHandler : Connection [2]
> > > >
> > > > java.io.IOException: Unable to unwrap data, invalid status [CLOSED]
> > > > at org.apache.tomcat.util.net
> > > > .SecureNioChannel.read(SecureNioChannel.java:766)
> > > > at org.apache.tomcat.util.net
> > > >
> > >
> >
> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
> > > >
> > >
> > > When I tested HTTP/2, I used h2c (unencrypted) to get a better idea at
> > > what's going on. Otherwise you don't really know what proportion of TLS
> > or
> > > HTTP/2 impacts performance more [and then you have to test more things
> > like
> > > OpenSSL, be careful that the ciphers used are the same and equally well
> > > optimized in each impl, etc].
> > >
> > > Then once you feel happy about h2c, you can see how things go with TLS.
> > >
> >
> > Chris also suggested that TLS might be the problem for the low throughput
> > but I get good throughput for both HTTP (15-16 K) and HTTPS (12-13 K
> > reqs/s). Only when HTTP2 is enabled it drops. The reason is more clear
> now
> > - it is due to the extra RST packets being sent.
> >
> > Vegeta does support h2c! So I can give it a try!
> >
> > How one configures Tomcat to support h2c ? Just remove <SSLHostConfig> ?
> > I've just tried this but I am not sure how to verify that it works.
> > The browsers do not support h2c. curl and httpie neither.
> > Quick search suggested me https://github.com/fstab/h2c "h2c connect
> > localhost:18080" failed with "Failed to connect to localhost:18080: tls:
> > oversized record received with length 20527"
> >
>
> Yes, it depends on the client. h2load works just fine without TLS for
> example, and it's actually the reason why I added h2c support in Tomcat.
>
> As for the configuration, it's a normal non TLS HTTP/1.1 config with the
> UpgradeProtocol element added.
>
The way to use h2c with curl is: curl -i --http2-prior-knowledge
http://localhost:18080/...
(with my change in reset() to avoid the connection closes):
vegeta ... -http2=f -h2c ... gives 13 K reqs/s
vegeta ... -http2 ... gives 8.2 K reqs/s
so, it seems TLS reduces the throughput with 40%
Martin
>
> Rémy
>
>
> >
> >
> >
> > >
> > > Rémy
> > >
> > >
> > >
> > >
> >
>
Re: Low throughput with HTTP2
Posted by Rémy Maucherat <re...@apache.org>.
On Mon, Sep 21, 2020 at 2:49 PM Martin Grigorov <mg...@apache.org>
wrote:
> Hi Remy,
>
> On Mon, Sep 21, 2020 at 2:56 PM Rémy Maucherat <re...@apache.org> wrote:
>
> <snip/>
>
>
> > > 2020-09-21 14:25:04.850 DEBUG 232086 --- [https-jsse-nio-18080-exec-8]
> > > o.a.coyote.http11.Http11NioProtocol : Found processor [null] for
> > > socket [org.apache.tomcat.util.net.SecureNioChannel@2b435926
> > > :java.nio.channels.SocketChannel[connected
> > > local=/127.0.0.1:18080 remote=/127.0.0.1:42229]]
> > > 2020-09-21 14:25:04.850 DEBUG 232086 --- [https-jsse-nio-18080-exec-6]
> > > o.a.coyote.http2.Http2UpgradeHandler : Connection [2]
> > >
> > > java.io.IOException: Unable to unwrap data, invalid status [CLOSED]
> > > at org.apache.tomcat.util.net
> > > .SecureNioChannel.read(SecureNioChannel.java:766)
> > > at org.apache.tomcat.util.net
> > >
> >
> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
> > >
> >
> > When I tested HTTP/2, I used h2c (unencrypted) to get a better idea at
> > what's going on. Otherwise you don't really know what proportion of TLS
> or
> > HTTP/2 impacts performance more [and then you have to test more things
> like
> > OpenSSL, be careful that the ciphers used are the same and equally well
> > optimized in each impl, etc].
> >
> > Then once you feel happy about h2c, you can see how things go with TLS.
> >
>
> Chris also suggested that TLS might be the problem for the low throughput
> but I get good throughput for both HTTP (15-16 K) and HTTPS (12-13 K
> reqs/s). Only when HTTP2 is enabled it drops. The reason is more clear now
> - it is due to the extra RST packets being sent.
>
> Vegeta does support h2c! So I can give it a try!
>
> How one configures Tomcat to support h2c ? Just remove <SSLHostConfig> ?
> I've just tried this but I am not sure how to verify that it works.
> The browsers do not support h2c. curl and httpie neither.
> Quick search suggested me https://github.com/fstab/h2c "h2c connect
> localhost:18080" failed with "Failed to connect to localhost:18080: tls:
> oversized record received with length 20527"
>
Yes, it depends on the client. h2load works just fine without TLS for
example, and it's actually the reason why I added h2c support in Tomcat.
As for the configuration, it's a normal non TLS HTTP/1.1 config with the
UpgradeProtocol element added.
Rémy
>
>
>
> >
> > Rémy
> >
> >
> >
> >
>
Re: Low throughput with HTTP2
Posted by Mark Thomas <ma...@apache.org>.
On 25/09/2020 12:18, Berneburg, Cris J. - US wrote:
> Thanks again Mark :-)
>
> mt> how that Map is pruned (it is currently too aggressive)
>
> mt> if Tomcat is processing 10k req/s just keeping track of
> mt> the last 30s is potentially 300k streams. How to do that
> mt> efficiently for all usage patterns is a problem that
> mt> needs some thought.
>
> Sounds a bit like garbage collection. Is aging part of the process - a map/queue combo?
Yes, but only very simplisticly. Streams with lower IDs are removed first.
> cjb> How could the closed stream footprint be reduced?
> cjb> Could the structure holding a closed stream:
> cjb> a. Be replaced with a smaller one?
> cjb> c. Or did you already have something in mind?
>
> mt> A form of a). I'm looking at this now.
I committed this earlier today. See dev@ for details.
> cjb> b. De-reference other objects no longer needed?
> cjb> Hmm... that might lead to NPE's and thus unnecessary
> cjb> null checking.
>
> mt> Tried that. Lots of NPE regressions to the point that
> mt> I reverted the change to look for a better solution.
>
> Hey great, I'm beginning to understand! :-D
>
> mt> we have all the plumbing to correctly determine
> mt> relative priority [...] we don't use it to prioritise
> mt> streams when flow control windows are not an issue
>
> mt> I started to look at this a while ago but it gets very
> mt> complex quite quickly. It would be simpler if we were
> mt> just serving static content.
>
> Ha ha, httpd! Hang on, does httpd handle a similar situation too?
I don't know. I imagine so.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
RE: Low throughput with HTTP2
Posted by "Berneburg, Cris J. - US" <cb...@caci.com.INVALID>.
Thanks again Mark :-)
mt> how that Map is pruned (it is currently too aggressive)
mt> if Tomcat is processing 10k req/s just keeping track of
mt> the last 30s is potentially 300k streams. How to do that
mt> efficiently for all usage patterns is a problem that
mt> needs some thought.
Sounds a bit like garbage collection. Is aging part of the process - a map/queue combo?
cjb> How could the closed stream footprint be reduced?
cjb> Could the structure holding a closed stream:
cjb> a. Be replaced with a smaller one?
cjb> c. Or did you already have something in mind?
mt> A form of a). I'm looking at this now.
cjb> b. De-reference other objects no longer needed?
cjb> Hmm... that might lead to NPE's and thus unnecessary
cjb> null checking.
mt> Tried that. Lots of NPE regressions to the point that
mt> I reverted the change to look for a better solution.
Hey great, I'm beginning to understand! :-D
mt> we have all the plumbing to correctly determine
mt> relative priority [...] we don't use it to prioritise
mt> streams when flow control windows are not an issue
mt> I started to look at this a while ago but it gets very
mt> complex quite quickly. It would be simpler if we were
mt> just serving static content.
Ha ha, httpd! Hang on, does httpd handle a similar situation too?
--
Cris Berneburg
CACI Senior Software Engineer
________________________________
This electronic message contains information from CACI International Inc or subsidiary companies, which may be company sensitive, proprietary, privileged or otherwise protected from disclosure. The information is intended to be used solely by the recipient(s) named above. If you are not an intended recipient, be aware that any review, disclosure, copying, distribution or use of this transmission or its contents is prohibited. If you have received this transmission in error, please notify the sender immediately.
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Low throughput with HTTP2
Posted by Mark Thomas <ma...@apache.org>.
On 23/09/2020 15:50, Berneburg, Cris J. - US wrote:
> Hi Mark
>
> Thanks for taking the time to explain that to me. :-)
>
> A few more questions, if you don't mind.
>
> cjb> TC thinks the stream should be closed when the client
> cjb> thinks the stream is still open? Basically RST_STREAM
> cjb> is a keep-alive?
>
> mt> No. The stream closed cleanly. The client is sending
> mt> RST_STREAM due to what is suspected to be a client bug.
> mt> RFC 7540 says the server must ignore such frames and can,
> mt> if a frame is received a significant period after the
> mt> stream closed, treat it as a protocol error (and close
> mt> the connection).
>
> mt> Separately, the server should (as per the RFC) retain
> mt> state for closed streams to support prioritisation.
>
> mt> Currently Tomcat uses a single Map to track the state of
> mt> closed streams for priority and to identify streams have
> mt> been closed for an *in*significant amount of time.
>
> mt> The issues immediately at hand are:
> mt> - how that Map is pruned (it is currently too aggressive)
>
> What would you consider "less aggressive"?
Not reducing the number of streams below the maximum number of
concurrent streams.
> Would aggressiveness depend on system load?
Possibly. The less it does so, the better. But, for example, if Tomcat
is processing 10k req/s just keeping track of the last 30s is
potentially 300k streams. How to do that efficiently for all usage
patterns is a problem that needs some thought.
> mt> - that under high load a "significant period" becomes a
> mt> few milliseconds
>
> Sounds like "significant period" varies depending on system load.
At the moment there is a fairly direct inverse relationship. Ideally
there should be no relationship. Not sure how achievable that is at the
moment.
> mt> currently memory footprint of a closed stream is much
> mt> larger than it needs to be
>
> How could the closed stream footprint be reduced? Could the structure holding a closed stream:
>
> a. Be replaced with a smaller one?
Potentially.
> b. De-reference other objects no longer needed? Hmm... that might lead to NPE's and thus unnecessary null checking.
Tried that. Lots of NPE regressions to the point that I reverted the
change to look for a better solution.
> c. Or did you already have something in mind?
A form of a). I'm looking at this now.
> mt> while we have all the plumbing to correctly determine
> mt> relative priority and use it when allocating window
> mt> updates in the case where the connection flow control
> mt> window is smaller than the total data the streams want
> mt> to send - we don't use it to prioritise streams when
> mt> flow control windows are not an issue
>
> Is that an FYI or a to-do?
Both. I started to look at this a while ago but it gets very complex
quite quickly. It would be simpler if we were just serving static content.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
RE: Low throughput with HTTP2
Posted by "Berneburg, Cris J. - US" <cb...@caci.com.INVALID>.
Hi Mark
Thanks for taking the time to explain that to me. :-)
A few more questions, if you don't mind.
cjb> TC thinks the stream should be closed when the client
cjb> thinks the stream is still open? Basically RST_STREAM
cjb> is a keep-alive?
mt> No. The stream closed cleanly. The client is sending
mt> RST_STREAM due to what is suspected to be a client bug.
mt> RFC 7540 says the server must ignore such frames and can,
mt> if a frame is received a significant period after the
mt> stream closed, treat it as a protocol error (and close
mt> the connection).
mt> Separately, the server should (as per the RFC) retain
mt> state for closed streams to support prioritisation.
mt> Currently Tomcat uses a single Map to track the state of
mt> closed streams for priority and to identify streams have
mt> been closed for an *in*significant amount of time.
mt> The issues immediately at hand are:
mt> - how that Map is pruned (it is currently too aggressive)
What would you consider "less aggressive"? Would aggressiveness depend on system load?
mt> - that under high load a "significant period" becomes a
mt> few milliseconds
Sounds like "significant period" varies depending on system load.
mt> currently memory footprint of a closed stream is much
mt> larger than it needs to be
How could the closed stream footprint be reduced? Could the structure holding a closed stream:
a. Be replaced with a smaller one?
b. De-reference other objects no longer needed? Hmm... that might lead to NPE's and thus unnecessary null checking.
c. Or did you already have something in mind?
mt> while we have all the plumbing to correctly determine
mt> relative priority and use it when allocating window
mt> updates in the case where the connection flow control
mt> window is smaller than the total data the streams want
mt> to send - we don't use it to prioritise streams when
mt> flow control windows are not an issue
Is that an FYI or a to-do?
--
Cris Berneburg
CACI Senior Software Engineer
________________________________
This electronic message contains information from CACI International Inc or subsidiary companies, which may be company sensitive, proprietary, privileged or otherwise protected from disclosure. The information is intended to be used solely by the recipient(s) named above. If you are not an intended recipient, be aware that any review, disclosure, copying, distribution or use of this transmission or its contents is prohibited. If you have received this transmission in error, please notify the sender immediately.
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Low throughput with HTTP2
Posted by Mark Thomas <ma...@apache.org>.
On 22/09/2020 13:47, Berneburg, Cris J. - US wrote:
> Hi Mark
>
> As with most topics here, I struggle to understand what is being discussed. :-) So please bear with me.
>
>> improving how Tomcat handles traffic like this.
>>
>> Looks like Tomcat could prune the closed streams
>> less aggressively.
>>
>> At the moment it waits until there are
>> maxConcurrentStreams + 10% in the map and then:
>> - removes all closed streams without children
>> - [snip] with children [snip]
>> - [snip] closed final streams [snip]
>>
>> [snip] the size of the map increases to ~110 and
>> then drops to ~5, increases to ~110 and repeats.
>>
>> I'm currently thinking about different pruning
>> strategies. The associated memory footprint is
>> also part of my thinking.
>
> TC thinks the stream should be closed when the client thinks the stream is still open? Basically RST_STREAM is a keep-alive?
No. The stream closed cleanly. The client is sending RST_STREAM due to
what is suspected to be a client bug. RFC 7540 says the server must
ignore such frames and can, if a frame is received a significant period
after the stream closed, treat it as a protocol error (and close the
connection).
Separately, the server should (as per the RFC) retain state for closed
streams to support prioritisation.
Currently Tomcat uses a single Map to track the state of closed streams
for priority and to identify streams have been closed for an
*in*significant amount of time.
The issues immediately at hand are:
- how that Map is pruned (it is currently too aggressive)
- that under high load a "significant period" becomes a few milliseconds
Also in the mix:
- currently memory footprint of a closed stream is much larger than it
needs to be
- while we have all the plumbing to correctly determine relative
priority and use it when allocating window updates in the case
where the connection flow control window is smaller than the total
data the streams want to send - we don't use it to prioritise streams
when flow control windows are not an issue
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
RE: Low throughput with HTTP2
Posted by "Berneburg, Cris J. - US" <cb...@caci.com.INVALID>.
Hi Mark
As with most topics here, I struggle to understand what is being discussed. :-) So please bear with me.
> improving how Tomcat handles traffic like this.
>
> Looks like Tomcat could prune the closed streams
> less aggressively.
>
> At the moment it waits until there are
> maxConcurrentStreams + 10% in the map and then:
> - removes all closed streams without children
> - [snip] with children [snip]
> - [snip] closed final streams [snip]
>
> [snip] the size of the map increases to ~110 and
> then drops to ~5, increases to ~110 and repeats.
>
> I'm currently thinking about different pruning
> strategies. The associated memory footprint is
> also part of my thinking.
TC thinks the stream should be closed when the client thinks the stream is still open? Basically RST_STREAM is a keep-alive?
So a passenger (client) discharges from a taxi and pays the driver (server), but asks the driver to wait (RST_STREAM), so the meter (stream) is still running. How long does the driver wait (timeout) before driving away? Does the driver honk the horn (send a wake-up packet) before looking for a new customer?
Is the issue a matter of "how" or "when"? If TC receives RST_STREAM then restart the timeout clock. To prevent abuse allow a limited number of successive keep-alive frames. If a certain number of RST_STREAM's are received, aka threshold is reached, with nothing else occurring, then close the stream. That could be configurable.
How about instead of a binary state of open or closed the state is trinary - open, stale, closed?
- Open, don't prune.
- Closed, prune.
- Stale:
a. Move to closed after timeout or too many RST_STREAM's.
b. Consider open if receive useful traffic.
Also, if there are multiple pruning strategies, allow a single method to be selected per connector config or for the whole TC instance.
I hope this is helpful. If not, well, maybe at least it's educational. ;-)
--
Cris Berneburg
CACI Senior Software Engineer
________________________________
This electronic message contains information from CACI International Inc or subsidiary companies, which may be company sensitive, proprietary, privileged or otherwise protected from disclosure. The information is intended to be used solely by the recipient(s) named above. If you are not an intended recipient, be aware that any review, disclosure, copying, distribution or use of this transmission or its contents is prohibited. If you have received this transmission in error, please notify the sender immediately.
Re: Low throughput with HTTP2
Posted by Mark Thomas <ma...@apache.org>.
On 21/09/2020 15:52, Mark Thomas wrote:
<snip/>
> That doesn't
> exclude, of course, the possibility of improving how Tomcat handles
> traffic like this.
Looks like Tomcat could prune the closed streams less aggressively.
At the moment it waits until there are maxConcurrentStreams + 10% in the
map and then:
- removes all closed streams without children
- removes all closed streams with children (re-prioritising as
appropriate)
- if there are still more than maxConcurrentStreams + 10% streams in the
map, removes closed final streams (that are likely part of the
priority tree) until the number of streams in the map is less than
maxConcurrentStreams + 10% or there are no more closed streams to
remove
This means, with defaults and the load profile in this test, that the
size of the map increases to ~110 and then drops to ~5, increases to
~110 and repeats.
I'm currently thinking about different pruning strategies. The
associated memory footprint is also part of my thinking.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Low throughput with HTTP2
Posted by Martin Grigorov <mg...@apache.org>.
On Mon, Sep 21, 2020 at 9:31 PM Martin Grigorov <mg...@apache.org>
wrote:
>
>
> On Mon, Sep 21, 2020 at 5:52 PM Mark Thomas <ma...@apache.org> wrote:
>
>> On 21/09/2020 13:48, Martin Grigorov wrote:
>> > Hi Remy,
>> >
>> > On Mon, Sep 21, 2020 at 2:56 PM Rémy Maucherat <re...@apache.org> wrote:
>> >
>> > <snip/>
>> >
>> >
>> >>> 2020-09-21 14:25:04.850 DEBUG 232086 --- [https-jsse-nio-18080-exec-8]
>> >>> o.a.coyote.http11.Http11NioProtocol : Found processor [null] for
>> >>> socket [org.apache.tomcat.util.net.SecureNioChannel@2b435926
>> >>> :java.nio.channels.SocketChannel[connected
>> >>> local=/127.0.0.1:18080 remote=/127.0.0.1:42229]]
>> >>> 2020-09-21 14:25:04.850 DEBUG 232086 --- [https-jsse-nio-18080-exec-6]
>> >>> o.a.coyote.http2.Http2UpgradeHandler : Connection [2]
>> >>>
>> >>> java.io.IOException: Unable to unwrap data, invalid status [CLOSED]
>> >>> at org.apache.tomcat.util.net
>> >>> .SecureNioChannel.read(SecureNioChannel.java:766)
>> >>> at org.apache.tomcat.util.net
>> >>>
>> >>
>> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>> >>>
>> >>
>> >> When I tested HTTP/2, I used h2c (unencrypted) to get a better idea at
>> >> what's going on. Otherwise you don't really know what proportion of
>> TLS or
>> >> HTTP/2 impacts performance more [and then you have to test more things
>> like
>> >> OpenSSL, be careful that the ciphers used are the same and equally well
>> >> optimized in each impl, etc].
>> >>
>> >> Then once you feel happy about h2c, you can see how things go with TLS.
>> >>
>> >
>> > Chris also suggested that TLS might be the problem for the low
>> throughput
>> > but I get good throughput for both HTTP (15-16 K) and HTTPS (12-13 K
>> > reqs/s). Only when HTTP2 is enabled it drops. The reason is more clear
>> now
>> > - it is due to the extra RST packets being sent.
>> >
>> > Vegeta does support h2c! So I can give it a try!
>>
>> I've just done that. I am seeing the client sending RST_STREAM frames
>> AFTER the request/response has been processed cleanly.
>>
>> The RST_STREAM frames are being sent with the CANCEL error. i.e. the
>> client is no longer interested in reading the response body.
>>
>> This doesn't make much sense as there is little more than two or three
>> milliseconds between the start of the request and the RST_STREAM. It
>> isn't happening due to a timeout. It is also always sent AFTER the
>> server has sent the complete response (the end of stream flag is set)
>> and sometimes after the next request has been sent.
>>
>> However you look at it, this looks like a bug in Vegeta. That doesn't
>>
>
> I will contact the Vegeta community!
>
https://github.com/tsenart/vegeta/issues/540
>
>
>> exclude, of course, the possibility of improving how Tomcat handles
>> traffic like this.
>>
>> Mark
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>>
Re: Low throughput with HTTP2
Posted by Martin Grigorov <mg...@apache.org>.
On Mon, Sep 21, 2020 at 5:52 PM Mark Thomas <ma...@apache.org> wrote:
> On 21/09/2020 13:48, Martin Grigorov wrote:
> > Hi Remy,
> >
> > On Mon, Sep 21, 2020 at 2:56 PM Rémy Maucherat <re...@apache.org> wrote:
> >
> > <snip/>
> >
> >
> >>> 2020-09-21 14:25:04.850 DEBUG 232086 --- [https-jsse-nio-18080-exec-8]
> >>> o.a.coyote.http11.Http11NioProtocol : Found processor [null] for
> >>> socket [org.apache.tomcat.util.net.SecureNioChannel@2b435926
> >>> :java.nio.channels.SocketChannel[connected
> >>> local=/127.0.0.1:18080 remote=/127.0.0.1:42229]]
> >>> 2020-09-21 14:25:04.850 DEBUG 232086 --- [https-jsse-nio-18080-exec-6]
> >>> o.a.coyote.http2.Http2UpgradeHandler : Connection [2]
> >>>
> >>> java.io.IOException: Unable to unwrap data, invalid status [CLOSED]
> >>> at org.apache.tomcat.util.net
> >>> .SecureNioChannel.read(SecureNioChannel.java:766)
> >>> at org.apache.tomcat.util.net
> >>>
> >>
> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
> >>>
> >>
> >> When I tested HTTP/2, I used h2c (unencrypted) to get a better idea at
> >> what's going on. Otherwise you don't really know what proportion of TLS
> or
> >> HTTP/2 impacts performance more [and then you have to test more things
> like
> >> OpenSSL, be careful that the ciphers used are the same and equally well
> >> optimized in each impl, etc].
> >>
> >> Then once you feel happy about h2c, you can see how things go with TLS.
> >>
> >
> > Chris also suggested that TLS might be the problem for the low throughput
> > but I get good throughput for both HTTP (15-16 K) and HTTPS (12-13 K
> > reqs/s). Only when HTTP2 is enabled it drops. The reason is more clear
> now
> > - it is due to the extra RST packets being sent.
> >
> > Vegeta does support h2c! So I can give it a try!
>
> I've just done that. I am seeing the client sending RST_STREAM frames
> AFTER the request/response has been processed cleanly.
>
> The RST_STREAM frames are being sent with the CANCEL error. i.e. the
> client is no longer interested in reading the response body.
>
> This doesn't make much sense as there is little more than two or three
> milliseconds between the start of the request and the RST_STREAM. It
> isn't happening due to a timeout. It is also always sent AFTER the
> server has sent the complete response (the end of stream flag is set)
> and sometimes after the next request has been sent.
>
> However you look at it, this looks like a bug in Vegeta. That doesn't
>
I will contact the Vegeta community!
> exclude, of course, the possibility of improving how Tomcat handles
> traffic like this.
>
> Mark
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
Re: Low throughput with HTTP2
Posted by Mark Thomas <ma...@apache.org>.
On 21/09/2020 13:48, Martin Grigorov wrote:
> Hi Remy,
>
> On Mon, Sep 21, 2020 at 2:56 PM Rémy Maucherat <re...@apache.org> wrote:
>
> <snip/>
>
>
>>> 2020-09-21 14:25:04.850 DEBUG 232086 --- [https-jsse-nio-18080-exec-8]
>>> o.a.coyote.http11.Http11NioProtocol : Found processor [null] for
>>> socket [org.apache.tomcat.util.net.SecureNioChannel@2b435926
>>> :java.nio.channels.SocketChannel[connected
>>> local=/127.0.0.1:18080 remote=/127.0.0.1:42229]]
>>> 2020-09-21 14:25:04.850 DEBUG 232086 --- [https-jsse-nio-18080-exec-6]
>>> o.a.coyote.http2.Http2UpgradeHandler : Connection [2]
>>>
>>> java.io.IOException: Unable to unwrap data, invalid status [CLOSED]
>>> at org.apache.tomcat.util.net
>>> .SecureNioChannel.read(SecureNioChannel.java:766)
>>> at org.apache.tomcat.util.net
>>>
>> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>>
>>
>> When I tested HTTP/2, I used h2c (unencrypted) to get a better idea at
>> what's going on. Otherwise you don't really know what proportion of TLS or
>> HTTP/2 impacts performance more [and then you have to test more things like
>> OpenSSL, be careful that the ciphers used are the same and equally well
>> optimized in each impl, etc].
>>
>> Then once you feel happy about h2c, you can see how things go with TLS.
>>
>
> Chris also suggested that TLS might be the problem for the low throughput
> but I get good throughput for both HTTP (15-16 K) and HTTPS (12-13 K
> reqs/s). Only when HTTP2 is enabled it drops. The reason is more clear now
> - it is due to the extra RST packets being sent.
>
> Vegeta does support h2c! So I can give it a try!
I've just done that. I am seeing the client sending RST_STREAM frames
AFTER the request/response has been processed cleanly.
The RST_STREAM frames are being sent with the CANCEL error. i.e. the
client is no longer interested in reading the response body.
This doesn't make much sense as there is little more than two or three
milliseconds between the start of the request and the RST_STREAM. It
isn't happening due to a timeout. It is also always sent AFTER the
server has sent the complete response (the end of stream flag is set)
and sometimes after the next request has been sent.
However you look at it, this looks like a bug in Vegeta. That doesn't
exclude, of course, the possibility of improving how Tomcat handles
traffic like this.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Low throughput with HTTP2
Posted by Martin Grigorov <mg...@apache.org>.
Hi Remy,
On Mon, Sep 21, 2020 at 2:56 PM Rémy Maucherat <re...@apache.org> wrote:
<snip/>
> > 2020-09-21 14:25:04.850 DEBUG 232086 --- [https-jsse-nio-18080-exec-8]
> > o.a.coyote.http11.Http11NioProtocol : Found processor [null] for
> > socket [org.apache.tomcat.util.net.SecureNioChannel@2b435926
> > :java.nio.channels.SocketChannel[connected
> > local=/127.0.0.1:18080 remote=/127.0.0.1:42229]]
> > 2020-09-21 14:25:04.850 DEBUG 232086 --- [https-jsse-nio-18080-exec-6]
> > o.a.coyote.http2.Http2UpgradeHandler : Connection [2]
> >
> > java.io.IOException: Unable to unwrap data, invalid status [CLOSED]
> > at org.apache.tomcat.util.net
> > .SecureNioChannel.read(SecureNioChannel.java:766)
> > at org.apache.tomcat.util.net
> >
> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
> >
>
> When I tested HTTP/2, I used h2c (unencrypted) to get a better idea at
> what's going on. Otherwise you don't really know what proportion of TLS or
> HTTP/2 impacts performance more [and then you have to test more things like
> OpenSSL, be careful that the ciphers used are the same and equally well
> optimized in each impl, etc].
>
> Then once you feel happy about h2c, you can see how things go with TLS.
>
Chris also suggested that TLS might be the problem for the low throughput
but I get good throughput for both HTTP (15-16 K) and HTTPS (12-13 K
reqs/s). Only when HTTP2 is enabled it drops. The reason is more clear now
- it is due to the extra RST packets being sent.
Vegeta does support h2c! So I can give it a try!
How one configures Tomcat to support h2c ? Just remove <SSLHostConfig> ?
I've just tried this but I am not sure how to verify that it works.
The browsers do not support h2c. curl and httpie neither.
Quick search suggested me https://github.com/fstab/h2c "h2c connect
localhost:18080" failed with "Failed to connect to localhost:18080: tls:
oversized record received with length 20527"
>
> Rémy
>
>
>
>
Re: Low throughput with HTTP2
Posted by Rémy Maucherat <re...@apache.org>.
On Mon, Sep 21, 2020 at 1:36 PM Martin Grigorov <mg...@apache.org>
wrote:
> On Mon, Sep 21, 2020 at 12:08 PM Martin Grigorov <mg...@apache.org>
> wrote:
>
> >
> >
> > On Mon, Sep 21, 2020 at 11:23 AM Mark Thomas <ma...@apache.org> wrote:
> >
> >> On 21/09/2020 08:18, Martin Grigorov wrote:
> >> > On Fri, Sep 18, 2020 at 6:16 PM Mark Thomas <ma...@apache.org> wrote:
> >> >
> >> >> On 18/09/2020 14:07, Martin Grigorov wrote:
> >> >>
> >> >> <snip/>
> >> >>
> >> >>> What is the difference
> >> >>> between org.apache.coyote.http2.StreamStateMachine.State#CLOSED_RX
> >> >>> and org.apache.coyote.http2.StreamStateMachine.State#CLOSED_TX ?
> >> >>
> >> >> Compare the parameters used to construct the enums.
> >> >>
> >> >>> I read some parts of https://tools.ietf.org/html/rfc7540 but I
> don't
> >> see
> >> >>> anything related to two types of CLOSED state.
> >> >>
> >> >> Section 5.1. Definition of the closed state (page 20) explains the
> >> >> difference between the two.
> >> >>
> >> >
> >> > Still I do not understand what RX and TX stand for. But this is not
> >> > important.
> >>
> >> TX - transmit
> >>
> >> RX - receive
> >>
> >
> > Thanks!
> >
> >
> >>
> >>
> >> > The following patch fixes the issue for me/Vegeta:
> >> >
> >> > @@ -1570,12 +1571,15 @@ class Http2UpgradeHandler extends
> AbstractStream
> >> > implements InternalHttpUpgradeH
> >> >
> >> > @Override
> >> > public void reset(int streamId, long errorCode) throws
> >> Http2Exception
> >> > {
> >> > - Stream stream = getStream(streamId, true);
> >> > - boolean active = stream.isActive();
> >> > - stream.checkState(FrameType.RST);
> >> > - stream.receiveReset(errorCode);
> >> > - if (active) {
> >> > - activeRemoteStreamCount.decrementAndGet();
> >> > + boolean unknownIsError = Http2Error.CANCEL.getCode() !=
> >> errorCode;
> >> > + Stream stream = getStream(streamId, unknownIsError);
> >> > + if (stream != null) {
> >> > + boolean active = stream.isActive();
> >> > + stream.checkState(FrameType.RST);
> >> > + stream.receiveReset(errorCode);
> >> > + if (active) {
> >> > + activeRemoteStreamCount.decrementAndGet();
> >> > + }
> >> > }
> >> > }
> >> >
> >> > I.e. do not throw an error if the remote peer is trying to cancel an
> >> > already closed stream.
> >>
> >> RFC 7540 allows the connection to be closed with a protocol error if the
> >> reset is received "a significant time after sending END_STREAM".
> >>
> >> Tomcat retains state for maxConcurrentStreams + 10% with closed streams
> >> being pruned (oldest first) every 10 new streams.
> >>
> >
> > The spec talks about time but Tomcat uses the number of streams.
> > I understand that under normal usage this could be enough "time" but
> under
> > heavy load this number is reached quickly and the time is short.
> >
> > I've tried with these values for
> > maxConcurrentStreams/maxConcurrentStreamExecution: 8 (number of CPU
> cores),
> > 16, 100 (the default), 1024 and 8196. The throughput is around 10K only
> > until 100. After that it drops (as you said earlier).
> >
> >
> >>
> >> It isn't clear at this point why the client is sending the RST_STREAM.
> >>
> >
> > I don't know either. But Vegeta is using the Golang standard libraries,
> so
> > any Golang application should behave the same way.
> > Also as I investigated last week - Golang/Node.js/Rust/Netty HTTP2
> servers
> > do not complain about it.
> >
> >
> >> This normally indicates an error condition. From the description of the
> >> load test I don't see why the client would be sending a RST_STREAM.
> >>
> >> If the RST_STREAM is valid and it isn't received a significant time
> >> after the END_STREAM then Tomcat needs to handle this.
> >>
> >> If the RST_STREAM is valid but received a significant amount of time
> >> after the END_STREAM that would be a client error would be a client
> error.
> >>
> >> Of course, significant isn't defined in the specification.
> >>
> >> Any special handling for RST_STREAM also needs to be applied to
> >> WINDOW_UPDATE. It also needs to differentiate between a frame received
> >> for a past closed stream and a frame received for an stream that never
> >> existed.
> >>
> >> I think the key question here is why is the client sending the
> >> RST_STREAM in the first place. Is Tomcat doing something it shouldn't /
> >> not doing something it should to cause this? If so, we need to fix the
> >> root cause rather than tackle the symptom.
> >>
> >> There are a couple of options for debugging this to see why the client
> >> is sending the RST_STREAM:
> >> - Enable debug logging for HTTP/2 in Tomcat. This is very verbose and
> >> if the root cause is threading related typically changes the timing
> >> enough to mask the issue.
> >>
> >
> > Here are the logs of 20 seconds load:
> >
> >
> https://gist.githubusercontent.com/martin-g/37dacc12149d5cecbfd4e16dc2248cfd/raw/76693cd1dd1f37ba126edb84ebd7631802aa91a6/tomcat-http2.log
> >
>
> Actually the above was just the last logs.
> The previous logs were in .gz files which I've missed.
>
> https://gist.githubusercontent.com/martin-g/37dacc12149d5cecbfd4e16dc2248cfd/raw/00596b7dc31d30d275384334ff17c5416f5b363c/tomcat-http2.log
> - this file contains the first 7 seconds of the load run.
> I have 3 times more information for the last 13 seconds but it is more or
> less the same information.
>
> There are many like this:
>
> 2020-09-21 14:25:04.850 DEBUG 232086 --- [https-jsse-nio-18080-exec-8]
> o.a.coyote.http11.Http11NioProtocol : Found processor [null] for
> socket [org.apache.tomcat.util.net.SecureNioChannel@2b435926
> :java.nio.channels.SocketChannel[connected
> local=/127.0.0.1:18080 remote=/127.0.0.1:42229]]
> 2020-09-21 14:25:04.850 DEBUG 232086 --- [https-jsse-nio-18080-exec-6]
> o.a.coyote.http2.Http2UpgradeHandler : Connection [2]
>
> java.io.IOException: Unable to unwrap data, invalid status [CLOSED]
> at org.apache.tomcat.util.net
> .SecureNioChannel.read(SecureNioChannel.java:766)
> at org.apache.tomcat.util.net
> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>
When I tested HTTP/2, I used h2c (unencrypted) to get a better idea at
what's going on. Otherwise you don't really know what proportion of TLS or
HTTP/2 impacts performance more [and then you have to test more things like
OpenSSL, be careful that the ciphers used are the same and equally well
optimized in each impl, etc].
Then once you feel happy about h2c, you can see how things go with TLS.
Rémy
> at org.apache.tomcat.util.net
> .SocketWrapperBase$OperationState.start(SocketWrapperBase.java:1039)
> 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:238)
> at
> org.apache.coyote.http2.Http2AsyncUpgradeHandler.init(Http2AsyncUpgradeHandler.java:39)
> at
> org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch(Http2UpgradeHandler.java:313)
> at
> org.apache.coyote.http2.Http2AsyncUpgradeHandler.upgradeDispatch(Http2AsyncUpgradeHandler.java:39)
> 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
> .NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)
> at org.apache.tomcat.util.net
> .SocketProcessorBase.run(SocketProcessorBase.java:49)
> 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)
>
>
>
> >
> >
> > This is with my patch in #reset(). Without it there are also errors that
> > stream XYZ is already closed
> >
> >
> >> - Client side logging (I don't know what the capabilities are here).
> >> - JVM level TLS debug logging (even more verbose than Tomcat's HTTP/2
> >> debug and harder to work with)
> >> - Wireshark (or similar)
> >>
> >> I'd recommend Wireshark. I don't think JSSE supports SSLKEYLOGFILE so
> >> I'd use the APR/Native connector with SSLKEYLOGFILE to get the cleartext
> >> in Wireshark.
> >>
> >> > With this change and Vegeta's -max-workers=100 I can get 12 K
> reqs/sec.
> >>
> >> That is odd. If the client is sending RST_STREAM messages then I'd
> >> expect to see requests failing as RST_STREAM indicates something has
> >> gone wrong or the client has aborted the request.
> >>
> >
> > According to https://tools.ietf.org/html/rfc7540#section-5.1 when the
> > stream is in HALF_CLOSED_REMOTE state it should send either END_STREAM or
> > RST_STREAM to the remote peer.
> > In the logs I see such sequence of events:
> >
> > ...
> > o.a.coyote.http2.StreamStateMachine : Connection [124], Stream
> > [5,279], State changed from [OPEN] to [HALF_CLOSED_REMOTE]
> > o.a.coyote.http2.Http2UpgradeHandler : Connection [124], Stream
> > [5,279], Writing the headers
> > org.apache.coyote.http2.Stream : Connection [124], Stream
> > [5,279], flushing output with buffer at position [12], writeInProgress
> > [false] and closed [true]
> > org.apache.coyote.http2.AbstractStream : Connection [124], Stream
> > [5,279], reduce flow control window by [12] to [4194292]
> > o.a.coyote.http2.Http2UpgradeHandler : Connection [124], Stream
> > [5,279], Data length [12]
> > o.a.coyote.http2.StreamStateMachine : Connection [124], Stream
> > [5,279], State changed from [HALF_CLOSED_REMOTE] to [CLOSED_TX]
> > org.apache.coyote.http2.Stream : Connection [124], Stream
> > [5,279] has been recycled
> >
> >
> > From the logs it is not clear whether any of these flags is being sent to
> > the client. I will investigate!
> >
> > Note: ", Writing the headers" is added by me. The current log entry is
> > "upgradeHandler.writeHeaders=Connection [{0}], Stream [{1}]"
> >
> >
> >>
> >> > With more workers it starts failing with:
> >> >
> >> > "status_codes": {
> >> > "0": 1000,
> >> > "200": 1
> >> > },
> >> > "errors": [
> >> > "Get \"https://localhost:18080/testbed/plaintext\": net/http:
> >> request
> >> > canceled while waiting for connection (Client.Timeout exceeded while
> >> > awaiting headers)",
> >> > "Get \"https://localhost:18080/testbed/plaintext\": context
> >> deadline
> >> > exceeded",
> >> > "Get \"https://localhost:18080/testbed/plaintext\": context
> >> deadline
> >> > exceeded (Client.Timeout exceeded while awaiting headers)"
> >> > ]
> >> > i.e. out of 1001 requests only one succeeds and the others fail with
> >> > timeout. I will try to debug this one too and run a profiler too.
> >>
> >> I'd probably start by enabling Tomcat's HTTP/2 debug logging for this
> >> one. I'm wondering if something is triggering a connection level error
> >> early in the processing.
> >>
> >> Mark
> >>
> >> ---------------------------------------------------------------------
> >> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> >> For additional commands, e-mail: users-help@tomcat.apache.org
> >>
> >>
>
Re: Low throughput with HTTP2
Posted by Martin Grigorov <mg...@apache.org>.
On Mon, Sep 21, 2020 at 12:08 PM Martin Grigorov <mg...@apache.org>
wrote:
>
>
> On Mon, Sep 21, 2020 at 11:23 AM Mark Thomas <ma...@apache.org> wrote:
>
>> On 21/09/2020 08:18, Martin Grigorov wrote:
>> > On Fri, Sep 18, 2020 at 6:16 PM Mark Thomas <ma...@apache.org> wrote:
>> >
>> >> On 18/09/2020 14:07, Martin Grigorov wrote:
>> >>
>> >> <snip/>
>> >>
>> >>> What is the difference
>> >>> between org.apache.coyote.http2.StreamStateMachine.State#CLOSED_RX
>> >>> and org.apache.coyote.http2.StreamStateMachine.State#CLOSED_TX ?
>> >>
>> >> Compare the parameters used to construct the enums.
>> >>
>> >>> I read some parts of https://tools.ietf.org/html/rfc7540 but I don't
>> see
>> >>> anything related to two types of CLOSED state.
>> >>
>> >> Section 5.1. Definition of the closed state (page 20) explains the
>> >> difference between the two.
>> >>
>> >
>> > Still I do not understand what RX and TX stand for. But this is not
>> > important.
>>
>> TX - transmit
>>
>> RX - receive
>>
>
> Thanks!
>
>
>>
>>
>> > The following patch fixes the issue for me/Vegeta:
>> >
>> > @@ -1570,12 +1571,15 @@ class Http2UpgradeHandler extends AbstractStream
>> > implements InternalHttpUpgradeH
>> >
>> > @Override
>> > public void reset(int streamId, long errorCode) throws
>> Http2Exception
>> > {
>> > - Stream stream = getStream(streamId, true);
>> > - boolean active = stream.isActive();
>> > - stream.checkState(FrameType.RST);
>> > - stream.receiveReset(errorCode);
>> > - if (active) {
>> > - activeRemoteStreamCount.decrementAndGet();
>> > + boolean unknownIsError = Http2Error.CANCEL.getCode() !=
>> errorCode;
>> > + Stream stream = getStream(streamId, unknownIsError);
>> > + if (stream != null) {
>> > + boolean active = stream.isActive();
>> > + stream.checkState(FrameType.RST);
>> > + stream.receiveReset(errorCode);
>> > + if (active) {
>> > + activeRemoteStreamCount.decrementAndGet();
>> > + }
>> > }
>> > }
>> >
>> > I.e. do not throw an error if the remote peer is trying to cancel an
>> > already closed stream.
>>
>> RFC 7540 allows the connection to be closed with a protocol error if the
>> reset is received "a significant time after sending END_STREAM".
>>
>> Tomcat retains state for maxConcurrentStreams + 10% with closed streams
>> being pruned (oldest first) every 10 new streams.
>>
>
> The spec talks about time but Tomcat uses the number of streams.
> I understand that under normal usage this could be enough "time" but under
> heavy load this number is reached quickly and the time is short.
>
> I've tried with these values for
> maxConcurrentStreams/maxConcurrentStreamExecution: 8 (number of CPU cores),
> 16, 100 (the default), 1024 and 8196. The throughput is around 10K only
> until 100. After that it drops (as you said earlier).
>
>
>>
>> It isn't clear at this point why the client is sending the RST_STREAM.
>>
>
> I don't know either. But Vegeta is using the Golang standard libraries, so
> any Golang application should behave the same way.
> Also as I investigated last week - Golang/Node.js/Rust/Netty HTTP2 servers
> do not complain about it.
>
>
>> This normally indicates an error condition. From the description of the
>> load test I don't see why the client would be sending a RST_STREAM.
>>
>> If the RST_STREAM is valid and it isn't received a significant time
>> after the END_STREAM then Tomcat needs to handle this.
>>
>> If the RST_STREAM is valid but received a significant amount of time
>> after the END_STREAM that would be a client error would be a client error.
>>
>> Of course, significant isn't defined in the specification.
>>
>> Any special handling for RST_STREAM also needs to be applied to
>> WINDOW_UPDATE. It also needs to differentiate between a frame received
>> for a past closed stream and a frame received for an stream that never
>> existed.
>>
>> I think the key question here is why is the client sending the
>> RST_STREAM in the first place. Is Tomcat doing something it shouldn't /
>> not doing something it should to cause this? If so, we need to fix the
>> root cause rather than tackle the symptom.
>>
>> There are a couple of options for debugging this to see why the client
>> is sending the RST_STREAM:
>> - Enable debug logging for HTTP/2 in Tomcat. This is very verbose and
>> if the root cause is threading related typically changes the timing
>> enough to mask the issue.
>>
>
> Here are the logs of 20 seconds load:
>
> https://gist.githubusercontent.com/martin-g/37dacc12149d5cecbfd4e16dc2248cfd/raw/76693cd1dd1f37ba126edb84ebd7631802aa91a6/tomcat-http2.log
>
Actually the above was just the last logs.
The previous logs were in .gz files which I've missed.
https://gist.githubusercontent.com/martin-g/37dacc12149d5cecbfd4e16dc2248cfd/raw/00596b7dc31d30d275384334ff17c5416f5b363c/tomcat-http2.log
- this file contains the first 7 seconds of the load run.
I have 3 times more information for the last 13 seconds but it is more or
less the same information.
There are many like this:
2020-09-21 14:25:04.850 DEBUG 232086 --- [https-jsse-nio-18080-exec-8]
o.a.coyote.http11.Http11NioProtocol : Found processor [null] for
socket [org.apache.tomcat.util.net.SecureNioChannel@2b435926:java.nio.channels.SocketChannel[connected
local=/127.0.0.1:18080 remote=/127.0.0.1:42229]]
2020-09-21 14:25:04.850 DEBUG 232086 --- [https-jsse-nio-18080-exec-6]
o.a.coyote.http2.Http2UpgradeHandler : Connection [2]
java.io.IOException: Unable to unwrap data, invalid status [CLOSED]
at org.apache.tomcat.util.net.SecureNioChannel.read(SecureNioChannel.java:766)
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
at org.apache.tomcat.util.net.SocketWrapperBase$OperationState.start(SocketWrapperBase.java:1039)
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:238)
at org.apache.coyote.http2.Http2AsyncUpgradeHandler.init(Http2AsyncUpgradeHandler.java:39)
at org.apache.coyote.http2.Http2UpgradeHandler.upgradeDispatch(Http2UpgradeHandler.java:313)
at org.apache.coyote.http2.Http2AsyncUpgradeHandler.upgradeDispatch(Http2AsyncUpgradeHandler.java:39)
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.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1590)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
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)
>
>
> This is with my patch in #reset(). Without it there are also errors that
> stream XYZ is already closed
>
>
>> - Client side logging (I don't know what the capabilities are here).
>> - JVM level TLS debug logging (even more verbose than Tomcat's HTTP/2
>> debug and harder to work with)
>> - Wireshark (or similar)
>>
>> I'd recommend Wireshark. I don't think JSSE supports SSLKEYLOGFILE so
>> I'd use the APR/Native connector with SSLKEYLOGFILE to get the cleartext
>> in Wireshark.
>>
>> > With this change and Vegeta's -max-workers=100 I can get 12 K reqs/sec.
>>
>> That is odd. If the client is sending RST_STREAM messages then I'd
>> expect to see requests failing as RST_STREAM indicates something has
>> gone wrong or the client has aborted the request.
>>
>
> According to https://tools.ietf.org/html/rfc7540#section-5.1 when the
> stream is in HALF_CLOSED_REMOTE state it should send either END_STREAM or
> RST_STREAM to the remote peer.
> In the logs I see such sequence of events:
>
> ...
> o.a.coyote.http2.StreamStateMachine : Connection [124], Stream
> [5,279], State changed from [OPEN] to [HALF_CLOSED_REMOTE]
> o.a.coyote.http2.Http2UpgradeHandler : Connection [124], Stream
> [5,279], Writing the headers
> org.apache.coyote.http2.Stream : Connection [124], Stream
> [5,279], flushing output with buffer at position [12], writeInProgress
> [false] and closed [true]
> org.apache.coyote.http2.AbstractStream : Connection [124], Stream
> [5,279], reduce flow control window by [12] to [4194292]
> o.a.coyote.http2.Http2UpgradeHandler : Connection [124], Stream
> [5,279], Data length [12]
> o.a.coyote.http2.StreamStateMachine : Connection [124], Stream
> [5,279], State changed from [HALF_CLOSED_REMOTE] to [CLOSED_TX]
> org.apache.coyote.http2.Stream : Connection [124], Stream
> [5,279] has been recycled
>
>
> From the logs it is not clear whether any of these flags is being sent to
> the client. I will investigate!
>
> Note: ", Writing the headers" is added by me. The current log entry is
> "upgradeHandler.writeHeaders=Connection [{0}], Stream [{1}]"
>
>
>>
>> > With more workers it starts failing with:
>> >
>> > "status_codes": {
>> > "0": 1000,
>> > "200": 1
>> > },
>> > "errors": [
>> > "Get \"https://localhost:18080/testbed/plaintext\": net/http:
>> request
>> > canceled while waiting for connection (Client.Timeout exceeded while
>> > awaiting headers)",
>> > "Get \"https://localhost:18080/testbed/plaintext\": context
>> deadline
>> > exceeded",
>> > "Get \"https://localhost:18080/testbed/plaintext\": context
>> deadline
>> > exceeded (Client.Timeout exceeded while awaiting headers)"
>> > ]
>> > i.e. out of 1001 requests only one succeeds and the others fail with
>> > timeout. I will try to debug this one too and run a profiler too.
>>
>> I'd probably start by enabling Tomcat's HTTP/2 debug logging for this
>> one. I'm wondering if something is triggering a connection level error
>> early in the processing.
>>
>> Mark
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
>> For additional commands, e-mail: users-help@tomcat.apache.org
>>
>>
Re: Low throughput with HTTP2
Posted by Martin Grigorov <mg...@apache.org>.
On Mon, Sep 21, 2020 at 11:23 AM Mark Thomas <ma...@apache.org> wrote:
> On 21/09/2020 08:18, Martin Grigorov wrote:
> > On Fri, Sep 18, 2020 at 6:16 PM Mark Thomas <ma...@apache.org> wrote:
> >
> >> On 18/09/2020 14:07, Martin Grigorov wrote:
> >>
> >> <snip/>
> >>
> >>> What is the difference
> >>> between org.apache.coyote.http2.StreamStateMachine.State#CLOSED_RX
> >>> and org.apache.coyote.http2.StreamStateMachine.State#CLOSED_TX ?
> >>
> >> Compare the parameters used to construct the enums.
> >>
> >>> I read some parts of https://tools.ietf.org/html/rfc7540 but I don't
> see
> >>> anything related to two types of CLOSED state.
> >>
> >> Section 5.1. Definition of the closed state (page 20) explains the
> >> difference between the two.
> >>
> >
> > Still I do not understand what RX and TX stand for. But this is not
> > important.
>
> TX - transmit
>
> RX - receive
>
Thanks!
>
>
> > The following patch fixes the issue for me/Vegeta:
> >
> > @@ -1570,12 +1571,15 @@ class Http2UpgradeHandler extends AbstractStream
> > implements InternalHttpUpgradeH
> >
> > @Override
> > public void reset(int streamId, long errorCode) throws
> Http2Exception
> > {
> > - Stream stream = getStream(streamId, true);
> > - boolean active = stream.isActive();
> > - stream.checkState(FrameType.RST);
> > - stream.receiveReset(errorCode);
> > - if (active) {
> > - activeRemoteStreamCount.decrementAndGet();
> > + boolean unknownIsError = Http2Error.CANCEL.getCode() !=
> errorCode;
> > + Stream stream = getStream(streamId, unknownIsError);
> > + if (stream != null) {
> > + boolean active = stream.isActive();
> > + stream.checkState(FrameType.RST);
> > + stream.receiveReset(errorCode);
> > + if (active) {
> > + activeRemoteStreamCount.decrementAndGet();
> > + }
> > }
> > }
> >
> > I.e. do not throw an error if the remote peer is trying to cancel an
> > already closed stream.
>
> RFC 7540 allows the connection to be closed with a protocol error if the
> reset is received "a significant time after sending END_STREAM".
>
> Tomcat retains state for maxConcurrentStreams + 10% with closed streams
> being pruned (oldest first) every 10 new streams.
>
The spec talks about time but Tomcat uses the number of streams.
I understand that under normal usage this could be enough "time" but under
heavy load this number is reached quickly and the time is short.
I've tried with these values for
maxConcurrentStreams/maxConcurrentStreamExecution: 8 (number of CPU cores),
16, 100 (the default), 1024 and 8196. The throughput is around 10K only
until 100. After that it drops (as you said earlier).
>
> It isn't clear at this point why the client is sending the RST_STREAM.
>
I don't know either. But Vegeta is using the Golang standard libraries, so
any Golang application should behave the same way.
Also as I investigated last week - Golang/Node.js/Rust/Netty HTTP2 servers
do not complain about it.
> This normally indicates an error condition. From the description of the
> load test I don't see why the client would be sending a RST_STREAM.
>
> If the RST_STREAM is valid and it isn't received a significant time
> after the END_STREAM then Tomcat needs to handle this.
>
> If the RST_STREAM is valid but received a significant amount of time
> after the END_STREAM that would be a client error would be a client error.
>
> Of course, significant isn't defined in the specification.
>
> Any special handling for RST_STREAM also needs to be applied to
> WINDOW_UPDATE. It also needs to differentiate between a frame received
> for a past closed stream and a frame received for an stream that never
> existed.
>
> I think the key question here is why is the client sending the
> RST_STREAM in the first place. Is Tomcat doing something it shouldn't /
> not doing something it should to cause this? If so, we need to fix the
> root cause rather than tackle the symptom.
>
> There are a couple of options for debugging this to see why the client
> is sending the RST_STREAM:
> - Enable debug logging for HTTP/2 in Tomcat. This is very verbose and
> if the root cause is threading related typically changes the timing
> enough to mask the issue.
>
Here are the logs of 20 seconds load:
https://gist.githubusercontent.com/martin-g/37dacc12149d5cecbfd4e16dc2248cfd/raw/76693cd1dd1f37ba126edb84ebd7631802aa91a6/tomcat-http2.log
This is with my patch in #reset(). Without it there are also errors that
stream XYZ is already closed
> - Client side logging (I don't know what the capabilities are here).
> - JVM level TLS debug logging (even more verbose than Tomcat's HTTP/2
> debug and harder to work with)
> - Wireshark (or similar)
>
> I'd recommend Wireshark. I don't think JSSE supports SSLKEYLOGFILE so
> I'd use the APR/Native connector with SSLKEYLOGFILE to get the cleartext
> in Wireshark.
>
> > With this change and Vegeta's -max-workers=100 I can get 12 K reqs/sec.
>
> That is odd. If the client is sending RST_STREAM messages then I'd
> expect to see requests failing as RST_STREAM indicates something has
> gone wrong or the client has aborted the request.
>
According to https://tools.ietf.org/html/rfc7540#section-5.1 when the
stream is in HALF_CLOSED_REMOTE state it should send either END_STREAM or
RST_STREAM to the remote peer.
In the logs I see such sequence of events:
...
o.a.coyote.http2.StreamStateMachine : Connection [124], Stream
[5,279], State changed from [OPEN] to [HALF_CLOSED_REMOTE]
o.a.coyote.http2.Http2UpgradeHandler : Connection [124], Stream
[5,279], Writing the headers
org.apache.coyote.http2.Stream : Connection [124], Stream
[5,279], flushing output with buffer at position [12], writeInProgress
[false] and closed [true]
org.apache.coyote.http2.AbstractStream : Connection [124], Stream
[5,279], reduce flow control window by [12] to [4194292]
o.a.coyote.http2.Http2UpgradeHandler : Connection [124], Stream
[5,279], Data length [12]
o.a.coyote.http2.StreamStateMachine : Connection [124], Stream
[5,279], State changed from [HALF_CLOSED_REMOTE] to [CLOSED_TX]
org.apache.coyote.http2.Stream : Connection [124], Stream [5,279]
has been recycled
From the logs it is not clear whether any of these flags is being sent to
the client. I will investigate!
Note: ", Writing the headers" is added by me. The current log entry is
"upgradeHandler.writeHeaders=Connection [{0}], Stream [{1}]"
>
> > With more workers it starts failing with:
> >
> > "status_codes": {
> > "0": 1000,
> > "200": 1
> > },
> > "errors": [
> > "Get \"https://localhost:18080/testbed/plaintext\": net/http:
> request
> > canceled while waiting for connection (Client.Timeout exceeded while
> > awaiting headers)",
> > "Get \"https://localhost:18080/testbed/plaintext\": context deadline
> > exceeded",
> > "Get \"https://localhost:18080/testbed/plaintext\": context deadline
> > exceeded (Client.Timeout exceeded while awaiting headers)"
> > ]
> > i.e. out of 1001 requests only one succeeds and the others fail with
> > timeout. I will try to debug this one too and run a profiler too.
>
> I'd probably start by enabling Tomcat's HTTP/2 debug logging for this
> one. I'm wondering if something is triggering a connection level error
> early in the processing.
>
> Mark
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
Re: Low throughput with HTTP2
Posted by Mark Thomas <ma...@apache.org>.
On 21/09/2020 08:18, Martin Grigorov wrote:
> On Fri, Sep 18, 2020 at 6:16 PM Mark Thomas <ma...@apache.org> wrote:
>
>> On 18/09/2020 14:07, Martin Grigorov wrote:
>>
>> <snip/>
>>
>>> What is the difference
>>> between org.apache.coyote.http2.StreamStateMachine.State#CLOSED_RX
>>> and org.apache.coyote.http2.StreamStateMachine.State#CLOSED_TX ?
>>
>> Compare the parameters used to construct the enums.
>>
>>> I read some parts of https://tools.ietf.org/html/rfc7540 but I don't see
>>> anything related to two types of CLOSED state.
>>
>> Section 5.1. Definition of the closed state (page 20) explains the
>> difference between the two.
>>
>
> Still I do not understand what RX and TX stand for. But this is not
> important.
TX - transmit
RX - receive
> The following patch fixes the issue for me/Vegeta:
>
> @@ -1570,12 +1571,15 @@ class Http2UpgradeHandler extends AbstractStream
> implements InternalHttpUpgradeH
>
> @Override
> public void reset(int streamId, long errorCode) throws Http2Exception
> {
> - Stream stream = getStream(streamId, true);
> - boolean active = stream.isActive();
> - stream.checkState(FrameType.RST);
> - stream.receiveReset(errorCode);
> - if (active) {
> - activeRemoteStreamCount.decrementAndGet();
> + boolean unknownIsError = Http2Error.CANCEL.getCode() != errorCode;
> + Stream stream = getStream(streamId, unknownIsError);
> + if (stream != null) {
> + boolean active = stream.isActive();
> + stream.checkState(FrameType.RST);
> + stream.receiveReset(errorCode);
> + if (active) {
> + activeRemoteStreamCount.decrementAndGet();
> + }
> }
> }
>
> I.e. do not throw an error if the remote peer is trying to cancel an
> already closed stream.
RFC 7540 allows the connection to be closed with a protocol error if the
reset is received "a significant time after sending END_STREAM".
Tomcat retains state for maxConcurrentStreams + 10% with closed streams
being pruned (oldest first) every 10 new streams.
It isn't clear at this point why the client is sending the RST_STREAM.
This normally indicates an error condition. From the description of the
load test I don't see why the client would be sending a RST_STREAM.
If the RST_STREAM is valid and it isn't received a significant time
after the END_STREAM then Tomcat needs to handle this.
If the RST_STREAM is valid but received a significant amount of time
after the END_STREAM that would be a client error would be a client error.
Of course, significant isn't defined in the specification.
Any special handling for RST_STREAM also needs to be applied to
WINDOW_UPDATE. It also needs to differentiate between a frame received
for a past closed stream and a frame received for an stream that never
existed.
I think the key question here is why is the client sending the
RST_STREAM in the first place. Is Tomcat doing something it shouldn't /
not doing something it should to cause this? If so, we need to fix the
root cause rather than tackle the symptom.
There are a couple of options for debugging this to see why the client
is sending the RST_STREAM:
- Enable debug logging for HTTP/2 in Tomcat. This is very verbose and
if the root cause is threading related typically changes the timing
enough to mask the issue.
- Client side logging (I don't know what the capabilities are here).
- JVM level TLS debug logging (even more verbose than Tomcat's HTTP/2
debug and harder to work with)
- Wireshark (or similar)
I'd recommend Wireshark. I don't think JSSE supports SSLKEYLOGFILE so
I'd use the APR/Native connector with SSLKEYLOGFILE to get the cleartext
in Wireshark.
> With this change and Vegeta's -max-workers=100 I can get 12 K reqs/sec.
That is odd. If the client is sending RST_STREAM messages then I'd
expect to see requests failing as RST_STREAM indicates something has
gone wrong or the client has aborted the request.
> With more workers it starts failing with:
>
> "status_codes": {
> "0": 1000,
> "200": 1
> },
> "errors": [
> "Get \"https://localhost:18080/testbed/plaintext\": net/http: request
> canceled while waiting for connection (Client.Timeout exceeded while
> awaiting headers)",
> "Get \"https://localhost:18080/testbed/plaintext\": context deadline
> exceeded",
> "Get \"https://localhost:18080/testbed/plaintext\": context deadline
> exceeded (Client.Timeout exceeded while awaiting headers)"
> ]
> i.e. out of 1001 requests only one succeeds and the others fail with
> timeout. I will try to debug this one too and run a profiler too.
I'd probably start by enabling Tomcat's HTTP/2 debug logging for this
one. I'm wondering if something is triggering a connection level error
early in the processing.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Low throughput with HTTP2
Posted by Martin Grigorov <mg...@apache.org>.
On Fri, Sep 18, 2020 at 6:16 PM Mark Thomas <ma...@apache.org> wrote:
> On 18/09/2020 14:07, Martin Grigorov wrote:
>
> <snip/>
>
> > What is the difference
> > between org.apache.coyote.http2.StreamStateMachine.State#CLOSED_RX
> > and org.apache.coyote.http2.StreamStateMachine.State#CLOSED_TX ?
>
> Compare the parameters used to construct the enums.
>
> > I read some parts of https://tools.ietf.org/html/rfc7540 but I don't see
> > anything related to two types of CLOSED state.
>
> Section 5.1. Definition of the closed state (page 20) explains the
> difference between the two.
>
Still I do not understand what RX and TX stand for. But this is not
important.
The following patch fixes the issue for me/Vegeta:
@@ -1570,12 +1571,15 @@ class Http2UpgradeHandler extends AbstractStream
implements InternalHttpUpgradeH
@Override
public void reset(int streamId, long errorCode) throws Http2Exception
{
- Stream stream = getStream(streamId, true);
- boolean active = stream.isActive();
- stream.checkState(FrameType.RST);
- stream.receiveReset(errorCode);
- if (active) {
- activeRemoteStreamCount.decrementAndGet();
+ boolean unknownIsError = Http2Error.CANCEL.getCode() != errorCode;
+ Stream stream = getStream(streamId, unknownIsError);
+ if (stream != null) {
+ boolean active = stream.isActive();
+ stream.checkState(FrameType.RST);
+ stream.receiveReset(errorCode);
+ if (active) {
+ activeRemoteStreamCount.decrementAndGet();
+ }
}
}
I.e. do not throw an error if the remote peer is trying to cancel an
already closed stream.
With this change and Vegeta's -max-workers=100 I can get 12 K reqs/sec.
With more workers it starts failing with:
"status_codes": {
"0": 1000,
"200": 1
},
"errors": [
"Get \"https://localhost:18080/testbed/plaintext\": net/http: request
canceled while waiting for connection (Client.Timeout exceeded while
awaiting headers)",
"Get \"https://localhost:18080/testbed/plaintext\": context deadline
exceeded",
"Get \"https://localhost:18080/testbed/plaintext\": context deadline
exceeded (Client.Timeout exceeded while awaiting headers)"
]
i.e. out of 1001 requests only one succeeds and the others fail with
timeout. I will try to debug this one too and run a profiler too.
>
> Mark
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
Re: Low throughput with HTTP2
Posted by Mark Thomas <ma...@apache.org>.
On 18/09/2020 14:07, Martin Grigorov wrote:
<snip/>
> What is the difference
> between org.apache.coyote.http2.StreamStateMachine.State#CLOSED_RX
> and org.apache.coyote.http2.StreamStateMachine.State#CLOSED_TX ?
Compare the parameters used to construct the enums.
> I read some parts of https://tools.ietf.org/html/rfc7540 but I don't see
> anything related to two types of CLOSED state.
Section 5.1. Definition of the closed state (page 20) explains the
difference between the two.
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Low throughput with HTTP2
Posted by Martin Grigorov <mg...@apache.org>.
On Fri, Sep 18, 2020 at 10:48 AM Martin Grigorov <mg...@apache.org>
wrote:
> Hi,
>
> On Wed, Sep 16, 2020 at 10:24 AM Martin Grigorov <mg...@apache.org>
> wrote:
>
>> Hi Remy,
>>
>> On Tue, Sep 15, 2020 at 6:16 PM Rémy Maucherat <re...@apache.org> wrote:
>>
>>> On Tue, Sep 15, 2020 at 5:08 PM Martin Grigorov <mg...@apache.org>
>>> wrote:
>>>
>>> > Hi Mark,
>>> >
>>> > On Tue, Sep 15, 2020 at 3:34 PM Mark Thomas <ma...@apache.org> wrote:
>>> >
>>> > > On 15/09/2020 12:46, Martin Grigorov wrote:
>>> > > > On Tue, Sep 15, 2020 at 2:37 PM Martin Grigorov <
>>> mgrigorov@apache.org>
>>> > > > wrote:
>>> > > >
>>> > > >> Hi,
>>> > > >>
>>> > > >> I am running some load tests on Tomcat and I've noticed that when
>>> > HTTP2
>>> > > is
>>> > > >> enabled the throughput drops considerably.
>>> > > >>
>>> > > >> Here are the steps to reproduce:
>>> > > >>
>>> > > >> 1) Enable HTTP2, e.g. by commenting out this connector:
>>> > > >>
>>> > > >>
>>> > >
>>> >
>>> https://github.com/apache/tomcat/blob/d381d87005fa89d1f19d9091c0954f317c135d9d/conf/server.xml#L103-L112
>>> > > >>
>>> > > >> 2) Download Vegeta load tool from:
>>> > > >> https://github.com/tsenart/vegeta/releases/
>>> > > >>
>>> > > >> 3) Run the load tests:
>>> > > >>
>>> > > >> 3.1) HTTP/1.1
>>> > > >> echo -e '{"method": "GET", "url": "
>>> http://localhost:8080/examples/"}'
>>> > |
>>> > > >> vegeta attack -format=json -rate=0 -max-workers=1000
>>> -duration=10s |
>>> > > >> vegeta encode > /tmp/http1.json; and vegeta report -type=json
>>> > > >> /tmp/http1.json | jq .
>>> > > >>
>>> > > >> 3.2) HTTP2
>>> > > >> echo -e '{"method": "GET", "url": "
>>> https://localhost:8443/examples/
>>> > "}'
>>> > > |
>>> > > >> vegeta attack -format=json -http2 -rate=0 -max-workers=1000
>>> -insecure
>>> > > >> -duration=10s | vegeta encode > /tmp/http2.json; and vegeta report
>>> > > >> -type=json /tmp/http2.json | jq .
>>> > > >>
>>> > > >> As explained at https://github.com/tsenart/vegeta#-rate -rate=0
>>> means
>>> > > >> that Vegeta will try to send as many requests as possible with the
>>> > > >> configured number of workers.
>>> > > >> I use '-insecure' because I use self-signed certificate.
>>> > > >>
>>> > > >> On my machine I get around 14-15K reqs/sec for HTTP1.1 with only
>>> > > responses
>>> > > >> with code=200 .
>>> > > >> But for HTTP2 Tomcat starts returning such kind of errors:
>>> > > >>
>>> > > >> "errors": [
>>> > > >> "Get \"https://localhost:8443/examples/\": http2: server sent
>>> > > GOAWAY
>>> > > >> and closed the connection; LastStreamID=9259,
>>> ErrCode=PROTOCOL_ERROR,
>>> > > >> debug=\"Stream [9,151] has been closed for some time\"",
>>> > > >> "http2: server sent GOAWAY and closed the connection;
>>> > > >> LastStreamID=9259, ErrCode=PROTOCOL_ERROR, debug=\"Stream [9,151]
>>> has
>>> > > been
>>> > > >> closed for some time\"",
>>> > > >> "Get \"https://localhost:8443/examples/\": http2: server sent
>>> > > GOAWAY
>>> > > >> and closed the connection; LastStreamID=239,
>>> ErrCode=PROTOCOL_ERROR,
>>> > > >> debug=\"Stream [49] has been closed for some time\""
>>> > > >> ]
>>> > > >>
>>> > > >> when I ask for more than 2000 reqs/sec, i.e. -rate=2000/1s
>>> > >
>>> > > That indicates that the client has sent a frame associated with a
>>> stream
>>> > > that the server closed previously and that that stream has been
>>> removed
>>> > > from the Map of known streams to make room for new ones. See
>>> > > Http2UpgardeHandler.pruneClosedStreams()
>>> > >
>>> > > It looks like the client is making assumptions about server behaviour
>>> > > that go beyond the requirements of RFC 7540, section 5.3.4.
>>> > >
>>> >
>>> > This is possible!
>>> > I've just tested with two more HTTP2 impls:
>>> >
>>> > 1) Node.js
>>> >
>>> > http2-server.js
>>> > ===================================================
>>> > const http2 = require('http2');
>>> > const fs = require('fs');
>>> >
>>> > const server = http2.createSecureServer({
>>> > key: fs.readFileSync('/path/to/server.key'),
>>> > cert: fs.readFileSync('/path/to/server.crt')
>>> > });
>>> > server.on('error', (err) => console.error(err));
>>> >
>>> > server.on('stream', (stream, headers) => {
>>> > // stream is a Duplex
>>> > stream.respond({
>>> > 'content-type': 'text/plain; charset=utf-8',
>>> > ':status': 200
>>> > });
>>> > stream.end('Hello world!');
>>> > });
>>> >
>>> > server.listen(18080);
>>> > ===================================================
>>> >
>>> > run with: node http2-server.js
>>> >
>>> > Runs fine with -rate=0 and gives around 8K reqs/sec
>>> >
>>> > 2) Rust
>>> >
>>> > Cargo.toml
>>> > ===================================================
>>> > [package]
>>> > name = "my-http2-server"
>>> > version = "0.0.1"
>>> > publish = false
>>> > authors = ["Martin Grigorov <mg...@apache.org>"]
>>> > license = "MIT/Apache-2.0"
>>> > description = "Load test HTTP/2 "
>>> > repository = "https://github.com/martin-g/http2-server-rust"
>>> > keywords = ["http2"]
>>> > edition = "2018"
>>> >
>>> > [dependencies]
>>> > actix-web = { version = "3", features = ["openssl"] }
>>> > openssl = { version = "0.10", features = ["v110"] }
>>> > ===================================================
>>> >
>>> > src/main.rs
>>> > ===================================================
>>> > use actix_web::{web, App, HttpRequest, HttpServer, Responder};
>>> > use openssl::ssl::{SslAcceptor, SslFiletype, SslMethod};
>>> >
>>> > async fn index(_req: HttpRequest) -> impl Responder {
>>> > "Hello world!"
>>> > }
>>> >
>>> > #[actix_web::main]
>>> > async fn main() -> std::io::Result<()> {
>>> > let mut builder =
>>> > SslAcceptor::mozilla_intermediate(SslMethod::tls()).unwrap();
>>> > builder
>>> > .set_private_key_file("/path/to/server.key", SslFiletype::PEM)
>>> > .unwrap();
>>> > builder.set_certificate_chain_file("/path/to/server.crt").unwrap();
>>> >
>>> > HttpServer::new(|| App::new().route("/", web::get().to(index)))
>>> > .bind_openssl("127.0.0.1:18080", builder)?
>>> > .run()
>>> > .await
>>> > }
>>> > ===================================================
>>> >
>>> > run with: cargo run
>>> > Again no errors, throughput: 3K reqs/sec
>>> >
>>> > I will test with Netty tomorrow too, but so far it looks like only
>>> Tomcat
>>> > fails under load.
>>> >
>>> >
>>> >
>>> > > >> All the access logs look like:
>>> > > >>
>>> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/
>>> HTTP/2.0"
>>> > 200
>>> > > >> 1126
>>> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/
>>> HTTP/2.0"
>>> > 200
>>> > > >> 1126
>>> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/
>>> HTTP/2.0"
>>> > 200
>>> > > >> 1126
>>> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/
>>> HTTP/2.0"
>>> > 200
>>> > > >> 1126
>>> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/
>>> HTTP/2.0"
>>> > 200
>>> > > >> 1126
>>> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/
>>> HTTP/2.0"
>>> > 200
>>> > > >> 1126
>>> > > >>
>>> > > >> i.e. there are no error codes, just 200.
>>> > > >> Vegeta reports the error with status code = 0. I think this just
>>> means
>>> > > >> that it didn't get a proper HTTP response but just TCP error.
>>> > > >> There are no errors in catalina.out.
>>> > > >>
>>> > > >> Are there any settings I can tune to get better throughput with
>>> HTTP2
>>> > ?
>>> > > >>
>>> > > >> Tomcat 10.0.0-M8.
>>> > >
>>> > > If you really want to maximise throughput then you need to reduce the
>>> > > number of concurrent requests to (or a little above) the number of
>>> cores
>>> > > available on the server. Go higher and you'll start to see throughput
>>> > > tail off due to context switching.
>>> > >
>>> > > If you want to demonstrate throughput with a large number of clients
>>> > > you'll probably need to experiment with both maxThreads,
>>> > >
>>> >
>>> > I've forgot to say that I use maxThreads=8.
>>> >
>>> >
>>> > > maxConcurrentStreams and maxConcurrentStreamExecution.
>>> > >
>>> > > If I had to guess, I'd expect maxConcurrentStreams ==
>>> > > maxConcurrentStreamExecution and low numbers for all of them to give
>>> the
>>> > > best results.
>>>
>>
> These didn't help
>
> I've created a GitHub repo with all HTTP2 server I've tested with so far:
> https://github.com/martin-g/http2-server-perf-tests
> Throughput with default settings:
> - Netty: 29K reqs/s
> - Golang: 19K
> - Node.js: 17K
> - Rust: 3K
> - Tomcat: 400, with many errors
>
> So far only Tomcat returns errors :-/
>
> I'll keep digging!
>
What is the difference
between org.apache.coyote.http2.StreamStateMachine.State#CLOSED_RX
and org.apache.coyote.http2.StreamStateMachine.State#CLOSED_TX ?
I read some parts of https://tools.ietf.org/html/rfc7540 but I don't see
anything related to two types of CLOSED state.
> Martin
>
>
>
>> > >
>>> >
>>> > I will check those tomorrow!
>>> >
>>>
>>> I use h2load, and IMO I have very good performance with h2c. No errors.
>>> However, same as your tool, it's concurrency flag only controls how many
>>> streams it will use *inside a single connection* [I respect that, but I
>>>
>>
>> I think this is not the case here.
>> As far as I can see Vegeta does not use custom ClientConnPool and the
>> default pool in net::http2 shares many connections per host:port key:
>> https://github.com/golang/net/blob/62affa334b73ec65ed44a326519ac12c421905e3/http2/client_conn_pool.go
>>
>>
>>
>>> would have expected instead the tool would also use multiple connections
>>> in
>>> an attempt to simulate multiple users, but nope]. This can only go so far
>>> and the performance numbers caused me to add the flags to limit stream
>>> concurrency.
>>>
>>> Rémy
>>>
>>
Re: Low throughput with HTTP2
Posted by Martin Grigorov <mg...@apache.org>.
Hi,
On Wed, Sep 16, 2020 at 10:24 AM Martin Grigorov <mg...@apache.org>
wrote:
> Hi Remy,
>
> On Tue, Sep 15, 2020 at 6:16 PM Rémy Maucherat <re...@apache.org> wrote:
>
>> On Tue, Sep 15, 2020 at 5:08 PM Martin Grigorov <mg...@apache.org>
>> wrote:
>>
>> > Hi Mark,
>> >
>> > On Tue, Sep 15, 2020 at 3:34 PM Mark Thomas <ma...@apache.org> wrote:
>> >
>> > > On 15/09/2020 12:46, Martin Grigorov wrote:
>> > > > On Tue, Sep 15, 2020 at 2:37 PM Martin Grigorov <
>> mgrigorov@apache.org>
>> > > > wrote:
>> > > >
>> > > >> Hi,
>> > > >>
>> > > >> I am running some load tests on Tomcat and I've noticed that when
>> > HTTP2
>> > > is
>> > > >> enabled the throughput drops considerably.
>> > > >>
>> > > >> Here are the steps to reproduce:
>> > > >>
>> > > >> 1) Enable HTTP2, e.g. by commenting out this connector:
>> > > >>
>> > > >>
>> > >
>> >
>> https://github.com/apache/tomcat/blob/d381d87005fa89d1f19d9091c0954f317c135d9d/conf/server.xml#L103-L112
>> > > >>
>> > > >> 2) Download Vegeta load tool from:
>> > > >> https://github.com/tsenart/vegeta/releases/
>> > > >>
>> > > >> 3) Run the load tests:
>> > > >>
>> > > >> 3.1) HTTP/1.1
>> > > >> echo -e '{"method": "GET", "url": "http://localhost:8080/examples/
>> "}'
>> > |
>> > > >> vegeta attack -format=json -rate=0 -max-workers=1000
>> -duration=10s |
>> > > >> vegeta encode > /tmp/http1.json; and vegeta report -type=json
>> > > >> /tmp/http1.json | jq .
>> > > >>
>> > > >> 3.2) HTTP2
>> > > >> echo -e '{"method": "GET", "url": "
>> https://localhost:8443/examples/
>> > "}'
>> > > |
>> > > >> vegeta attack -format=json -http2 -rate=0 -max-workers=1000
>> -insecure
>> > > >> -duration=10s | vegeta encode > /tmp/http2.json; and vegeta report
>> > > >> -type=json /tmp/http2.json | jq .
>> > > >>
>> > > >> As explained at https://github.com/tsenart/vegeta#-rate -rate=0
>> means
>> > > >> that Vegeta will try to send as many requests as possible with the
>> > > >> configured number of workers.
>> > > >> I use '-insecure' because I use self-signed certificate.
>> > > >>
>> > > >> On my machine I get around 14-15K reqs/sec for HTTP1.1 with only
>> > > responses
>> > > >> with code=200 .
>> > > >> But for HTTP2 Tomcat starts returning such kind of errors:
>> > > >>
>> > > >> "errors": [
>> > > >> "Get \"https://localhost:8443/examples/\": http2: server sent
>> > > GOAWAY
>> > > >> and closed the connection; LastStreamID=9259,
>> ErrCode=PROTOCOL_ERROR,
>> > > >> debug=\"Stream [9,151] has been closed for some time\"",
>> > > >> "http2: server sent GOAWAY and closed the connection;
>> > > >> LastStreamID=9259, ErrCode=PROTOCOL_ERROR, debug=\"Stream [9,151]
>> has
>> > > been
>> > > >> closed for some time\"",
>> > > >> "Get \"https://localhost:8443/examples/\": http2: server sent
>> > > GOAWAY
>> > > >> and closed the connection; LastStreamID=239,
>> ErrCode=PROTOCOL_ERROR,
>> > > >> debug=\"Stream [49] has been closed for some time\""
>> > > >> ]
>> > > >>
>> > > >> when I ask for more than 2000 reqs/sec, i.e. -rate=2000/1s
>> > >
>> > > That indicates that the client has sent a frame associated with a
>> stream
>> > > that the server closed previously and that that stream has been
>> removed
>> > > from the Map of known streams to make room for new ones. See
>> > > Http2UpgardeHandler.pruneClosedStreams()
>> > >
>> > > It looks like the client is making assumptions about server behaviour
>> > > that go beyond the requirements of RFC 7540, section 5.3.4.
>> > >
>> >
>> > This is possible!
>> > I've just tested with two more HTTP2 impls:
>> >
>> > 1) Node.js
>> >
>> > http2-server.js
>> > ===================================================
>> > const http2 = require('http2');
>> > const fs = require('fs');
>> >
>> > const server = http2.createSecureServer({
>> > key: fs.readFileSync('/path/to/server.key'),
>> > cert: fs.readFileSync('/path/to/server.crt')
>> > });
>> > server.on('error', (err) => console.error(err));
>> >
>> > server.on('stream', (stream, headers) => {
>> > // stream is a Duplex
>> > stream.respond({
>> > 'content-type': 'text/plain; charset=utf-8',
>> > ':status': 200
>> > });
>> > stream.end('Hello world!');
>> > });
>> >
>> > server.listen(18080);
>> > ===================================================
>> >
>> > run with: node http2-server.js
>> >
>> > Runs fine with -rate=0 and gives around 8K reqs/sec
>> >
>> > 2) Rust
>> >
>> > Cargo.toml
>> > ===================================================
>> > [package]
>> > name = "my-http2-server"
>> > version = "0.0.1"
>> > publish = false
>> > authors = ["Martin Grigorov <mg...@apache.org>"]
>> > license = "MIT/Apache-2.0"
>> > description = "Load test HTTP/2 "
>> > repository = "https://github.com/martin-g/http2-server-rust"
>> > keywords = ["http2"]
>> > edition = "2018"
>> >
>> > [dependencies]
>> > actix-web = { version = "3", features = ["openssl"] }
>> > openssl = { version = "0.10", features = ["v110"] }
>> > ===================================================
>> >
>> > src/main.rs
>> > ===================================================
>> > use actix_web::{web, App, HttpRequest, HttpServer, Responder};
>> > use openssl::ssl::{SslAcceptor, SslFiletype, SslMethod};
>> >
>> > async fn index(_req: HttpRequest) -> impl Responder {
>> > "Hello world!"
>> > }
>> >
>> > #[actix_web::main]
>> > async fn main() -> std::io::Result<()> {
>> > let mut builder =
>> > SslAcceptor::mozilla_intermediate(SslMethod::tls()).unwrap();
>> > builder
>> > .set_private_key_file("/path/to/server.key", SslFiletype::PEM)
>> > .unwrap();
>> > builder.set_certificate_chain_file("/path/to/server.crt").unwrap();
>> >
>> > HttpServer::new(|| App::new().route("/", web::get().to(index)))
>> > .bind_openssl("127.0.0.1:18080", builder)?
>> > .run()
>> > .await
>> > }
>> > ===================================================
>> >
>> > run with: cargo run
>> > Again no errors, throughput: 3K reqs/sec
>> >
>> > I will test with Netty tomorrow too, but so far it looks like only
>> Tomcat
>> > fails under load.
>> >
>> >
>> >
>> > > >> All the access logs look like:
>> > > >>
>> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/
>> HTTP/2.0"
>> > 200
>> > > >> 1126
>> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/
>> HTTP/2.0"
>> > 200
>> > > >> 1126
>> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/
>> HTTP/2.0"
>> > 200
>> > > >> 1126
>> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/
>> HTTP/2.0"
>> > 200
>> > > >> 1126
>> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/
>> HTTP/2.0"
>> > 200
>> > > >> 1126
>> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/
>> HTTP/2.0"
>> > 200
>> > > >> 1126
>> > > >>
>> > > >> i.e. there are no error codes, just 200.
>> > > >> Vegeta reports the error with status code = 0. I think this just
>> means
>> > > >> that it didn't get a proper HTTP response but just TCP error.
>> > > >> There are no errors in catalina.out.
>> > > >>
>> > > >> Are there any settings I can tune to get better throughput with
>> HTTP2
>> > ?
>> > > >>
>> > > >> Tomcat 10.0.0-M8.
>> > >
>> > > If you really want to maximise throughput then you need to reduce the
>> > > number of concurrent requests to (or a little above) the number of
>> cores
>> > > available on the server. Go higher and you'll start to see throughput
>> > > tail off due to context switching.
>> > >
>> > > If you want to demonstrate throughput with a large number of clients
>> > > you'll probably need to experiment with both maxThreads,
>> > >
>> >
>> > I've forgot to say that I use maxThreads=8.
>> >
>> >
>> > > maxConcurrentStreams and maxConcurrentStreamExecution.
>> > >
>> > > If I had to guess, I'd expect maxConcurrentStreams ==
>> > > maxConcurrentStreamExecution and low numbers for all of them to give
>> the
>> > > best results.
>>
>
These didn't help
I've created a GitHub repo with all HTTP2 server I've tested with so far:
https://github.com/martin-g/http2-server-perf-tests
Throughput with default settings:
- Netty: 29K reqs/s
- Golang: 19K
- Node.js: 17K
- Rust: 3K
- Tomcat: 400, with many errors
So far only Tomcat returns errors :-/
I'll keep digging!
Martin
> > >
>> >
>> > I will check those tomorrow!
>> >
>>
>> I use h2load, and IMO I have very good performance with h2c. No errors.
>> However, same as your tool, it's concurrency flag only controls how many
>> streams it will use *inside a single connection* [I respect that, but I
>>
>
> I think this is not the case here.
> As far as I can see Vegeta does not use custom ClientConnPool and the
> default pool in net::http2 shares many connections per host:port key:
> https://github.com/golang/net/blob/62affa334b73ec65ed44a326519ac12c421905e3/http2/client_conn_pool.go
>
>
>
>> would have expected instead the tool would also use multiple connections
>> in
>> an attempt to simulate multiple users, but nope]. This can only go so far
>> and the performance numbers caused me to add the flags to limit stream
>> concurrency.
>>
>> Rémy
>>
>
Re: Low throughput with HTTP2
Posted by Martin Grigorov <mg...@apache.org>.
Hi Remy,
On Tue, Sep 15, 2020 at 6:16 PM Rémy Maucherat <re...@apache.org> wrote:
> On Tue, Sep 15, 2020 at 5:08 PM Martin Grigorov <mg...@apache.org>
> wrote:
>
> > Hi Mark,
> >
> > On Tue, Sep 15, 2020 at 3:34 PM Mark Thomas <ma...@apache.org> wrote:
> >
> > > On 15/09/2020 12:46, Martin Grigorov wrote:
> > > > On Tue, Sep 15, 2020 at 2:37 PM Martin Grigorov <
> mgrigorov@apache.org>
> > > > wrote:
> > > >
> > > >> Hi,
> > > >>
> > > >> I am running some load tests on Tomcat and I've noticed that when
> > HTTP2
> > > is
> > > >> enabled the throughput drops considerably.
> > > >>
> > > >> Here are the steps to reproduce:
> > > >>
> > > >> 1) Enable HTTP2, e.g. by commenting out this connector:
> > > >>
> > > >>
> > >
> >
> https://github.com/apache/tomcat/blob/d381d87005fa89d1f19d9091c0954f317c135d9d/conf/server.xml#L103-L112
> > > >>
> > > >> 2) Download Vegeta load tool from:
> > > >> https://github.com/tsenart/vegeta/releases/
> > > >>
> > > >> 3) Run the load tests:
> > > >>
> > > >> 3.1) HTTP/1.1
> > > >> echo -e '{"method": "GET", "url": "http://localhost:8080/examples/
> "}'
> > |
> > > >> vegeta attack -format=json -rate=0 -max-workers=1000 -duration=10s
> |
> > > >> vegeta encode > /tmp/http1.json; and vegeta report -type=json
> > > >> /tmp/http1.json | jq .
> > > >>
> > > >> 3.2) HTTP2
> > > >> echo -e '{"method": "GET", "url": "https://localhost:8443/examples/
> > "}'
> > > |
> > > >> vegeta attack -format=json -http2 -rate=0 -max-workers=1000
> -insecure
> > > >> -duration=10s | vegeta encode > /tmp/http2.json; and vegeta report
> > > >> -type=json /tmp/http2.json | jq .
> > > >>
> > > >> As explained at https://github.com/tsenart/vegeta#-rate -rate=0
> means
> > > >> that Vegeta will try to send as many requests as possible with the
> > > >> configured number of workers.
> > > >> I use '-insecure' because I use self-signed certificate.
> > > >>
> > > >> On my machine I get around 14-15K reqs/sec for HTTP1.1 with only
> > > responses
> > > >> with code=200 .
> > > >> But for HTTP2 Tomcat starts returning such kind of errors:
> > > >>
> > > >> "errors": [
> > > >> "Get \"https://localhost:8443/examples/\": http2: server sent
> > > GOAWAY
> > > >> and closed the connection; LastStreamID=9259,
> ErrCode=PROTOCOL_ERROR,
> > > >> debug=\"Stream [9,151] has been closed for some time\"",
> > > >> "http2: server sent GOAWAY and closed the connection;
> > > >> LastStreamID=9259, ErrCode=PROTOCOL_ERROR, debug=\"Stream [9,151]
> has
> > > been
> > > >> closed for some time\"",
> > > >> "Get \"https://localhost:8443/examples/\": http2: server sent
> > > GOAWAY
> > > >> and closed the connection; LastStreamID=239, ErrCode=PROTOCOL_ERROR,
> > > >> debug=\"Stream [49] has been closed for some time\""
> > > >> ]
> > > >>
> > > >> when I ask for more than 2000 reqs/sec, i.e. -rate=2000/1s
> > >
> > > That indicates that the client has sent a frame associated with a
> stream
> > > that the server closed previously and that that stream has been removed
> > > from the Map of known streams to make room for new ones. See
> > > Http2UpgardeHandler.pruneClosedStreams()
> > >
> > > It looks like the client is making assumptions about server behaviour
> > > that go beyond the requirements of RFC 7540, section 5.3.4.
> > >
> >
> > This is possible!
> > I've just tested with two more HTTP2 impls:
> >
> > 1) Node.js
> >
> > http2-server.js
> > ===================================================
> > const http2 = require('http2');
> > const fs = require('fs');
> >
> > const server = http2.createSecureServer({
> > key: fs.readFileSync('/path/to/server.key'),
> > cert: fs.readFileSync('/path/to/server.crt')
> > });
> > server.on('error', (err) => console.error(err));
> >
> > server.on('stream', (stream, headers) => {
> > // stream is a Duplex
> > stream.respond({
> > 'content-type': 'text/plain; charset=utf-8',
> > ':status': 200
> > });
> > stream.end('Hello world!');
> > });
> >
> > server.listen(18080);
> > ===================================================
> >
> > run with: node http2-server.js
> >
> > Runs fine with -rate=0 and gives around 8K reqs/sec
> >
> > 2) Rust
> >
> > Cargo.toml
> > ===================================================
> > [package]
> > name = "my-http2-server"
> > version = "0.0.1"
> > publish = false
> > authors = ["Martin Grigorov <mg...@apache.org>"]
> > license = "MIT/Apache-2.0"
> > description = "Load test HTTP/2 "
> > repository = "https://github.com/martin-g/http2-server-rust"
> > keywords = ["http2"]
> > edition = "2018"
> >
> > [dependencies]
> > actix-web = { version = "3", features = ["openssl"] }
> > openssl = { version = "0.10", features = ["v110"] }
> > ===================================================
> >
> > src/main.rs
> > ===================================================
> > use actix_web::{web, App, HttpRequest, HttpServer, Responder};
> > use openssl::ssl::{SslAcceptor, SslFiletype, SslMethod};
> >
> > async fn index(_req: HttpRequest) -> impl Responder {
> > "Hello world!"
> > }
> >
> > #[actix_web::main]
> > async fn main() -> std::io::Result<()> {
> > let mut builder =
> > SslAcceptor::mozilla_intermediate(SslMethod::tls()).unwrap();
> > builder
> > .set_private_key_file("/path/to/server.key", SslFiletype::PEM)
> > .unwrap();
> > builder.set_certificate_chain_file("/path/to/server.crt").unwrap();
> >
> > HttpServer::new(|| App::new().route("/", web::get().to(index)))
> > .bind_openssl("127.0.0.1:18080", builder)?
> > .run()
> > .await
> > }
> > ===================================================
> >
> > run with: cargo run
> > Again no errors, throughput: 3K reqs/sec
> >
> > I will test with Netty tomorrow too, but so far it looks like only Tomcat
> > fails under load.
> >
> >
> >
> > > >> All the access logs look like:
> > > >>
> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0"
> > 200
> > > >> 1126
> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0"
> > 200
> > > >> 1126
> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0"
> > 200
> > > >> 1126
> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0"
> > 200
> > > >> 1126
> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0"
> > 200
> > > >> 1126
> > > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0"
> > 200
> > > >> 1126
> > > >>
> > > >> i.e. there are no error codes, just 200.
> > > >> Vegeta reports the error with status code = 0. I think this just
> means
> > > >> that it didn't get a proper HTTP response but just TCP error.
> > > >> There are no errors in catalina.out.
> > > >>
> > > >> Are there any settings I can tune to get better throughput with
> HTTP2
> > ?
> > > >>
> > > >> Tomcat 10.0.0-M8.
> > >
> > > If you really want to maximise throughput then you need to reduce the
> > > number of concurrent requests to (or a little above) the number of
> cores
> > > available on the server. Go higher and you'll start to see throughput
> > > tail off due to context switching.
> > >
> > > If you want to demonstrate throughput with a large number of clients
> > > you'll probably need to experiment with both maxThreads,
> > >
> >
> > I've forgot to say that I use maxThreads=8.
> >
> >
> > > maxConcurrentStreams and maxConcurrentStreamExecution.
> > >
> > > If I had to guess, I'd expect maxConcurrentStreams ==
> > > maxConcurrentStreamExecution and low numbers for all of them to give
> the
> > > best results.
> > >
> >
> > I will check those tomorrow!
> >
>
> I use h2load, and IMO I have very good performance with h2c. No errors.
> However, same as your tool, it's concurrency flag only controls how many
> streams it will use *inside a single connection* [I respect that, but I
>
I think this is not the case here.
As far as I can see Vegeta does not use custom ClientConnPool and the
default pool in net::http2 shares many connections per host:port key:
https://github.com/golang/net/blob/62affa334b73ec65ed44a326519ac12c421905e3/http2/client_conn_pool.go
> would have expected instead the tool would also use multiple connections in
> an attempt to simulate multiple users, but nope]. This can only go so far
> and the performance numbers caused me to add the flags to limit stream
> concurrency.
>
> Rémy
>
Re: Low throughput with HTTP2
Posted by Rémy Maucherat <re...@apache.org>.
On Tue, Sep 15, 2020 at 5:08 PM Martin Grigorov <mg...@apache.org>
wrote:
> Hi Mark,
>
> On Tue, Sep 15, 2020 at 3:34 PM Mark Thomas <ma...@apache.org> wrote:
>
> > On 15/09/2020 12:46, Martin Grigorov wrote:
> > > On Tue, Sep 15, 2020 at 2:37 PM Martin Grigorov <mg...@apache.org>
> > > wrote:
> > >
> > >> Hi,
> > >>
> > >> I am running some load tests on Tomcat and I've noticed that when
> HTTP2
> > is
> > >> enabled the throughput drops considerably.
> > >>
> > >> Here are the steps to reproduce:
> > >>
> > >> 1) Enable HTTP2, e.g. by commenting out this connector:
> > >>
> > >>
> >
> https://github.com/apache/tomcat/blob/d381d87005fa89d1f19d9091c0954f317c135d9d/conf/server.xml#L103-L112
> > >>
> > >> 2) Download Vegeta load tool from:
> > >> https://github.com/tsenart/vegeta/releases/
> > >>
> > >> 3) Run the load tests:
> > >>
> > >> 3.1) HTTP/1.1
> > >> echo -e '{"method": "GET", "url": "http://localhost:8080/examples/"}'
> |
> > >> vegeta attack -format=json -rate=0 -max-workers=1000 -duration=10s |
> > >> vegeta encode > /tmp/http1.json; and vegeta report -type=json
> > >> /tmp/http1.json | jq .
> > >>
> > >> 3.2) HTTP2
> > >> echo -e '{"method": "GET", "url": "https://localhost:8443/examples/
> "}'
> > |
> > >> vegeta attack -format=json -http2 -rate=0 -max-workers=1000 -insecure
> > >> -duration=10s | vegeta encode > /tmp/http2.json; and vegeta report
> > >> -type=json /tmp/http2.json | jq .
> > >>
> > >> As explained at https://github.com/tsenart/vegeta#-rate -rate=0 means
> > >> that Vegeta will try to send as many requests as possible with the
> > >> configured number of workers.
> > >> I use '-insecure' because I use self-signed certificate.
> > >>
> > >> On my machine I get around 14-15K reqs/sec for HTTP1.1 with only
> > responses
> > >> with code=200 .
> > >> But for HTTP2 Tomcat starts returning such kind of errors:
> > >>
> > >> "errors": [
> > >> "Get \"https://localhost:8443/examples/\": http2: server sent
> > GOAWAY
> > >> and closed the connection; LastStreamID=9259, ErrCode=PROTOCOL_ERROR,
> > >> debug=\"Stream [9,151] has been closed for some time\"",
> > >> "http2: server sent GOAWAY and closed the connection;
> > >> LastStreamID=9259, ErrCode=PROTOCOL_ERROR, debug=\"Stream [9,151] has
> > been
> > >> closed for some time\"",
> > >> "Get \"https://localhost:8443/examples/\": http2: server sent
> > GOAWAY
> > >> and closed the connection; LastStreamID=239, ErrCode=PROTOCOL_ERROR,
> > >> debug=\"Stream [49] has been closed for some time\""
> > >> ]
> > >>
> > >> when I ask for more than 2000 reqs/sec, i.e. -rate=2000/1s
> >
> > That indicates that the client has sent a frame associated with a stream
> > that the server closed previously and that that stream has been removed
> > from the Map of known streams to make room for new ones. See
> > Http2UpgardeHandler.pruneClosedStreams()
> >
> > It looks like the client is making assumptions about server behaviour
> > that go beyond the requirements of RFC 7540, section 5.3.4.
> >
>
> This is possible!
> I've just tested with two more HTTP2 impls:
>
> 1) Node.js
>
> http2-server.js
> ===================================================
> const http2 = require('http2');
> const fs = require('fs');
>
> const server = http2.createSecureServer({
> key: fs.readFileSync('/path/to/server.key'),
> cert: fs.readFileSync('/path/to/server.crt')
> });
> server.on('error', (err) => console.error(err));
>
> server.on('stream', (stream, headers) => {
> // stream is a Duplex
> stream.respond({
> 'content-type': 'text/plain; charset=utf-8',
> ':status': 200
> });
> stream.end('Hello world!');
> });
>
> server.listen(18080);
> ===================================================
>
> run with: node http2-server.js
>
> Runs fine with -rate=0 and gives around 8K reqs/sec
>
> 2) Rust
>
> Cargo.toml
> ===================================================
> [package]
> name = "my-http2-server"
> version = "0.0.1"
> publish = false
> authors = ["Martin Grigorov <mg...@apache.org>"]
> license = "MIT/Apache-2.0"
> description = "Load test HTTP/2 "
> repository = "https://github.com/martin-g/http2-server-rust"
> keywords = ["http2"]
> edition = "2018"
>
> [dependencies]
> actix-web = { version = "3", features = ["openssl"] }
> openssl = { version = "0.10", features = ["v110"] }
> ===================================================
>
> src/main.rs
> ===================================================
> use actix_web::{web, App, HttpRequest, HttpServer, Responder};
> use openssl::ssl::{SslAcceptor, SslFiletype, SslMethod};
>
> async fn index(_req: HttpRequest) -> impl Responder {
> "Hello world!"
> }
>
> #[actix_web::main]
> async fn main() -> std::io::Result<()> {
> let mut builder =
> SslAcceptor::mozilla_intermediate(SslMethod::tls()).unwrap();
> builder
> .set_private_key_file("/path/to/server.key", SslFiletype::PEM)
> .unwrap();
> builder.set_certificate_chain_file("/path/to/server.crt").unwrap();
>
> HttpServer::new(|| App::new().route("/", web::get().to(index)))
> .bind_openssl("127.0.0.1:18080", builder)?
> .run()
> .await
> }
> ===================================================
>
> run with: cargo run
> Again no errors, throughput: 3K reqs/sec
>
> I will test with Netty tomorrow too, but so far it looks like only Tomcat
> fails under load.
>
>
>
> > >> All the access logs look like:
> > >>
> > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0"
> 200
> > >> 1126
> > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0"
> 200
> > >> 1126
> > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0"
> 200
> > >> 1126
> > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0"
> 200
> > >> 1126
> > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0"
> 200
> > >> 1126
> > >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0"
> 200
> > >> 1126
> > >>
> > >> i.e. there are no error codes, just 200.
> > >> Vegeta reports the error with status code = 0. I think this just means
> > >> that it didn't get a proper HTTP response but just TCP error.
> > >> There are no errors in catalina.out.
> > >>
> > >> Are there any settings I can tune to get better throughput with HTTP2
> ?
> > >>
> > >> Tomcat 10.0.0-M8.
> >
> > If you really want to maximise throughput then you need to reduce the
> > number of concurrent requests to (or a little above) the number of cores
> > available on the server. Go higher and you'll start to see throughput
> > tail off due to context switching.
> >
> > If you want to demonstrate throughput with a large number of clients
> > you'll probably need to experiment with both maxThreads,
> >
>
> I've forgot to say that I use maxThreads=8.
>
>
> > maxConcurrentStreams and maxConcurrentStreamExecution.
> >
> > If I had to guess, I'd expect maxConcurrentStreams ==
> > maxConcurrentStreamExecution and low numbers for all of them to give the
> > best results.
> >
>
> I will check those tomorrow!
>
I use h2load, and IMO I have very good performance with h2c. No errors.
However, same as your tool, it's concurrency flag only controls how many
streams it will use *inside a single connection* [I respect that, but I
would have expected instead the tool would also use multiple connections in
an attempt to simulate multiple users, but nope]. This can only go so far
and the performance numbers caused me to add the flags to limit stream
concurrency.
Rémy
Re: Low throughput with HTTP2
Posted by Martin Grigorov <mg...@apache.org>.
Hi Mark,
On Tue, Sep 15, 2020 at 3:34 PM Mark Thomas <ma...@apache.org> wrote:
> On 15/09/2020 12:46, Martin Grigorov wrote:
> > On Tue, Sep 15, 2020 at 2:37 PM Martin Grigorov <mg...@apache.org>
> > wrote:
> >
> >> Hi,
> >>
> >> I am running some load tests on Tomcat and I've noticed that when HTTP2
> is
> >> enabled the throughput drops considerably.
> >>
> >> Here are the steps to reproduce:
> >>
> >> 1) Enable HTTP2, e.g. by commenting out this connector:
> >>
> >>
> https://github.com/apache/tomcat/blob/d381d87005fa89d1f19d9091c0954f317c135d9d/conf/server.xml#L103-L112
> >>
> >> 2) Download Vegeta load tool from:
> >> https://github.com/tsenart/vegeta/releases/
> >>
> >> 3) Run the load tests:
> >>
> >> 3.1) HTTP/1.1
> >> echo -e '{"method": "GET", "url": "http://localhost:8080/examples/"}' |
> >> vegeta attack -format=json -rate=0 -max-workers=1000 -duration=10s |
> >> vegeta encode > /tmp/http1.json; and vegeta report -type=json
> >> /tmp/http1.json | jq .
> >>
> >> 3.2) HTTP2
> >> echo -e '{"method": "GET", "url": "https://localhost:8443/examples/"}'
> |
> >> vegeta attack -format=json -http2 -rate=0 -max-workers=1000 -insecure
> >> -duration=10s | vegeta encode > /tmp/http2.json; and vegeta report
> >> -type=json /tmp/http2.json | jq .
> >>
> >> As explained at https://github.com/tsenart/vegeta#-rate -rate=0 means
> >> that Vegeta will try to send as many requests as possible with the
> >> configured number of workers.
> >> I use '-insecure' because I use self-signed certificate.
> >>
> >> On my machine I get around 14-15K reqs/sec for HTTP1.1 with only
> responses
> >> with code=200 .
> >> But for HTTP2 Tomcat starts returning such kind of errors:
> >>
> >> "errors": [
> >> "Get \"https://localhost:8443/examples/\": http2: server sent
> GOAWAY
> >> and closed the connection; LastStreamID=9259, ErrCode=PROTOCOL_ERROR,
> >> debug=\"Stream [9,151] has been closed for some time\"",
> >> "http2: server sent GOAWAY and closed the connection;
> >> LastStreamID=9259, ErrCode=PROTOCOL_ERROR, debug=\"Stream [9,151] has
> been
> >> closed for some time\"",
> >> "Get \"https://localhost:8443/examples/\": http2: server sent
> GOAWAY
> >> and closed the connection; LastStreamID=239, ErrCode=PROTOCOL_ERROR,
> >> debug=\"Stream [49] has been closed for some time\""
> >> ]
> >>
> >> when I ask for more than 2000 reqs/sec, i.e. -rate=2000/1s
>
> That indicates that the client has sent a frame associated with a stream
> that the server closed previously and that that stream has been removed
> from the Map of known streams to make room for new ones. See
> Http2UpgardeHandler.pruneClosedStreams()
>
> It looks like the client is making assumptions about server behaviour
> that go beyond the requirements of RFC 7540, section 5.3.4.
>
This is possible!
I've just tested with two more HTTP2 impls:
1) Node.js
http2-server.js
===================================================
const http2 = require('http2');
const fs = require('fs');
const server = http2.createSecureServer({
key: fs.readFileSync('/path/to/server.key'),
cert: fs.readFileSync('/path/to/server.crt')
});
server.on('error', (err) => console.error(err));
server.on('stream', (stream, headers) => {
// stream is a Duplex
stream.respond({
'content-type': 'text/plain; charset=utf-8',
':status': 200
});
stream.end('Hello world!');
});
server.listen(18080);
===================================================
run with: node http2-server.js
Runs fine with -rate=0 and gives around 8K reqs/sec
2) Rust
Cargo.toml
===================================================
[package]
name = "my-http2-server"
version = "0.0.1"
publish = false
authors = ["Martin Grigorov <mg...@apache.org>"]
license = "MIT/Apache-2.0"
description = "Load test HTTP/2 "
repository = "https://github.com/martin-g/http2-server-rust"
keywords = ["http2"]
edition = "2018"
[dependencies]
actix-web = { version = "3", features = ["openssl"] }
openssl = { version = "0.10", features = ["v110"] }
===================================================
src/main.rs
===================================================
use actix_web::{web, App, HttpRequest, HttpServer, Responder};
use openssl::ssl::{SslAcceptor, SslFiletype, SslMethod};
async fn index(_req: HttpRequest) -> impl Responder {
"Hello world!"
}
#[actix_web::main]
async fn main() -> std::io::Result<()> {
let mut builder =
SslAcceptor::mozilla_intermediate(SslMethod::tls()).unwrap();
builder
.set_private_key_file("/path/to/server.key", SslFiletype::PEM)
.unwrap();
builder.set_certificate_chain_file("/path/to/server.crt").unwrap();
HttpServer::new(|| App::new().route("/", web::get().to(index)))
.bind_openssl("127.0.0.1:18080", builder)?
.run()
.await
}
===================================================
run with: cargo run
Again no errors, throughput: 3K reqs/sec
I will test with Netty tomorrow too, but so far it looks like only Tomcat
fails under load.
> >> All the access logs look like:
> >>
> >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
> >> 1126
> >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
> >> 1126
> >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
> >> 1126
> >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
> >> 1126
> >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
> >> 1126
> >> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
> >> 1126
> >>
> >> i.e. there are no error codes, just 200.
> >> Vegeta reports the error with status code = 0. I think this just means
> >> that it didn't get a proper HTTP response but just TCP error.
> >> There are no errors in catalina.out.
> >>
> >> Are there any settings I can tune to get better throughput with HTTP2 ?
> >>
> >> Tomcat 10.0.0-M8.
>
> If you really want to maximise throughput then you need to reduce the
> number of concurrent requests to (or a little above) the number of cores
> available on the server. Go higher and you'll start to see throughput
> tail off due to context switching.
>
> If you want to demonstrate throughput with a large number of clients
> you'll probably need to experiment with both maxThreads,
>
I've forgot to say that I use maxThreads=8.
> maxConcurrentStreams and maxConcurrentStreamExecution.
>
> If I had to guess, I'd expect maxConcurrentStreams ==
> maxConcurrentStreamExecution and low numbers for all of them to give the
> best results.
>
I will check those tomorrow!
Thanks!
>
> Mark
>
>
> > Forgot to mention that I've also tested with JMeter +
> > https://github.com/Blazemeter/jmeter-http2-plugin but there it fails
> with
> > OOM if I use more than 2000 virtual users. Increasing the memory still
> does
> > not give such good results as Vegeta for HTTP/1.1. Also JMeter uses
> > sequential model.
> >
> > For comparison, I've also tested with a simple Golang based HTTP2 server:
> >
> > http2-server.go:
> > ==========================================================
> > package main
> >
> > import (
> > "fmt"
> > "log"
> > "net/http"
> > "os"
> > )
> >
> > func main() {
> >
> > port := 8080
> > if port == "" {
> > log.Fatal("Please specify the HTTP port as environment variable,
> e.g.
> > env PORT=8081 go run http-server.go")
> > }
> >
> > tls_root := "/path/to/certs/"
> > srv := &http.Server{Addr: ":" + port, Handler:
> http.HandlerFunc(handle)}
> > log.Fatal(srv.ListenAndServeTLS(tls_root + "server.crt", tls_root +
> > "server.key"))
> > }
> >
> > func handle(w http.ResponseWriter, r *http.Request) {
> > // log.Printf("Got connection: %s", r.Proto) // prints HTTP/2.0
> > fmt.Fprintf(w, "Hello World")
> > }
> > ==========================================================
> >
> > Here Vegeta makes around 13K reqs/sec without error responses.
> >
> > To run this app do: go run http2-server.go
> >
> >
> >> Regards,
> >> Martin
> >>
> >
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
Re: Low throughput with HTTP2
Posted by Mark Thomas <ma...@apache.org>.
On 15/09/2020 12:46, Martin Grigorov wrote:
> On Tue, Sep 15, 2020 at 2:37 PM Martin Grigorov <mg...@apache.org>
> wrote:
>
>> Hi,
>>
>> I am running some load tests on Tomcat and I've noticed that when HTTP2 is
>> enabled the throughput drops considerably.
>>
>> Here are the steps to reproduce:
>>
>> 1) Enable HTTP2, e.g. by commenting out this connector:
>>
>> https://github.com/apache/tomcat/blob/d381d87005fa89d1f19d9091c0954f317c135d9d/conf/server.xml#L103-L112
>>
>> 2) Download Vegeta load tool from:
>> https://github.com/tsenart/vegeta/releases/
>>
>> 3) Run the load tests:
>>
>> 3.1) HTTP/1.1
>> echo -e '{"method": "GET", "url": "http://localhost:8080/examples/"}' |
>> vegeta attack -format=json -rate=0 -max-workers=1000 -duration=10s |
>> vegeta encode > /tmp/http1.json; and vegeta report -type=json
>> /tmp/http1.json | jq .
>>
>> 3.2) HTTP2
>> echo -e '{"method": "GET", "url": "https://localhost:8443/examples/"}' |
>> vegeta attack -format=json -http2 -rate=0 -max-workers=1000 -insecure
>> -duration=10s | vegeta encode > /tmp/http2.json; and vegeta report
>> -type=json /tmp/http2.json | jq .
>>
>> As explained at https://github.com/tsenart/vegeta#-rate -rate=0 means
>> that Vegeta will try to send as many requests as possible with the
>> configured number of workers.
>> I use '-insecure' because I use self-signed certificate.
>>
>> On my machine I get around 14-15K reqs/sec for HTTP1.1 with only responses
>> with code=200 .
>> But for HTTP2 Tomcat starts returning such kind of errors:
>>
>> "errors": [
>> "Get \"https://localhost:8443/examples/\": http2: server sent GOAWAY
>> and closed the connection; LastStreamID=9259, ErrCode=PROTOCOL_ERROR,
>> debug=\"Stream [9,151] has been closed for some time\"",
>> "http2: server sent GOAWAY and closed the connection;
>> LastStreamID=9259, ErrCode=PROTOCOL_ERROR, debug=\"Stream [9,151] has been
>> closed for some time\"",
>> "Get \"https://localhost:8443/examples/\": http2: server sent GOAWAY
>> and closed the connection; LastStreamID=239, ErrCode=PROTOCOL_ERROR,
>> debug=\"Stream [49] has been closed for some time\""
>> ]
>>
>> when I ask for more than 2000 reqs/sec, i.e. -rate=2000/1s
That indicates that the client has sent a frame associated with a stream
that the server closed previously and that that stream has been removed
from the Map of known streams to make room for new ones. See
Http2UpgardeHandler.pruneClosedStreams()
It looks like the client is making assumptions about server behaviour
that go beyond the requirements of RFC 7540, section 5.3.4.
>> All the access logs look like:
>>
>> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
>> 1126
>> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
>> 1126
>> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
>> 1126
>> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
>> 1126
>> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
>> 1126
>> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
>> 1126
>>
>> i.e. there are no error codes, just 200.
>> Vegeta reports the error with status code = 0. I think this just means
>> that it didn't get a proper HTTP response but just TCP error.
>> There are no errors in catalina.out.
>>
>> Are there any settings I can tune to get better throughput with HTTP2 ?
>>
>> Tomcat 10.0.0-M8.
If you really want to maximise throughput then you need to reduce the
number of concurrent requests to (or a little above) the number of cores
available on the server. Go higher and you'll start to see throughput
tail off due to context switching.
If you want to demonstrate throughput with a large number of clients
you'll probably need to experiment with both maxThreads,
maxConcurrentStreams and maxConcurrentStreamExecution.
If I had to guess, I'd expect maxConcurrentStreams ==
maxConcurrentStreamExecution and low numbers for all of them to give the
best results.
Mark
> Forgot to mention that I've also tested with JMeter +
> https://github.com/Blazemeter/jmeter-http2-plugin but there it fails with
> OOM if I use more than 2000 virtual users. Increasing the memory still does
> not give such good results as Vegeta for HTTP/1.1. Also JMeter uses
> sequential model.
>
> For comparison, I've also tested with a simple Golang based HTTP2 server:
>
> http2-server.go:
> ==========================================================
> package main
>
> import (
> "fmt"
> "log"
> "net/http"
> "os"
> )
>
> func main() {
>
> port := 8080
> if port == "" {
> log.Fatal("Please specify the HTTP port as environment variable, e.g.
> env PORT=8081 go run http-server.go")
> }
>
> tls_root := "/path/to/certs/"
> srv := &http.Server{Addr: ":" + port, Handler: http.HandlerFunc(handle)}
> log.Fatal(srv.ListenAndServeTLS(tls_root + "server.crt", tls_root +
> "server.key"))
> }
>
> func handle(w http.ResponseWriter, r *http.Request) {
> // log.Printf("Got connection: %s", r.Proto) // prints HTTP/2.0
> fmt.Fprintf(w, "Hello World")
> }
> ==========================================================
>
> Here Vegeta makes around 13K reqs/sec without error responses.
>
> To run this app do: go run http2-server.go
>
>
>> Regards,
>> Martin
>>
>
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org
Re: Low throughput with HTTP2
Posted by Martin Grigorov <mg...@apache.org>.
On Tue, Sep 15, 2020 at 2:37 PM Martin Grigorov <mg...@apache.org>
wrote:
> Hi,
>
> I am running some load tests on Tomcat and I've noticed that when HTTP2 is
> enabled the throughput drops considerably.
>
> Here are the steps to reproduce:
>
> 1) Enable HTTP2, e.g. by commenting out this connector:
>
> https://github.com/apache/tomcat/blob/d381d87005fa89d1f19d9091c0954f317c135d9d/conf/server.xml#L103-L112
>
> 2) Download Vegeta load tool from:
> https://github.com/tsenart/vegeta/releases/
>
> 3) Run the load tests:
>
> 3.1) HTTP/1.1
> echo -e '{"method": "GET", "url": "http://localhost:8080/examples/"}' |
> vegeta attack -format=json -rate=0 -max-workers=1000 -duration=10s |
> vegeta encode > /tmp/http1.json; and vegeta report -type=json
> /tmp/http1.json | jq .
>
> 3.2) HTTP2
> echo -e '{"method": "GET", "url": "https://localhost:8443/examples/"}' |
> vegeta attack -format=json -http2 -rate=0 -max-workers=1000 -insecure
> -duration=10s | vegeta encode > /tmp/http2.json; and vegeta report
> -type=json /tmp/http2.json | jq .
>
> As explained at https://github.com/tsenart/vegeta#-rate -rate=0 means
> that Vegeta will try to send as many requests as possible with the
> configured number of workers.
> I use '-insecure' because I use self-signed certificate.
>
> On my machine I get around 14-15K reqs/sec for HTTP1.1 with only responses
> with code=200 .
> But for HTTP2 Tomcat starts returning such kind of errors:
>
> "errors": [
> "Get \"https://localhost:8443/examples/\": http2: server sent GOAWAY
> and closed the connection; LastStreamID=9259, ErrCode=PROTOCOL_ERROR,
> debug=\"Stream [9,151] has been closed for some time\"",
> "http2: server sent GOAWAY and closed the connection;
> LastStreamID=9259, ErrCode=PROTOCOL_ERROR, debug=\"Stream [9,151] has been
> closed for some time\"",
> "Get \"https://localhost:8443/examples/\": http2: server sent GOAWAY
> and closed the connection; LastStreamID=239, ErrCode=PROTOCOL_ERROR,
> debug=\"Stream [49] has been closed for some time\""
> ]
>
> when I ask for more than 2000 reqs/sec, i.e. -rate=2000/1s
>
>
> All the access logs look like:
>
> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
> 1126
> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
> 1126
> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
> 1126
> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
> 1126
> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
> 1126
> 127.0.0.1 - - [15/Sep/2020:13:59:24 +0300] "GET /examples/ HTTP/2.0" 200
> 1126
>
> i.e. there are no error codes, just 200.
> Vegeta reports the error with status code = 0. I think this just means
> that it didn't get a proper HTTP response but just TCP error.
> There are no errors in catalina.out.
>
> Are there any settings I can tune to get better throughput with HTTP2 ?
>
> Tomcat 10.0.0-M8.
>
Forgot to mention that I've also tested with JMeter +
https://github.com/Blazemeter/jmeter-http2-plugin but there it fails with
OOM if I use more than 2000 virtual users. Increasing the memory still does
not give such good results as Vegeta for HTTP/1.1. Also JMeter uses
sequential model.
For comparison, I've also tested with a simple Golang based HTTP2 server:
http2-server.go:
==========================================================
package main
import (
"fmt"
"log"
"net/http"
"os"
)
func main() {
port := 8080
if port == "" {
log.Fatal("Please specify the HTTP port as environment variable, e.g.
env PORT=8081 go run http-server.go")
}
tls_root := "/path/to/certs/"
srv := &http.Server{Addr: ":" + port, Handler: http.HandlerFunc(handle)}
log.Fatal(srv.ListenAndServeTLS(tls_root + "server.crt", tls_root +
"server.key"))
}
func handle(w http.ResponseWriter, r *http.Request) {
// log.Printf("Got connection: %s", r.Proto) // prints HTTP/2.0
fmt.Fprintf(w, "Hello World")
}
==========================================================
Here Vegeta makes around 13K reqs/sec without error responses.
To run this app do: go run http2-server.go
> Regards,
> Martin
>
Re: Low throughput with HTTP2
Posted by Martin Grigorov <mg...@apache.org>.
Hi Chris,
On Tue, Sep 15, 2020 at 5:09 PM Christopher Schultz <
chris@christopherschultz.net> wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA256
>
> Martin,
>
> On 9/15/20 07:37, Martin Grigorov wrote:
> > I am running some load tests on Tomcat and I've noticed that when
> > HTTP2 is enabled the throughput drops considerably.
> >
> > Here are the steps to reproduce:
> >
> > 1) Enable HTTP2, e.g. by commenting out this connector:
> > https://github.com/apache/tomcat/blob/d381d87005fa89d1f19d9091c0954f31
> 7c135d9d/conf/server.xml#L103-L112
> <https://github.com/apache/tomcat/blob/d381d87005fa89d1f19d9091c0954f317c135d9d/conf/server.xml#L103-L112>
> >
> > 2) Download Vegeta load tool from:
> > https://github.com/tsenart/vegeta/releases/
> >
> > 3) Run the load tests:
> >
> > 3.1) HTTP/1.1 echo -e '{"method": "GET", "url":
> > "http://localhost:8080/examples/"}' | vegeta attack -format=json
> > -rate=0 -max-workers=1000 -duration=10s | vegeta encode >
> > /tmp/http1.json; and vegeta report -type=json /tmp/http1.json | jq
> > .
> >
> > 3.2) HTTP2 echo -e '{"method": "GET", "url":
> > "https://localhost:8443/examples/"}' | vegeta attack -format=json
> > -http2 -rate=0 -max-workers=1000 -insecure -duration=10s | vegeta
> > encode > /tmp/http2.json; and vegeta report -type=json
> > /tmp/http2.json | jq .
>
> You are using HTTP with 1.1 and HTTPS with h2. Maybe you are seeing
> CPU slowdown for the (probably double encryption) taking place on the
> same host?
>
I've tested against HTTPS without H2 - it makes 13K reqs/sec here, i.e. 2-3
K less than HTTP.
The above numbers are when I use the examples' index.html page as a target.
When I use
=====================================================
package load.servlet;
import javax.servlet.annotation.WebServlet;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.nio.charset.StandardCharsets;
@WebServlet(urlPatterns = PlainTextServlet.URL_PATTERN)
public class PlainTextServlet extends HttpServlet {
static final String URL_PATTERN = "/servlet/plaintext";
private static final String CONTENT_TYPE = "text/plain;charset=UTF-8";
private static final byte[] CONTENT = "Hello
world!".getBytes(StandardCharsets.UTF_8);
private static final int CONTENT_LENGTH = CONTENT.length;
@Override
protected void doGet(final HttpServletRequest req, final
HttpServletResponse resp) throws IOException {
resp.setContentType(CONTENT_TYPE);
resp.setContentLength(CONTENT_LENGTH);
resp.getOutputStream().write(CONTENT);
}
}
=====================================================
I can get 33-35 K reqs/sec with HTTP
>
> - -chris
> -----BEGIN PGP SIGNATURE-----
> Comment: Using GnuPG with Thunderbird - https://www.enigmail.net/
>
> iQIzBAEBCAAdFiEEMmKgYcQvxMe7tcJcHPApP6U8pFgFAl9gyyIACgkQHPApP6U8
> pFiNUxAAnUQVU73nNitIyn6zD9t4JfkLIv/AKTlds4/W/p6TRtIQgTX7nIJjGDfw
> BOKznCHmieMJon4rMZ3d8GFhmUP8CawQlJHpqABeITBzLZZ5x9fuOf22G6HJb3r+
> +k0qDoKzFTWlJuWLwaLZHy6fO9ugi4OPAW0G0efa2T6sTDZzImGnjmoZ5PWBExoz
> mXmYWnZeP7R+3QkAWUYArJh9yPEJyIb9nFX1YKZ1l5Erzrn0F9uEYFgWT/UkQoKM
> L65AMh/qEvzJhP2wHOLm4NfAiNO4OgTmo+nm4F/SIMGFNURPFi2sl/jTUHVAzEa4
> mAqlJqX1swimyjjsunlfhbU/bApvVFsYSPuSYcZmLN1lkmaQOAuWHnZdd4e9h+tt
> rhoKXipk8OairYzwQsPVnzCTHaiAhOXJ3MSE966YwlvhSMOoqDsN3y7ySrboresD
> iC0cDo+43/wR3IQlOJYFxcFX+tI2Y29ZjrX/IwnJXuVyU095YZWmRFC2JgRfzBtI
> toM2ofpqnSBaS22ZBTbqp+q1QxRZfC3r0vuvuiXK620QRcbk1Ya0+U17LOIEYnuY
> URY94kL80upiADQMIdryq4ubRAma2t0s5c6JuO/QqsXVjJfawlRGQA5arORgfE2J
> yDCscyyFCHitEGTglIJUXW/KfFPtraWnON3TSCm7dQ55EmInxpc=
> =76Zf
> -----END PGP SIGNATURE-----
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
> For additional commands, e-mail: users-help@tomcat.apache.org
>
>
Re: Low throughput with HTTP2
Posted by Christopher Schultz <ch...@christopherschultz.net>.
-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256
Martin,
On 9/15/20 07:37, Martin Grigorov wrote:
> I am running some load tests on Tomcat and I've noticed that when
> HTTP2 is enabled the throughput drops considerably.
>
> Here are the steps to reproduce:
>
> 1) Enable HTTP2, e.g. by commenting out this connector:
> https://github.com/apache/tomcat/blob/d381d87005fa89d1f19d9091c0954f31
7c135d9d/conf/server.xml#L103-L112
>
> 2) Download Vegeta load tool from:
> https://github.com/tsenart/vegeta/releases/
>
> 3) Run the load tests:
>
> 3.1) HTTP/1.1 echo -e '{"method": "GET", "url":
> "http://localhost:8080/examples/"}' | vegeta attack -format=json
> -rate=0 -max-workers=1000 -duration=10s | vegeta encode >
> /tmp/http1.json; and vegeta report -type=json /tmp/http1.json | jq
> .
>
> 3.2) HTTP2 echo -e '{"method": "GET", "url":
> "https://localhost:8443/examples/"}' | vegeta attack -format=json
> -http2 -rate=0 -max-workers=1000 -insecure -duration=10s | vegeta
> encode > /tmp/http2.json; and vegeta report -type=json
> /tmp/http2.json | jq .
You are using HTTP with 1.1 and HTTPS with h2. Maybe you are seeing
CPU slowdown for the (probably double encryption) taking place on the
same host?
- -chris
-----BEGIN PGP SIGNATURE-----
Comment: Using GnuPG with Thunderbird - https://www.enigmail.net/
iQIzBAEBCAAdFiEEMmKgYcQvxMe7tcJcHPApP6U8pFgFAl9gyyIACgkQHPApP6U8
pFiNUxAAnUQVU73nNitIyn6zD9t4JfkLIv/AKTlds4/W/p6TRtIQgTX7nIJjGDfw
BOKznCHmieMJon4rMZ3d8GFhmUP8CawQlJHpqABeITBzLZZ5x9fuOf22G6HJb3r+
+k0qDoKzFTWlJuWLwaLZHy6fO9ugi4OPAW0G0efa2T6sTDZzImGnjmoZ5PWBExoz
mXmYWnZeP7R+3QkAWUYArJh9yPEJyIb9nFX1YKZ1l5Erzrn0F9uEYFgWT/UkQoKM
L65AMh/qEvzJhP2wHOLm4NfAiNO4OgTmo+nm4F/SIMGFNURPFi2sl/jTUHVAzEa4
mAqlJqX1swimyjjsunlfhbU/bApvVFsYSPuSYcZmLN1lkmaQOAuWHnZdd4e9h+tt
rhoKXipk8OairYzwQsPVnzCTHaiAhOXJ3MSE966YwlvhSMOoqDsN3y7ySrboresD
iC0cDo+43/wR3IQlOJYFxcFX+tI2Y29ZjrX/IwnJXuVyU095YZWmRFC2JgRfzBtI
toM2ofpqnSBaS22ZBTbqp+q1QxRZfC3r0vuvuiXK620QRcbk1Ya0+U17LOIEYnuY
URY94kL80upiADQMIdryq4ubRAma2t0s5c6JuO/QqsXVjJfawlRGQA5arORgfE2J
yDCscyyFCHitEGTglIJUXW/KfFPtraWnON3TSCm7dQ55EmInxpc=
=76Zf
-----END PGP SIGNATURE-----
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscribe@tomcat.apache.org
For additional commands, e-mail: users-help@tomcat.apache.org