RESTEasy Reactive Executor Thread

[Luca Masini]

Hi guys, I write here but may be is not a bug but only a problem of my understanding of the execution model.

I have an endpoint like this:

@GET
@Path("test/{myParam}")
public Uni<URI> testUni(@PathParam("myParam") String myParam) {
return Uni.createFrom().item(myParam).map( p -> {
// this is a memory fetch, so I decided to leave it imperative
Negozio negozio = negozioControl.getSingle();

log.info(negozio.getNomeNegozio());

return UriBuilder.fromPath(p).build();
});
}

and it runs on the event-loop:

2021-04-02 10:46:48,795 INFO  [io.qua.htt.access-log] (vert.x-eventloop-thread-18) 0:0:0:0:0:0:0:1 - admin 02/Apr/2021:10:46:48 +0200 "GET /resources/spesa/test/prova HTTP/1.1" 200 7

I reduced it for simplicity. But the real endpoint doesn't, after that it chains reactive call to REST Client and parsing of the response.

The latter  runs on the event-loop, the first doesn't:

2021-04-02 10:51:15,065 INFO  [xxx] (executor-thread-198) REQUEST -> http://hostname:8080/xxxx/
2021-04-02 10:51:15,145 INFO  [xxx] (vert.x-eventloop-thread-21) RESPONSE -> {}
2021-04-02 10:51:15,159 INFO  [xxx] (vert.x-eventloop-thread-21) REQUEST -> {}
2021-04-02 10:51:15,224 INFO  [xxx] (vert.x-eventloop-thread-21) RESPONSE -> {}
2021-04-02 10:51:15,225 INFO  [xxx] (vert.x-eventloop-thread-21) Closed with basketId 4153298
2021-04-02 10:51:15,225 INFO  [xxx] (vert.x-eventloop-thread-21) info response ResponseEntity@58ed098

How can I understand how the execution model is decided ?

Is this driven by Reactor+Mutiny or is RESTEasy Reactive ?

Thanks.

[Georgios Andrianakis]

Hi,

I can't say I really understand the problem you are describing based on the code sample.

The threading model is rather simple in RESTEasy Reactive: Everything runs on the event loop unless you add @Blocking to the endpoint.

You should not need to do a thread handling in the body of the method

--
You received this message because you are subscribed to the Google Groups "Quarkus Development mailing list" group.
To unsubscribe from this group and stop receiving emails from it, send an email to quarkus-dev...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/quarkus-dev/320a067e-2f06-46a1-b414-fea0ac30876fn%40googlegroups.com.

[Luca Masini]

Hi Georgios, I don't have any thread management in my code either @Blocking annotations.

But the first stage of the reactive pipeline (which only creates an URI using UriBuilder) runs on an executor thread.

Do you have any hints of where I can debug to understand what is going on?

--

****************************************
http://www.lucamasini.net
http://twitter.com/lmasini
http://www.linkedin.com/pub/luca-masini/7/10/2b9
****************************************

[Georgios Andrianakis]

Where is

[xxx] (executor-thread-198) REQUEST -> http://hostname:8080/xxxx/

printed from?

What does the code look like?

[Luca Masini]

This is the original code:

//TODO: la prima stage viene eseguita su un executor-thread, potrebbe rallentare se sotto alto carico
return Uni.createFrom().item(command.getNegozio()).map( negozioPK -> {
        Negozio negozio = negozioRepository.findById(negozioPK).get();

        URI uri = uriBuilder.apply(negozio);

        log.info("REQUEST -> " + uri.toString());

        return uri;
    })
    .chain( uri -> Uni.createFrom().completionStage(client.target(uri).request().rx().get()) )
    .chain( response -> {.......});

[Georgios Andrianakis]

I don't see why that would happen. @Clement Escoffier any ideas?

We would likely need a reproducer to check it out

[Luca Masini]

That's what I'm trying to figure out, but the reproducer works as expected, running everything on the event-loop thread.

It's only a UriBuilder that creates an URI that run on the executor-thread but

1) I hate when I don't understand something I thought I know

2) That can impact performance under heavy load

As always, thank you @Georgios Andrianakis  !!!!

[Georgios Andrianakis]

On Fri, Apr 2, 2021 at 12:16 PM Luca Masini <luca....@gmail.com> wrote:

That's what I'm trying to figure out, but the reproducer works as expected, running everything on the event-loop thread.

It's only a UriBuilder that creates an URI that run on the executor-thread but

1) I hate when I don't understand something I thought I know

2) That can impact performance under heavy load

Yeah, changing between threads can definitely have an effect.

As always, thank you @Georgios Andrianakis  !!!!

Sure thing! If you do come up with a reproducer, please let us know. 

[Luca Masini]

Thank you Clement, I checked your point and :

1) command.getNegozio is a getter, it return a String

2) The call

negozioRepository.findById

return an Optional from a local cache, it doesn't use any thread or CompletionStage

3) Regarding the "Reactive Extension" of the JAX-RS Client, I used this before 1.13 because MP Rest Client was not reactive and yes, it returns a Completion Stage.

I created a better test-case to understand if the problem was the rx() and this works as expected:

@GET
@Path("test/{myParam}")

public Uni<Response> testUni(@PathParam("myParam") String myParam, @Context UriInfo uriInfo) {

    return Uni.createFrom().item(myParam).map( p -> {
        // this is a memory fetch, so I decided to leave it imperative
        Negozio negozio = negozioControl.getSingle();

        log.info(negozio.getNomeNegozio());

        return uriInfo.getBaseUriBuilder().path("q/dev").build();

    })
            .chain( uri -> Uni.createFrom().completionStage(client.target(uri).request().rx().get()) )
            .chain( response -> {

                log.info(response.toString());
                return Uni.createFrom().item(response);
            } );
}

