Re: HTTP2: POST request with a small body leads to GOAWAY + ErrCode=ENHANCE_YOUR_CALM
On Wed, Sep 30, 2020 at 1:15 PM Martin Grigorov
wrote:
>
>
> On Wed, Sep 30, 2020 at 1:01 PM Martin Grigorov
> wrote:
>
>> Hi,
>>
>> I've tried to test the scenario of Arshiya Shariff:
>> "With a payload of 200 bytes we were able to send 20K requests/sec with
>> 200 users from Jmeter without any memory issue . On increasing the payload
>> to 5Kb and the number of users to 1000 in Jmeter and sending 1000 requests
>> per second , the heap of 20GB got filled in 2 minutes . With 200 users the
>> memory is cleared in the G1 mixed GC itself , but with 1000 users the
>> memory is not cleared in the mixed GC , it takes full GCs of 7 to 10
>> seconds to clear the memory. These cases were executed with maxThreads 200
>> in tomcat , so we tried increasing the maxThreads from 200 to 1000, but
>> still GC was struggling ."
>>
>> My Servlet looks like this:
>> https://github.com/martin-g/http2-server-perf-tests/blob/f5e73d73a864d4c7dbcbbbe80024764352383116/java/tomcat/src/main/java/info/mgsolutions/tomcat/PlainTextServlet.java#L37-L54
>>
>> And the Vegeta command I issue is:
>>
>> jq -ncM '{"method": "POST", "url": "
>> https://localhost:8080/testbed/plaintext";, "body":"payload=Some payload"
>> | @base64, header: {"Content-Type":
>> ["application/x-www-form-urlencoded"]}}' | vegeta attack -format=json
>> -http2 -rate=1 -max-workers=8 -insecure -duration=3s | vegeta encode >
>> /tmp/http2.json; and vegeta report -type=json /tmp/http2.json | jq .
>>
>> The outcome is:
>>
>> {
>> "latencies": {
>> "total": 114369584,
>> "mean": 38123194,
>> "50th": 45737841,
>> "90th": 62258803,
>> "95th": 62258803,
>> "99th": 62258803,
>> "max": 62258803,
>> "min": 6372940
>> },
>> "bytes_in": {
>> "total": 24,
>> "mean": 8
>> },
>> "bytes_out": {
>> "total": 40,
>> "mean": 13.334
>> },
>> "earliest": "2020-09-30T12:40:15.208111926+03:00",
>> "latest": "2020-09-30T12:40:17.208170426+03:00",
>> "end": "2020-09-30T12:40:17.253908267+03:00",
>> "duration": 258500,
>> "wait": 45737841,
>> "requests": 3,
>> "rate": 1.499956126283306,
>> "throughput": 0.9776144183650195,
>> "success": 0.,
>> "status_codes": {
>> "0": 1,
>> "200": 2
>> },
>> "errors": [
>> "Post \"https://localhost:8080/testbed/plaintext\": http2: server
>> sent GOAWAY and closed the connection; LastStreamID=3,
>> ErrCode=ENHANCE_YOUR_CALM, debug=\"Connection [4], Too much overhead so the
>> connection will be closed\""
>> ]
>> }
>>
>> I.e. it sends 1 POST request every second for 3 seconds and this leads to
>> GOAWAY+ENHANCE_YOUR_CALM !
>>
>> From my understanding on "overhead" this should happen if there are more
>> SETTINGS|PING|WINDOW_UPDATE|PRIORITY frames than HTTP_HEADERS or DATA.
>>
>> I am not able to decrypt TLS data in Wireshark when the client is Vegeta,
>> so I will try to debug it or to reproduce it with Firefox (to be able to
>> use Wireframe).
>>
>> Any ideas why this happens ?
>>
>
> The reason is here:
> https://github.com/apache/tomcat/blob/16181fc7b1930ff202ec2e475f2fbdc587f3e314/java/org/apache/coyote/http2/Http2UpgradeHandler.java#L1448
> overheadThreshold is 1024 and average is 20
> It goes twice in this method and then fails at
> https://github.com/apache/tomcat/blob/16181fc7b1930ff202ec2e475f2fbdc587f3e314/java/org/apache/coyote/http2/Http2UpgradeHandler.java#L352
>
https://bz.apache.org/bugzilla/show_bug.cgi?id=63690#c7 explains the issue.
No idea why but Vegeta/Golang sends two DATA frames and the second one
(with END_STREAM) is empty:
30-Sep-2020 14:45:35.646 FINE [https-jsse-nio-8080-exec-6]
org.apache.coyote.http2.Stream.emitHeader Connection [1], Stream [1], HTTP
header [accept-encoding], Value [gzip]
30-Sep-2020 14:45:35.646 FINE [https-jsse-nio-8080-exec-6]
org.apache.coyote.http2.Stream.emitHeader Connection [1], Stream [1], HTTP
header [user-agent], Value [Go-http-client/2.0]
30-Sep-2020 14:45:35.647 FINE [https-jsse-nio-8080-exec-6]
org.apache.coyote.http2.Http2Parser.swallow Connection [1], Stream [1],
Swallowed [0] bytes
30-Sep-2020 14:45:35.647 FINE [https-jsse-nio-8080-exec-6]
org.apache.coyote.http2.Http2Parser.validateFrame Connection [1], Stream
[1], Frame type [DATA], Flags [0], Payload size [20]
30-Sep-2020 14:45:35.647 FINE [https-jsse-nio-8080-exec-6]
org.apache.coyote.http2.Http2Parser.readDataFrame Connection [1], Stream
[1], Data length, [20], Padding length [none]
30-Sep-2020 14:45:35.647 FINE [https-jsse-nio-8080-exec-6]
org.apache.coyote.http2.Stream$StreamInputBuffer.onDataAvailable Data added
to inBuffer when read thread is waiting. Signalling that thread to continue
30-Sep-2020 14:45:35.647 FINE [https-jsse-nio-8080-exec-6]
org.apache.coyote.http2.Http2Parser.validateFrame Connection [1], Stream
[1], Frame type [DATA], Flags [1], Payload size [0]
>
>
>>
>> Martin
>>
>
Re: HTTP2: POST request with a small body leads to GOAWAY + ErrCode=ENHANCE_YOUR_CALM
On Wed, Sep 30, 2020 at 1:01 PM Martin Grigorov
wrote:
> Hi,
>
> I've tried to test the scenario of Arshiya Shariff:
> "With a payload of 200 bytes we were able to send 20K requests/sec with
> 200 users from Jmeter without any memory issue . On increasing the payload
> to 5Kb and the number of users to 1000 in Jmeter and sending 1000 requests
> per second , the heap of 20GB got filled in 2 minutes . With 200 users the
> memory is cleared in the G1 mixed GC itself , but with 1000 users the
> memory is not cleared in the mixed GC , it takes full GCs of 7 to 10
> seconds to clear the memory. These cases were executed with maxThreads 200
> in tomcat , so we tried increasing the maxThreads from 200 to 1000, but
> still GC was struggling ."
>
> My Servlet looks like this:
> https://github.com/martin-g/http2-server-perf-tests/blob/f5e73d73a864d4c7dbcbbbe80024764352383116/java/tomcat/src/main/java/info/mgsolutions/tomcat/PlainTextServlet.java#L37-L54
>
> And the Vegeta command I issue is:
>
> jq -ncM '{"method": "POST", "url": "
> https://localhost:8080/testbed/plaintext";, "body":"payload=Some payload"
> | @base64, header: {"Content-Type":
> ["application/x-www-form-urlencoded"]}}' | vegeta attack -format=json
> -http2 -rate=1 -max-workers=8 -insecure -duration=3s | vegeta encode >
> /tmp/http2.json; and vegeta report -type=json /tmp/http2.json | jq .
>
> The outcome is:
>
> {
> "latencies": {
> "total": 114369584,
> "mean": 38123194,
> "50th": 45737841,
> "90th": 62258803,
> "95th": 62258803,
> "99th": 62258803,
> "max": 62258803,
> "min": 6372940
> },
> "bytes_in": {
> "total": 24,
> "mean": 8
> },
> "bytes_out": {
> "total": 40,
> "mean": 13.334
> },
> "earliest": "2020-09-30T12:40:15.208111926+03:00",
> "latest": "2020-09-30T12:40:17.208170426+03:00",
> "end": "2020-09-30T12:40:17.253908267+03:00",
> "duration": 258500,
> "wait": 45737841,
> "requests": 3,
> "rate": 1.499956126283306,
> "throughput": 0.9776144183650195,
> "success": 0.,
> "status_codes": {
> "0": 1,
> "200": 2
> },
> "errors": [
> "Post \"https://localhost:8080/testbed/plaintext\": http2: server
> sent GOAWAY and closed the connection; LastStreamID=3,
> ErrCode=ENHANCE_YOUR_CALM, debug=\"Connection [4], Too much overhead so the
> connection will be closed\""
> ]
> }
>
> I.e. it sends 1 POST request every second for 3 seconds and this leads to
> GOAWAY+ENHANCE_YOUR_CALM !
>
> From my understanding on "overhead" this should happen if there are more
> SETTINGS|PING|WINDOW_UPDATE|PRIORITY frames than HTTP_HEADERS or DATA.
>
> I am not able to decrypt TLS data in Wireshark when the client is Vegeta,
> so I will try to debug it or to reproduce it with Firefox (to be able to
> use Wireframe).
>
> Any ideas why this happens ?
>
The reason is here:
https://github.com/apache/tomcat/blob/16181fc7b1930ff202ec2e475f2fbdc587f3e314/java/org/apache/coyote/http2/Http2UpgradeHandler.java#L1448
overheadThreshold is 1024 and average is 20
It goes twice in this method and then fails at
https://github.com/apache/tomcat/blob/16181fc7b1930ff202ec2e475f2fbdc587f3e314/java/org/apache/coyote/http2/Http2UpgradeHandler.java#L352
>
> Martin
>
HTTP2: POST request with a small body leads to GOAWAY + ErrCode=ENHANCE_YOUR_CALM
Hi,
I've tried to test the scenario of Arshiya Shariff:
"With a payload of 200 bytes we were able to send 20K requests/sec with 200
users from Jmeter without any memory issue . On increasing the payload to
5Kb and the number of users to 1000 in Jmeter and sending 1000 requests per
second , the heap of 20GB got filled in 2 minutes . With 200 users the
memory is cleared in the G1 mixed GC itself , but with 1000 users the
memory is not cleared in the mixed GC , it takes full GCs of 7 to 10
seconds to clear the memory. These cases were executed with maxThreads 200
in tomcat , so we tried increasing the maxThreads from 200 to 1000, but
still GC was struggling ."
My Servlet looks like this:
https://github.com/martin-g/http2-server-perf-tests/blob/f5e73d73a864d4c7dbcbbbe80024764352383116/java/tomcat/src/main/java/info/mgsolutions/tomcat/PlainTextServlet.java#L37-L54
And the Vegeta command I issue is:
jq -ncM '{"method": "POST", "url": "https://localhost:8080/testbed/plaintext";,
"body":"payload=Some payload" | @base64, header: {"Content-Type":
["application/x-www-form-urlencoded"]}}' | vegeta attack -format=json
-http2 -rate=1 -max-workers=8 -insecure -duration=3s | vegeta encode >
/tmp/http2.json; and vegeta report -type=json /tmp/http2.json | jq .
The outcome is:
{
"latencies": {
"total": 114369584,
"mean": 38123194,
"50th": 45737841,
"90th": 62258803,
"95th": 62258803,
"99th": 62258803,
"max": 62258803,
"min": 6372940
},
"bytes_in": {
"total": 24,
"mean": 8
},
"bytes_out": {
"total": 40,
"mean": 13.334
},
"earliest": "2020-09-30T12:40:15.208111926+03:00",
"latest": "2020-09-30T12:40:17.208170426+03:00",
"end": "2020-09-30T12:40:17.253908267+03:00",
"duration": 258500,
"wait": 45737841,
"requests": 3,
"rate": 1.499956126283306,
"throughput": 0.9776144183650195,
"success": 0.,
"status_codes": {
"0": 1,
"200": 2
},
"errors": [
"Post \"https://localhost:8080/testbed/plaintext\": http2: server sent
GOAWAY and closed the connection; LastStreamID=3,
ErrCode=ENHANCE_YOUR_CALM, debug=\"Connection [4], Too much overhead so the
connection will be closed\""
]
}
I.e. it sends 1 POST request every second for 3 seconds and this leads to
GOAWAY+ENHANCE_YOUR_CALM !
>From my understanding on "overhead" this should happen if there are more
SETTINGS|PING|WINDOW_UPDATE|PRIORITY frames than HTTP_HEADERS or DATA.
I am not able to decrypt TLS data in Wireshark when the client is Vegeta,
so I will try to debug it or to reproduce it with Firefox (to be able to
use Wireframe).
Any ideas why this happens ?
Martin
