HTTP2: POST request with a small body leads to GOAWAY + ErrCode=ENHANCE_YOUR_CALM

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

HTTP2: POST request with a small body leads to GOAWAY + ErrCode=ENHANCE_YOUR_CALM

Martin Grigorov
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.333333333333334
  },
  "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": 2000058500,
  "wait": 45737841,
  "requests": 3,
  "rate": 1.499956126283306,
  "throughput": 0.9776144183650195,
  "success": 0.6666666666666666,
  "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
Reply | Threaded
Open this post in threaded view
|

Re: HTTP2: POST request with a small body leads to GOAWAY + ErrCode=ENHANCE_YOUR_CALM

Martin Grigorov
On Wed, Sep 30, 2020 at 1:01 PM Martin Grigorov <[hidden email]>
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.333333333333334
>   },
>   "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": 2000058500,
>   "wait": 45737841,
>   "requests": 3,
>   "rate": 1.499956126283306,
>   "throughput": 0.9776144183650195,
>   "success": 0.6666666666666666,
>   "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
>
Reply | Threaded
Open this post in threaded view
|

Re: HTTP2: POST request with a small body leads to GOAWAY + ErrCode=ENHANCE_YOUR_CALM

Martin Grigorov
On Wed, Sep 30, 2020 at 1:15 PM Martin Grigorov <[hidden email]>
wrote:

>
>
> On Wed, Sep 30, 2020 at 1:01 PM Martin Grigorov <[hidden email]>
> 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.333333333333334
>>   },
>>   "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": 2000058500,
>>   "wait": 45737841,
>>   "requests": 3,
>>   "rate": 1.499956126283306,
>>   "throughput": 0.9776144183650195,
>>   "success": 0.6666666666666666,
>>   "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
>>
>