2021-04-02 12:46:51,623 INFO  [xxx] (vert.x-eventloop-thread-8) Laboratorio yyyy
2021-04-02 12:46:51,624 INFO  [io.qua.htt.access-log] (vert.x-eventloop-thread-12) 127.0.0.1 - - 02/Apr/2021:12:46:51 +0200 "GET /resources/q/dev HTTP/1.1" 307 -
2021-04-02 12:46:51,625 INFO  [xxx] (vert.x-eventloop-thread-6) org.jboss.resteasy.reactive.client.impl.ClientResponseImpl@562a065e
2021-04-02 12:46:51,626 INFO  [io.qua.htt.access-log] (vert.x-eventloop-thread-0) 0:0:0:0:0:0:0:1 - admin 02/Apr/2021:12:46:51 +0200 "GET /resources/test/prova HTTP/1.1" 307 -


going on trying to create a reproducer.

Thanks

Il giorno ven 2 apr 2021 alle ore 11:27 Clement Escoffier <clement....@redhat.com> ha scritto:

In:

return Uni.createFrom().item(command.getNegozio()).map( negozioPK -> {
        Negozio negozio = negozioRepository.findById(negozioPK).get();

        URI uri = uriBuilder.apply(negozio);

        log.info("REQUEST -> " + uri.toString());

        return uri;
    })
    .chain( uri -> Uni.createFrom().completionStage(client.target(uri).request().rx().get()) )
    .chain( response -> {.......});

There are a few things to check:

1. what does command.getNegozio() do, and it is returning a Supplier (in that case on which thread the item is emitted).

2. I'm seing a findById().get(), hopefully, this is not using CompletionStage, because if it does that would be blocking.

3. The client.target(...).request().rx().get() is also suspicious. First "rx", is it related to Reactive eXtensions? If not (and don't believe it does), is it returning a CompletionStage? In this case, veriy on which thread it emits, probably the fork join (do not use this in a container)

Clement

[Stuart Douglas]

Are you using security? If you have a blocking authentication mechanism installed this may result in a dispatch to a worker thread. If this happens we don't dispatch back to the IO thread for performance reasons but continue execution on the worker.

Stuart

To view this discussion on the web visit https://groups.google.com/d/msgid/quarkus-dev/CAG%3D-wFPwfZ9kjbbpPjgha9Z2U186%2BAnoiO-fi%3Dt4k3iSv5SXng%40mail.gmail.com.

[Luca Masini]

Hi Stuart, thank you for clarifying that, I'll remember for future reference.

All the application is under basic-auth using:

quarkus.http.auth.basic=true

but only this endpoint doesn't execute the first reactive stage on the event-thread.

I tried many ways to reproduce without the real app with no success.

Any hint to understand what is going on is welcome.

[John O'Hara]

You could use a byteman (https://byteman.jboss.org/) rule to dump a stack trace at the context switch;

RULE trace executor context switch

CLASS org.jboss.threads.EnhancedQueueExecutor

METHOD execute

AT ENTRY
IF true

DO traceStack("Context Switch: \n");

ENDRULE

and run the app with `-javaagent:${BYTEMAN_HOME}/lib/byteman.jar=script:/tmp/contextSwitch.btm` The stack trace will show you where the switch occurs

To view this discussion on the web visit https://groups.google.com/d/msgid/quarkus-dev/CAG%3D-wFNHM8gRGe_AXpx0jn9sVWTokQP3fW0mUsp-qcfgdJgL4A%40mail.gmail.com.

--

John O'Hara

Principal Software Engineer, Middleware (Performance)

Red Hat

[Luca Masini]

Byteman is GREAT !!

That's the stacktrace:

Context Switch:
org.jboss.threads.EnhancedQueueExecutor.execute(EnhancedQueueExecutor.java:-1)
io.quarkus.security.runtime.IdentityProviderManagerCreator$1.execute(IdentityProviderManagerCreator.java:49)
io.quarkus.security.runtime.QuarkusIdentityProviderManagerImpl$1$1$1.accept(QuarkusIdentityProviderManagerImpl.java:54)
io.quarkus.security.runtime.QuarkusIdentityProviderManagerImpl$1$1$1.accept(QuarkusIdentityProviderManagerImpl.java:51)
io.smallrye.context.impl.wrappers.SlowContextualConsumer.accept(SlowContextualConsumer.java:21)
io.smallrye.mutiny.operators.uni.builders.UniCreateWithEmitter.subscribe(UniCreateWithEmitter.java:22)
io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
io.smallrye.mutiny.operators.uni.builders.UniCreateFromDeferredSupplier.subscribe(UniCreateFromDeferredSupplier.java:36)
io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
io.smallrye.mutiny.operators.uni.UniMemoizeOp.subscribe(UniMemoizeOp.java:76)
io.smallrye.mutiny.operators.AbstractUni.subscribe(AbstractUni.java:36)
io.smallrye.mutiny.groups.UniSubscribe.withSubscriber(UniSubscribe.java:50)
io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$2.handle(HttpSecurityRecorder.java:104)
io.quarkus.vertx.http.runtime.security.HttpSecurityRecorder$2.handle(HttpSecurityRecorder.java:51)

it seems that @Stuart Douglas was right, but the question is why this happens only on this reactive endpoint.....

I'll dig inside the code.

Thank you John.