追記: こちらの記事は執筆時点(2019/12/20)での Quarkus 最新バージョンであった 1.0.1.Final の動作を元に記載されていました。しかし、その後に以下の修正によって Quarkus 1.1.0.Final 以降からは、Quarkus RESTEasy では Vert.x スレッドプールは使われなくなり、Servlet 依存の有無によらず quarkus.thread-pool.max-threads で設定される main のスレッドプールが利用されるように動作が変更されました。
Red Hat で JBoss ミドルウェアのサポートをしている三浦です。この記事は赤帽エンジニア Advent Calendar 2019の20日目のエントリです。
Quarkus の HTTP レイヤーのスレッドプールについて書きたいと思います。
TL; DR
- Quarkus の HTTP レイヤーは Vert.x ベースになっている
- Vert.x 関連スレッドプールの設定は
quarkus.vertx.event-loops-pool-size/quarkus.vertx.worker-pool-sizeプロパティで調整可能 - 依存関係に Servlet があると、Undertow を利用する実装にフォールバックして、
quarkus.thread-pool.max-threadsで設定される別スレッドプール が利用される - プロパティの設定および確認には
quarkus:generate-configが便利
Quarkus の HTTP レイヤーの実装
Quarkus の HTTP レイヤーの実装は、2019/12/20 現時点で最新の 1.0.1 になるまでにバージョンによって以下のような変遷をとげてきています。
- 0.22 まで: JAX-RS/Servlet アプリケーションなどのHTTPリクエスト処理は Undertow/XNIO を経由して行われていた (Reactive系のアプリケーションで明示的に Vert.x を使った場合を除く)
- 0.23 以降: すべてのHTTPリクエスト処理は Vert.x を経由するように変更された
- さらに 0.24 以降で、JAX-RS アプリケーションにおいて Servlet API が不要であれば、Undertow を経由することなく直接 Vert.x 上で処理されるように変更された
JAX-RS アプリケーションで Servlet API を利用したい場合には、依存ライブラリとして quarkus-undertow を追加することで可能です。依存関係に quarkus-undertow があることが検知された場合には、Quarkus は自動的に JAX-RS 実装である RESTEasy が Servlet 上で動くようにフォールバックする挙動になっています。
なお、この Quarkus における Servlet 実装は Undertow ベースのままですが、実態は Undertow 3.x となる予定だったものからフォークした Vert.x based Undertow となっています。
Quarkus/JAX-RSアプリケーションで確認する
まずは、 https://code.quarkus.io/ で "RESTEasy JAX-RS" のみを選択してサンプルの maven プロジェクトを生成して動かしてみましょう。
code-with-quarkus.zip が生成されるので、それを展開して以下のコマンドでコンパイルして Hot Reloading が有効な Quarkus Dev モードで動かします。
$ ./mvnw compile quarkus:dev
サンプルプロジェクトの src/main/java/org/acme/ExampleResource.java の hello() メソッドにスレッド名や呼び出しのスタックトレースを出力するログを追加します。
... import org.jboss.logging.Logger; @Path("/hello") public class ExampleResource { Logger logger = Logger.getLogger(getClass()); @GET @Produces(MediaType.TEXT_PLAIN) public String hello() { logger.infof(new Throwable(), "ExampleResource#hello() is invoked : thread name [%s], thread class name [%s]", Thread.currentThread().getName(), Thread.currentThread().getClass().getName()); return "hello"; } }
これで http://localhost:8080/hello にアクセスしてみると、ログから以下のように vert.x-worker-thread-N というブロッキングな処理を行うための worker スレッドプール上で実行されていることがわかります。
2019-12-01 17:39:29,744 INFO [org.acm.ExampleResource] (vert.x-worker-thread-1) ExampleResource#hello() is invoked : thread name [vert.x-worker-thread-1], thread class name [io.vertx.core.impl.VertxThread]: java.lang.Throwable
at org.acme.ExampleResource.hello(ExampleResource.java:21)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:151)
at org.jboss.resteasy.core.MethodInjectorImpl.lambda$invoke$3(MethodInjectorImpl.java:122)
at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616)
at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:628)
at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1996)
at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:110)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:122)
at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:594)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:468)
at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:421)
at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:363)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:423)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:391)
at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invoke$1(ResourceMethodInvoker.java:365)
at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:995)
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2137)
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:110)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:365)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:477)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:252)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:153)
at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:363)
at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:156)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:238)
at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:118)
at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.lambda$handle$0(VertxRequestHandler.java:74)
at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$2(ContextImpl.java:316)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)
Quarkus のソースコードを確認すると、 io.quarkus.resteasy.runtime.standalone.VertxRequestHandler#handle() にて Vertx#executeBlocking() が呼び出されて、ブロッキングな処理を行うスレッドである vert.x-worker-thread-N に処理が渡されていることがわかります。
Vert.x関連スレッドプールとハングスレッド検知機能
この時点でスレッドダンプをとってみると、Vert.x 関連スレッドとして以下のようなスレッドが存在することがわかります。
"vert.x-worker-thread-1" #50 prio=5 os_prio=0 tid=0x00007f0e20186000 nid=0x7945 waiting on condition [0x00007f0e66aed000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000068d73f5b0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)
"vert.x-internal-blocking-0" #49 prio=5 os_prio=0 tid=0x00007f0e20185800 nid=0x7944 waiting on condition [0x00007f0e676f9000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000068d73f890> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)
"vert.x-worker-thread-0" #47 prio=5 os_prio=0 tid=0x00007f0e20162800 nid=0x7942 waiting on condition [0x00007f0e671f4000]
java.lang.Thread.State: WAITING (parking)
at sun.misc.Unsafe.park(Native Method)
- parking to wait for <0x000000068d73f5b0> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)
...
"vert.x-acceptor-thread-0" #44 prio=5 os_prio=0 tid=0x00007f0e200e5800 nid=0x783e runnable [0x00007f0e679fc000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
- locked <0x000000068d63ad38> (a io.netty.channel.nio.SelectedSelectionKeySet)
- locked <0x000000068d63be38> (a java.util.Collections$UnmodifiableSet)
- locked <0x000000068d63bd60> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:824)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:457)
at io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1044)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)
...
"vert.x-eventloop-thread-0" #36 prio=5 os_prio=0 tid=0x00007f0e908ca800 nid=0x7836 runnable [0x00007f0e674f7000]
java.lang.Thread.State: RUNNABLE
at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)
at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)
at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
- locked <0x000000068d78ba98> (a io.netty.channel.nio.SelectedSelectionKeySet)
- locked <0x000000068d78cba8> (a java.util.Collections$UnmodifiableSet)
- locked <0x000000068d78cac0> (a sun.nio.ch.EPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62)
at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:824)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:457)
at io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1044)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)
それぞれ大雑把に書くと、以下のような役割で動くスレッドです。
vert.x-acceptor-thread: TCP接続を受け付けるスレッドvert.x-eventloop-thread: ノンブロッキングIOを処理する EventLoop スレッドvert.x-worker-thread: ブロッキングな処理を行う Worker スレッド。executeBlocking()を呼び出すことでディスパッチされる。vert.x-internal-blocking: 通常のアプリで利用されるものではなく、内部で行われるブロッキングな処理(ファイルシステムからの読み込み処理など)を行うためのスレッド
vert.x-eventloop-thread、 vert.x-worker-thread および vert.x-internal-blocking のプールサイズは application.properties で以下のようなプロパティにて設定できます。
quarkus.vertx.event-loops-pool-size:vert.x-eventloop-threadのプールサイズ設定。デフォルトではCPUコア数 x 2。quarkus.vertx.worker-pool-size:vert.x-worker-threadのプールサイズ設定。デフォルトでは20。quarkus.vertx.internal-blocking-pool-size:vert.x-internal-blockingのプールサイズ設定。デフォルトでは20。
なお、application.properties に設定できるパラメータはQuarkus ドキュメントの All Config ページで確認できます。ただ、現時点のプロジェクトで関連する設定パラメータは quarkus:generate-config を実行することで src/main/resources/application.properties.example を生成でき、その application.properties.example の中にコメントアウトされた形で関連する設定パラメータが入っています。
そのため、これを application.properties にリネームして利用するか、適宜必要なものをコピーして使う方法が簡単だと思います。
$ ./mvnw quarkus:generate-config
生成された application.properties.example には、たとえば以下のように説明付きでリストされます。
# # The number of event loops. 2 x the number of core by default. # #quarkus.vertx.event-loops-pool-size= ... # # The size of the internal thread pool (used for the file system). # #quarkus.vertx.internal-blocking-pool-size=20 ... # # The size of the worker thread pool. # #quarkus.vertx.worker-pool-size=20
application.properties.example を見ていると、quarkus.vertx.max-worker-execute-time と quarkus.vertx.warning-exception-time といったパラメータがあることに気づきます。これは worker スレッドで処理に指定時間以上かかっているものをWARNログで出力するという機能に関連するパラメータです。なお、quarkus.vertx.max-worker-execute-time のコメントではデフォルト10s(=10秒)となっていますが、実際には60s(=60秒)です。
# # The maximum amount of time the worker thread can be blocked. # Default is 10s. # #quarkus.vertx.max-worker-execute-time= # # The amount of time before a warning is displayed if the event loop is blocked. # #quarkus.vertx.warning-exception-time=2
この機能を実際に試してみましょう。application.properties には以下のように 5s (=5秒) と指定してみます。なお、現時点で確認する限りは、quarkus.vertx.max-worker-execute-time などの変更は Hot Reloading が効かなかったので、一度停止してから起動しなおす必要があります。
quarkus.vertx.max-worker-execute-time=5s
src/main/java/org/acme/ExampleResource.java を以下のように10秒スリープするコードをいれます。
... import java.util.concurrent.TimeUnit; import org.jboss.logging.Logger; @Path("/hello") public class ExampleResource { Logger logger = Logger.getLogger(getClass()); @GET @Produces(MediaType.TEXT_PLAIN) public String hello() { logger.infof(new Throwable(), "ExampleResource#hello() is invoked : thread name [%s], thread class name [%s]", Thread.currentThread().getName(), Thread.currentThread().getClass().getName()); try { long duration = 10L; logger.info("sleeping " + duration + " seconds..."); TimeUnit.SECONDS.sleep(duration); logger.info("done!"); } catch (InterruptedException ignore) {} return "hello"; } }
これで http://localhost:8080/hello にアクセスしてみると、max-worker-execute-time 設定値の5秒経過後に、ハングしているスレッド名、何秒ハングしているかがスタックトレースとともに WARN ログに出力されることが確認できます。その後も引き続きスレッドのハングが継続していた場合には、 max-worker-execute-time の2秒(デフォルト値の)を経過するごとに出力されます。
2019-12-01 21:12:27,781 INFO [org.acm.ExampleResource] (vert.x-worker-thread-1) sleeping 10 seconds
2019-12-01 21:12:33,617 WARNING [io.ver.cor.imp.BlockedThreadChecker] (vertx-blocked-thread-checker) Thread Thread[vert.x-worker-thread-1,5,main]=Thread[vert.x-worker-thread-1,5,main] has been blocked for 5857 ms, time limit is 5000 ms: io.vertx.core.VertxException: Thread blocked
at java.lang.Thread.sleep(Native Method)
at java.lang.Thread.sleep(Thread.java:340)
at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
at org.acme.ExampleResource.hello(ExampleResource.java:30)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:151)
at org.jboss.resteasy.core.MethodInjectorImpl.lambda$invoke$3(MethodInjectorImpl.java:122)
at org.jboss.resteasy.core.MethodInjectorImpl$$Lambda$316/1812743798.apply(Unknown Source)
at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616)
at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:628)
at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1996)
at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:110)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:122)
at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:594)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:468)
at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:421)
at org.jboss.resteasy.core.ResourceMethodInvoker$$Lambda$315/408648673.get(Unknown Source)
at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:363)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:423)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:391)
at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invoke$1(ResourceMethodInvoker.java:365)
at org.jboss.resteasy.core.ResourceMethodInvoker$$Lambda$314/12574409.apply(Unknown Source)
at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:995)
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2137)
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:110)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:365)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:477)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:252)
at org.jboss.resteasy.core.SynchronousDispatcher$$Lambda$310/1423111402.run(Unknown Source)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:153)
at org.jboss.resteasy.core.SynchronousDispatcher$$Lambda$311/905682736.get(Unknown Source)
at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:363)
at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:156)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:238)
at io.quarkus.resteasy.runtime.standalone.RequestDispatcher.service(RequestDispatcher.java:73)
at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.dispatch(VertxRequestHandler.java:118)
at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler.lambda$handle$0(VertxRequestHandler.java:74)
at io.quarkus.resteasy.runtime.standalone.VertxRequestHandler$$Lambda$308/650568468.handle(Unknown Source)
at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$2(ContextImpl.java:316)
at io.vertx.core.impl.ContextImpl$$Lambda$302/216113056.run(Unknown Source)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)
2019-12-01 21:12:35,617 WARNING [io.ver.cor.imp.BlockedThreadChecker] (vertx-blocked-thread-checker) Thread Thread[vert.x-worker-thread-1,5,main]=Thread[vert.x-worker-thread-1,5,main] has been blocked for 7858 ms, time limit is 5000 ms: io.vertx.core.VertxException: Thread blocked
at java.lang.Thread.sleep(Native Method)
at java.lang.Thread.sleep(Thread.java:340)
at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
at org.acme.ExampleResource.hello(ExampleResource.java:30)
...(上と同じなので省略)...
2019-12-01 21:12:37,617 WARNING [io.ver.cor.imp.BlockedThreadChecker] (vertx-blocked-thread-checker) Thread Thread[vert.x-worker-thread-1,5,main]=Thread[vert.x-worker-thread-1,5,main] has been blocked for 9858 ms, time limit is 5000 ms: io.vertx.core.VertxException: Thread blocked
at java.lang.Thread.sleep(Native Method)
at java.lang.Thread.sleep(Thread.java:340)
at java.util.concurrent.TimeUnit.sleep(TimeUnit.java:386)
at org.acme.ExampleResource.hello(ExampleResource.java:30)
...(上と同じなので省略)...
2019-12-01 21:12:37,781 INFO [org.acm.ExampleResource] (vert.x-worker-thread-1) done!
Quarkus/JAX-RS アプリケーションで Servlet 依存を追加したときにどう変わる？
前述したように、依存関係に quarkus-undertow を追加することで、自動的に Servlet API を利用すると認識され、Vert.x based Undertow 上で処理されるようになります。この場合の動作も確認してみます。
既存プロジェクトへの quarkus-undertow 依存の追加は quarkus:add-extension で以下のように実行すればできます。
$ ./mvnw quarkus:add-extension -Dextensions=quarkus-undertow
これで pom.xml に quarkus-undertow への依存が追加されます。
<dependencies> <dependency> <groupId>io.quarkus</groupId> <artifactId>quarkus-resteasy</artifactId> </dependency> <dependency> <groupId>io.quarkus</groupId> <artifactId>quarkus-junit5</artifactId> <scope>test</scope> </dependency> <dependency> <groupId>io.rest-assured</groupId> <artifactId>rest-assured</artifactId> <scope>test</scope> </dependency> <!-- 以下の依存が追加される --> <dependency> <groupId>io.quarkus</groupId> <artifactId>quarkus-undertow</artifactId> </dependency> </dependencies>
これで起動してアクセスしてみます。依存を追加した以外、コードや設定は上で書いたもののままです。
2019-12-01 22:51:07,912 INFO [org.acm.ExampleResource] (executor-thread-1) ExampleResource#hello() is invoked : thread name [executor-thread-1], thread class name [org.jboss.threads.JBossThread]: java.lang.Throwable
at org.acme.ExampleResource.hello(ExampleResource.java:21)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:151)
at org.jboss.resteasy.core.MethodInjectorImpl.lambda$invoke$3(MethodInjectorImpl.java:122)
at java.util.concurrent.CompletableFuture.uniApply(CompletableFuture.java:616)
at java.util.concurrent.CompletableFuture.uniApplyStage(CompletableFuture.java:628)
at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:1996)
at java.util.concurrent.CompletableFuture.thenApply(CompletableFuture.java:110)
at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:122)
at org.jboss.resteasy.core.ResourceMethodInvoker.internalInvokeOnTarget(ResourceMethodInvoker.java:594)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTargetAfterFilter(ResourceMethodInvoker.java:468)
at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invokeOnTarget$2(ResourceMethodInvoker.java:421)
at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:363)
at org.jboss.resteasy.core.ResourceMethodInvoker.invokeOnTarget(ResourceMethodInvoker.java:423)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:391)
at org.jboss.resteasy.core.ResourceMethodInvoker.lambda$invoke$1(ResourceMethodInvoker.java:365)
at java.util.concurrent.CompletableFuture.uniComposeStage(CompletableFuture.java:995)
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:2137)
at java.util.concurrent.CompletableFuture.thenCompose(CompletableFuture.java:110)
at org.jboss.resteasy.core.ResourceMethodInvoker.invoke(ResourceMethodInvoker.java:365)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:477)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$invoke$4(SynchronousDispatcher.java:252)
at org.jboss.resteasy.core.SynchronousDispatcher.lambda$preprocess$0(SynchronousDispatcher.java:153)
at org.jboss.resteasy.core.interception.jaxrs.PreMatchContainerRequestContext.filter(PreMatchContainerRequestContext.java:363)
at org.jboss.resteasy.core.SynchronousDispatcher.preprocess(SynchronousDispatcher.java:156)
at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:238)
at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:249)
at io.quarkus.resteasy.runtime.ResteasyFilter$ResteasyResponseWrapper.sendError(ResteasyFilter.java:65)
at io.undertow.servlet.handlers.DefaultServlet.doGet(DefaultServlet.java:172)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:503)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:590)
at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:74)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:129)
at io.quarkus.resteasy.runtime.ResteasyFilter.doFilter(ResteasyFilter.java:28)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:61)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:131)
at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:84)
at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:63)
at io.undertow.servlet.handlers.ServletChain$1.handleRequest(ServletChain.java:68)
at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:133)
at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:57)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:46)
at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:65)
at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:60)
at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:77)
at io.undertow.security.handlers.NotificationReceiverHandler.handleRequest(NotificationReceiverHandler.java:50)
at io.undertow.security.handlers.AbstractSecurityContextAssociationHandler.handleRequest(AbstractSecurityContextAssociationHandler.java:43)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:43)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:270)
at io.undertow.servlet.handlers.ServletInitialHandler.access$100(ServletInitialHandler.java:59)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:116)
at io.undertow.servlet.handlers.ServletInitialHandler$2.call(ServletInitialHandler.java:113)
at io.undertow.servlet.core.ServletRequestContextThreadSetupAction$1.call(ServletRequestContextThreadSetupAction.java:48)
at io.undertow.servlet.core.ContextClassLoaderSetupAction$1.call(ContextClassLoaderSetupAction.java:43)
at io.quarkus.undertow.runtime.UndertowDeploymentRecorder$9$1$1.call(UndertowDeploymentRecorder.java:475)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:250)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:59)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:82)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:290)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:669)
at io.quarkus.runtime.CleanableExecutor$CleaningRunnable.run(CleanableExecutor.java:224)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at org.jboss.threads.ContextClassLoaderSavingRunnable.run(ContextClassLoaderSavingRunnable.java:35)
at org.jboss.threads.EnhancedQueueExecutor.safeRun(EnhancedQueueExecutor.java:2011)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.doRunTask(EnhancedQueueExecutor.java:1535)
at org.jboss.threads.EnhancedQueueExecutor$ThreadBody.run(EnhancedQueueExecutor.java:1395)
at org.jboss.threads.DelegatingRunnable.run(DelegatingRunnable.java:29)
at org.jboss.threads.ThreadLocalResettingRunnable.run(ThreadLocalResettingRunnable.java:29)
at java.lang.Thread.run(Thread.java:748)
at org.jboss.threads.JBossThread.run(JBossThread.java:479)
2019-12-01 22:51:07,913 INFO [org.acm.ExampleResource] (executor-thread-1) sleeping 10 seconds
2019-12-01 22:51:17,913 INFO [org.acm.ExampleResource] (executor-thread-1) done!
スタックトレースから Undertow 上で実行され、また、スレッド名も vert.x-worker-thread-N ではなく executor-thread-N という別なスレッドプールが利用されるように変わっていることが確認できます。また、Vert.x の worker スレッド上ではないため、max-worker-execute-time 設定による WARN ログも出なくなったことがわかります。
このスレッドプールは、Vert.x 関連とは異なる以下のプロパティで設定できるものが利用されています。依存関係の違いでアプリケーション処理で利用されるスレッドプールが変わるというのはチューニングする際に落とし穴になりそうですね。
quarkus.thread-pool.max-threads: スレッドプールの最大サイズ。デフォルトではCPUコア数 x 8。quarkus.thread-pool.core-threads: スレッドプールの最小サイズ。デフォルトでは1。quarkus.thread-pool.keep-alive-time: 使用されていないスレッドを保持しておく時間(単位は秒)。この時間を経過したスレッドは最小サイズまで破棄される。デフォルトは30(秒)。
