Low throughput with HTTP2

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

Low throughput with HTTP2

Martin Grigorov
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
Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

Martin Grigorov
On Tue, Sep 15, 2020 at 2:37 PM Martin Grigorov <[hidden email]>
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
>
Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

markt
On 15/09/2020 12:46, Martin Grigorov wrote:

> On Tue, Sep 15, 2020 at 2:37 PM Martin Grigorov <[hidden email]>
> 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: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

Christopher Schultz-2
In reply to this post by Martin Grigorov
-----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: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

Martin Grigorov
In reply to this post by markt
Hi Mark,

On Tue, Sep 15, 2020 at 3:34 PM Mark Thomas <[hidden email]> wrote:

> On 15/09/2020 12:46, Martin Grigorov wrote:
> > On Tue, Sep 15, 2020 at 2:37 PM Martin Grigorov <[hidden email]>
> > 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 <[hidden email]>"]
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: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

Martin Grigorov
In reply to this post by Christopher Schultz-2
Hi Chris,

On Tue, Sep 15, 2020 at 5:09 PM Christopher Schultz <
[hidden email]> 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: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

Rémy Maucherat
In reply to this post by Martin Grigorov
On Tue, Sep 15, 2020 at 5:08 PM Martin Grigorov <[hidden email]>
wrote:

> Hi Mark,
>
> On Tue, Sep 15, 2020 at 3:34 PM Mark Thomas <[hidden email]> wrote:
>
> > On 15/09/2020 12:46, Martin Grigorov wrote:
> > > On Tue, Sep 15, 2020 at 2:37 PM Martin Grigorov <[hidden email]>
> > > 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 <[hidden email]>"]
> 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
Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

Martin Grigorov
Hi Remy,

On Tue, Sep 15, 2020 at 6:16 PM Rémy Maucherat <[hidden email]> wrote:

> On Tue, Sep 15, 2020 at 5:08 PM Martin Grigorov <[hidden email]>
> wrote:
>
> > Hi Mark,
> >
> > On Tue, Sep 15, 2020 at 3:34 PM Mark Thomas <[hidden email]> wrote:
> >
> > > On 15/09/2020 12:46, Martin Grigorov wrote:
> > > > On Tue, Sep 15, 2020 at 2:37 PM Martin Grigorov <
> [hidden email]>
> > > > 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 <[hidden email]>"]
> > 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
>
Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

Martin Grigorov
Hi,

On Wed, Sep 16, 2020 at 10:24 AM Martin Grigorov <[hidden email]>
wrote:

> Hi Remy,
>
> On Tue, Sep 15, 2020 at 6:16 PM Rémy Maucherat <[hidden email]> wrote:
>
>> On Tue, Sep 15, 2020 at 5:08 PM Martin Grigorov <[hidden email]>
>> wrote:
>>
>> > Hi Mark,
>> >
>> > On Tue, Sep 15, 2020 at 3:34 PM Mark Thomas <[hidden email]> wrote:
>> >
>> > > On 15/09/2020 12:46, Martin Grigorov wrote:
>> > > > On Tue, Sep 15, 2020 at 2:37 PM Martin Grigorov <
>> [hidden email]>
>> > > > 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 <[hidden email]>"]
>> > 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
>>
>
Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

Martin Grigorov
On Fri, Sep 18, 2020 at 10:48 AM Martin Grigorov <[hidden email]>
wrote:

> Hi,
>
> On Wed, Sep 16, 2020 at 10:24 AM Martin Grigorov <[hidden email]>
> wrote:
>
>> Hi Remy,
>>
>> On Tue, Sep 15, 2020 at 6:16 PM Rémy Maucherat <[hidden email]> wrote:
>>
>>> On Tue, Sep 15, 2020 at 5:08 PM Martin Grigorov <[hidden email]>
>>> wrote:
>>>
>>> > Hi Mark,
>>> >
>>> > On Tue, Sep 15, 2020 at 3:34 PM Mark Thomas <[hidden email]> wrote:
>>> >
>>> > > On 15/09/2020 12:46, Martin Grigorov wrote:
>>> > > > On Tue, Sep 15, 2020 at 2:37 PM Martin Grigorov <
>>> [hidden email]>
>>> > > > 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 <[hidden email]>"]
>>> > 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
>>>
>>
Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

markt
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: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

Martin Grigorov
On Fri, Sep 18, 2020 at 6:16 PM Mark Thomas <[hidden email]> 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: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

markt
On 21/09/2020 08:18, Martin Grigorov wrote:

> On Fri, Sep 18, 2020 at 6:16 PM Mark Thomas <[hidden email]> 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: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

Martin Grigorov
On Mon, Sep 21, 2020 at 11:23 AM Mark Thomas <[hidden email]> wrote:

> On 21/09/2020 08:18, Martin Grigorov wrote:
> > On Fri, Sep 18, 2020 at 6:16 PM Mark Thomas <[hidden email]> 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: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

Martin Grigorov
On Mon, Sep 21, 2020 at 12:08 PM Martin Grigorov <[hidden email]>
wrote:

>
>
> On Mon, Sep 21, 2020 at 11:23 AM Mark Thomas <[hidden email]> wrote:
>
>> On 21/09/2020 08:18, Martin Grigorov wrote:
>> > On Fri, Sep 18, 2020 at 6:16 PM Mark Thomas <[hidden email]> 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: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

markt
On 21/09/2020 10:44, Martin Grigorov wrote:
> On Mon, Sep 21, 2020 at 12:08 PM Martin Grigorov <[hidden email]>
> wrote:
>> On Mon, Sep 21, 2020 at 11:23 AM Mark Thomas <[hidden email]> 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: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

Martin Grigorov
In reply to this post by Martin Grigorov
On Mon, Sep 21, 2020 at 12:08 PM Martin Grigorov <[hidden email]>
wrote:

>
>
> On Mon, Sep 21, 2020 at 11:23 AM Mark Thomas <[hidden email]> wrote:
>
>> On 21/09/2020 08:18, Martin Grigorov wrote:
>> > On Fri, Sep 18, 2020 at 6:16 PM Mark Thomas <[hidden email]> 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: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

Rémy Maucherat
On Mon, Sep 21, 2020 at 1:36 PM Martin Grigorov <[hidden email]>
wrote:

> On Mon, Sep 21, 2020 at 12:08 PM Martin Grigorov <[hidden email]>
> wrote:
>
> >
> >
> > On Mon, Sep 21, 2020 at 11:23 AM Mark Thomas <[hidden email]> wrote:
> >
> >> On 21/09/2020 08:18, Martin Grigorov wrote:
> >> > On Fri, Sep 18, 2020 at 6:16 PM Mark Thomas <[hidden email]> 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: [hidden email]
> >> For additional commands, e-mail: [hidden email]
> >>
> >>
>
Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

Martin Grigorov
Hi Remy,

On Mon, Sep 21, 2020 at 2:56 PM Rémy Maucherat <[hidden email]> 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
>
>
>
>
Reply | Threaded
Open this post in threaded view
|

Re: Low throughput with HTTP2

Martin Grigorov
On Mon, Sep 21, 2020 at 3:48 PM Martin Grigorov <[hidden email]>
wrote:

> Hi Remy,
>
> On Mon, Sep 21, 2020 at 2:56 PM Rémy Maucherat <[hidden email]> 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
>>
>>
>>
>>
12